log processing failed for unknown operator id post upgrade from 0.47 to 0.73 #27022

kadhamecha-conga · 2023-09-20T13:18:46Z

Component(s)

receiver/filelog

What happened?

hi team,

i'm facing issue with parsing the log as we upgraded out otel collector from 0.47 to 0.73.

we don't have operatorid as move2, but still we are getting operator it and log processing got failed with error i attached in log output.

there is extra attributes also added as part of logs. can you please help me?
thanks.

Collector version

0.73

Environment information

kubernetes

OpenTelemetry Collector configuration

exporters:
      logging: {}
      otlphttp:
        endpoint: test.com
      otlphttp/metrics:
        endpoint: test.com
        retry_on_failure:
          initial_interval: 1s
          max_elapsed_time: 60s
          max_interval: 10s
        sending_queue:
          num_consumers: 1
          queue_size: 500
        timeout: 5s
    extensions:
      health_check: {}
      memory_ballast:
        size_in_percentage: 40
        size_mib: "819"
    processors:
      batch:
        timeout: 10s
      k8sattributes/pod_uid:
        extract:
          labels:
          - key: app
          - key: release
          - from: pod
            key: service.namespace
            tag_name: service.namespace
          - from: pod
            key: service.name
            tag_name: service.name
          metadata:
          - k8s.pod.name
          - k8s.node.name
          - k8s.namespace.name
        filter:
          node_from_env_var: KUBE_NODE_NAME
      memory_limiter:
        check_interval: 5s
        limit_mib: 1638
        limit_percentage: 80
        spike_limit_mib: 512
        spike_limit_percentage: 25
      resource:
        attributes:
        - action: insert
          key: k8s.cluster.name
          value: test-cluster
        - action: insert
          key: deployment.environment
          value: test
        - action: insert
          from_attribute: k8s.pod.labels.service.namespace
          key: service.namespace
        - action: insert
          from_attribute: k8s.pod.name
          key: service.instance.id
        - action: upsert
          from_attribute: k8s.deployment.name
          key: service.name
        - action: insert
          from_attribute: k8s.pod.labels.service.name
          key: service.name
        - action: insert
          from_attribute: OrganizationFriendlyId
          key: OrganizationFriendlyId
        - action: insert
          from_attribute: OrganizationId
          key: OrganizationId
    receivers:
      filelog:
        include:
        - /var/log/pods/*/*/*.log
        include_file_name: false
        include_file_path: true
        operators:
        - id: get-format
          routes:
          - expr: body matches "^\\{"
            output: parser-docker
          - expr: body matches "^[^ Z]+ "
            output: parser-crio
          - expr: body matches "^[^ Z]+Z"
            output: parser-containerd
          type: router
        - id: parser-crio
          output: recombine-logtags
          regex: ^(?P<time>[^ Z]+) (?P<stream>stdout|stderr) (?P<logtag>[^ ]*) (?P<log>.*)$
          timestamp:
            layout: "2006-01-02T15:04:05.000000000-07:00"
            layout_type: gotime
            parse_from: attributes.time
          type: regex_parser
        - id: parser-containerd
          output: recombine-logtags
          regex: ^(?P<time>[^ ^Z]+Z) (?P<stream>stdout|stderr) (?P<logtag>[^ ]*) (?P<log>.*)$
          timestamp:
            layout: '%Y-%m-%dT%H:%M:%S.%LZ'
            parse_from: attributes.time
          type: regex_parser
        - id: parser-docker
          output: recombine-exceptions
          timestamp:
            layout: '%Y-%m-%dT%H:%M:%S.%LZ'
            parse_from: attributes.time
          type: json_parser
        - combine_field: attributes.log
          combine_with: ""
          id: recombine-logtags
          is_last_entry: attributes.logtag == 'F'
          max_sources: 2000
          source_identifier: attributes["log.file.path"]
          type: recombine
        - combine_field: attributes.log
          id: recombine-exceptions
          is_first_entry: attributes.log matches "^\\S"
          max_sources: 2000
          source_identifier: attributes["log.file.path"]
          type: recombine
        - id: extract_metadata_from_filepath
          parse_from: attributes["log.file.path"]
          regex: ^.*\/(?P<namespace>[^_]+)_(?P<pod_name>[^_]+)_(?P<uid>[a-f0-9\-]{32,36})\/(?P<container_name>[^\._]+)\/(?P<run_id>\d+)\.log$
          type: regex_parser
        - from: attributes.log
          to: body
          type: move
        - default: unknown-log
          routes:
          - expr: body startsWith "{" && (body endsWith "}" || body endsWith "}\n" ||
              body endsWith "}\r\n")
            output: general-body-json
          type: router
        - field: resource.unknown_log_format
          id: unknown-log
          output: attribute-cleanup
          type: add
          value: "true"
        - id: general-body-json
          on_error: drop
          parse_from: body
          type: json_parser
        - id: regex-parser-gopanic
          if: body startsWith "panic:"
          parse_from: body
          regex: (?m)^(?P<severity>panic):\s+(?P<log>[ \t\S]+)[\n\r]*(?P<stack_trace>[\s\S]+)?
          severity:
            mapping:
              fatal: panic
            parse_from: attributes.severity
          type: regex_parser
        - id: regex-parser-otcollector
          if: body matches "^[\\d:\\-\\.TZ]+\\s"
          output: attribute-cleanup
          parse_from: body
          regex: (?m)^(?P<timestamp>[\d:\-\.TZ]+)\s+(?P<severity>\S+)\s+(?P<location>\S+)\s+(?P<log>[
            \t\S]+)[\n\r]*(?P<stack_trace>[\s\S]+)?
          severity:
            mapping:
              debug: DEBUG
              error: ERROR
              fatal: FATAL
              info: INFO
              warn: WARN
            parse_from: attributes.severity
          type: regex_parser
        - id: regex-kv-msg
          if: body contains "msg="
          parse_from: body
          regex: msg="(?P<msg>([^"\\]*(\\.)?)+)"
          type: regex_parser
        - id: regex-kv-err
          if: body contains "err="
          output: attribute-cleanup
          parse_from: body
          regex: err="(?P<msg>([^"\\]*(\\.)?)+)"
          type: regex_parser
        - id: extract_traces
          if: attributes.TraceId != nil
          span_id:
            parse_from: attributes.SpanId
          trace_id:
            parse_from: attributes.TraceId
          type: trace_parser
        - field: attributes.stack_trace
          id: attribute-cleanup
          if: attributes.stack_trace == ""
          type: remove
        - field: attributes.stream
          if: attributes.stream != nil
          type: remove
        - from: body.ClassName
          id: move-ClassName
          if: body.ClassName != nil
          to: body.class_name
          type: move
        - from: attributes.Attributes.ExceptionType
          id: move-ExceptionType
          if: attributes.Attributes != nil and attributes.Attributes.ExceptionType !=
            nil
          to: attributes.exception_type
          type: move
        - from: attributes.Attributes.ExceptionMessage
          id: move-ExceptionMsg
          if: attributes.Attributes != nil and attributes.Attributes.ExceptionMessage
            != nil
          to: attributes.exception_message
          type: move
        - from: attributes.Attributes.ExceptionStackTrace
          id: move-ExceptionStackTrace
          if: attributes.Attributes != nil and attributes.Attributes.ExceptionStackTrace
            != nil
          to: attributes.exception_stacktrace
          type: move
        - field: attributes.Attributes
          if: attributes.Attributes != nil
          type: remove
        - field: attributes.TraceFlags
          if: attributes.TraceFlags != nil
          type: remove
        - field: body
          type: remove
        - from: attributes.Message
          id: move-Msg-body
          if: attributes.Message != nil
          to: body.message
          type: move
        - field: attributes.run_id
          type: remove
        - field: attributes.logtag
          type: remove
        start_at: end
      otlp:
        protocols:
          grpc:
            endpoint: 0.0.0.0:4317
          http:
            endpoint: 0.0.0.0:4318
    service:
      extensions:
      - health_check
      - memory_ballast
      pipelines:
        logs:
          exporters:
          - otlphttp
          processors:
          - memory_limiter
          - k8sattributes/pod_uid
          - batch
          - resource
          receivers:
          - filelog
          - otlp
      telemetry:
        logs:
          level: INFO

Log output

2023-09-20T12:45:06.233Z	error	helper/transformer.go:110	Failed to process entry	{"kind": "receiver", "name": "filelog", "data_type": "logs", **"operator_id": "move2"**, "operator_type": "move", "error": "move: field does not exist", "action": "send", "entry": {"observed_timestamp":"2023-09-20T12:45:05.434274957Z","timestamp":"2023-09-20T12:45:05.390206283Z","body":"2023-09-20T12:45:05.390206283Z stdout F {\"SeverityText\":\"Information\",\"Message\":\"Executed endpoint \\u0027.HistoryAsync ( ..test.API)\\u0027\"}","log.file.path":"/var/log/pods/test-7d766db845-bxngp_1eb5a1a0-2087-4f86-98eb-eb8312bea0fc/test/0.log","logtag":"F","run_id":"0","stream":"stdout","time":"2023-09-20T12:45:05.390206
283Z"},"k8s.pod.uid":"1eb5a1a0-2087-4f86-98eb-eb8312bea0fc"},"severity":0,"scope_name":""}}
2023-09-20T12:45:06.234005911Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*TransformerOperator).HandleEntryError
2023-09-20T12:45:06.234008373Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/helper/transformer.go:110
2023-09-20T12:45:06.234009708Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*TransformerOperator).ProcessWith
2023-09-20T12:45:06.234011041Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/helper/transformer.go:102
2023-09-20T12:45:06.234012350Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/transformer/move.(*Transformer).Process
2023-09-20T12:45:06.234013689Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/transformer/move/move.go:80
2023-09-20T12:45:06.234015421Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*WriterOperator).Write
2023-09-20T12:45:06.234016776Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/helper/writer.go:64
2023-09-20T12:45:06.234018228Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*TransformerOperator).ProcessWith
2023-09-20T12:45:06.234019948Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/helper/transformer.go:104
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/transformer/move.(*Transformer).Process
2023-09-20T12:45:06.234022652Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/transformer/move/move.go:80
2023-09-20T12:45:06.234023923Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*WriterOperator).Write
2023-09-20T12:45:06.234025150Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/helper/writer.go:64
2023-09-20T12:45:06.234028662Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*TransformerOperator).ProcessWith
2023-09-20T12:45:06.234030004Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/helper/transformer.go:104
2023-09-20T12:45:06.234038453Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/transformer/move.(*Transformer).Process
2023-09-20T12:45:06.234040037Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/transformer/move/move.go:80
2023-09-20T12:45:06.234041205Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*WriterOperator).Write
2023-09-20T12:45:06.234042402Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/helper/writer.go:64
2023-09-20T12:45:06.234043633Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*ParserOperator).ProcessWithCallback
2023-09-20T12:45:06.234052164Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/helper/parser.go:133
2023-09-20T12:45:06.234053899Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*ParserOperator).ProcessWith
2023-09-20T12:45:06.234055765Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/helper/parser.go:109
2023-09-20T12:45:06.234057683
Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/parser/regex.(*Parser).Process
2023-09-20T12:45:06.234060394Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/parser/regex/regex.go:110
2023-09-20T12:45:06.234061767Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*WriterOperator).Write
2023-09-20T12:45:06.234063039Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/helper/writer.go:64
2023-09-20T12:45:06.234064579Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/transformer/recombine.(*Transformer).flushSource
2023-09-20T12:45:06.234065876Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/transformer/recombine/recombine.go:355
2023-09-20T12:45:06.234067136Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/transformer/recombine.(*Transformer).Process
2023-09-20T12:45:06.234068395Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/transformer/recombine/recombine.go:247
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*WriterOperator).Write
2023-09-20T12:45:06.234071166Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/helper/writer.go:64
2023-09-20T12:45:06.234074107Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/transformer/recombine.(*Transformer).flushSource
2023-09-20T12:45:06.234075803Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/transformer/recombine/recombine.go:355
2023-09-20T12:45:06.234077620Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/transformer/recombine.(*Transformer).Process
2023-09-20T12:45:06.234079275Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/transformer/recombine/recombine.go:261
2023-09-20T12:45:06.234081037Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*WriterOperator).Write
2023-09-20T12:45:06.234083712Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/helper/writer.go:64
2023-09-20T12:45:06.234085013Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*ParserOperator).ProcessWithCallback
2023-09-20T12:45:06.234086255Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/helper/parser.go:133
2023-09-20T12:45:06.234087426Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*ParserOperator).ProcessWith
2023-09-20T12:45:06.234088808Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/helper/parser.go:109
2023-09-20T12:45:06.234089970Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/parser/regex.(*Parser).Process
2023-09-20T12:45:06.234091149Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/parser/regex/regex.go:110
2023
-09-20T12:45:06.234092398Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/transformer/router.(*Transformer).Process
2023-09-20T12:45:06.234093575Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/transformer/router/router.go:142
2023-09-20T12:45:06.234096078Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*WriterOperator).Write
2023-09-20T12:45:06.234097333Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/helper/writer.go:64
2023-09-20T12:45:06.234098522Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/file.(*Input).emit
2023-09-20T12:45:06.234106922Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/operator/input/file/file.go:65
2023-09-20T12:45:06.234108247Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer.(*Reader).ReadToEnd
2023-09-20T12:45:06.234109496Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/fileconsumer/reader.go:102
2023-09-20T12:45:06.234112099Z github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer.(*Manager).consume.func1
2023-09-20T12:45:06.234113506Z 	github.com/open-telemetry/opentelemetry-collector-contrib/pkg/[email protected]/fileconsumer/file.go:151

Additional context

logs format also affected post upgrade.

github-actions · 2023-09-20T13:19:05Z

Pinging code owners:

receiver/filelog: @djaglowski

See Adding Labels via Comments if you do not have permissions to add labels yourself.

adugar-conga · 2023-09-20T13:20:57Z

Team,

Just to clarify here is the exact error, which we are unable to resolve

2023-09-20T12:45:06.233Z error helper/transformer.go:110

Failed to process entry {"kind": "receiver", "name": "filelog", "data_type": "logs", "operator_id": "move2", "operator_type": "move", "error": "move: field does not exist", "action": "send", "entry": {"observed_timestamp":"2023-09-20T12:45:05.434274957Z","timestamp":"2023-09-20T12:45:05.390206283Z","body":"2023-09-20T12:45:05.390206283Z stdout F {"SeverityText":"Information","Message":"Executed endpoint \u0027.HistoryAsync ( ..test.API)\u0027"}","log.file.path":"/var/log/pods/test-7d766db845-bxngp_1eb5a1a0-2087-4f86-98eb-eb8312bea0fc/test/0.log","logtag":"F","run_id":"0","stream":"stdout","time":"2023-09-20T12:45:05.390206
283Z"},"k8s.pod.uid":"1eb5a1a0-2087-4f86-98eb-eb8312bea0fc"},"severity":0,"scope_name":""}}

djaglowski · 2023-09-20T13:52:53Z

The error indicates that one of the move operators is referencing a from field which does not exist on a log entry.

move2 is an autogenerated ID which would occur only if you have at least three move operators that do not have IDs. Unfortunately, this is inconsistent with the configuration shown on the issue because only one move operator does not have an ID. Is it possible the config has been modified since the error was generated? (You can see an example of the expected behavior here)

In any case, the entry does not appear to have any attributes when it reaches the move operator that reports the error. Please let me know if there is any indication that this is a bug. Otherwise, I hope this is helpful information for troubleshooting your configuration.

github-actions · 2023-11-20T03:30:44Z

This issue has been inactive for 60 days. It will be closed in 60 days if there is no activity. To ping code owners by adding a component label, see Adding Labels via Comments, or if you are unsure of which component this issue relates to, please ping @open-telemetry/collector-contrib-triagers. If this issue is still relevant, please ping the code owners or leave a comment explaining why it is still relevant. Otherwise, please close it.

Pinging code owners:

receiver/filelog: @djaglowski

See Adding Labels via Comments if you do not have permissions to add labels yourself.

djaglowski · 2023-12-06T12:24:17Z

I'm closing this as there does not currently appear to be any action to take. Please reopen if necessary.

kadhamecha-conga added bug Something isn't working needs triage New item requiring triage labels Sep 20, 2023

github-actions bot added the receiver/filelog label Sep 20, 2023

djaglowski removed the needs triage New item requiring triage label Sep 20, 2023

github-actions bot mentioned this issue Sep 26, 2023

Weekly Report: 2023-09-19 - 2023-09-26 kevinslin/opentelemetry-collector-contrib#27

Open

github-actions bot added the Stale label Nov 20, 2023

djaglowski closed this as completed Dec 6, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

log processing failed for unknown operator id post upgrade from 0.47 to 0.73 #27022

log processing failed for unknown operator id post upgrade from 0.47 to 0.73 #27022

kadhamecha-conga commented Sep 20, 2023

github-actions bot commented Sep 20, 2023

adugar-conga commented Sep 20, 2023

djaglowski commented Sep 20, 2023

github-actions bot commented Nov 20, 2023

djaglowski commented Dec 6, 2023