Transport crash when specifying alternate timestamp format

[clemarc]

Great work on this lib @Vunovati !

Using it on my project and found a bug related to timestamp format.

How to reproduce

I just tweaked the minimalist example to specify an alternative timestamp format which gives an isoTime (2024-05-09T11:12:49.897Z)

"use strict";

const path = require("path");
const pino = require("pino");

const logger = pino({
  transport: {
    target: path.join(
      __dirname,
      "..",
      "..",
      "lib",
      "pino-opentelemetry-transport"
    ),
  },
  timestamp: pino.stdTimeFunctions.isoTime,
});

logger.info("test log");

Error

node:events:497
      throw er; // Unhandled 'error' event
      ^

Error: the worker has exited

Root cause

The root cause comes from the fact that OpenTelemetry doesn't like a string timestamp

• The LogRecord creation is converting the timestamp here
  • https://github.com/open-telemetry/opentelemetry-js/blob/main/experimental/packages/sdk-logs/src/LogRecord.ts#L97
• Which only supports process.hrtime() / number / Date format
  • https://github.com/open-telemetry/opentelemetry-js/blob/main/packages/opentelemetry-core/src/common/time.ts#L66

Locally I patched the library to check if we have a string, in which case I convert to a Date in the mapper but that's still a bit wonky. Technically the timestamp option can even be a function that could return a format not recognised by new Date(time) so it might need to be more defensive and documented.

In case it doesn't parse it could drop the timestamp to let the SDK generate a new one?

Happy to get some thoughts and send a MR to improve this.

function toOpenTelemetry(..) {
  ...
  return {
    timestamp: typeof time === "string" ? new Date(time) : time,
    body: msg,
    severityNumber,
    attributes,
    severityText,
  };

}

[Vunovati]

Hello @clemarc

I think in this case the most pragmatic way to use the transport would probably be to omit the timestamp altogether (timestamp: false). As you said, the SDK will add a fallback Observed timestamp if Pino does not provide one.

For the timestamp option Pino docs say: Caution: attempting to format time in-process will significantly impact logging performance.

If we added such a function, we should probably document that using this solution is not optimal (performance-wise). Can you come up with an API that would allow for adding this conversion function optionally? By default, toOpenTelemetry should behave like it did before. We should not have to evaluate each log line to see if its timestamp needs to be converted.

I think this option should be added like we added severityNumberMap.

Another use case: if you have multiple transports and want to have your standard timestamps in other places but not in pino-opentelemetry-trasport, we should probably allow disabling/ignoring the timestamp alltogether when running toOpenTelemetry. (BTW. could this have been your use case?)

WDYT?

[clemarc]

Hi!

Thanks for looking at it!

Agreed the formatting is not ideal but imposed here. Using the pino provided one.

I am in the latter case, depending on configuration we use different transports and need that format for the timestamp in some but not in other, I guess I could tweak that option on my side as I switch transport.

An improvement could be what you suggest:

• document the expected format if using timestamp
• offer an option

I'll have a go at it if that sounds ok with you

[Vunovati]

That sounds great 👍🏻