Cannot get enricher to work with asp.net webapi

[dmoore1181]

Within my startup.cs file in my web api I have the following code, when I run the api, the logs do get written to the correct file location, but there isn't any difference if I remove the second line (.Enrich) from the statement. I am almost sure that I am doing something wrong, but I cannot figure out what that is. I have more detail in a stack overflow question here: StackOverflow

Log.Logger = new LoggerConfiguration()
    .Enrich.WithWebApiActionName()
    .WriteTo.File("D:/mytestresults.txt")
    .CreateLogger();

[tsimbalar]

Hi David,

I posted an answer : https://stackoverflow.com/a/55365329/474763 .

Here it is, copy/pasted :

I think that what is happening right now is that your "log events" are properly enriched with all the information, but the File sink is not configured properly to display that information.

The default output template of the File sink is {Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} \[{Level:u3}\] {Message:lj}{NewLine}{Exception} , which means that it will properly display the "rendered message" (the message template + the value of the properties that are referenced in the message template).

What you need to do is to configure it in a way that all the extra properties (the ones that are added to each log event when it is enriched) are also displayed.

For the File sink, you can for instance add the special {Properties} directive in you output template, and that will show all the properties that are attached to the event, but are not rendered as part of the message template.

That would look like :

Log.Logger = new LoggerConfiguration()
    .Enrich.WithWebApiActionName()
    .WriteTo.File("D:/mytestresults.txt", outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} \[{Level:u3}\] {Message:lj}{Properties}{NewLine}{Exception}")
    .CreateLogger();

(or {Properties:j} to have them formatted as JSON).

This will output all the properties attached to the event but not located anywhere else in the output template.

If you are only interested in the WebApiAction, you could also do something like :

Log.Logger = new LoggerConfiguration()
    .Enrich.WithWebApiActionName()
    .WriteTo.File("D:/mytestresults.txt", outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} \[{Level:u3}\]<{WebApiAction}> {Message:lj}{NewLine}{Exception}")
    .CreateLogger();

... and then you would end up with lines like this in the output :

2019-03-26 10:09:13.621 -04:00 [INF]<MyActionName> HTTP GET /api/actions/ responded 200 in 9ms

[tsimbalar]

Based on your comments on StackOverflow ...

We might need some extra information, and ideally a minimal repro to see if we can figure it out...

• Can you tell me which version of everything you use ? (Web API, Serilog packages etc)
• are you hosting your app in IIS ? IIS Express ? which version ?
• which version of .NET Framework are you targetting ?
• are you doing things in start-up / pre-start-up that may impact the AuthenticationFilters registered in Web API ?

Thanks !

[tsimbalar]

Also, based on this comment on Stack Overflow : https://stackoverflow.com/a/29897107/474763 ... can you confirm that the SerilogWeb.Classic.WebApi dll is present in your app'sbin` folder ?

[dmoore1181]

I can confirm that the SerilogWeb.Classic.WebApi.dll is present. I was using Microsoft.AspNet.WebApi V5.2.3, and just upgraded it to V5.2.7 to see if that would make any difference, but it stayed the same.

Serilog:
Serilog V2.8.0
Serilog.Sinks.Console V3.1.1
Serilog.Sinks.File V4.0.0
Serilog.Sinks.MSSqlServer V5.1.2
Serilog.Sinks.PeriodicBatching V2.1.1
SerilogWeb.Classic V5.0.48
SerilogWeb.Classic.WebApi V4.0.5

The site that I am using this for is an Angular 6 frontend with of course a Microsoft Web Api backend.

While I have been testing, I have been using IIS Express, but once released to production, this will then be in IIS.

I am using .Net Version 4.6.1

As far as impacting the AuthenticationFilter, I don't believe that we have anything that would do this. We do have a custom token service as our users use a smart card for login, but that should not be impacting the Authentication Filter as far as I know.

I would love to share my code, but unfortunately I am not able to. I can give a snippet from the Startup.cs:

public class Startup
{
    public void Configuration(IAppBuilder app)
    {
        app.UseCors(CorsOptions.AllowAll);

        ConfigureOAuth(app);

        var config = new HttpConfiguration();

        var jsonFormatter = config.Formatters.OfType<JsonMediaTypeFormatter>().First();
        jsonFormatter.SerializerSettings.ContractResolver = new CamelCasePropertyNamesContractResolver();

        config.MapHttpAttributeRoutes();

        // Convention-based routing.
        config.Routes.MapHttpRoute(
            name: "DefaultApi",
            routeTemplate: "api/{controller}/{id}",
            defaults: new { id = RouteParameter.Optional });

        config.EnsureInitialized();

        app.UseWebApi(config);                                 

        //configure signalr - enable detailed error messages
        var hubConfigutation = new HubConfiguration();
        hubConfigutation.EnableDetailedErrors = true;

        //enable signal r middleware
        app.MapSignalR(hubConfigutation);

        setupLogger();
    }

    private void setupLogger()
    {
        var connectionString = ConfigurationManager.ConnectionStrings["AppSecurityConnection"].ConnectionString;
        var tableName = "Logs";
        Log.Logger = new LoggerConfiguration()
        //  .Enrich.FromLogContext()
        //.Enrich.WithUserName()
        //.Enrich.WithWebApiRouteData()
        //.Enrich.WithWebApiControllerName()
        //.Enrich.WithWebApiRouteTemplate()
        .Enrich.WithWebApiActionName()
        //.Enrich.WithHttpRequestUrl()
        .WriteTo.MSSqlServer(connectionString, tableName, restrictedToMinimumLevel: 
Serilog.Events.LogEventLevel.Information, autoCreateSqlTable: true)
        .WriteTo.File("D:/mynewlog.txt", outputTemplate: "<{WebApiAction}> Time: {Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} Level:[{Level:u3}] Message:{Message:lj}Properties:{Properties}{NewLine}{Exception}")
        .CreateLogger();

        //For debugging purposes, you can log information when the logger is not working for some reason:
        //var file = File.CreateText("D:/logging.txt");
        //Serilog.Debugging.SelfLog.Enable(TextWriter.Synchronized(file));
        //You can also add this to the logger configuration to write to a file if needed. 
        //.WriteTo.File("D:/mynewlog.txt", outputTemplate: "Time: {Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} Level:[{Level:u3}] Message:{Message:lj}Properties:{Properties}{NewLine}{Exception}")
    }

[tsimbalar]

Not sure if

app.UseCors(CorsOptions.AllowAll);

ConfigureOAuth(app);

may be impacting the default filters in WebApi ...

What you can try is to try launching your Web API in the debugger, and take a look at what is present in GlobalConfiguration.Configuration.Filters at the end of your Configuration() method (or later, for instance with a breakpoint in the controller) ... and confirm that there is an instance of StoreWebApInfoInHttpContextAuthenticationFilter in there.

I hope this helps !

[tsimbalar]

( you probably want to call setupLogger() at the very beginning of your Configuration() method by the way)

[tsimbalar]

From your code snippet I see that you are using the OWIN-based hosting mode of Web API , i.e. Self-Hosting mode (the one described in this section).

The SerilowWeb.Classic.WebApi extension registers its "Filter" (ExceptionFilter and AuthenticationFilter) through GlobalConfiguration.Configuration.Services.Add(...) and GlobalConfiguration.Configuration.Filters.Add(...). From the documentation, it seems that this is designed for "non-OWIN" hosting mode :-/ .... maybe in that case you'd need to register those handlers explicitly 🤔

[dmoore1181]

Do you have any advice on how to go about registering the handlers explicitly? Unfortunately I don't have much knowledge at this level of the application.

Thank you for all your help so far.

[tsimbalar]

I'm going to suggest something ugly for now, just to test it and validate that it works, and later on come up with a plan to improve it :)

I would suggest you clone this repo, and copy the following source files to your project (because right now they are not public ...) :

• https://github.com/serilog-web/classic-webapi/blob/master/src/SerilogWeb.Classic.WebApi/Classic/WebApi/StoreWebApInfoInHttpContextAuthenticationFilter.cs
• https://github.com/serilog-web/classic-webapi/blob/master/src/SerilogWeb.Classic.WebApi/Classic/WebApi/WebApiRequestInfoKey.cs
• https://github.com/serilog-web/classic-webapi/blob/master/src/SerilogWeb.Classic.WebApi/Classic/WebApi/HttpActionContextExtensions.cs

(you may want/have to tweak the namespaces a bit if needed ;) )

and then as part of your Startup.Configuration(() method (just before config.EnsureInitialized(), I think), add :

config.Services.Add(typeof(IExceptionLogger), new WebApiExceptionLogger());
config.Filters.Add(new StoreWebApInfoInHttpContextAuthenticationFilter());

this should register in your Web API config the same Handlers that would normally be done automatically upon starting ...

[dmoore1181]

Unfortunately I am getting the same result. I added the following files to my project:

Constants.cs
HttpActionContextExtensions.cs
StoreWebApInfoInHttpContextAuthenticationFilter.cs
WebApiRequestInfoKey.cs

And I made the following changes in my code:

• Moved setupLogger(); to the top of the Configuration method
• Added the following lines before the EnsureInitialized method call:

config.Services.Add(typeof(IExceptionLogger), new WebApiExceptionLogger());
config.Filters.Add(new StoreWebApInfoInHttpContextAuthenticationFilter());

I set a break point just after the EnsureInitialized call to see if I can see if either of the two previous calls worked, and I can see the filter is in the config.Filters collection, but I cannot see, or don't know where to find, the WebApiExceptionLoggerwithin the Services. Again, not sure if that is due to me not knowing which node to look in, or if it isn't getting added successfully.

[tsimbalar]

don't worry about the WebApiExceptionLogger , that one is secondary and is not really required to track down the issue ...

The mystery remains then ... 🤔

Is there any chance you could put a breakpoint somewhere within StoreWebApInfoInHttpContextAuthenticationFilter and in HttpActionContextExtensions to validate that :

• AuthenticateAsync does get called
• in StoreWebApInfoInHttpContext, HttpContext.Current exists (we are relying on it to store the info and attach it to the logs)

[tsimbalar]

Also reading a bit around about how some settings related to async/await, SynchronizationContexts and other joys can break/fix some things with Web API , can you confirm that you have something like

<httpRuntime targetFramework="4.6.1" />

in your Web.config ?

Reading through https://devblogs.microsoft.com/aspnet/all-about-httpruntime-targetframework/ :

Certain features like WebSockets require that this switch be set. Importantly, the behavior of async / await is undefined in ASP.NET unless this switch has been set. (Remember: setting is also sufficient.)

[dmoore1181]

Yes, <httpRuntime targetFramework="4.6.1" /> is included in the web.config, and I have confirmed that both of the before mentioned files are being accessed and the HttpContext.Current does exist.

[tsimbalar]

OK, this is starting to be worrying :P

Can you try

• creating a CustomEnricher (class that implements Serilog.Core.ILogEventEnricher ) , with a dummy Enrich method implementation like

        public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
        {
            var property = propertyFactory.CreateProperty("MYPROPERTY", "WHATEVER", false);
            logEvent.AddPropertyIfAbsent(property);
}

• add that enricher to your log config by adding .Enrich.With(new CustomEnricher())
• set a breakpoint in the Enrich method
• run / debug your app
• when you hit the breakpoint, look at :
  • is HttpContext.Current set at that point ?
  • is there anything in HttpContext.Current.Items["SerilogWebClassicWebApiContextInfo"] ?

[dmoore1181]

I will try to do this tomorrow afternoon. I am off work till Monday, but should be able to remote in for a bit tomorrow afternoon. Thank you, David

[dmoore1181]

Sorry for the delay. I do have the HttpContext.Current at that point, but nothing in the point that you wanted. Here is an image of the watch window.

The good news is that the custom enricher did work, so ideally there should be a way to get this to work.

[dmoore1181]

I have done a little more investigating and found strangely that within the StoreWebApInfoInHttpContext method, that the contextualInfo is getting set correctly with the action and controller names. I would think that if it has the data at that point, that it would be able to record it. I will investigate some more and let you know if I find anything.

[tsimbalar]

I've heard about some bugs in some OWIN middleware that seem to subtly break the AsyncContext and therefore cause the HttpContext to be somehow lost at somepoint during the Web API/OWIN middleware pipeline. (i.e between the point where we add stuff to the HttpContext and the moment we actually write the log, quite late in the ASP.NET processing pipeline ...)

@Suchiman mentioned something like this in the serilog gitter chat :

@tsimbalar indeed ;) i'm using SerilogWeb.Classic in my current WebAPI 2 world domination project at work (which i'll hopefully one day get time for to move to core, i have a working prototype). The other Project is probably forever stuck on MVC 5.

but for some reasons… SerilogWeb.Classic doesn't work on my WebAPI 2, it does write the "HTTP {Method} {RawUrl} responded {StatusCode} in {ElapsedMilliseconds}ms" log message for web api requests but it doesn't attach things like HttpRequestId to the other log messages

i'm starting to remember what i've figured back then. For some reason, HttpContext.Current is null and i was unable to figure why it sometimes works and sometimes not

lol and now i know why it happens, Always suprising when you let a Problem rest and then much later figure it out almost instantly ( https://github.com/azzlack/Microsoft.AspNet.WebApi.MessageHandlers.Compression somehow breaks the async context)

and found an issue with an unpublished fix hehe azzlack/Microsoft.AspNet.WebApi.MessageHandlers.Compression#45

Do you happen to be using any of this middleware or similar ?

[tsimbalar]

Maybe taking a look at was is in GlobalConfiguration.Configuration.MessageHandlers could help see if there is possibly something that could affect the processing ...

[dmoore1181]

We are using this: https://github.com/aspnet-contrib/AspNet.Security.OpenIdConnect.Server for our middle ware, but that is running in a separate project. Not sure if that shines any light or not.

[tsimbalar]

Maybe, just to give it a try, could you remove it from your configuration and see if it improves anything ?

From those articles, it seems that there are some inconsistencies and pitfalls with the use of HttpContext.Current and the use of async/await somehow, as detailed on several blog posts, articles or Stack Overflow questions like :

https://blog.matrosov.by/2013/04/web-api-asyncawait-and-missed.html

https://stackoverflow.com/questions/18383923/why-is-httpcontext-current-null-after-await

Maybe, for the sake of testing, you could also play around with the appSettings parameters, toggling it between true and false, see if it changes anything :

<add key="aspnet:UseTaskFriendlySynchronizationContext" value="true" />

(which should not be necessary with <httpRuntime targetFramework="4.6.1" />, but well )

[tsimbalar]

Another doubt I have is ... I see you are using the OWIN version of Web API , but hosting it in IIS ...

Which package are you currently using ?

• https://www.nuget.org/packages/Microsoft.Owin.SelfHost/
• https://www.nuget.org/packages/Microsoft.Owin.Host.SystemWeb/
• something else ?

[Suchiman]

Just to add some details on my original issue, this was caused by ConfigureAwait(false) which works like this as far as i've seen.

public async Task Main()
{
    // HttpContext.Current ok here
    await Sub()
    // HttpContext.Current fine again here
}

public async Task Sub()
{
    // HttpContext.Current ok here
    await Task.Delay(1).ConfigureAwait(false);
    // HttpContext.Current null here due to false ^
    // if you were to make a call(back) from here to your code it would be without HttpContext.Current
}

[dmoore1181]

I am using Microsoft.Owin.Host.SystemWeb

[dmoore1181]

I have finally been able to get something to work, not sure if it will raise more questions than answers, but the following allows me to use a custom enricher to do this:

using Serilog.Core;
using Serilog.Events;
using System;
using System.Collections;
using System.Collections.Generic;
using System.Linq;
using System.Web;

namespace MyOrganization.Api.SerilogWebHelpers
{
    public class ControllerNameEnricher : ILogEventEnricher
    {
        public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
        {
            var seriLogWebApiContextInfo = (IDictionary)HttpContext.Current.Items["SerilogWebClassicWebApiContextInfo"];
            if (seriLogWebApiContextInfo != null)
            {
                var webInfo = new Dictionary<string, string>();
                foreach ( DictionaryEntry seriLogDictionaryEntry in seriLogWebApiContextInfo)
                {
                    if (seriLogDictionaryEntry.Value is string)
                    {
                        webInfo.Add(seriLogDictionaryEntry.Key.ToString(), seriLogDictionaryEntry.Value.ToString());
                    }
                }

                //I don't understand why this doesn't work, just returns null
                var myProp = seriLogWebApiContextInfo["ControllerName"];

                var property = propertyFactory.CreateProperty("ControllerName", webInfo["ControllerName"], false);
                logEvent.AddPropertyIfAbsent(property);
            }
        }
    }
}

The code seems a little convoluted, but I wasn't able to directly access the data via the seriLogWebApiContextInfo variable, instead I had to loop through it and create a dictionary that I could then read.

[tsimbalar]

Wow, that is indeed very bizarre !

Wondering if this could be related to the fact that we use enums as keys to out dictionary ?

Theoretically, the type of HttpContext.Current.Items["SerilogWebClassicWebApiContextInfo"] should be Dictionary<WebApiRequestInfoKey, object> ... but when retrievinf data we just care that it implements IReadOnlyDictionary<WebApiRequestInfoKey, object> ...

//I don't understand why this doesn't work, just returns null var myProp = seriLogWebApiContextInfo["ControllerName"];

the keys in our dictionary are actually enum members of

https://github.com/serilog-web/classic-webapi/blob/1f6c2c174f8b3c117b4f02be0d2046463a7d7356/src/SerilogWeb.Classic.WebApi/Classic/WebApi/WebApiRequestInfoKey.cs#L7-L15

so the keys are not really strings ...

You could try seriLogWebApiContextInfo[1] , to see if it changes anything (1 being the underlying value of WebApiRequestInfoKey.ControllerName)

[dmoore1181]

That helps out a lot, got it simplified down to this which appears to be working as I need. Thank you for all your assistance on this.

using System.Collections.Generic;
using System.Web;
using Serilog.Core;
using Serilog.Events;

namespace MyOrganization.Api.SerilogWebHelpers
{
    public class ControllerNameEnricher : ILogEventEnricher
    {
        public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
        {
            var seriLogWebApiContextInfo = (Dictionary<WebApiRequestInfoKey, object>)HttpContext.Current.Items["SerilogWebClassicWebApiContextInfo"];
            if (seriLogWebApiContextInfo != null)
            {
                var controllerName = seriLogWebApiContextInfo[WebApiRequestInfoKey.ControllerName];
                var property = propertyFactory.CreateProperty("ControllerName", controllerName, false);
                logEvent.AddPropertyIfAbsent(property);
            }
        }
    }
}

[tsimbalar]

What is disturbing is that this is pretty much exactly what is in

https://github.com/serilog-web/classic-webapi/blob/master/src/SerilogWeb.Classic.WebApi/Classic/WebApi/Enrichers/WebApiControllerNameEnricher.cs

and

https://github.com/serilog-web/classic-webapi/blob/master/src/SerilogWeb.Classic.WebApi/Classic/WebApi/Enrichers/BaseWebApiContextInfoEnricher.cs