How to troubleshoot the ApplicationLifecycleModule HttpModule is loading and configured properly?

[serilog-web]

How to troubleshoot the ApplicationLifecycleModule HttpModule is loading and configured properly?

[brian-pickens]

Anyone watching these issues at all?

[tsimbalar]

Hi Brian,

yes, I am watching those, but I am also quite busy with other things ;)

I think I'm missing a bit of context here, and I'm not 100% sure what it is you are trying to achieve

Can you confirm that you are indeed using ASP.NET MVC ?

I don't think I understand what it is you are trying to do with

 "WriteTo": [
      // ...
      {
        "Name":  "Mvc"
      },
      // ...
    ],

this would map in code to a configuration like .WriteTo.Mvc() ... and indeed, as the error says, there is no such thing : Unable to find a method called Mvc.

Also, note that by default, the HttpModule writes to the global static Log.Logger instance, so this is the one you need to configure properly, or alternatively, you can tell the HttpModule to which instance of Loggerto write to.

To use the default global logger, this means you should be doing something like

// configuration / creation of a logger
// _logger = new LoggerConfiguration()
//    .xxxx()
//    .CreateLogger();

// make it the default global logger
Log.Logger = _logger ;

or you can do this, as seen in the README:

SerilogWebClassic.Configure(cfg => cfg
  .UseLogger(_logger )
));

I hope this helps !

[brian-pickens]

Yes, this is a classic asp.net mvc app. The issue is that no http requests are being logged out.

The last part about configuring the global logger or the .UseLogger configuration method isn't mentioned in the README as a requirement to enable request logging output. That being said, I added both and yet I am not seeing any request logs being output. Here is my updated setup and settings. At the end I included the log output to show that the logger is correctly logging to the file output as I expect but I don't get any request logs when navigating around the web app.

So my real question is: Is there anyway to debug that the actual ApplicationLifecycleModule HttpModule is loaded and configured properly?

Application_Start

            var environmentName = (Environment.GetEnvironmentVariable("ASPNET_ENVIRONMENT") ??
                                   Environment.GetEnvironmentVariable("ASPNETCORE_ENVIRONMENT") ??
                                   DefaultEnvironmentName).ToLower();

            Serilog.Debugging.SelfLog.Enable(msg => Debug.WriteLine(msg));

            // Configure from serilog json configuration
            var configuration = new ConfigurationBuilder()
                .SetBasePath(AppDomain.CurrentDomain.BaseDirectory)
                .AddJsonFile($"serilog.{environmentName}.json")
                .Build();

             // Manual code configuration
            _logger = new LoggerConfiguration()
                .ReadFrom.Configuration(configuration)
                .CreateLogger();

            // Set the global logger
            Log.Logger = _logger;

            // Should be enabled by default but adding this to ensure it is true
            SerilogWebClassic.Configure(cfg => cfg
                .UseLogger(_logger)
                .LogAtLevel(LogEventLevel.Verbose)
                .EnableFormDataLogging()
                );

            _logger.Information("Application Start");
            _logger.Information("----IS THIS LOGGING----");

Serilog.development.json

{
  "Serilog": {
    "Using": "SerilogWeb.Classic.Mvc",
    "MinimumLevel": "Information",
    "WriteTo": [
      {
        "Name": "Debug"
      },
      {
        "Name": "File",
        "Args": {
          "path": "%PROGRAMDATA%\\logs\\Log.txt",
          "formatter": "Serilog.Formatting.Compact.RenderedCompactJsonFormatter, Serilog.Formatting.Compact"
        }
      }
    ],
    "Enrich": [
      "FromLogContext",
      "WithMachineName",
      "WithThreadId"
    ],
    "Properties": {
      "Application": "MyApplication",
      "Environment": "Development"
    }
  }
}

Log Output

{"@t":"2020-11-02T16:49:50.9885754Z","@m":"Application Start","@i":"41091c09","MachineName":"blahblah","ThreadId":47,"Application":"MyApplication","Environment":"Development"}
{"@t":"2020-11-02T16:49:51.0115770Z","@m":"----IS THIS LOGGING----","@i":"9e8e5ea3","MachineName":"blahblah","ThreadId":47,"Application":"MyApplication","Environment":"Development"}

EDIT:
I found how to view the loaded HttpModules. Here is a screenshot that shows the module is loaded properly.

[brian-pickens]

Update

Okay, I honestly don't know what is going on, but seemingly without change, it simply started logging requests. The only explanation I can think of is that Rebuilding and restarting my IIS site still somehow wasn't running updated binaries. It started working once I went into Modules and decompiled and loaded the Serilog.Classic symbols with resharper and debugged into the HttpModule. Which I guess means you can close this issue. Now I just have to figure out why its double logging the requests.

[tsimbalar]

The last part about configuring the global logger or the .UseLogger configuration method isn't mentioned in the README as a requirement to enable request logging output.

It is there in a sample, but maybe not as visible as it should be. Pull Requests are welcome :)

When trying to figure out issues, I found that it usually helps to :

• go back to writing all the Serilog configuration code in C# instead of loading from the settings first.
• use a "simpler" Sink like the console one to validate that entries are indeed written (with the file ones, there are many reasons why things would not go according to plan, like permissions, disk issues etc etc)

And only once you have confirmed that it works, move it to configuration file (although in my opinion, you usually only need a minor part of the configuration to be settable through the config file. In your example, for instance, I believe the enrichment FromLogContext and WithMachineName might as well be configured in C# code.

Not sure this is related at all, but from the code samples you posted, I see :

SerilogWebClassic.Configure(cfg => cfg
                .UseLogger(_logger)
                .LogAtLevel(LogEventLevel.Verbose)
                .EnableFormDataLogging()
                );

.LogAtLevel(LogEventLevel.Verbose) means that log entries for http requests will be logged at the level Verbose (i.e. the lowest level available) ...

but your Logger is configured with "MinimumLevel": "Information" , meaning entries of levels lower than Information will be completely ignored. This would explain why you do not observe any entries in your log file ?

[tsimbalar]

Okay, I honestly don't know what is going on, but seemingly without change, it simply started logging requests. The only explanation I can think of is that Rebuilding and restarting my IIS site still somehow wasn't running updated binaries. It started working once I went into Modules and decompiled and loaded the Serilog.Classic symbols with resharper and debugged into the HttpModule. Which I guess means you can close this issue. Now I just have to figure out why its double logging the requests.

I think I've had issues in the past, about IIS aggressively caching some Http modules, and not seeing changes until I actively tried to clean up that cache. Things I remember doing back in the days was deleting file in each of the "Temporary ASP.NET files" folder of each variant of each installed version of .NET (x86 and x64) ... glorious times 🤕

I'll close this issue for now, as I believe you could solve the part related to Serilog.