log buffering (Microsoft.Extensions.Telemetry): Question regarding timestamp of records/IBufferedLogger w OpenTelemetry

[dlosch]

Hi,

I tried the log buffering and read through the proposal #5123 and discussion specific with the timestamping question. I also looked at the code and I see that the buffering does capture the timestamp before the log record gets written to the buffer. The .NET ConsoleLogger does print the correct timestamp (time of buffering).

Other log sinks (tried opentelemetry and serilog) seem to log the timestamp when the buffer is flushed (and first enters otel/serilog code), and do not use the timestamp the buffered logger code creates.

Can anyone just confirm these logger libraries need to be updated in order to use the correct timestamps and that the OpenTelemetry .NET log sink doesn't do that currently? Or is there a configuration to make them use the existing timestamps

Thanks.

[evgenyfedorov2]

Yes, every logger library does need to be updated to support it, namely, they need to implement this interface https://learn.microsoft.com/dotnet/api/microsoft.extensions.logging.abstractions.ibufferedlogger - it is explained there in the Remarks section.

Specifically for the OpenTelemetry .NET, the place where timestamp update is here - there is no any config. It just needs to implement the interface :)

P.S. converted to a Discussion.

[KalleOlaviNiemitalo]

ActivitySpanId and ActivityTraceId being always null in the Microsoft.Extensions.Telemetry log buffering implementation will hurt the usefulness of OpenTelemetry logging. It can still read Activity.Current when the log buffer is flushed, and hopefully the log records in a per-request log buffer will be part of the same trace as that Activity; but it won't be able to associate the log records with the correct child spans, and the global log buffer can contain log records from multiple traces and those will be mixed up.

I imagine it would be possible to define a setting that would make Microsoft.Extensions.Telemetry save the ActivitySpanId and ActivityTraceId with each buffered log entry. I'm not sure what the API for that should be, though. A new property in GlobalLogBufferingOptions would be possible but that feels wrong because the setting would affect per-request buffered log records too. For developer convenience, it would be nicer if the logging infrastructure automatically enabled the saving of ActivitySpanId and ActivityTraceId if at least one ILoggerProvider claims interest in them; but that would require a new interface for the providers to implement. Or perhaps one could just always save the activity information, but I don't know what the CPU and memory costs would be.

Re the timestamp, there is an expectation that ConsoleFormatter.Write<TState> should recognise LogEntry<TState>.State being an instance of BufferedLogEntry and read the timestamp from there. I think this currently applies only when TState is exactly BufferedLogEntry (rather than Object, or some class derived from BufferedLogEntry), but that doesn't seem to be formally documented. Anyhow, I don't expect an OpenTelemetry logger to use ConsoleFormatter.

[evgenyfedorov2]

see also #6502

[Skleni]

We implemented log buffering in our solution because the docs say:

The order of logs is not guaranteed to be preserved. However, original timestamps are preserved.

Only when we were finished did we notice that the timestamps are in fact not preserved when using OpenTelemetry. IMHO the docs are misleading here and this should be mentioned, especially with all the promotion for Aspire.

@evgenyfedorov2 Are there any plans for when this will be supported with OpenTelemetry?