Serilog Timings does not log SourceContext

[alekdavisintel]

I was looking though my logs and noticed that the Timings log entries (so-and-so completed/abandoned in X ms) do not contain the SourceContext values. I can see that the log entry before the Timings record and the HTTP request completion record (set via the UseSerilogRequestLogging call) do have the SourceContext, so it seems odd for the Timings to not include it. Seems like a bug. Any ideas? Using Serilog 3.1.1 and SerilogTimings 3.1.0 in ASP.NET Core project.

Here is a snippet from the log with sensitive values masked (the first entry shows the template properties; I added spaces to align the columns):

[{@t:yyyy-MM-dd HH:mm:ss.ffffff zzz}] [{@l:u3}] [{MachineName}] [{ProcessId}:{ThreadId}] [{CorrelationId}                     ] [{ClientIp}] [{UserName}] [{ApplicationId}] [{SourceContext}                             ] [{ActionName}                                                                                ] [{MethodName}            ] {EscapedMessage:lj}
[2024-05-10 14:54:22.973188 -07:00  ] [INF    ] [XXXXXX-XXXX  ] [12436:18              ] [21ff86c7-02b6-41af-8ead-fa19962fe09d] [::1       ] [x@y.z     ] [xxxxx          ] [Xxxxx.Yyy.Common.Web.Server.Auth.AuthService] [Xxxxx.Yyy.Common.Controllers.Ping.PingController.GetCaller (Xxxxx.Yyy.PingControllerLibrary)] [AuthService:Authenticate] Authenticated caller: {XXX}
[2024-05-10 14:54:22.974175 -07:00  ] [INF    ] [XXXXXX-XXXX  ] [12436:18              ] [21ff86c7-02b6-41af-8ead-fa19962fe09d] [::1       ] [x@y.z     ] [xxxxx          ] [                                            ] [Xxxxx.Yyy.Common.Controllers.Ping.PingController.GetCaller (Xxxxx.Yyy.PingControllerLibrary)] [PingController:GetCaller] PingController:GetCaller "completed" in 10.8 ms
[2024-05-10 14:54:22.975135 -07:00  ] [INF    ] [XXXXXX-XXXX  ] [12436:18              ] [21ff86c7-02b6-41af-8ead-fa19962fe09d] [::1       ] [x@y.z     ] [xxxxx          ] [Serilog.AspNetCore.RequestLoggingMiddleware ] [                                                                                            ] [                        ] HTTP GET /ping/caller returned 200 in 13.9 ms

[nblumhardt]

Hi @alekdavisintel, thanks for the note.

This is a caller responsibility, e.g. you need:

using var op = log.ForContext<MyClass>().TimeOperation(...);

It's common to already have a contextual logger handy in the context of a class. In this way the timings and other log messages from the same source get the same context.

If you use Operation.X() you won't get a SourceContext, in the same way that the basic Log.X() won't set one.

In the static context, Log.ForContext<T>().TimeOperation(...) etc. will do what you need. HTH!

[alekdavisintel]

@nblumhardt Thank you, but I'm a bit lost here. All our classes (except the startup logic) use the standard Microsoft.Extensions.Logging.ILogger objects (initialized as ILogger). So, a class member handling logging is defined as:

private ILogger _logger;

The ForContext or TimeOperation methods are not available under the standard ILogger interface. I read https://github.com/nblumhardt/serilog-timings?tab=readme-ov-file#use-with-ilogger, but the example would not compile. Maybe I'm missing something but I do not see how to plug the contextual logger object (and as you can see in my post's example, we do get the SourceContext info from all ILogger calls).

I think I get your point that when using the Operation methods (such as Operation.Begin), we do not get the context, but I'm not sure what to do if we already have a contextual logger object. Our current code looks like this, and I would not want to complicate it, so if it is not possible, it's not a big deal:

using (LogContext.PushProperty(LogProperty.MethodName, CallContext.GetClassMethodName(this)))
using (Operation timer = Operation.Begin(CallContext.GetClassMethodName(this)))
{
    ...
    try
    {
        ...
        _logger.LogDebug(...);
        ... 
        timer.Complete();
    }
    catch (Exception ex)
    {
        ...
    }
 }

The CallContext.GetClassMethodName(this) returns the class and method name from the location the call was made (this way we can use it as a template in any class and/or method without hard coding anything.

[nblumhardt]

Hi @alekdavisintel; SerilogTimings extends the Serilog API with timed operations; if you want to use the MEL API you'll need something like https://github.com/eltoncezar/LoggingTimings or https://github.com/ogulcanturan/Ogu.Extensions.Logging.Timings (similar to this project, but targeting MEL).

Another option, if you're using Serilog on the back-end with MEL API, is to use System.Diagnostics.Activity for your timings, and process these via SerilogTracing (more complicated, but including this for completeness). HTH!

[alekdavisintel]

@nblumhardt Sorry, what is MEL API? Never heard of MEL.

[nblumhardt]

Microsoft.Extensions.Logging :-)