Capture username with log4net

Question

I currently write all log4net events to a database, and it seems to work just fine. To capture the logged in user account I use this piece of code:

HttpContext context = HttpContext.Current;
if (context != null && context.User != null && context.User.Identity.IsAuthenticated)
{
    MDC.Set("user", HttpContext.Current.User.Identity.Name);
}

The code seems ok, except for events that have no user context associated with them (ie. a user on our public web page). In that case the log4net capture seems to sometime write the last logged in user account (bad) and sometime write a null (good). Anyone got this feature to work reliably in all cases? I believe I saw a note that MDC is no longer a recommended feature to use, but I wasn't able to find any alternatives that are recommended.

Note: I find it odd that MDC is set with an account name, but never cleared if no user is active. That could be part of the problem. However, I didn't find any MDC code extracts that also clear the username.

Not familiar with MDC, but in an else clause could you set the "user" to `null`? — , Jan 27 '11 at 06:08
Agreed, but that's why I added the Note above. I'm kind of weary to set the "user" to null when ALL code extracts look exactly like what I pasted. I will test it out, but it's just not ideal if this logging code fails once deployed into production with a larger number of customers than our test DB. — Simon at LabSlice-com, Jan 27 '11 at 06:12
As of Log4Net version 1.2.11 you can get the username using an appender pattern. See here http://stackoverflow.com/a/26277219/203371 — Ben Smith, Oct 09 '14 at 14:03

score 27 · Accepted Answer · edited May 23 '17 at 12:16

If the information that is available in the HttpContext is sufficient, that is, if the sample code you posted gives you the right answer (except for the MDC issue) and you would just rather just not write:

HttpContext context = HttpContext.Current; 
if (context != null && context.User != null && context.User.Identity.IsAuthenticated)
{     
  MDC.Set("user", HttpContext.Current.User.Identity.Name); 
}

so often, then you might be able to add the username to your log "automatically" by writing your own custom PatternLayoutConverter for log4net. They are pretty easy to write and you can configure them in your log4net logging configuration just like the built in ones.

See this question for one example of how to write a custom PatternLayoutConverter:

Custom log4net property PatternLayoutConverter (with index)

Using the example at that link, you might be able to do something like this:

namespace Log4NetTest
{
  class HttpContextUserPatternConverter : PatternLayoutConverter
  {
    protected override void Convert(System.IO.TextWriter writer, LoggingEvent loggingEvent)
    {
      string name = "";
      HttpContext context = HttpContext.Current;
      if (context != null && context.User != null && context.User.Identity.IsAuthenticated)
      {
        name = context.User.Identity.Name;
      }
      writer.Write(name);
    }
  }
}

You would configure this in log4net something like this:

  //Log HttpContext.Current.User.Identity.Name
  <layout type="log4net.Layout.PatternLayout">
    <param name="ConversionPattern" value="%d [%t] %-5p [User = %HTTPUser] %m%n"/>
    <converter>
      <name value="HTTPUser" />
      <type value="Log4NetTest.HttpContextUserPatternConverter" />
    </converter>
  </layout>

In addition, you could build other pattern converters that use the Option parameter (see the example at the link above) to pull a specific item from the HttpContext.Current.Items or HttpContext.Current.Session collections.

Something like:

namespace Log4NetTest
{
  class HttpContextSessionPatternConverter : PatternLayoutConverter
  {
    protected override void Convert(System.IO.TextWriter writer, LoggingEvent loggingEvent)
    {
      //Use the value in Option as a key into HttpContext.Current.Session
      string setting = "";

      HttpContext context = HttpContext.Current;
      if (context != null)
      {
        object sessionItem;
        sessionItem = context.Session[Option];
        if (sessionItem != null)
        {
          setting = sessionItem.ToString();
        }
        writer.Write(setting);
      }
    }
  }
}


namespace Log4NetTest
{
  class HttpContextItemPatternConverter : PatternLayoutConverter
  {
    protected override void Convert(System.IO.TextWriter writer, LoggingEvent loggingEvent)
    {
      //Use the value in Option as a key into HttpContext.Current.Session
      string setting = "";

      HttpContext context = HttpContext.Current;
      if (context != null)
      {
        object item;
        item = context.Items[Option];
        if (item != null)
        {
          setting = item.ToString();
        }
        writer.Write(setting);
      }
    }
  }
}

You might also find these links useful:

http://piers7.blogspot.com/2005/12/log4net-context-problems-with-aspnet.html

Here, the blogger proposes a different solution to logging values from HttpContext than what I proposed. Read the blog post to see his description of the problem and for his solution. To summarize the solution, he stores an object in the GlobalDiagnosticContext (the more modern name for MDC). When log4net logs the value of the object it uses ToString(). the Implementation of his object retrieves a value from the HttpContext:

So, you might do something like this:

public class HttpContextUserNameProvider
{
  public override string ToString()
  {
    HttpContext context = HttpContext.Current;  
    if (context != null && context.User != null && context.User.Identity.IsAuthenticated)
    {
      return context.Identity.Name;
    }
    return "";
  }
}

You can put an instance of this object in the GlobalDiagnosticContext (MDC) early in your program and it will always return the right value since it is accessing HttpContext.Current.

MDC.Set("user", new HttpContextUserNameProvider());

This seems a lot easier than what I proposed!

For completeness, if someone wants to know how to do the same thing in NLog, NLog appears to make most/all of the HttpContext information available through its "aspnet-*" LayoutRenderers:

https://github.com/nlog/nlog/wiki/Layout-Renderers

+1 For the `HttpContextUserNameProvider` solution. This gets around the problem of actually storing the username data on threads directly and instead provides the data on demand - very neat solution. You would still need to make sure that an instance of this was set for each request though. — Tim Lloyd, Jan 27 '11 at 16:59
I initially tried the 2nd solution, but it seems that MDC.set only takes string, string. So that won't really work.... — CtrlDot, Sep 30 '11 at 16:28
@CtrlDot `MDC` is deprecated, this solution works with `GlobalContext`, which replaces some of its use cases. Use `GlobalContext.Properties["user"] = new HttpContextUserNameProvider();`. (And maybe this way of setting custom properties was already available with MDC.) — Frédéric, Aug 31 '15 at 10:00

Gian Marco · Answer 2 · 2018-03-31T07:19:55.210

According to Log4Net official API docs, MDC is deprecated:

The MDC is deprecated and has been replaced by the Properties. The current MDC implementation forwards to the ThreadContext.Properties.

Other than that MDC.Set only accept strings as values, so the last solution from @wageoghe cannot work (the one that uses HttpContextUserNameProvider)

My solution has been to use HttpContextUserNameProvider with log4net.GlobalContext, also suggested in official API docs:

Add this immediatley after log4net initialization (for example in Global.Application_Start)
```
log4net.GlobalContext.Properties["user"] = new HttpContextUserNameProvider();
```

Add this class

public class HttpContextUserNameProvider
{
    public override string ToString()
    {
        HttpContext context = HttpContext.Current;
        if (context != null && context.User != null && context.User.Identity.IsAuthenticated)
        {
            return context.User.Identity.Name;
        }
        return "";
    }
}

Modify log4net configuration by adding the "user" property value, for example:
```
<layout type="log4net.Layout.PatternLayout" value="%property{user}"/>
```

after tried a few solutions, feel this one should be the answer. — L.T., Aug 06 '15 at 20:33
This solution lacks support of buffered appenders like ado net appender: properties providers are by default evaluated at buffer flush time. So it will use the HTTP context of the request having caused the flush to occur, not of the request having emitted the log. Fortunately the provider just have to implement `log4net.Core.IFixingRequired` for getting evaluated at log time rather than at buffer flush time. See [my answer](http://stackoverflow.com/a/32308262/1178314) on another question for an example. — Frédéric, Aug 31 '15 at 10:07

Ben Smith · Answer 3 · 2017-07-06T22:08:39.097

11

As of Log4Net version 1.2.11 you can now simply use the appender pattern to get the authorized user via the ASP .NET request e.g.

%aspnet-request{AUTH_USER}

edited Jul 06 '17 at 22:08

answered Oct 09 '14 at 11:26

Ben Smith

19,589
6
65
93

2

This gets AUTH_USER server variable, which itself is set from request header. So this format would work only in limited scenarios, such as ASP.NET app using Windows authentication. – Mark Meyerovich Dec 10 '15 at 19:16

score 2 · Answer 4 · answered Jan 27 '11 at 08:25

2

This is pure speculation, but this sounds very much like it could be an issue related to shared request threads i.e. ThreadPool threads. When you set an MDC value it is associated with the current thread, and that thread will be returned to the ThreadPool at the end of the request and then re-used for subsequent requests. If the value is not overwritten, then you could see old values on new requests.

Consider managing this data in request start and end events, where you can set the username when a request starts, and then clear it on request end. This should give this data the correct lifetime i.e. for the lifetime of the request.

answered Jan 27 '11 at 08:25

Tim Lloyd

37,954
10
100
130

Smart answer. I am not sure that this is indeed our problem, but it's something I will look out for. Is there any other way to set a username without the use of MDC (ie. simply as part of the logging function call)? – Simon at LabSlice-com Jan 27 '11 at 09:11
@Simon If you have a layer of indirection for your logging calls, you could include this information in the log message e.g. by pre-pending it to the message. – Tim Lloyd Jan 27 '11 at 09:15

score 2 · Answer 5 · edited May 23 '17 at 12:01

2

There are two different ways of doing what you want %identity and %username.

Those can be used in your appender pattern.

I've done it before but with unexpected results until I read the following post which cleared it up for me.

See this posting: Log4Net can't find %username property when I name the file in my appender

edited May 23 '17 at 12:01

Community

1
1

answered Jan 27 '11 at 15:29

phillip

2,618
19
22

Seems to me that %identity only works when the logging assembly has a reference to System.Web (And thus access to HttpContext.Current.User, which I assume is where %identity finds the username) – Arve Systad Apr 23 '13 at 10:37
%identity worked for me in my MVC app. See https://logging.apache.org/log4net/log4net-1.2.13/release/sdk/log4net.Layout.PatternLayout.html for more options. – garethb Aug 08 '16 at 00:56

score -2 · Answer 6 · answered Feb 21 '13 at 18:16

-2

I've used the solution of wageoghe and Gian Marco Gherardi, but rather than GlobalContext have set the thread context immediatley before logging the message:

ThreadContext.Properties["user"] = new HttpContextUserNameProvider();

answered Feb 21 '13 at 18:16

SteveL

857
10
18

@CasperLeonNielsen please explain why not – Thierry May 09 '16 at 15:29
Because you would have to do this all over your code base. – Paul Swetz Mar 23 '18 at 17:27
If you do this you forget to change the user, you risk logging an action for the wrong user if the thread context was shared. Especially don't use this for GlobalContext properties. – Cᴏʀʏ Feb 26 '19 at 17:09

Capture username with log4net

6 Answers6

Linked