`kubernetes_logs` source seems to fail to annotate when pod names are reused #13467

jszwedko · 2022-07-07T15:17:21Z

A note for the community

Please vote on this issue by adding a 👍 reaction to the original issue to help the community and maintainers prioritize this request
If you are interested in working on this issue or have submitted a pull request, please leave a comment

Problem

Vector seems to fail to annotate logs from the kubernetes_logs source when pod names are reused. I didn't reproduce this, but there are a few comments (in the references section) that seem to indicate this is the case.

One hypothesis is that

vector/src/sources/kubernetes_logs/pod_metadata_annotator.rs

Line 100 in aee1984

    
           let obj = ObjectRef::<Pod>::new(file_info.pod_name).within(file_info.pod_namespace);

should be looking up by the uid as well (under extra) rather than just name and namespace.

Configuration

No response

Version

vector 0.22.3

Debug Output

No response

Example Data

No response

Additional Context

No response

References

The text was updated successfully, but these errors were encountered:

r0b3r4 · 2022-07-29T19:17:21Z

Hello. Any updates here? We are suffering :(

jszwedko · 2022-07-29T19:48:03Z

Hi @r0b3r4 ! Unfortunately not yet, but it is on our backlog. We are also happy to help guide a contribution if someone has the time and ability to address it.

sillent · 2022-08-05T11:56:37Z

Hello,

Error

Failed to annotate event with pod metadata

is happened here

vector/src/sources/kubernetes_logs/mod.rs

Line 498 in c402e6e

if file_info.is_none() {

and None is maybe happened here

vector/src/sources/kubernetes_logs/pod_metadata_annotator.rs

Line 99 in c402e6e

let file_info = parse_log_file_path(file)?;

or here

vector/src/sources/kubernetes_logs/pod_metadata_annotator.rs

Line 101 in c402e6e

let resource = self.pods_state_reader.get(&obj)?;

Second variant is more suitable

And i think it's happened because stored information about pod is deleted with event Deleted

vector/src/kubernetes/reflector.rs

Line 38 in c402e6e

watcher::Event::Deleted(_) => {

After pod is deleted (some one wrote that problem is appear when the pod scale down and up and it's name is the same) event Delete is delayed.
The new event Create, store information about new created pod into Store, but when delay timer exceeded - the information about old pod with the same name is deleted, and because new pod has the same name from Store deleted information about new create pod
And code
self.pods_state_reader.get(&obj)?;
return None

It's just my opinion based on my investigation of the problem.
I cannot reproduce the problem by myself, and my opinion it's just a theory

sillent · 2022-08-10T05:52:29Z

comment:
@jszwedko

One hypothesis is that
...
should be looking up by the uid as well (under extra) rather than just name and namespace

I think it won't work

We can't take uid, that presented in Kubernetes Resource

he looks like this
uid: 5751f785-5689-4868-a573-d9e0096821ff
but the pod_uid that we can get from file_info is not that uid that we need

extra not implement Hash and PartialEq

https://github.com/kube-rs/kube-rs/blob/bf885f05c39c046f68e34f19b95402d3326c1715/kube-runtime/src/reflector/object_ref.rs#L56

and when we try

vector/src/sources/kubernetes_logs/pod_metadata_annotator.rs

Line 101 in c402e6e

let resource = self.pods_state_reader.get(&obj)?;

the method at work will not be based on the data of this field

jszwedko · 2022-08-12T18:40:28Z

Thanks @sillent . It does appear to be the case that the extra data isn't included in comparisons of pod info. That strikes me as a bit odd. I wonder if we should open an issue upstream on kube-rs to get their thoughts around this.

shenxn · 2022-08-31T13:44:05Z

Maybe we should consider having our own metadata cache based on uid instead of changing the event order of kube-rs store. It seems that the whole kube-rs is built around resource names instead of uids so it can be hard to just add uid support.

zhongzc · 2022-10-10T10:35:18Z

I have steps to reproduce the problem. Hope it helps.

Arch: x86_64
OS: Ubuntu 20.04

Install minikube & helm

curl -LO https://storage.googleapis.com/minikube/releases/latest/minikube-linux-amd64
sudo install minikube-linux-amd64 /usr/local/bin/minikube
minikube start

curl https://raw.githubusercontent.com/helm/helm/main/scripts/get-helm-3 | bash

Install vector using helm

helm repo add vector https://helm.vector.dev
helm repo update

cat <<EOF > values.yaml
role: Agent
service:
  enabled: false
image:
  pullPolicy: IfNotPresent
  repository: timberio/vector
  tag: 0.24.1-distroless-libc
customConfig:
  data_dir: /vector-data-dir
  api:
    enabled: true
    address: 127.0.0.1:8686
    playground: false
  sources:
    kubernetes_logs:
      type: kubernetes_logs
      extra_field_selector: "metadata.namespace=app"
      delay_deletion_ms: 30000
      glob_minimum_cooldown_ms: 5000
  sinks:
    stdout:
      type: blackhole
      inputs: [kubernetes_logs]
      print_interval_secs: 1
EOF

helm install vector vector/vector --namespace vector --create-namespace --values values.yaml

Deploy a StatefulSet that generates logs

cat <<EOF > stateful.yaml
apiVersion: apps/v1
kind: StatefulSet
metadata:
  name: flog
  namespace: app
spec:
  selector:
    matchLabels:
      app: flog
  serviceName: flog
  template:
    metadata:
      labels:
        app: flog
    spec:
      containers:
      - name: flog
        image: mingrammer/flog
        imagePullPolicy: IfNotPresent
        command: ['/bin/flog', '--delay', '300ms', '--loop']
EOF

kubectl create namespace app
kubectl apply -f stateful.yaml

Wait a few seconds and restart StatefulSet

kubectl rollout restart statefulset flog -n app

After delay_deletion_ms (30s), got errors and no longer watching the file

kubectl logs -n vector daemonset/vector -f

...
2022-10-11T07:18:50.138699Z  INFO vector::sinks::blackhole::sink: Total events collected events=0 raw_bytes_collected=0
2022-10-11T07:18:51.139505Z  INFO vector::sinks::blackhole::sink: Total events collected events=0 raw_bytes_collected=0
2022-10-11T07:18:52.138783Z  INFO vector::sinks::blackhole::sink: Total events collected events=0 raw_bytes_collected=0
2022-10-11T07:18:53.139386Z  INFO vector::sinks::blackhole::sink: Total events collected events=0 raw_bytes_collected=0
2022-10-11T07:18:54.139460Z  INFO vector::sinks::blackhole::sink: Total events collected events=0 raw_bytes_collected=0
2022-10-11T07:18:55.139002Z  INFO vector::sinks::blackhole::sink: Total events collected events=0 raw_bytes_collected=0
2022-10-11T07:18:55.385353Z  INFO source{component_kind="source" component_id=kubernetes_logs component_type=kubernetes_logs component_name=kubernetes_logs}:file_server: vector::internal_events::file::source: Found new file to watch. file=/var/log/pods/app_flog-0_41bb0f6a-a088-472f-abab-2cc656ce5a55/flog/0.log
2022-10-11T07:18:56.139296Z  INFO vector::sinks::blackhole::sink: Total events collected events=17 raw_bytes_collected=63827
2022-10-11T07:18:57.139732Z  INFO vector::sinks::blackhole::sink: Total events collected events=21 raw_bytes_collected=78965
2022-10-11T07:18:58.138776Z  INFO vector::sinks::blackhole::sink: Total events collected events=23 raw_bytes_collected=86516
2022-10-11T07:18:59.138964Z  INFO vector::sinks::blackhole::sink: Total events collected events=27 raw_bytes_collected=101657
2022-10-11T07:19:00.139495Z  INFO vector::sinks::blackhole::sink: Total events collected events=30 raw_bytes_collected=112995
2022-10-11T07:19:01.139166Z  INFO vector::sinks::blackhole::sink: Total events collected events=33 raw_bytes_collected=124380
2022-10-11T07:19:02.139552Z  INFO vector::sinks::blackhole::sink: Total events collected events=37 raw_bytes_collected=139510
2022-10-11T07:19:03.139134Z  INFO vector::sinks::blackhole::sink: Total events collected events=40 raw_bytes_collected=150888
2022-10-11T07:19:04.139703Z  INFO vector::sinks::blackhole::sink: Total events collected events=44 raw_bytes_collected=166004
2022-10-11T07:19:05.139373Z  INFO vector::sinks::blackhole::sink: Total events collected events=47 raw_bytes_collected=177326
2022-10-11T07:19:06.139341Z  INFO vector::sinks::blackhole::sink: Total events collected events=51 raw_bytes_collected=192442
2022-10-11T07:19:07.139243Z  INFO vector::sinks::blackhole::sink: Total events collected events=53 raw_bytes_collected=200011
2022-10-11T07:19:08.139022Z  INFO vector::sinks::blackhole::sink: Total events collected events=56 raw_bytes_collected=211358
2022-10-11T07:19:09.138961Z  INFO vector::sinks::blackhole::sink: Total events collected events=60 raw_bytes_collected=226545
2022-10-11T07:19:10.138944Z  INFO vector::sinks::blackhole::sink: Total events collected events=62 raw_bytes_collected=234098
2022-10-11T07:19:11.139492Z  INFO vector::sinks::blackhole::sink: Total events collected events=62 raw_bytes_collected=234098
2022-10-11T07:19:11.511156Z  WARN source{component_kind="source" component_id=kubernetes_logs component_type=kubernetes_logs component_name=kubernetes_logs}:file_server: vector::internal_events::file::source: Currently ignoring file too small to fingerprint. file=/var/log/pods/app_flog-0_976669c2-8cd7-41b5-9a13-bd481c386c7f/flog/0.log
2022-10-11T07:19:11.511228Z  INFO source{component_kind="source" component_id=kubernetes_logs component_type=kubernetes_logs component_name=kubernetes_logs}:file_server: vector::internal_events::file::source: Stopped watching file. file=/var/log/pods/app_flog-0_41bb0f6a-a088-472f-abab-2cc656ce5a55/flog/0.log
2022-10-11T07:19:12.139431Z  INFO vector::sinks::blackhole::sink: Total events collected events=62 raw_bytes_collected=234098
2022-10-11T07:19:13.139277Z  INFO vector::sinks::blackhole::sink: Total events collected events=62 raw_bytes_collected=234098
2022-10-11T07:19:14.139486Z  INFO vector::sinks::blackhole::sink: Total events collected events=62 raw_bytes_collected=234098
2022-10-11T07:19:15.139013Z  INFO vector::sinks::blackhole::sink: Total events collected events=62 raw_bytes_collected=234098
2022-10-11T07:19:16.139594Z  INFO vector::sinks::blackhole::sink: Total events collected events=62 raw_bytes_collected=234098
2022-10-11T07:19:17.139294Z  INFO vector::sinks::blackhole::sink: Total events collected events=62 raw_bytes_collected=234098
2022-10-11T07:19:17.658813Z  INFO source{component_kind="source" component_id=kubernetes_logs component_type=kubernetes_logs component_name=kubernetes_logs}:file_server: vector::internal_events::file::source: Found new file to watch. file=/var/log/pods/app_flog-0_976669c2-8cd7-41b5-9a13-bd481c386c7f/flog/0.log
2022-10-11T07:19:18.139459Z  INFO vector::sinks::blackhole::sink: Total events collected events=83 raw_bytes_collected=317571
2022-10-11T07:19:19.139381Z  INFO vector::sinks::blackhole::sink: Total events collected events=86 raw_bytes_collected=329623
2022-10-11T07:19:20.139517Z  INFO vector::sinks::blackhole::sink: Total events collected events=90 raw_bytes_collected=345653
2022-10-11T07:19:21.139715Z  INFO vector::sinks::blackhole::sink: Total events collected events=93 raw_bytes_collected=357649
2022-10-11T07:19:22.138940Z  INFO vector::sinks::blackhole::sink: Total events collected events=97 raw_bytes_collected=373676
2022-10-11T07:19:23.139384Z  INFO vector::sinks::blackhole::sink: Total events collected events=100 raw_bytes_collected=385710
2022-10-11T07:19:24.138941Z  INFO vector::sinks::blackhole::sink: Total events collected events=103 raw_bytes_collected=397726
2022-10-11T07:19:25.139395Z  INFO vector::sinks::blackhole::sink: Total events collected events=107 raw_bytes_collected=413761
2022-10-11T07:19:26.138829Z  INFO vector::sinks::blackhole::sink: Total events collected events=110 raw_bytes_collected=425802
2022-10-11T07:19:27.139129Z  INFO vector::sinks::blackhole::sink: Total events collected events=113 raw_bytes_collected=437853
2022-10-11T07:19:28.139585Z  INFO vector::sinks::blackhole::sink: Total events collected events=117 raw_bytes_collected=453871
2022-10-11T07:19:29.138723Z  INFO vector::sinks::blackhole::sink: Total events collected events=119 raw_bytes_collected=461851
2022-10-11T07:19:30.139117Z  INFO vector::sinks::blackhole::sink: Total events collected events=123 raw_bytes_collected=477880
2022-10-11T07:19:31.139719Z  INFO vector::sinks::blackhole::sink: Total events collected events=126 raw_bytes_collected=489856
2022-10-11T07:19:32.139152Z  INFO vector::sinks::blackhole::sink: Total events collected events=130 raw_bytes_collected=505897
2022-10-11T07:19:33.138772Z  INFO vector::sinks::blackhole::sink: Total events collected events=133 raw_bytes_collected=517883
2022-10-11T07:19:34.139463Z  INFO vector::sinks::blackhole::sink: Total events collected events=137 raw_bytes_collected=533925
2022-10-11T07:19:35.139263Z  INFO vector::sinks::blackhole::sink: Total events collected events=140 raw_bytes_collected=545969
2022-10-11T07:19:36.139564Z  INFO vector::sinks::blackhole::sink: Total events collected events=143 raw_bytes_collected=558021
2022-10-11T07:19:37.139875Z  INFO vector::sinks::blackhole::sink: Total events collected events=147 raw_bytes_collected=574050
2022-10-11T07:19:38.138709Z  INFO vector::sinks::blackhole::sink: Total events collected events=150 raw_bytes_collected=586065
2022-10-11T07:19:39.139025Z  INFO vector::sinks::blackhole::sink: Total events collected events=153 raw_bytes_collected=598091
2022-10-11T07:19:40.139408Z  INFO vector::sinks::blackhole::sink: Total events collected events=157 raw_bytes_collected=614132
2022-10-11T07:19:41.131602Z ERROR source{component_kind="source" component_id=kubernetes_logs component_type=kubernetes_logs component_name=kubernetes_logs}: vector::internal_events::kubernetes_logs: Failed to annotate event with pod metadata. event=Log(LogEvent { inner: Inner { fields: Object({"file": Bytes(b"/var/log/pods/app_flog-0_976669c2-8cd7-41b5-9a13-bd481c386c7f/flog/0.log"), "message": Bytes(b"{\"log\":\"95.78.162.196 - - [11/Oct/2022:07:19:40 +0000] \\\"POST /plug-and-play/infomediaries/back-end/partnerships HTTP/2.0\\\" 502 26105\\n\",\"stream\":\"stdout\",\"time\":\"2022-10-11T07:19:40.910539473Z\"}"), "source_type": Bytes(b"kubernetes_logs"), "timestamp": Timestamp(2022-10-11T07:19:41.131434537Z)}), size_cache: AtomicCell { value: Some(641) } }, metadata: EventMetadata { value: Object({}), secrets: {}, finalizers: EventFinalizers([]), schema_definition: Definition { event_kind: Kind { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), undefined: Some(()), array: Some(Collection { known: {}, unknown: Unknown(Infinite(Infinite { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), array: Some(()), object: Some(()) })) }), object: Some(Collection { known: {}, unknown: Unknown(Infinite(Infinite { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), array: Some(()), object: Some(()) })) }) }, metadata_kind: Kind { bytes: None, integer: None, float: None, boolean: None, timestamp: None, regex: None, null: None, undefined: None, array: None, object: Some(Collection { known: {}, unknown: Unknown(Exact(Kind { bytes: None, integer: None, float: None, boolean: None, timestamp: None, regex: None, null: None, undefined: Some(()), array: None, object: None })) }) }, meaning: {}, log_namespaces: {Vector, Legacy} } } }) error_code="annotation_failed" error_type="reader_failed" stage="processing"
2022-10-11T07:19:41.138897Z  INFO vector::sinks::blackhole::sink: Total events collected events=160 raw_bytes_collected=623012
2022-10-11T07:19:41.264256Z ERROR source{component_kind="source" component_id=kubernetes_logs component_type=kubernetes_logs component_name=kubernetes_logs}: vector::internal_events::kubernetes_logs: Failed to annotate event with pod metadata. event=Log(LogEvent { inner: Inner { fields: Object({"file": Bytes(b"/var/log/pods/app_flog-0_976669c2-8cd7-41b5-9a13-bd481c386c7f/flog/0.log"), "message": Bytes(b"{\"log\":\"244.25.77.220 - - [11/Oct/2022:07:19:40 +0000] \\\"DELETE /innovative/systems/bandwidth/rich HTTP/1.1\\\" 401 212\\n\",\"stream\":\"stdout\",\"time\":\"2022-10-11T07:19:41.210739632Z\"}"), "source_type": Bytes(b"kubernetes_logs"), "timestamp": Timestamp(2022-10-11T07:19:41.264157015Z)}), size_cache: AtomicCell { value: Some(625) } }, metadata: EventMetadata { value: Object({}), secrets: {}, finalizers: EventFinalizers([]), schema_definition: Definition { event_kind: Kind { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), undefined: Some(()), array: Some(Collection { known: {}, unknown: Unknown(Infinite(Infinite { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), array: Some(()), object: Some(()) })) }), object: Some(Collection { known: {}, unknown: Unknown(Infinite(Infinite { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), array: Some(()), object: Some(()) })) }) }, metadata_kind: Kind { bytes: None, integer: None, float: None, boolean: None, timestamp: None, regex: None, null: None, undefined: None, array: None, object: Some(Collection { known: {}, unknown: Unknown(Exact(Kind { bytes: None, integer: None, float: None, boolean: None, timestamp: None, regex: None, null: None, undefined: Some(()), array: None, object: None })) }) }, meaning: {}, log_namespaces: {Vector, Legacy} } } }) error_code="annotation_failed" error_type="reader_failed" stage="processing"
2022-10-11T07:19:41.528271Z ERROR source{component_kind="source" component_id=kubernetes_logs component_type=kubernetes_logs component_name=kubernetes_logs}: vector::internal_events::kubernetes_logs: Failed to annotate event with pod metadata. event=Log(LogEvent { inner: Inner { fields: Object({"file": Bytes(b"/var/log/pods/app_flog-0_976669c2-8cd7-41b5-9a13-bd481c386c7f/flog/0.log"), "message": Bytes(b"{\"log\":\"94.186.229.214 - spencer6681 [11/Oct/2022:07:19:41 +0000] \\\"GET /strategize/compelling HTTP/1.1\\\" 304 27222\\n\",\"stream\":\"stdout\",\"time\":\"2022-10-11T07:19:41.51087386Z\"}"), "source_type": Bytes(b"kubernetes_logs"), "timestamp": Timestamp(2022-10-11T07:19:41.528173029Z)}), size_cache: AtomicCell { value: Some(622) } }, metadata: EventMetadata { value: Object({}), secrets: {}, finalizers: EventFinalizers([]), schema_definition: Definition { event_kind: Kind { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), undefined: Some(()), array: Some(Collection { known: {}, unknown: Unknown(Infinite(Infinite { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), array: Some(()), object: Some(()) })) }), object: Some(Collection { known: {}, unknown: Unknown(Infinite(Infinite { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), array: Some(()), object: Some(()) })) }) }, metadata_kind: Kind { bytes: None, integer: None, float: None, boolean: None, timestamp: None, regex: None, null: None, undefined: None, array: None, object: Some(Collection { known: {}, unknown: Unknown(Exact(Kind { bytes: None, integer: None, float: None, boolean: None, timestamp: None, regex: None, null: None, undefined: Some(()), array: None, object: None })) }) }, meaning: {}, log_namespaces: {Vector, Legacy} } } }) error_code="annotation_failed" error_type="reader_failed" stage="processing"
2022-10-11T07:19:42.048539Z ERROR source{component_kind="source" component_id=kubernetes_logs component_type=kubernetes_logs component_name=kubernetes_logs}: vector::internal_events::kubernetes_logs: Failed to annotate event with pod metadata. event=Log(LogEvent { inner: Inner { fields: Object({"file": Bytes(b"/var/log/pods/app_flog-0_976669c2-8cd7-41b5-9a13-bd481c386c7f/flog/0.log"), "message": Bytes(b"{\"log\":\"158.241.102.206 - - [11/Oct/2022:07:19:41 +0000] \\\"POST /vortals HTTP/2.0\\\" 204 5896\\n\",\"stream\":\"stdout\",\"time\":\"2022-10-11T07:19:41.811246315Z\"}"), "source_type": Bytes(b"kubernetes_logs"), "timestamp": Timestamp(2022-10-11T07:19:42.048425827Z)}), size_cache: AtomicCell { value: Some(600) } }, metadata: EventMetadata { value: Object({}), secrets: {}, finalizers: EventFinalizers([]), schema_definition: Definition { event_kind: Kind { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), undefined: Some(()), array: Some(Collection { known: {}, unknown: Unknown(Infinite(Infinite { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), array: Some(()), object: Some(()) })) }), object: Some(Collection { known: {}, unknown: Unknown(Infinite(Infinite { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), array: Some(()), object: Some(()) })) }) }, metadata_kind: Kind { bytes: None, integer: None, float: None, boolean: None, timestamp: None, regex: None, null: None, undefined: None, array: None, object: Some(Collection { known: {}, unknown: Unknown(Exact(Kind { bytes: None, integer: None, float: None, boolean: None, timestamp: None, regex: None, null: None, undefined: Some(()), array: None, object: None })) }) }, meaning: {}, log_namespaces: {Vector, Legacy} } } }) error_code="annotation_failed" error_type="reader_failed" stage="processing"
2022-10-11T07:19:42.116620Z ERROR source{component_kind="source" component_id=kubernetes_logs component_type=kubernetes_logs component_name=kubernetes_logs}: vector::internal_events::kubernetes_logs: Failed to annotate event with pod metadata. event=Log(LogEvent { inner: Inner { fields: Object({"file": Bytes(b"/var/log/pods/app_flog-0_976669c2-8cd7-41b5-9a13-bd481c386c7f/flog/0.log"), "message": Bytes(b"{\"log\":\"81.60.133.76 - - [11/Oct/2022:07:19:41 +0000] \\\"POST /next-generation/plug-and-play HTTP/1.0\\\" 501 12366\\n\",\"stream\":\"stdout\",\"time\":\"2022-10-11T07:19:42.111452547Z\"}"), "source_type": Bytes(b"kubernetes_logs"), "timestamp": Timestamp(2022-10-11T07:19:42.116528443Z)}), size_cache: AtomicCell { value: Some(620) } }, metadata: EventMetadata { value: Object({}), secrets: {}, finalizers: EventFinalizers([]), schema_definition: Definition { event_kind: Kind { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), undefined: Some(()), array: Some(Collection { known: {}, unknown: Unknown(Infinite(Infinite { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), array: Some(()), object: Some(()) })) }), object: Some(Collection { known: {}, unknown: Unknown(Infinite(Infinite { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), array: Some(()), object: Some(()) })) }) }, metadata_kind: Kind { bytes: None, integer: None, float: None, boolean: None, timestamp: None, regex: None, null: None, undefined: None, array: None, object: Some(Collection { known: {}, unknown: Unknown(Exact(Kind { bytes: None, integer: None, float: None, boolean: None, timestamp: None, regex: None, null: None, undefined: Some(()), array: None, object: None })) }) }, meaning: {}, log_namespaces: {Vector, Legacy} } } }) error_code="annotation_failed" error_type="reader_failed" stage="processing"
2022-10-11T07:19:42.139693Z  INFO vector::sinks::blackhole::sink: Total events collected events=164 raw_bytes_collected=626348
2022-10-11T07:19:42.636272Z ERROR source{component_kind="source" component_id=kubernetes_logs component_type=kubernetes_logs component_name=kubernetes_logs}: vector::internal_events::kubernetes_logs: Failed to annotate event with pod metadata. event=Log(LogEvent { inner: Inner { fields: Object({"file": Bytes(b"/var/log/pods/app_flog-0_976669c2-8cd7-41b5-9a13-bd481c386c7f/flog/0.log"), "message": Bytes(b"{\"log\":\"3.227.108.2 - runte6855 [11/Oct/2022:07:19:42 +0000] \\\"HEAD /integrate/disintermediate/productize HTTP/2.0\\\" 100 27015\\n\",\"stream\":\"stdout\",\"time\":\"2022-10-11T07:19:42.411685455Z\"}"), "source_type": Bytes(b"kubernetes_logs"), "timestamp": Timestamp(2022-10-11T07:19:42.636161954Z)}), size_cache: AtomicCell { value: Some(634) } }, metadata: EventMetadata { value: Object({}), secrets: {}, finalizers: EventFinalizers([]), schema_definition: Definition { event_kind: Kind { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), undefined: Some(()), array: Some(Collection { known: {}, unknown: Unknown(Infinite(Infinite { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), array: Some(()), object: Some(()) })) }), object: Some(Collection { known: {}, unknown: Unknown(Infinite(Infinite { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), array: Some(()), object: Some(()) })) }) }, metadata_kind: Kind { bytes: None, integer: None, float: None, boolean: None, timestamp: None, regex: None, null: None, undefined: None, array: None, object: Some(Collection { known: {}, unknown: Unknown(Exact(Kind { bytes: None, integer: None, float: None, boolean: None, timestamp: None, regex: None, null: None, undefined: Some(()), array: None, object: None })) }) }, meaning: {}, log_namespaces: {Vector, Legacy} } } }) error_code="annotation_failed" error_type="reader_failed" stage="processing"
2022-10-11T07:19:42.769753Z ERROR source{component_kind="source" component_id=kubernetes_logs component_type=kubernetes_logs component_name=kubernetes_logs}: vector::internal_events::kubernetes_logs: Failed to annotate event with pod metadata. event=Log(LogEvent { inner: Inner { fields: Object({"file": Bytes(b"/var/log/pods/app_flog-0_976669c2-8cd7-41b5-9a13-bd481c386c7f/flog/0.log"), "message": Bytes(b"{\"log\":\"117.108.17.233 - king2280 [11/Oct/2022:07:19:42 +0000] \\\"PUT /experiences HTTP/1.1\\\" 203 28004\\n\",\"stream\":\"stdout\",\"time\":\"2022-10-11T07:19:42.711893151Z\"}"), "source_type": Bytes(b"kubernetes_logs"), "timestamp": Timestamp(2022-10-11T07:19:42.769613709Z)}), size_cache: AtomicCell { value: Some(610) } }, metadata: EventMetadata { value: Object({}), secrets: {}, finalizers: EventFinalizers([]), schema_definition: Definition { event_kind: Kind { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), undefined: Some(()), array: Some(Collection { known: {}, unknown: Unknown(Infinite(Infinite { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), array: Some(()), object: Some(()) })) }), object: Some(Collection { known: {}, unknown: Unknown(Infinite(Infinite { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), array: Some(()), object: Some(()) })) }) }, metadata_kind: Kind { bytes: None, integer: None, float: None, boolean: None, timestamp: None, regex: None, null: None, undefined: None, array: None, object: Some(Collection { known: {}, unknown: Unknown(Exact(Kind { bytes: None, integer: None, float: None, boolean: None, timestamp: None, regex: None, null: None, undefined: Some(()), array: None, object: None })) }) }, meaning: {}, log_namespaces: {Vector, Legacy} } } }) error_code="annotation_failed" error_type="reader_failed" stage="processing"
2022-10-11T07:19:43.032013Z ERROR source{component_kind="source" component_id=kubernetes_logs component_type=kubernetes_logs component_name=kubernetes_logs}: vector::internal_events::kubernetes_logs: Failed to annotate event with pod metadata. event=Log(LogEvent { inner: Inner { fields: Object({"file": Bytes(b"/var/log/pods/app_flog-0_976669c2-8cd7-41b5-9a13-bd481c386c7f/flog/0.log"), "message": Bytes(b"{\"log\":\"216.225.220.81 - - [11/Oct/2022:07:19:42 +0000] \\\"DELETE /functionalities/viral/magnetic/bricks-and-clicks HTTP/1.0\\\" 404 29636\\n\",\"stream\":\"stdout\",\"time\":\"2022-10-11T07:19:43.012386844Z\"}"), "source_type": Bytes(b"kubernetes_logs"), "timestamp": Timestamp(2022-10-11T07:19:43.031919873Z)}), size_cache: AtomicCell { value: Some(643) } }, metadata: EventMetadata { value: Object({}), secrets: {}, finalizers: EventFinalizers([]), schema_definition: Definition { event_kind: Kind { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), undefined: Some(()), array: Some(Collection { known: {}, unknown: Unknown(Infinite(Infinite { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), array: Some(()), object: Some(()) })) }), object: Some(Collection { known: {}, unknown: Unknown(Infinite(Infinite { bytes: Some(()), integer: Some(()), float: Some(()), boolean: Some(()), timestamp: Some(()), regex: Some(()), null: Some(()), array: Some(()), object: Some(()) })) }) }, metadata_kind: Kind { bytes: None, integer: None, float: None, boolean: None, timestamp: None, regex: None, null: None, undefined: None, array: None, object: Some(Collection { known: {}, unknown: Unknown(Exact(Kind { bytes: None, integer: None, float: None, boolean: None, timestamp: None, regex: None, null: None, undefined: Some(()), array: None, object: None })) }) }, meaning: {}, log_namespaces: {Vector, Legacy} } } }) error_code="annotation_failed" error_type="reader_failed" stage="processing"
2022-10-11T07:19:43.139729Z  INFO vector::sinks::blackhole::sink: Total events collected events=167 raw_bytes_collected=628886
2022-10-11T07:19:43.293952Z  INFO source{component_kind="source" component_id=kubernetes_logs component_type=kubernetes_logs component_name=kubernetes_logs}:file_server: vector::internal_events::file::source: Stopped watching file. file=/var/log/pods/app_flog-0_976669c2-8cd7-41b5-9a13-bd481c386c7f/flog/0.log
2022-10-11T07:19:44.138910Z  INFO vector::sinks::blackhole::sink: Total events collected events=167 raw_bytes_collected=628886
2022-10-11T07:19:45.139601Z  INFO vector::sinks::blackhole::sink: Total events collected events=167 raw_bytes_collected=628886
2022-10-11T07:19:46.139902Z  INFO vector::sinks::blackhole::sink: Total events collected events=167 raw_bytes_collected=628886
2022-10-11T07:19:47.138870Z  INFO vector::sinks::blackhole::sink: Total events collected events=167 raw_bytes_collected=628886
2022-10-11T07:19:48.138703Z  INFO vector::sinks::blackhole::sink: Total events collected events=167 raw_bytes_collected=628886
2022-10-11T07:19:49.139712Z  INFO vector::sinks::blackhole::sink: Total events collected events=167 raw_bytes_collected=628886
2022-10-11T07:19:50.139388Z  INFO vector::sinks::blackhole::sink: Total events collected events=167 raw_bytes_collected=628886
...

r0b3r4 · 2022-10-24T05:37:14Z

Any news :)?

CharlieC3 · 2022-12-01T20:06:20Z

See my comment here, but in summary version 0.25.0 seems to contain a temporary or partial fix to this issue. I wasn't able to locate anything mentioning this in the release notes for this version, so some people may have missed it.

After upgrading to this version a couple weeks ago, I haven't had any annotation issues.

r0b3r4 · 2022-12-05T06:30:44Z

The only thing that confuses me that fix somehow connected with non-related options. As i understand this might works only like temporary kludge, right?

version >=0.25.x +

max_line_bytes: 16777216
max_read_bytes: 16777216
glob_minimum_cooldown_ms: 1000

CharlieC3 · 2022-12-05T16:32:22Z

@r0b3r4 The config options were only helpful in the linked issue for me, while upgrading to version >=0.25.x is specifically what helped me resolve this annotation issue.

scMarkus · 2024-09-17T07:37:11Z

It seams we are having a related problem to this issue. In our case we are not using stateful sets but Pods directly which reuse names in the same namespace over time. My assumption is that delay_deletion_ms delayes delete events as intended but at times the actual execution of an delete event does remove the follow up pod from the metadata cache. Hence the annotation lookup fails.

#21303 is a draft at the moment for discussion. Potentially it is enough to only store the uid in favor of name and namespace?

EDIT:
It already turned out that the proposed fix is not working. will continue to look into it. Thoughts are appreciated.

jszwedko · 2024-09-23T17:03:53Z

Thanks for taking a look at this @scMarkus ! The PR you put together would have been roughly what I expected so I'm surprised it didn't work for you 🤔

jszwedko added type: bug A code related bug. source: kubernetes_logs Anything `kubernetes_logs` source related platform: kubernetes Anything `kubernetes` platform related labels Jul 7, 2022

jszwedko mentioned this issue Jul 7, 2022

Vector randomly stops shipping certain k8s logs #12014

Open

neuronull assigned neuronull and unassigned neuronull Jul 7, 2022

sillent mentioned this issue Aug 8, 2022

fix(kubernetes_logs): delaying applied new pod #13886

Closed

mjperrone mentioned this issue Sep 9, 2022

Debugging kubernetes_logs reader_failed error #14354

Closed

sillent mentioned this issue Sep 18, 2022

fix(kubernetes_logs) problem with fail to annotate when pod names are reused #14462

Merged

scMarkus linked a pull request Sep 17, 2024 that will close this issue

fix(kubernetes_logs source): UID to identify meta cache #21303

Draft

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

`kubernetes_logs` source seems to fail to annotate when pod names are reused #13467

`kubernetes_logs` source seems to fail to annotate when pod names are reused #13467

jszwedko commented Jul 7, 2022

r0b3r4 commented Jul 29, 2022

jszwedko commented Jul 29, 2022

sillent commented Aug 5, 2022 •

edited

Loading

sillent commented Aug 10, 2022

jszwedko commented Aug 12, 2022

shenxn commented Aug 31, 2022

zhongzc commented Oct 10, 2022 •

edited

Loading

r0b3r4 commented Oct 24, 2022

CharlieC3 commented Dec 1, 2022

r0b3r4 commented Dec 5, 2022

CharlieC3 commented Dec 5, 2022

scMarkus commented Sep 17, 2024 •

edited

Loading

jszwedko commented Sep 23, 2024

kubernetes_logs source seems to fail to annotate when pod names are reused #13467

kubernetes_logs source seems to fail to annotate when pod names are reused #13467

Comments

jszwedko commented Jul 7, 2022

A note for the community

Problem

Configuration

Version

Debug Output

Example Data

Additional Context

References

r0b3r4 commented Jul 29, 2022

jszwedko commented Jul 29, 2022

sillent commented Aug 5, 2022 • edited Loading

sillent commented Aug 10, 2022

jszwedko commented Aug 12, 2022

shenxn commented Aug 31, 2022

zhongzc commented Oct 10, 2022 • edited Loading

r0b3r4 commented Oct 24, 2022

CharlieC3 commented Dec 1, 2022

r0b3r4 commented Dec 5, 2022

CharlieC3 commented Dec 5, 2022

scMarkus commented Sep 17, 2024 • edited Loading

jszwedko commented Sep 23, 2024

`kubernetes_logs` source seems to fail to annotate when pod names are reused #13467

`kubernetes_logs` source seems to fail to annotate when pod names are reused #13467

sillent commented Aug 5, 2022 •

edited

Loading

zhongzc commented Oct 10, 2022 •

edited

Loading

scMarkus commented Sep 17, 2024 •

edited

Loading