[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?

[amachado-pie]

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.

[amachado-pie]

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

[amachado-pie]

@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

[JannikBrand]

Hey, for me this is still a valid issue.

When sending data without observedTimeUnixNano and timeUnixNano fields directly to Data Prepper, it will create Documents in OpenSearch including the time and observedTime field set to epoch 0 (Jan 1 1970).

Based on the spec of the observedTime field, it "is the time when OpenTelemetry’s code observed the event measured by the clock of the OpenTelemetry code", so Data Prepper should set it to the current time.

Based on the spec of the time field, setting it to epoch 0 seems wrong. Either the field should be dropped (because it is optional) or set to the value of observedTime. The latter would make sense, since the spec mentions: "Use Timestamp if it is present, otherwise use ObservedTimestamp".

---

Below some details to my test setup:

• DP version: 2.9.0

First, create a "otel-log-without-time.json" file, e.g.:

{
  "resourceLogs": [
    {
      "resource": {
        "attributes": [
          {
            "key": "service.name",
            "value": { "stringValue": "my-application" }
          }
        ],
        "droppedAttributesCount": 0
      },
      "scopeLogs": [
        {
          "scope": {
            "name": "scopeName",
            "version": "version1"
          },
          "logRecords": [
            {
              "severityNumber": 9,
              "severityText": "Info",
              "body": { "stringValue": "This is a log message" },
              "attributes": [],
              "droppedAttributesCount": 0,
              "traceId": "08040201000000000000000000000000",
              "spanId": "0102040800000000"
            }
          ],
          "schemaUrl": "foo"
        }
      ],
      "schemaUrl": "bar"
    }
  ]
}

Second, sent it via grpcurl to Data Prepper, e.g.:

grpcurl -insecure -d @ < otel-log-without-time.json <dp_endpoint>:<dp_otel_log_port> opentelemetry.proto.collector.logs.v1.LogsService/Export

Data Prepper log pipeline looks sth. like this (highlighting that the proto_reflection_service is enabled for grpcurl):

logs-pipeline:
  source:
    otel_logs_source:
      ssl: false
      proto_reflection_service: true

  buffer:
    bounded_blocking:
      buffer_size: 12800
      batch_size: 200
  processor:
  sink:
    - opensearch:
        hosts: [ "<opensearch_endpoint>" ]
        insecure: true
        username: <os_username>
        password: <os_user_password>
        index: logs-otel-v1-%{yyyy.MM.dd}

Resulting OpenSearch doc:

{
  "_index": "logs-otel-v1-2024.12.19",
  "_type": "_doc",
  "_id": "GB2n3pMB0Mc1_i72fE8Y",
  "_version": 1,
  "_score": null,
  "_source": {
    "traceId": "d3cd38d36d35d34d34d34d34d34d34d34d34d34d34d34d34",
    "spanId": "d35d36d38d3cd34d34d34d34",
    "severityText": "Info",
    "flags": 0,
    "time": "1970-01-01T00:00:00Z",
    "severityNumber": 9,
    "droppedAttributesCount": 0,
    "serviceName": "my-application",
    "body": "This is a log message",
    "observedTime": "1970-01-01T00:00:00Z",
    "schemaUrl": "bar",
    "instrumentationScope.name": "scopeName",
    "resource.attributes.service@name": "my-application",
    "instrumentationScope.version": "version1"
  },
  "fields": {
    "observedTime": [
      "1970-01-01T00:00:00.000Z"
    ],
    "time": [
      "1970-01-01T00:00:00.000Z"
    ]
  },
  "sort": [
    0
  ]
}

[amachado-pie]

Well, I'm not sure if DataPrepper should set these fields or if that is the responsibility of the SDK/collector that uses the OpenTelemetry instrumentation to create the trace/log event.
The original issue in this thread was fixed in the opentelemetry-cpp project because that SDK was not going to assign a value to this field and thus exported the ObservedTimestamp with the default Unix epoch time.

If we think that this event was "collected" or "sent" by an OpenTelemetry instrumentation, I think it's the event source that is responsible for including the correct fields, like for example with the traceId.

But perhaps I suggest you create another issue or contact the DataPreper staff through channels like Slack to get a better opinion.

[JannikBrand]

Well, I'm not sure if DataPrepper should set these fields or if that is the responsibility of the SDK/collector that uses the OpenTelemetry instrumentation to create the trace/log event.

The spec says: "is the time when OpenTelemetry’s code observed the event measured by the clock of the OpenTelemetry code".
Since Data Prepper is the first instance in my experiment that contains OTel code, imo it makes sense that Data Prepper should set it.

I created => #5275 let's continue the discussion there (if needed.)