Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Helm chart logsCollection Failed to process entry #718

Closed
jonaskello opened this issue Mar 30, 2023 · 11 comments · Fixed by #721
Closed

Helm chart logsCollection Failed to process entry #718

jonaskello opened this issue Mar 30, 2023 · 11 comments · Fixed by #721
Labels
bug Something isn't working chart:collector Issue related to opentelemetry-collector helm chart

Comments

@jonaskello
Copy link
Contributor

When using the helm chart and enabling value:

    presets:
      logsCollection:
        enabled: true

The following error is logged in the otel pods:

2023-03-30T14:56:53.387Z        error   helper/transformer.go:110       Failed to process entry {"kind": "receiver", "name": "filelog", "data_type": "logs", "operator_id": "parser-crio", "operator_type": "regex_parser", "error": {"description": "time parser: parsing time \"2023-03-30T16:56:53.35660177+02:00\" as \"2006-01-02T15:04:05.000000000-07:00\": cannot parse \"02:00\" as \".000000000\""}, "action": "send", "entry": {"observed_timestamp":"2023-03-30T14:56:53.387119724Z","timestamp":"0001-01-01T00:00:00Z","body":"2023-03-30T16:56:53.35660177+02:00 stdout F 1680188213356307439 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp","attributes":{"log":"1680188213356307439 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp","log.file.path":"/var/log/pods/loki_loki-canary-gkqj7_43afddb9-9b8c-474d-a00d-2c77e272ff90/loki-canary/0.log","logtag":"F","stream":"stdout","time":"2023-03-30T16:56:53.35660177+02:00"},"severity":0,"scope_name":""}}

Seems related to #376 which was never resolved.

@TylerHelmuth TylerHelmuth added the chart:collector Issue related to opentelemetry-collector helm chart label Mar 30, 2023
@TylerHelmuth
Copy link
Member

@jonaskello please share the log that caused the error.

@jonaskello
Copy link
Contributor Author

Yes, the whole file it's quite big but here is a sample of it:

# tail -100 /var/log/pods/loki_loki-canary-gkqj7_43afddb9-9b8c-474d-a00d-2c77e272ff90/loki-canary/0.log
2023-03-30T17:40:50.374518594+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680179143355823226&end=1680179163355823226&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:40:50.383070724+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680180044356100470&end=1680180064356100470&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:40:50.38863496+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680180944356464954&end=1680180964356464954&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:40:50.393147208+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680181844356535682&end=1680181864356535682&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:40:50.39974025+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680182745355711770&end=1680182765355711770&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:40:50.407098785+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680183645356551171&end=1680183665356551171&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:40:50.41871925+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680184546356835860&end=1680184566356835860&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:40:50.424816314+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680185447355974762&end=1680185467355974762&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:40:50.431379199+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680186347356100852&end=1680186367356100852&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:40:50.438102676+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680187247356435321&end=1680187267356435321&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:40:50.446950279+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680188148356188354&end=1680188168356188354&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:40:50.453976623+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680189049356019039&end=1680189069356019039&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:40:50.460746236+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680189950356277106&end=1680189970356277106&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:40:51.3564967+02:00 stdout F 1680190851356330709 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:40:52.356586742+02:00 stdout F 1680190852356466026 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:40:53.356398206+02:00 stdout F 1680190853356262742 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:40:54.356225037+02:00 stdout F 1680190854356071750 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:40:55.356137617+02:00 stdout F 1680190855356016721 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:40:56.356609683+02:00 stdout F 1680190856356486483 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:40:57.356582185+02:00 stdout F 1680190857356277956 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:40:58.356134391+02:00 stdout F 1680190858356001473 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:40:59.35634442+02:00 stdout F 1680190859356252187 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:00.356225482+02:00 stdout F 1680190860355613877 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:01.356052642+02:00 stdout F 1680190861355721312 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:02.356928195+02:00 stdout F 1680190862356554316 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:03.356188717+02:00 stdout F 1680190863356067490 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:04.356291773+02:00 stdout F 1680190864356095776 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:05.35588282+02:00 stdout F 1680190865355719625 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:06.35625945+02:00 stdout F 1680190866355914394 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:07.356382154+02:00 stdout F 1680190867355847323 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:08.356488919+02:00 stdout F 1680190868356131109 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:09.355669442+02:00 stdout F 1680190869355527506 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:10.355906107+02:00 stdout F 1680190870355774461 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:11.356185573+02:00 stdout F 1680190871356047925 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:12.356083858+02:00 stdout F 1680190872355925101 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:13.355763681+02:00 stdout F 1680190873355610494 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:14.356277568+02:00 stdout F 1680190874355929777 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:15.355879568+02:00 stdout F 1680190875355677700 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:16.356328479+02:00 stdout F 1680190876355946054 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:17.356552534+02:00 stdout F 1680190877356394378 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:18.355856962+02:00 stdout F 1680190878355722521 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:19.356100884+02:00 stdout F 1680190879355927139 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:20.356473233+02:00 stdout F 1680190880356339643 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:21.35662356+02:00 stdout F 1680190881356268555 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:22.355862999+02:00 stdout F 1680190882355709151 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:23.355695678+02:00 stdout F 1680190883355545838 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:24.355829251+02:00 stdout F 1680190884355683949 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:25.356152809+02:00 stdout F 1680190885355773329 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:26.356619245+02:00 stdout F 1680190886356492678 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:27.355840431+02:00 stdout F 1680190887355676534 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:28.356009682+02:00 stdout F 1680190888355612108 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:29.356786778+02:00 stdout F 1680190889356245154 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:30.356188299+02:00 stdout F 1680190890355815822 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:31.35612309+02:00 stdout F 1680190891355776711 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:32.355796801+02:00 stdout F 1680190892355633034 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:33.35634504+02:00 stdout F 1680190893355962233 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:34.355805913+02:00 stdout F 1680190894355605488 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:35.356164216+02:00 stdout F 1680190895355638071 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:36.355903981+02:00 stdout F 1680190896355743781 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:37.356005653+02:00 stdout F 1680190897355850974 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:38.35565548+02:00 stdout F 1680190898355532901 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:39.356419443+02:00 stdout F 1680190899356257580 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:40.356100377+02:00 stdout F 1680190900355977006 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:41.35623997+02:00 stdout F 1680190901356045536 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:42.356694263+02:00 stdout F 1680190902356528382 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:43.356643059+02:00 stdout F 1680190903356497387 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:44.355730842+02:00 stdout F 1680190904355599937 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:45.356315348+02:00 stdout F 1680190905356173563 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:46.355754179+02:00 stdout F 1680190906355597686 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:47.355699098+02:00 stdout F 1680190907355579865 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:48.356572504+02:00 stdout F 1680190908356261251 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:49.356571754+02:00 stdout F 1680190909356409219 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:50.35628069+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680177341356541783&end=1680177361356541783&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:41:50.356330954+02:00 stdout F 1680190910356139716 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:50.363984722+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680178242356188395&end=1680178262356188395&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:41:50.368602928+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680179143355823226&end=1680179163355823226&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:41:50.373621152+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680180044356100470&end=1680180064356100470&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:41:50.379617939+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680180944356464954&end=1680180964356464954&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:41:50.38815514+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680181844356535682&end=1680181864356535682&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:41:50.394524284+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680182745355711770&end=1680182765355711770&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:41:50.404301317+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680183645356551171&end=1680183665356551171&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:41:50.411016188+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680184546356835860&end=1680184566356835860&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:41:50.417430846+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680185447355974762&end=1680185467355974762&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:41:50.430629244+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680186347356100852&end=1680186367356100852&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:41:50.441967089+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680187247356435321&end=1680187267356435321&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:41:50.448317367+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680188148356188354&end=1680188168356188354&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:41:50.454397469+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680189049356019039&end=1680189069356019039&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:41:50.459702951+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680189950356277106&end=1680189970356277106&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:41:50.464587916+02:00 stderr F Querying loki for logs with query: https://loki-gateway.loki.svc.cluster.local./loki/api/v1/query_range?start=1680190851355721312&end=1680190871355721312&query=%7Bstream%3D%22stdout%22%2Cpod%3D%22loki-canary-gkqj7%22%7D&limit=1000
2023-03-30T17:41:51.356693967+02:00 stdout F 1680190911356480728 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:52.356518579+02:00 stdout F 1680190912356422339 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:53.356826006+02:00 stdout F 1680190913356498533 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:54.35594312+02:00 stdout F 1680190914355745080 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:55.356178512+02:00 stdout F 1680190915355976644 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:56.355990342+02:00 stdout F 1680190916355837626 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:57.356124626+02:00 stdout F 1680190917355928409 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:58.355699051+02:00 stdout F 1680190918355554250 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:41:59.356207792+02:00 stdout F 1680190919355833582 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:42:00.356225835+02:00 stdout F 1680190920356093307 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp
2023-03-30T17:42:01.355796864+02:00 stdout F 1680190921355621356 ppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp

@TylerHelmuth TylerHelmuth added the bug Something isn't working label Mar 30, 2023
@TylerHelmuth
Copy link
Member

It appears your timestamps have too many digits in after the . to be parsed as the preset's CRI-O format, which is the format the preset identified for your logs. How are you generating these logs? The preset only knows how to handle CRI-0, CRI-containerd, and Docker formatted logs.

@jonaskello
Copy link
Contributor Author

The logs are from a worker node in the k8s cluster where the chart is deployed. The worker node has this config:

 Ubuntu 20.04.2 LTS             5.4.0-110-generic   containerd:https://1.6.4

So the logs are from containerd.

These are the datetime setting on the node (not sure if it is relevant):

$ timedatectl
               Local time: Thu 2023-03-30 21:17:48 CEST
           Universal time: Thu 2023-03-30 19:17:48 UTC
                 RTC time: Thu 2023-03-30 19:17:48
                Time zone: Europe/Stockholm (CEST, +0200)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no

@jonaskello
Copy link
Contributor Author

The regex for containerd logs which is here seems to assume Z for timezone.

So this string does not match:

2023-03-30T17:40:54.356225037+02:00 stdout F 1680190854356071750 ppppppppppppppppppppppppppp

Because of the +02:00 part. However if that is changed to Z it matches, so this will match:

2023-03-30T17:40:54.356225037Z stdout F 1680190854356071750 ppppppppppppppppppppppppppp

@TylerHelmuth
Copy link
Member

Interesting. From the original error we can see that the filelog receiver routed the log to parser-crio instead of parser-containerd. parser-containerd uses %Y-%m-%dT%H:%M:%S.%LZ for the timestamp. Here is how the filelogreceiver does the routing:

routes:
  - output: parser-docker
    expr: 'body matches "^\\{"'
  - output: parser-crio
    expr: 'body matches "^[^ Z]+ "'
  - output: parser-containerd
    expr: 'body matches "^[^ Z]+Z"'

So it is expecting containerd logs to use Z. None of the formats expect time timezone offset (%z I believe).

I believe there are a couple possibilities here:

  1. The default configuration is making incorrect assumptions about the formatting of containerd logs
  2. The default configuration is making incorrect assumptions about the formatting of cri-0 logs
  3. Your logs, although containerd logs, are not being formatted like other containerd logs for some reason.
  4. Your logs, although containerd logs, are being formatted like CRI-0 logs, but with too many milisecond precision.

The cri-o parser would be able to handle your timezone offset if the millisecond precision matched.

@djaglowski @dmitryax do you see anything out of the ordinary with our operators?

operators:
# Find out which format is used by kubernetes
- type: router
id: get-format
routes:
- output: parser-docker
expr: 'body matches "^\\{"'
- output: parser-crio
expr: 'body matches "^[^ Z]+ "'
- output: parser-containerd
expr: 'body matches "^[^ Z]+Z"'
# Parse CRI-O format
- type: regex_parser
id: parser-crio
regex: '^(?P<time>[^ Z]+) (?P<stream>stdout|stderr) (?P<logtag>[^ ]*) ?(?P<log>.*)$'
output: extract_metadata_from_filepath
timestamp:
parse_from: attributes.time
layout_type: gotime
layout: '2006-01-02T15:04:05.000000000-07:00'
# Parse CRI-Containerd format
- type: regex_parser
id: parser-containerd
regex: '^(?P<time>[^ ^Z]+Z) (?P<stream>stdout|stderr) (?P<logtag>[^ ]*) ?(?P<log>.*)$'
output: extract_metadata_from_filepath
timestamp:
parse_from: attributes.time
layout: '%Y-%m-%dT%H:%M:%S.%LZ'
# Parse Docker format
- type: json_parser
id: parser-docker
output: extract_metadata_from_filepath
timestamp:
parse_from: attributes.time
layout: '%Y-%m-%dT%H:%M:%S.%LZ'
The closest thing I could find to maybe indicate our formats are wrong was here: https://github.com/microsoft/fluentbit-containerd-cri-o-json-log#config-changes

@jonaskello
Copy link
Contributor Author

jonaskello commented Mar 31, 2023

While researching this issue I found this which may be of interest:

https://github.com/kubernetes/design-proposals-archive/blob/main/node/kubelet-cri-logging.md

The runtime should decorate each log entry with a RFC 3339Nano timestamp prefix, the stream type (i.e., "stdout" or "stderr"), the tags of the log entry, the log content that ends with a newline.

It gives this example:

2016-10-06T00:17:09.669794202Z stdout F The content of the log entry 1

Original found linked in this issue.

@jonaskello
Copy link
Contributor Author

Found this in one of the worker's logs:

image

Something weird seems to be going on with the way containerd is creating the logs on our workers. Sometimes, for some entries the number of chars for milliseconds is 8 instead of 9.

So I think otel-collector is correct here, it is chosing the cri logging format which is also what containerd is using. Got thrown off by the parser-containerd entry in the config which it seems should not be used for containerd.

@jonaskello
Copy link
Contributor Author

I researched the format for the RFC3339Nano constant in golang and found the docs here which defines it as:

RFC3339Nano = "2006-01-02T15:04:05.999999999Z07:00"

Comparing that to the format layout used in the helm chart here which is:

layout_type: gotime
layout: '2006-01-02T15:04:05.000000000-07:00'

I could see they did not exactly look the same so I switched the one in the otel collector config to look exactly like the one defined in golang time pacakge, and now the error is not appearing anymore.

I have no clue why, but I'm happy it is working now :-)

@djaglowski
Copy link
Member

@jonaskello, thanks for digging into this. It looks like a change we should make in the chart.

Using Z instead of - changes the format when the timestamp is in the UTC zone (no offset). The go docs say: "Replacing the sign in the format with a Z triggers the ISO 8601 behavior of printing Z instead of an offset for the UTC zone"

Using 9's instead of 0's allows trailing 0's to be omitted from the timestamp. (.123 instead of .1230)

jonaskello added a commit to jonaskello/opentelemetry-helm-charts that referenced this issue Mar 31, 2023
@jonaskello
Copy link
Contributor Author

Made a PR in #721 with the change that worked for me.

jonaskello added a commit to jonaskello/opentelemetry-collector-contrib that referenced this issue Mar 31, 2023
TylerHelmuth pushed a commit that referenced this issue Apr 3, 2023
* Update time layout for cri-o log format

Fixes #718

* bump chart version and generate examples
TylerHelmuth pushed a commit to open-telemetry/opentelemetry-collector-contrib that referenced this issue Jun 7, 2023
* Fix cri-o log format time layout

See related discussion and PR in open-telemetry/opentelemetry-helm-charts#718

* Create fix-cri-o-log-format-time-layout.yaml

Add changelog file

* Update fix-cri-o-log-format-time-layout.yaml

Remove external issue as it seems it does not validate

* Update fix-cri-o-log-format-time-layout.yaml

Add issue number
Caleb-Hurshman pushed a commit to observIQ/opentelemetry-collector-contrib that referenced this issue Jul 6, 2023
* Fix cri-o log format time layout

See related discussion and PR in open-telemetry/opentelemetry-helm-charts#718

* Create fix-cri-o-log-format-time-layout.yaml

Add changelog file

* Update fix-cri-o-log-format-time-layout.yaml

Remove external issue as it seems it does not validate

* Update fix-cri-o-log-format-time-layout.yaml

Add issue number
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working chart:collector Issue related to opentelemetry-collector helm chart
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants