[BUG] OTEL Logs source created has observed timestamp of 1970

[derek-ho]

Describe the bug
Observed Timestamp is set as 1970 01 01, should this take on time if not present?

This is messing up observability plugin, which assumes observedtimestamp as the default timestamp field

To Reproduce
opensearch-project/dashboards-observability#245 (comment)

Expected behavior
A clear and concise description of what you expected to happen.

Screenshots
If applicable, add screenshots to help explain your problem.

Environment (please complete the following information):

• OS: [e.g. Ubuntu 20.04 LTS]
• Version [e.g. 22]

Additional context
Add any other context about the problem here.

[graytaylor0]

Hi @derek-ho,

It is not clear to me what the expected behaviour/outcome is. Could you update that section of the issue to clarify? Where has the timestamp of 1970 been observed?

[derek-ho]

Sample document:

  "took": 0,
  "timed_out": false,
  "_shards": {
    "total": 1,
    "successful": 1,
    "skipped": 0,
    "failed": 0
  },
  "hits": {
    "total": {
      "value": 34,
      "relation": "eq"
    },
    "max_score": 1,
    "hits": [
      {
        "_index": "otel-v1-logs-2023.06",
        "_id": "301iN4YB9XlfGxwRbxlY",
        "_score": 1,
        "_source": {
          "traceId": "",
          "spanId": "",
          "flags": 0,
          "time": "2023-02-09T18:14:02.883556488Z",
          "severityNumber": 9,
          "droppedAttributesCount": 0,
          "serviceName": "my-service",
          "body": "Service running on hostname: xxxxx with instance id: i-XXXXXXXXXX",
          "observedTime": "1970-01-01T00:00:00Z",
          "schemaUrl": "",
          "resource.attributes.service@instance@local_hostname": "XXXXXXXXXX.compute.internal",
          "resource.attributes.service@instance@local_ipv4": "172.24.160.99",
          "instrumentationScope.name": "my-service",
          "resource.attributes.service@version": "2.0.0+2f6c1d",
          "resource.attributes.telemetry@sdk@name": "opentelemetry",
          "resource.attributes.telemetry@sdk@language": "cpp",
          "resource.attributes.service@namespace": "pte",
          "resource.attributes.telemetry@sdk@version": "1.8.2",
          "resource.attributes.service@instance@id": "i-XXXXXXXXXX",
          "resource.attributes.service@name": "my-service",
          "resource.attributes.service@instance@public_hostname": "XXXXXXXXXX.amazonaws.com",
          "instrumentationScope.version": "2.0.0+2f6c1d"
        }
      }
    ]
  }
}```

[derek-ho]

@graytaylor0 details on how this was created can be found here: opensearch-project/dashboards-observability#245 (comment). I didn't want to paste a huge block of text. I also asked the initial reporter of the other issue to also record here how he got the document such as language/ingest method, etc.

[graytaylor0]

Thanks for sharing that. Looks like that field is populated by OpenTelemetry and not by data prepper (https://opentelemetry.io/docs/reference/specification/logs/data-model/#field-observedtimestamp). Have you been able to confirm if the observedTimestamp field is set before it is sent to data prepper, and if so does it already contain a value of 1970?

[derek-ho]

@MrSparc can you add some more details?

[ArielGMachado]

With the tests I did, it doesn't seem to be populated by the Data-Prepper either.

I changed the otel-collector-config.yaml and sending the logs, in addition to the data-prepper, for logging in the output:

receivers:
  otlp:
    protocols:
      grpc:
        endpoint: 0.0.0.0:4317

processors:
  batch:
    send_batch_size: 10000
    send_batch_max_size: 11000
    timeout: 10s

exporters:
  logging:
    verbosity: Detailed

  otlp/data-prepper-logs:
    endpoint: data-prepper:21892
    tls:
      insecure: true
      insecure_skip_verify: true

service:
    logs:
      receivers: [otlp]
      processors: [batch]
      exporters: [otlp/data-prepper-logs, logging]

This logs to stdout shows that same Unix epoch date start date in ObservedTimestamp field:

2023-02-14T00:51:16.814Z        info    ResourceLog #0
Resource SchemaURL: 
Resource attributes:
     -> telemetry.sdk.version: Str(1.8.2)
     -> telemetry.sdk.language: Str(cpp)
     -> service.version: Str(2.0.0+757106)
     -> service.namespace: Str(pte)
     -> service.name: Str(primum-tunnel-engine)
     -> telemetry.sdk.name: Str(opentelemetry)
     -> service.instance.id: Str(wks-pvz-124)
     -> service.instance.public_hostname: Str(wks-pvz-124)
     -> service.instance.local_hostname: Str(wks-pvz-124)
     -> service.instance.local_ipv4: Str(wks-pvz-124)
ScopeLogs #0
ScopeLogs SchemaURL: 
InstrumentationScope primum-tunnel-engine 2.0.0+757106
LogRecord #0
ObservedTimestamp: 1970-01-01 00:00:00 +0000 UTC
Timestamp: 2023-02-14 00:51:11.723679652 +0000 UTC
SeverityText: INFO
SeverityNumber: Info(9)
Body: Str(PTE running on hostname: wks-pvz-124 with instance id: wks-pvz-124)
Trace ID: 
Span ID: 
Flags: 0

That value 00:00:00 [UTC] on 1 January 1970, the beginning of the Unix epoch.

Now, I don't know if this field should not be sent by OpenTelemetry, or if sent as now, this value should be considered equivalent to a NULL value for date type fields and not be taken into account in filters like in the OpenSearch Observability plugin...

I'm going to ping this issue on the Slack otel-cpp channel to see if someone can help us to identifiy if this it's a lib implementation issue or if it's working as expected.

[ArielGMachado]

This is a bug in the C++ OpenTelemetry (otel-cpp) that will be handled by this issue open-telemetry/opentelemetry-cpp#1984

[derek-ho]

@ArielGMachado we should be able to close this now, right? Seems like PR is merged

[ArielGMachado]

@derek-ho yes, this issue was not Data-prepper related and PR to fix otel-cpp is merged.

[derek-ho]

Great, thanks so much @ArielGMachado , @graytaylor0 closing this now