serilog-web/classic

Serilog web request logging and enrichment for classic ASP.NET applications

SerilogWeb.Classic

Web request logging and enrichment for classic ASP.NET applications (System.Web).

Package - SerilogWeb.Classic | Platforms - .NET 4.5

This package replaces the Serilog.Extras.Web package previously included in the Serilog project.

This package is designed for full framework ASP.NET applications. For ASP.NET Core, have a look at Serilog.AspNetCore

When you work with an ASP.NET web application, this package adds

• additional enrichers
• an HttpModule to enhance the logging output.

When working with ASP.NET MVC (not Core) or ASP.NET Web API, you may also want to have a look at SerilogWeb.Classic.Mvc and SerilogWeb.Classic.WebAPI

Enrichers

The following enrichers are available as extension methods from the LoggerConfiguration.Enrich API:

• WithClaimValue : adds a property contaning the value of a given claim from the current ClaimsIdentity User
• WithHttpRequestClientHostIP : adds a property HttpRequestClientHostIP containing Request.UserHostAddress (optionally checking for proxy header)
• WithHttpRequestClientHostName : adds a property HttpRequestClientHostName containing Request.UserHostName
• WithHttpRequestId : adds a property HttpRequestId with a GUID used to identify requests.
• WithHttpRequestNumber : adds a property HttpRequestNumber with an incrementing number per request.
• WithHttpRequestRawUrl : adds a property HttpRequestRawUrl with the Raw Url of the Request.
• WithHttpRequestTraceId : adds a property HttpRequestTraceId with a GUID matching the RequestTraceIdentifier assigned by IIS and used throughout ASP.NET/ETW. (IIS ETW tracing must be enabled for this to work)
• WithHttpRequestType : adds a property HttpRequestType with the Request Type (GET or POST).
• WithHttpRequestUrl : adds a property HttpRequestUrl with the Url of the Request.
• WithHttpRequestUrlReferrer : adds a property HttpRequestUrlReferrer with the UrlReferrer of the Request.
• WithHttpRequestUserAgent : adds a property HttpRequestUserAgent with the User Agent of the Request.
• WithHttpSessionId : adds a property HttpSessionId with the current ASP.NET session id.
• WithUserName : adds a property UserName with the current username or, when anonymous, a defined value. By default this is set to (anonymous).

var log = new LoggerConfiguration()
    .WriteTo.Console()
    .Enrich.WithHttpRequestId()
    .Enrich.WithUserName()
    .CreateLogger();

To override the username enricher behaviour:

var log = new LoggerConfiguration()
    .WriteTo.ColoredConsole()
    .Enrich.WithUserName("not known yet", System.Environment.UserName)
    .CreateLogger();

Enrichers can also be defined in a configuration file by using Serilog.Settings.AppSettings as follows:

<appSettings>
    <add key="serilog:using:SerilogWeb.Classic" value="SerilogWeb.Classic"/>
    <add key="serilog:enrich:WithClaimValue.claimProperty" value="MyClaimPropertyName"/>
    <add key="serilog:enrich:WithHttpRequestClientHostIP"/>
    <add key="serilog:enrich:WithHttpRequestClientHostName"/>
    <add key="serilog:enrich:WithHttpRequestId"/>
    <add key="serilog:enrich:WithHttpRequestNumber"/>
    <add key="serilog:enrich:WithHttpRequestRawUrl"/>
    <add key="serilog:enrich:WithHttpRequestTraceId"/>
    <add key="serilog:enrich:WithHttpRequestType"/>
    <add key="serilog:enrich:WithHttpRequestUrl"/>
    <add key="serilog:enrich:WithHttpRequestUrlReferrer"/>
    <add key="serilog:enrich:WithHttpRequestUserAgent"/>
    <add key="serilog:enrich:WithHttpSessionId"/>
    <add key="serilog:enrich:WithUserName"/>
</appSettings>

HttpModule

The ApplicationLifecycleModule Http module is automatically hooked up into your ASP.NET application as soon as you install the SerilogWeb.Classic package.

For each HTTP request that hits your application, this module will write log events containing information such as :

• Url
• Http Method
• Response status code
• Processing time

Regular events are written at Information level, and unhandled exceptions are captured and written at the Error level.

Optionally, form data that is posted to the server can also be captured.

The behavior of the Http module should fit most needs by default, but can be customized for finer control.

Fluent Configuration API

SerilogWeb.Classic v4.1 introduced a new fluent configuration API that is more discoverable and easier to test. The previous configuration mechanisms are still supported, but are considered obsolete and will be removed in a future major version.

All the configuration is done through method calls on SerilogWebClassic.Configure(cfg => cfg.xxx()).

By default, all requests will be logged at the Information level. To change this (i.e. to generate less events under normal conditions) use the LogAtLevel() method:

SerilogWebClassic.Configure(cfg => cfg
  .LogAtLevel(LogEventLevel.Debug)
);

(new in v5.1) If you want even more control, you can pass a callback to .LogAtLevel() and provide a Func<HttpContextBase, TimeSpan, LogEventLevel> like this :

SerilogWebClassic.Configure(cfg => cfg
  .LogAtLevel((context, elapsed) => elapsed.TotalMilliseconds > 3000 ? LogEventLevel.Warning : LogEventLevel.Information)
);

To enable the capture of posted form data:

SerilogWebClassic.Configure(cfg => cfg
  .EnableFormDataLogging()
);
// or
SerilogWebClassic.Configure(cfg => cfg
  .EnableFormDataLogging(forms => forms
    .OnlyOnError()
));
// or
SerilogWebClassic.Configure(cfg => cfg.
  .EnableFormDataLogging(forms => forms
    .OnMatch(ctx => !ctx.Request.Url.PathAndQuery.StartsWith("/__browserLink"))
));

Any fields containing the phrase 'password' will be filtered from the logged form data. This can be disabled with:

SerilogWebClassic.Configure(cfg => cfg
  .EnableFormDataLogging(forms => forms
    .DisablePasswordFiltering()
));

If you want to disable the logging completely, use the following statement:

SerilogWebClassic.Configure(cfg => cfg
  .Disable()
);

The configuration method calls are chainable, so a full configuration may look like :

SerilogWebClassic.Configure(cfg => cfg
  .UseLogger(myCustomLogger)
  .LogAtLevel(LogEventLevel.Debug)
  .IgnoreRequestsMatching(ctx => !ctx.Request.IsAuthenticated)
  .EnableFormDataLogging(forms => forms
    .AtLevel(LogEventLevel.Debug)
    .OnlyOnError()
    .FilterKeywords(new[] {"password", "authToken"} )
));

Legacy configuration

Before SerilogWeb.Classic v4.1, the configuration was done through static properties on ApplicationLifecycleModule class, as documented below.

This API is considered obsolete and may be removed in a future major version. Users should migrate to the newer fluent API documented above.

By default, all requests will be logged at the Information level. To change this (i.e. to generate less events under normal conditions) use the RequestLoggingLevel property:

ApplicationLifecycleModule.RequestLoggingLevel = LogEventLevel.Debug;

To enable the posting of form data:

ApplicationLifecycleModule.LogPostedFormData = LogPostedFormDataOption.Always;
// or
ApplicationLifecycleModule.LogPostedFormData = LogPostedFormDataOption.OnlyOnError;

Any fields containing the phrase 'password' will be filtered from the logged form data. This can be disabled with:

ApplicationLifecycleModule.FilterPasswordsInFormData = false;

If you want to disable the logging completely, use the following statement:

ApplicationLifecycleModule.IsEnabled = false;

classic's Issues

WithUserName Only Working With HttpModule Logging But Doesnt Log During Web Service/API Logs

I have configured logging with below values
.Enrich.WithUserName(noneUsername: "not found")
.Enrich.WithClaimValue(ClaimTypes.NameIdentifier, "TestUserName");

Its getting logged correctly when code logs HTTP calls but for any service/web api calls from the app it doesn't get log

ClientHostIP, RawUrl, UserAgent Enrichers?

I've migrated from the old SerilogExtras.Web and this doesn't seem to include enrichers for client IP, RawUrl, UrlReferrer, etc that the old one did.

Am I missing something? Any workarounds?

Thanks

Calling cfg.LogAtLevel to set the LogEventLevel seems to disable HTTP request logging?

I'm using a LoggingLevelSwitch and writing to a Seq sink. For some reason when I call

SerilogWebClassic.Configure(cfg => cfg.LogAtLevel(LogEventLevel.Debug));

We cease to get log events for the HTTP requests (however we still get logs for requests resulting in a 500 level HttpResponse)

My log level for the Seq API key token is set to verbose.

Here is an example of the configuration initialization.. perhaps I'm doing something wrong?

 internal void InitializeLogger()
{
    var levelSwitch = new LoggingLevelSwitch();

    var loggerConfiguration = new LoggerConfiguration()
            .Destructure.ByTransforming<System.Data.SqlClient.SqlException>(ex =>
            {
                // This particular exception is causing problems in Serilog when it gets decomposed into properties and values, hence the need to decompose it to something that won't have a problem
                // SQL System Error Messages (i.e. ex.Number): https://msdn.microsoft.com/en-us/library/cc645603(v=sql.105).aspx
                return new { ex.Message, ex.Server, ex.StackTrace, ex.HResult, ex.Data, ex.ErrorCode, ex.Procedure, ex.Number, ex.LineNumber, ex.Errors, ex.ClientConnectionId, ex.Class };
            })
            .Destructure.ByTransforming<System.Data.Common.DbException>(ex =>
            {
                return new { ex.Message, ex.Source, ex.StackTrace, ex.HResult, ex.Data, ex.ErrorCode };
            })
            .Enrich.FromLogContext()
            .Enrich.WithExceptionDetails()
            .Enrich.WithProperty("Application Server", Environment.MachineName)
            .Enrich.WithProperty("Application", "Enterprise Web API")
            .Enrich.WithHttpRequestClientHostIP()
            .Enrich.WithHttpRequestClientHostName()
            .Enrich.WithHttpRequestUrl()
            .Enrich.WithHttpRequestUrlReferrer()
            .Enrich.WithHttpRequestUserAgent()
            .Enrich.WithHttpSessionId()
            .Enrich.WithUserName()
            .Enrich.WithWebApiActionName()
            .Enrich.WithWebApiControllerName()
            .Enrich.WithWebApiRouteData()
            .Enrich.WithWebApiRouteTemplate();


    
    loggerConfiguration.WriteTo.Seq(
    ConfigurationManager.AppSettings["SeqServerUrl"],
    apiKey: ConfigurationManager.AppSettings["SeqApiKey"],
    controlLevelSwitch: levelSwitch,
    compact: true);
    

    Log.Logger = loggerConfiguration.CreateLogger();
	
    // If below line is commented out, all HTTP requests are logged... if left, only 500 responses are logged
    SerilogWebClassic.Configure(cfg => cfg.LogAtLevel(LogEventLevel.Debug));

}

We are also using the Classic-Webapi package if that has some affect...
Am I doing something out of order here?

In the sample app SerilogWeb.Test of the project log messages seem inconsistent

I first thought I had broken things while working on #49 , but I saw the same behavior when running from the master branch.

When debugging the application in VS 2017 + Firefox, I see log messages written to the Debug Output window that don't seem to match the observed behavior from the browser :

1. when loading the default page (http://localhost:49951/), 3 events are written to the log when I expected only 2 :

2018-03-10 15:11:39.199 +01:00 [Information] Page viewed!
2018-03-10 15:11:39.217 +01:00 [Information] HTTP "GET" "/" responded 200 in 18ms
2018-03-10 15:11:39.220 +01:00 [Information] HTTP "GET" "/" responded 200 in 26ms

2. when I click the (only) button of the only page , which throws an exception in the OnServerClick, I see 2 log events when I expected only 1 :

2018-03-10 15:12:50.952 +01:00 [Error] HTTP "POST" "/" responded 500 in 3697ms
System.Web.HttpUnhandledException (0x80004005): Exception of type 'System.Web.HttpUnhandledException' was thrown. ---> System.InvalidOperationException: Kablooey
   at SerilogWeb.Test.Default.Fail(Object sender, EventArgs e) in C:\Dev\classic\test\SerilogWeb.Test\Default.aspx.cs:line 17
   at System.Web.UI.HtmlControls.HtmlButton.OnServerClick(EventArgs e)
   ... snip ...
   at ASP.default_aspx.ProcessRequest(HttpContext context) in C:\Users\tdesodt.DEV\AppData\Local\Temp\Temporary ASP.NET Files\vs\d04cc936\cd123ae6\App_Web_lvoyjva2.0.cs:line 0
   at System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
   at System.Web.HttpApplication.ExecuteStepImpl(IExecutionStep step)
   at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)
2018-03-10 15:12:50.961 +01:00 [Information] HTTP "POST" "/" responded 200 in 3713ms

3. when I navigate to a url that does not exist like http://localhost:49951/ThisDoesNotExist, while my browser sees a 404 status code, the following line appears in the logs, with status code 200 ....

2018-03-10 15:17:30.620 +01:00 [Information] HTTP "GET" "/ThisDoesNotExist" responded 200 in 1ms

I'm not quite sure whether that is the expected behavior, some subtle strange oddity of IIS Express, or some specific behavior of ASP.NET or WebForms ... that did surprise me though, so I'd love to understand what is going on here :)

Log CorrelationId with SerilogWeb.Classic's log entries

I was looking to find a way I can push a Correlation Id into SerilogWeb.Classic's log events similar to the suggestion in #72 response.

If I push a property in the OnPreInit and dispose of it at the end of Page_Load it works ok for requests that actaully make it to my page e.g. not 401 errors.

If I dispose of my CorrelationId in the OnUnload it isn't logged with SerilogWeb.Classic's log events.

What is the best place to do this? I need to manage the CorrelationId myself so I can return it to the User if there is an issue and I don't think you can read Serilog properties once pushed.

Serilog 2.4.0 doesn't work

Hello,

I updated my projects with latest serilog. Cleaned packages and after that I started getting Serilog 1.5.0.0 dependency not found exception. Is there workaround for latest version of Serilog?

Thanks!

HttpModule isn't extensible?

What would be great is if the http module, in SerilogWeb.Classic.ApplicationLifecycleModule had some sort of hook to mix in more information from the http context when it was logging.

For instance, I have a scenario where I would really like to grab all the session data and dump it into the current log entry (enriched ideally) as the entire session.

Perhaps another take would be to have a hook that would allow me to set a particular context item, for the sake of logging, that had the data that I wanted, and then access to it with some clean enrichment, LogEventProperty, or something like that.

Really, having this module at all is helpful, thanks. Just thinking that some smoother way to sometimes add more session or context to a particular sink would be helpful.

Make the configuration API more discoverable and usable

Currently, all the configuration is done through static properties on the ApplicationLifecycleModule class.

This approach has several drawbacks :

• the naming makes it hard to figure out that this configuration class has anything to do with SerilogWeb, and makes it possibly hard for new-comers to a code base to establish any relationship with SerilogWeb
• the usage of some of the properties is counter intuitive and requires knowledge of the internals (like knowing that FilterPasswordsInFormData makes sense only if FormData is enabled

The current solution to those issues is the documentation (in the README or in the Intellisense), but it would be great if it could be more discoverable and prevented the user from applying settings that do not make sense.

I would like to propose a new configuration API that tries to fix those issues.

Because it is a big change, the previous API should remain available at least until the next major version (but be marked as Obsolete).

500 errors not logging

I am using version 2.0.9 of this component to log an ASP.NET MVC 5 application. It is working correctly, however does not log any 500 Internal server errors. All exceptions for other HTTP error codes are caught (400, 404 etc). Is there anything that may stop the logging of these 500 errors? Does an unhandled exception handler need to be setup at all? The app is fairly standard configuration wise.

Allow to pass an exception to the "logging module" through other means than HttpContext.AddError

The current means for the module to log the errors is to take a look at Server.GetLastError() (this is actually how the SerilogWeb.Classic.WebAPI pushes unhandled exceptions to the logging module).

While it covers most scenarios, it is kind of problematic when using IIS Custom Error Pages and ASP.NET MVC together.

In MVC, the standard one way to handle errors is by using HandleErrorAttribute (or a subclass) that states which view should be shown depending on the thrown exception.

While this sets the proper HttpCode for the response (the generated log event has the proper status code), the Exception is actually lost and does not appear in the log. (see #29 where this exception is logged only when CustomErrors="Off" ).

When I write a custom IExceptionFilter / FilterAttribute , I can add the exception through a call to filterContext.HttpContext.AddError(myException). When I do that, the Exception properly appears in the logs, but the presence of this Exception in the list of errors seems to trigger the IIS Custom Errors mechanism, and no matter what, instead of showing a custom view (passed to the attribute), the IIS-custom error page that is configured for Status Code 500 is shown ...

It seems I can either choose between either using AuthorizeAttribute or having exceptions in my logs ... which is not ideal ...

Maybe we should need a way to report an exception to the Logging Module without going through HttpContext.AddError() ...

I am thinking that it could be something like :

• adding an extension method on top of HttpContext (and friends) : AddSerilogWebError(Exception ex) that would store that Exception somewhere in the current context
• modify the current LoggingModule to look for Exceptions in :
  1. Server.GetLastError() (current behavior)
  2. Context.AllErrors.LastOrDefault() (current behavior)
  3. in the part of context where AddSerilogWebError stored it (new behavior)

This would allow to add write a custom AuthorizeAttribute that would store exceptions specifically for the logging module.

Optionnally SerilogWeb.Classic.WebApi could also use that channel to report to the logging module instead of using Context.AddError().

Does that make sense ?

Asynchronous operation kills module

Nick,

When I save files asynchronously to our filer the module dies... I think .

Just letting you know.

-Stephen

Special cases when using `FilterKeywords()` with `EnableFormDataLogging()`

Found that if the keywordBlackList parameter contains string.Empty / "", ALL the form values are obfuscated. I understood that IndexOf() that works internally on the list, finds the empty string at the beginning of any non-null string. Is this to be expected? I think that the intention would be more obvious if one could be able to configure EnableFormDataLogging with something like .ObfuscateAllValues() while the empty string will be ignored or stripped from the keywordBlackList.

Also, if a null slips into keywordBlackList, it crashes with the same IndexOf() throwing ArgumentNullException. Null should be ignored/stripped from the list.

What are your thoughts on these?

ApplicationLifecycleModule.IsEnabled = false; not working

I have 3 slots of an Azure Web Application running slightly different versions of the same ASP.NET MVC web app.

I'm logging to an external Seq server through Serilog with some enrichers from SerilogWeb.Classic. Each slot has its own ApiKey so I can differentiate each event in the Seq dashboard.

I don't want to log every HTTP request and this was working fine until now. All of a sudden one of the slots started logging every HTTP request. So I went back and make sure ApplicationLifecycleModule.IsEnabled = false; was there. It's there. I also went further and added ApplicationLifecycleModule.RequestLoggingLevel = Serilog.Events.LogEventLevel.Verbose; but it's not working either, the requests are still being logged with level Information.

The only real difference between the slots during deployment is the web.config that gets transformed in order to modify some appSettings, nothing strange.

What could be causing this behaviour? Is there another place where this could be overwritten?

Just to provide more information, this is the method that gets called in Global.asax Application_Start() method.

    public static class SerilogConfig
    {
        private const string SeqServerUrl = "http://mySeqUrl";
        private static readonly string ApiKey = ConfigurationManager.AppSettings["Seq.ApiKey"];

        public static void Initialize()
        {
            ApplicationLifecycleModule.IsEnabled = false; // disable logging every HTTP request
            ApplicationLifecycleModule.RequestLoggingLevel = Serilog.Events.LogEventLevel.Verbose;

            Log.Logger = new LoggerConfiguration()
                .WriteTo.Seq(SeqServerUrl, apiKey: ApiKey)
                .WriteTo.RollingFile(AppDomain.CurrentDomain.BaseDirectory + "App_Data\\" + "Logs\\" + "{Date}.txt")
                .Enrich.WithMachineName()            
                .Enrich.With(new HttpRequestClientHostIPEnricher(true))
                .Enrich.With(new HttpRequestClientHostNameEnricher())
                .Enrich.With(new HttpRequestRawUrlEnricher())
                .Enrich.With(new HttpRequestUrlReferrerEnricher())
                .Enrich.With(new HttpRequestUserAgentEnricher())              
                .CreateLogger();

            Log.Information("Application started.");
        }
    }

Complete the README

Add details about :

• enrichers included in the package (Claims enricher is not listed)
• relation with sub-packages (WebApi / Mvc)

How to write own local Enrichers

Hello,

I was trying to extend the existing enrichers for specific ones we need for our logging and realized that this is not possible due to HttpContextCurrent being an internal class.

So I was wondering how to write custom Enrichers?

For example we need to extract a specific cookie and log it as well.

I do not mind sending PR for the Enrichers, however a different solution to the problem would be appreciated.

Applicationlifecycle module question

In our Web API controllers we have the following:

        [HttpPost]
        public async Task<HttpResponseMessage> GetCommitmentsAsync(CommitmentSearchCriteria criteria)
        {
            try
            {
                // var result = result of some data access call...
                return CreateResponse(result);
            }
            catch (Exception ex)
            {
                Log.Error(ex, "Error getting commitments");
                return CreateErrorResponse(ex);
            }
        }

What we expect to see (and do see in most cases) is two logs

1. One from the catch block with the message "Error getting commitments" and the destructed exception object
2. One from the applicationlifecycle module with the information it adds

However we have a few methods in which it seams the logging statement in the catch block is never hitting. We see the logs from the applicationlifecycle module and that they failed very quickly (often 0 or 1ms as in the screenshot below) However, we do not see the corresponding log that should be in generated in the catch block.

Can you provide any input on what the root cause of this may be? Is there some request type that could result in a 500 level error that we should be filtering out?

HttpRequestUrlEnricher gives "Request is not available in this context" exception

I am currently using SerilogWeb.Classic v5.0.56 in a legacy webforms website.
After I decided to enable SelfLog, I found that adding log entries from the Application_Start in Global.asax while enriching with HttpRequestUrl chained to new LoggerConfiguration() throws the following exception

2020-04-17T16:29:46.1743072Z Exception System.Web.HttpException (0x80004005): Request is not available in this context
   at System.Web.HttpContext.get_Request()
   at SerilogWeb.Classic.Enrichers.HttpRequestUrlEnricher.Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
   at Serilog.Core.Enrichers.SafeAggregateEnricher.Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory) caught while enriching Serilog.Events.LogEvent with SerilogWeb.Classic.Enrichers.HttpRequestUrlEnricher.

'This well known exception raises its fancy head again', I told myself. So, I've looked into HttpContextCurrent.cs and HttpRequestUrlEnricher.cs.

I think that replacing if (HttpContext.Current?.Request?.Url == null) with if (HttpContextCurrent.Request?.Url == null) would fix it.

I am new to github. If I make mistakes please forgive a newbie, I'm learning/discovering :)

PS: Also I looked through the other files in the project and found no other instance of Request being accessed outside project's HttpContextCurrent. I was thinking of renaming this to help against any future confusion with HttpContext.Current.

HttpRequestClientHostIPEnricher throws exception with ASP.NET Integrated Mode

Logging events from Application_Start in global.asax can throw Exception if enriching with HttpRequestClientHostIPEnricher

for background/discussion see http://stackoverflow.com/questions/2518057/request-is-not-available-in-this-context

Exception with null key in form data

I have an old site using ASP.NET web forms and MS ajax. The MS ajax seems to be adding an extra ampersand to the post data:
...&__spDummyText2=&__ASYNCPOST=true&

I believe this is being translated into a null entry in the Form.AllKeys array. When I try to output form data in the log I get a null reference error. I believe it's the "key.IndexOf" on this line (SerilogWebClassicConfiguration.cs):
if (FilterPasswordsInFormData && FilteredKeywordsInFormData.Any(keyword => key.IndexOf(keyword, StringComparison.OrdinalIgnoreCase) != -1))

Here is the top of the stack trace:
[NullReferenceException: Object reference not set to an instance of an object.]
SerilogWeb.Classic.<>c__DisplayClass38_0.<FilterPasswords>b__0(String keyword) +7
System.Linq.Enumerable.Any(IEnumerable1 source, Func2 predicate) +169
SerilogWeb.Classic.SerilogWebClassicConfiguration.FilterPasswords(String key, String value) +121

If I don't apply any filter there is no error, the problem is that being the old web forms I have a large __VIEWSTATE that I don't want in the log.

Can a null check on the key variable be added? Or possibly in the calling code something like:
configuration.FilterPasswords(k ?? "", v)

IIS Web application hang up after multiple requests stuck on "Begin request"

We had a problematic scenario today which a .NET Framework 4.8 ASP.NET application hung up after queuing multiple requests stuck on "Begin request" state, on the __DynamicModule_SerilogWeb.Classic.ApplicationLifecycleModule module.

That same web application runs simultaneously on another 4 servers (webfarm), and we haven't had any issues on those at that moment. And just to be specific, the problem happened hours after the application startup.
We also noted that CPU usage went down when the requests started to queue.

After a while:

I have looked on the source code and the OnBeginRequest is where a simple stopwatch is added to the application context.
Is there a chance of concurrency on that part that might cause this behavior?

HttpRequestClaimValueEnricher

Hi.

What do you think about adding new enricher named HttpRequestClaimValueEnricher:

    public class HttpRequestClaimValueEnricher : ILogEventEnricher
    {
        /// <summary>
        /// The claim property name searched for value to enrich log events.
        /// </summary>
        private readonly string _claimProperty;

        /// <summary>
        /// The property name added to enriched log events.
        /// </summary>
        private readonly string _logEventProperty;

        public HttpRequestClaimValueEnricher(string claimProperty) : this(claimProperty, null)
        {
            _claimProperty = claimProperty;
        }

        public HttpRequestClaimValueEnricher(string claimProperty, string logEventProperty)
        {
            _claimProperty = claimProperty;
            _logEventProperty = logEventProperty ?? claimProperty;
        }

        public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
        {
            if (logEvent == null) throw new ArgumentNullException(nameof(logEvent));

            if (HttpContext.Current == null)
                return;

            if (HttpContextCurrent.Request == null)
                return;

            var user = HttpContext.Current.User;
            if (user == null)
                return;

            var claims = ((ClaimsIdentity) user.Identity).Claims;

            var value = claims?.FirstOrDefault(c => c.Type == _claimProperty)?.Value;
            if (string.IsNullOrWhiteSpace(value))
                return;

            var claimProperty = new LogEventProperty(_logEventProperty, new ScalarValue(value));
            logEvent.AddPropertyIfAbsent(claimProperty);
        }
    }

?

Using the EnvironmentUserName if none?

Would you be open to a PR which uses a specified LogEvent Property as the "noneUsername"? Ideally (for us) what we'd get is during app initialization or other non-HttpRequest threads (like a scheduled task) the UserName would provide EnvironmentUserName rather than null (rendered as blank in log files).

I tried setting the noneUsername to %USERDOMAIN%\%USERNAME%, but I assume since that is expanded at a different part of the app lifecycle, %USERNAME% is actually <mymachinename>$, rather than the user that w3wp is running as - which is correctly set with the EnvironmentUserName enricher.

We could hard code it as the service account user name, but that's a new maintenance issue for the various environments. I'd also rather be able to do this in the outputTemplate, but from what I can see that's not possible something like {UserName ?? EnvironmentUserName} would work, but that's for another project.

UserName enricher shows (anonymous) in ApplicationLifecycleModule with Microsoft.AspNet.WebApi.* >= 5.2.5

Microsoft made some changes in Microsoft.AspNet.WebApi.* version >= 5.2.5, which result in UserName enricher showing (anonymous) on the final log event, issued for ApplicationLifecycleModule, while all other events in the same context have the value of the authenticated API user.

My project ran initially on version 5.2.4, and after updating it to 5.2.6, I noticed the problem. I identified that the problem first appeared in 5.2.5 of Microsoft.AspNet.WebApi.* packages.

It looks like the user in HttpContext.Current holds user identity that is no longer authenticated at the time OnLogRequest is executed

Add Http Data To All Logging Events

Hello, this package adds a new logging event for each HTTP request that occurs. I was wondering if it's possible to add the HTTP logging to all logging events, so we can have the HTTP data available to us. So if I log some data, Log.Information("Testing"), the HTTP data gets added to it too.

Thanks

Multiple log messages for single Request with error 404

Hi,
I'm facing a problem with getting multiple log messages for a single request. One log message with status 404 (correct one) and one with status 200.

More particular, for requests that ends up with error 404 - and even more interestingly, only for request that doesn't end with file extension.

• /foo/invalid/request.jpg - this works fine, just a single error 404 is logged
• /foo/invalid/request - this is broken, multiple messages are logged, first one with error 404 and second one with status 200.

Example:

[15:28:12 INF] HTTP GET /file-manager/backend/permissions/a responded 404 in 0ms
Response sent: http://localhost:36700/file-manager/backend/permissions/a with HTTP status 404.0
[15:28:12 INF] HTTP GET /file-manager/backend/permissions/a responded 200 in 22ms

So far I managed to find out ApplicationLifecycleModule.Init is getting called multiple times and also Application.BeginRequest is called multiple times (which results into multiple calls of WebRequestLoggingHandler.OnBeginRequest). Also LogRequest is called multiple times.

I know ASP.NET is bit dated and now world has moved on to ASP.NET Core, but I still have few old projects to support until we can figure out migration to ASP.NET Core :(

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

In my Application_Start method, I'm configuring my logger using appsettings.json like so:

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

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

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

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

The problem is it appears the HttpModule is not to be getting picked up, so no requests are getting logged. I'm also not sure how to properly configure the enrichers using the appsettings.json file. Is it possible to configure the enrichers in this way?

appsettings.json

  "Serilog": {
    "Using": [ "SerilogWeb.Classic.Mvc" ],
    "MinimumLevel": "Information",
    "WriteTo": [
      {
        "Name": "Debug"
      },
      {
        "Name":  "Mvc"
      },
      {
        "Name": "File",
        "Args": {
          "path": "logs\\log.txt",
          "formatter": "Serilog.Formatting.Compact.RenderedCompactJsonFormatter, Serilog.Formatting.Compact"
        }
      }
    ],
    "Enrich": [
      "FromLogContext",
      "WithMachineName",
      "WithThreadId",
      "WithMvcRouteTemplate",
      "WithMvcControllerName",
      "WithMvcRouteData",
      "WithMvcActionName",
      "WithHttpRequestUrl"
    ],
    "Properties": {
      "Environment": "Development"
    }
  }
}

Selflog Output

2020-10-15T14:37:27.0423536Z Unable to find a method called Mvc. Candidate methods are:
Serilog.LoggerConfiguration Providers(Serilog.Configuration.LoggerSinkConfiguration, Serilog.Extensions.Logging.LoggerProviderCollection, Serilog.Events.LogEventLevel, Serilog.Core.LoggingLevelSwitch)
Serilog.LoggerConfiguration Debug(Serilog.Configuration.LoggerSinkConfiguration, Serilog.Events.LogEventLevel, System.String, System.IFormatProvider, Serilog.Core.LoggingLevelSwitch)
Serilog.LoggerConfiguration Debug(Serilog.Configuration.LoggerSinkConfiguration, Serilog.Formatting.ITextFormatter, Serilog.Events.LogEventLevel, Serilog.Core.LoggingLevelSwitch)
Serilog.LoggerConfiguration File(Serilog.Configuration.LoggerSinkConfiguration, System.String, Serilog.Events.LogEventLevel, System.String, System.IFormatProvider, System.Nullable`1[System.Int64], Serilog.Core.LoggingLevelSwitch, Boolean, Boolean, System.Nullable`1[System.TimeSpan])
Serilog.LoggerConfiguration File(Serilog.Configuration.LoggerSinkConfiguration, Serilog.Formatting.ITextFormatter, System.String, Serilog.Events.LogEventLevel, System.Nullable`1[System.Int64], Serilog.Core.LoggingLevelSwitch, Boolean, Boolean, System.Nullable`1[System.TimeSpan])
Serilog.LoggerConfiguration File(Serilog.Configuration.LoggerSinkConfiguration, System.String, Serilog.Events.LogEventLevel, System.String, System.IFormatProvider, System.Nullable`1[System.Int64], Serilog.Core.LoggingLevelSwitch, Boolean, Boolean, System.Nullable`1[System.TimeSpan], Serilog.RollingInterval, Boolean, System.Nullable`1[System.Int32], System.Text.Encoding)
Serilog.LoggerConfiguration File(Serilog.Configuration.LoggerSinkConfiguration, Serilog.Formatting.ITextFormatter, System.String, Serilog.Events.LogEventLevel, System.Nullable`1[System.Int64], Serilog.Core.LoggingLevelSwitch, Boolean, Boolean, System.Nullable`1[System.TimeSpan], Serilog.RollingInterval, Boolean, System.Nullable`1[System.Int32], System.Text.Encoding)
Serilog.LoggerConfiguration File(Serilog.Configuration.LoggerSinkConfiguration, System.String, Serilog.Events.LogEventLevel, System.String, System.IFormatProvider, System.Nullable`1[System.Int64], Serilog.Core.LoggingLevelSwitch, Boolean, Boolean, System.Nullable`1[System.TimeSpan], Serilog.RollingInterval, Boolean, System.Nullable`1[System.Int32], System.Text.Encoding, Serilog.Sinks.File.FileLifecycleHooks)
Serilog.LoggerConfiguration File(Serilog.Configuration.LoggerSinkConfiguration, Serilog.Formatting.ITextFormatter, System.String, Serilog.Events.LogEventLevel, System.Nullable`1[System.Int64], Serilog.Core.LoggingLevelSwitch, Boolean, Boolean, System.Nullable`1[System.TimeSpan], Serilog.RollingInterval, Boolean, System.Nullable`1[System.Int32], System.Text.Encoding, Serilog.Sinks.File.FileLifecycleHooks)
Serilog.LoggerConfiguration Sink(Serilog.Configuration.LoggerSinkConfiguration, Serilog.Core.ILogEventSink, Serilog.Events.LogEventLevel, Serilog.Core.LoggingLevelSwitch)
Serilog.LoggerConfiguration Logger(Serilog.Configuration.LoggerSinkConfiguration, System.Action`1[Serilog.LoggerConfiguration], Serilog.Events.LogEventLevel, Serilog.Core.LoggingLevelSwitch)

.netStandard v2 version ?

Hey there, is it scheduled a .netStandard v2 version ?

Request for new functionality in HttpRequestEnricher

Hello.

I’d like to have some new functionality in the HttpRequestIdEnricher class because in some scenarios, it’s necessary to propagate the ActivityId for later tracking.

Use case:
1- You have a Web Application that calls a Web Service.
2- The user logs in, and starts to use the Web Application. The HttpRequestId is created for this request.
3- The application calls to Web Service, passing the HttpRequestId in the http Header.
4- The web service (via HTTPModule or global.asax) captures the header.
a. In the present design, the Web Service has a different ActivityId than the Web Application.
b. [CHANGE] We would like to be able to set the Web App ActivityId in the HttpRequestId of the Web Service. This way we could spread the ActivityId to any app or service (instead having different ones for each app/service). That would be very useful for tracking the ActivityId later, using tools like Graylog (we have an Enricher that writes in GELF format).

One possible solution is to include in the HttpRequestIdEnricher class a method like this one:
public static bool SetCurrentHttpRequestId(Guid requestId)
{
if (HttpContext.Current == null)
{
return false;
}

        var requestIdItem = HttpContext.Current.Items[RequestIdItemName];
        if (!HttpContext.Current.Items.Contains(RequestIdItemName))
        {
            HttpContext.Current.Items.Add(RequestIdItemName, requestId);
        }
        else
        {
            HttpContext.Current.Items[RequestIdItemName] = requestId;
        }

        return true;
    }

With this change, we could set the HttpRequestId in the Web Service, and in case of failure we could consult the logs from the Web Application and any Web Services that this application called using the same ActivityId to track ALL the activity through different applications.

Regards

Need a way to log all HTTP headers

I don't see that this library offers a way to log all of the HTTP headers present when logging. We are trying to replace Elmah, and this functionality is included out-of-the-box in Elmah. Can we get such an enricher added here?

EnableFormDataLogging not logging anything with WebApi

I have used this sink along with classic-webapi and use this syntax at configuration

 .EnableFormDataLogging(forms => forms
                    .AtLevel(LogEventLevel.Information)
                    .FilterKeywords(new[] { "password", "authToken" })
                )

But when I post data to my webApi I see no any information logged ... Is that even possible ? Or does it only make sense on a ASP.Net MVC project ?

Turning on LogPostedFormData causes exceptions due to form validation

If you post values that contain data that would normally fail MVC form validation (links, etc.), then ApplicationLifecycleModule.LogRequest(...) will throw a HttpRequestValidationException when iterating over all the form values while executing this line:

var formData = form.AllKeys.SelectMany(k => (form.GetValues(k) ?? new string[0]).Select(v => new { Name = k, Value = FilterPasswords(k, v) }));

The stack trace looks like this:

System.Web.HttpRequestValidationException (0x80004005): A potentially dangerous Request.Form value was detected from the client (Link="<a href='/WorkSiteUt...").
   at System.Web.HttpRequest.ValidateString(String value, String collectionKey, RequestValidationSource requestCollection)
   at System.Web.HttpRequest.<>c__DisplayClass5.<ValidateHttpValueCollection>b__3(String key, String value)
   at System.Web.HttpValueCollection.EnsureKeyValidated(String key)
   at System.Web.HttpValueCollection.GetValues(String name)
   at SerilogWeb.Classic.ApplicationLifecycleModule.<>c__DisplayClass3.<LogRequest>b__0(String k)
   at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()
   at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
   at System.Linq.Buffer`1..ctor(IEnumerable`1 source)
   at System.Linq.Enumerable.ToArray[TSource](IEnumerable`1 source)
   at Serilog.Events.SequenceValue..ctor(IEnumerable`1 elements) in c:\projects\serilog\src\Serilog\Events\SequenceValue.cs:line 37
   at Serilog.Parameters.PropertyValueConverter.CreatePropertyValue(Object value, Destructuring destructuring, Int32 depth) in c:\projects\serilog\src\Serilog\Parameters\PropertyValueConverter.cs:line 147
   at Serilog.Parameters.PropertyValueConverter.CreatePropertyValue(Object value, Destructuring destructuring) in c:\projects\serilog\src\Serilog\Parameters\PropertyValueConverter.cs:line 86
   at Serilog.Parameters.PropertyBinder.ConstructProperty(PropertyToken propertyToken, Object value) in c:\projects\serilog\src\Serilog\Parameters\PropertyBinder.cs:line 122
   at Serilog.Parameters.PropertyBinder.ConstructNamedProperties(MessageTemplate template, Object[] messageTemplateParameters) in c:\projects\serilog\src\Serilog\Parameters\PropertyBinder.cs:line 114
   at Serilog.Parameters.PropertyBinder.ConstructProperties(MessageTemplate messageTemplate, Object[] messageTemplateParameters) in c:\projects\serilog\src\Serilog\Parameters\PropertyBinder.cs:line 57
   at Serilog.Parameters.MessageTemplateProcessor.Process(String messageTemplate, Object[] messageTemplateParameters, MessageTemplate& parsedTemplate, IEnumerable`1& properties) in c:\projects\serilog\src\Serilog\Parameters\MessageTemplateProcessor.cs:line 38
   at Serilog.Core.Pipeline.Logger.Write(LogEventLevel level, Exception exception, String messageTemplate, Object[] propertyValues) in c:\projects\serilog\src\Serilog\Core\Pipeline\Logger.cs:line 138
   at Serilog.Core.Pipeline.Logger.Write(LogEventLevel level, String messageTemplate, Object[] propertyValues) in c:\projects\serilog\src\Serilog\Core\Pipeline\Logger.cs:line 111
   at Serilog.Log.Write(LogEventLevel level, String messageTemplate, Object[] propertyValues) in c:\projects\serilog\src\Serilog\Log.cs:line 116
   at SerilogWeb.Classic.ApplicationLifecycleModule.LogRequest(Object sender, EventArgs e)

In any case, there may be perfectly valid reasons why you want to post data that MVC considers invalid. The logging infrastructure should just log whatever it gets safely, without throwing any exceptions.

The fix is probably to call Request.Unvalidated.Form.GetValues(...) instead of Request.Form.GetValues(...). I'll submit a PR momentarily.

Include plain POST payload not only FormData

Is it by design that we it are able only to log FormData and not any other plain POST payload like JSON. I know it would be aweful to log binary data or stuff like that but maybe we can add some configurable filter on the content type of the request.

It would be nice if we can have logs of full payload of at least failed HTTP requests

HttpModule stops working when stressed.

When using the HttpModule and putting a large number of requests through it suddenly stops working with no error logs or exceptions. Once this occurs all Serilog logging stops and the service has to be restarted.

Using

• .net 4.7
• Serilog 2.7.1
• Serilog-Web/classic - 4.2.42
  If you need more details please let me know.
  Any ideas on how I can resolve this issue?
  Thank you

SerilogWeb.Classic IIS classic mode incompatibility

Hello,

I am using an app that was working fine with the IIS Classic Mode until I started using Serilog and SerilogWeb.Classic for logging.
Now that the application was deployed in Test environment, I get this exception :

[PlatformNotSupportedException: This operation requires IIS integrated pipeline mode..]
System.Web.HttpApplication.add_LogRequest(EventHandler value) +3674928
SerilogWeb.Classic.ApplicationLifecycleModule.Init(HttpApplication application) +159
System.Web.HttpApplication.InitModulesCommon() +170
System.Web.HttpApplication.InitModules() +71
System.Web.HttpApplication.InitInternal(HttpContext context, HttpApplicationState state, MethodInfo[] handlers) +824
System.Web.HttpApplicationFactory.GetNormalApplicationInstance(HttpContext context) +209
System.Web.HttpApplicationFactory.GetApplicationInstance(HttpContext context) +113
System.Web.HttpRuntime.ProcessRequestInternal(HttpWorkerRequest wr) +539

Is there any issue with using SerilogWeb.Classic in IIS Classic mode ? Because I cannot change the type of mode (I can change it on local environment but in test or production environment, the IIS pools are set to Classic mode and I can't have it changed)

Thank you for helping me,
Regars

Julien

When using Serilog version 1.5.7, web classic is looking for version 1.4.0.

When using SerilogWeb.Classic with Serilog version 1.5.7 the following error occurs;

Could not load file or assembly 'Serilog, Version=1.4.0.0, Culture=neutral, PublicKeyToken=24c2f752a8e58a10' or one of its dependencies. The located assembly's manifest definition does not match the assembly reference. (Exception from HRESULT: 0x80131040)

Tried BindingRedirect which did not resolve the issue, probably due to the sn.

Does it make sense to update this assembly to reference the newer version of Serilog?

How can I get current request id?

Hi,
Although it's very helpful to have request id included in logs, I would also like to return this Id to the user on error screen. I know I can get it directly from current HttpContext, but it might not be there yet and I have to know internals of HttpRequestIdEnricher.

Thanks

Configurable Form Values to Filter

Right now, fields with the key "password" are filtered out of the log properties by default.

It would be nice if this was configurable, in case we wanted to add things like SSN's or Credit Card Number fields from our forms.

Reconfigure the AppVeyor CI build

The CI build is using the generic Git hook, rather than the more capable GitHub one (originally hit an issue during setup). Needs to be changed so that PRs get built and builds trigger automatically.

HttpRequestClientHostIPEnricher: Value does not fall within the expected range

Moved from: serilog/serilog#646

@vidarkongsli wrote:

Found the following stack trace in the self-log from time to time.

2016-01-25T14:18:13 Exception System.ArgumentException: Value does not fall within the expected range.
   at System.Runtime.InteropServices.Marshal.ThrowExceptionForHRInternal(Int32 errorCode, IntPtr errorInfo)
   at System.Web.Hosting.IIS7WorkerRequest.GetServerVariableInternal(String name)
   at SerilogWeb.Classic.Enrichers.HttpRequestClientHostIPEnricher.Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
   at Serilog.Core.Pipeline.Logger.Dispatch(LogEvent logEvent) in C:\projects\serilog\src\Serilog\Core\Pipeline\Logger.cs:line 163 caught while enriching Serilog.Events.LogEvent with SerilogWeb.Classic.Enrichers.HttpRequestClientHostIPEnricher.

Serilog 1.5.14
SerilogWeb.Classic 2.0.6

HTTP protocol information

I think it could be useful to enrich logs with information about which protocol version was used (i.e. HTTP/1.1 or HTTP/2) and if the request was made over HTTPS.

What do you think? Should it be part of SerilogWeb.Classic?

I might be able to create a pull request for this in the coming weeks.

Enable enrichers from web.config appsettings?

Is it possible to enable the enrichers (ie HttpRequestIdEnricher) from the web.config using the Serilog.Settings.AppSettings package? I've tried the following as well as many variations in the web.config but it never outputs the RequestId. (NOTE... the request id comes thru if I use the .Enrich.With<> line in the code.

<add key="serilog:using:Classic" value="SerilogWeb.Classic" /> <add key="serilog:enrich:With" value="HttpRequestIdEnricher" />

Thanks

Customize HttpRequestEventMessageTemplate

Hello,

First of all, great project you have here.

I'm working on a classic web with ASMX services and I was wondering if there is any chance to customize the HttpRequestEventMessageTemplate to add the "SOAPAction" so I can easily identify which ASMX method is being invoked.

Best regards,
Pedro

ASP .NET Core enrichers?

How do I get the enrichers for ASP .NET Core? You refer to the Serilog.AspNetCore package, but it doesn't contain the nice enrichers that the classic package does.