Logging in a Web App (Threads, Sessions and Requests)

["Hart, Leo" <Le...@FMR.COM>]

I have a Log4Net problem/situation that I'm sure many of you have come
across and have (hopefully) overcome.  I scoured the 'net for an answer
but wasn't able to find exactly what I needed.
 
I'm starting to use Log4Net in my web application and I'm quite pleased
with it overall.  I was a user of Log4J when I was programming J2EE
apps, so obviously Log4Net is a comfortable fit.  
 
I've embedded log statements throughout the various tiers of my
enterprise app and it's outputting useful information to my rolling log
file just fine.  The problem is when the app leaves my development
machine and moves to a production server with multiple users hitting it
at once.  At that point it becomes very difficult to identify which log
entries pertain to which users.  
 
So obviously I want to embed the session ID and/or the request ID in my
log entry.  The first thing that came to mind was to simply log the
session/request IDs in the Page_Load/Page_Unload event, but that doesn't
work because the other log entries that occur in between Page_Load and
Page_Unload won't have that info.  
 
The next thing that came to mind was MDC/NDC.  The problem with that is
that MDC/NDC seems to be thread-based and since a given IIS server
thread can support multiple sessions at once, the sessionID MDC can be
overwritten.  I realized this fact once I coded the following in my
global.asax:
 

	Sub Session_Start(ByVal sender As Object, ByVal e As EventArgs)
	    ' Fires when the session is started

	    log4net.MDC.Set("sessionID", Session.SessionID)

	    m_log.Info("Session " & Session.SessionID & " is starting.")
	End Sub
	
	

	Sub Session_End(ByVal sender As Object, ByVal e As EventArgs)
	    ' Fires when the session ends

	    log4net.MDC.Remove("sessionID")

	    m_log.Info("Session " & Session.SessionID & " has ended.")
	End Sub

	

The last approach that came to mind was making the MDC.Set/Remove calls
in my ASPX page in the Page_Load/Page_Unload events, but that might not
work either given that, once again, multiple sessions are in each
thread.  Things would get especially confusing if I turned on logging in
not only my presentation tier, but my business tier, my data tier and
any third party assemblies I'm utilizing.
 
So what do I do?  How do I solve this problem?  CAN I solve this
problem?
 
 
Thanks for your time...
Leo Hart

Re: Logging in a Web App (Threads, Sessions and Requests)

[Ron Grabowski <ro...@yahoo.com>]

Have you tried creating a HttpModule and populating the MDC that way?
There are lot of events you can subscribe to:

 http://www.eggheadcafe.com/articles/20030701.asp

One way to do it might be this way:

public class Log4NetHttpModule : System.Web.IHttpModule
{
 public Log4NetHttpModule()
 {

 }

 public void Init(System.Web.HttpApplication context)
 {
  context.AuthorizeRequest += new
EventHandler(context_AuthorizeRequest);
 }

 private void context_AuthorizeRequest(object sender, EventArgs e)
 {
  HttpApplication context = (HttpApplication)sender;

  if (context.Request.IsAuthenticated == true)
  {
   log4net.MDC.Set("UserIdentityName", context.User.Identity.Name);
  }
  else
  {
   log4net.MDC.Set("UserIdentityName", "N/A");
  }
 }
	
 public void Dispose()
 {
			
 }

Make sure to add this to your web.config:

<httpModules>
 <add type="Foo.HttpModules.Log4NetHttpModule, Foo"
name="Log4NetHttpModule" />
</httpModules>

inside of <system.web>

Here is the conversion pattern:

"%5p %d{yyyy-MM-dd hh:mm:ss tt} (%c:%L) - [%X{UserIdentityName}] %m%n"

I think NLog supports things like
${aspnet-session:variable=MyVariableName} directly in its conversion
patterns so you wouldn't have to mess with the HttpModule. 

- Ron

--- "Hart, Leo" <Le...@FMR.COM> wrote:

> I have a Log4Net problem/situation that I'm sure many of you have
> come
> across and have (hopefully) overcome.  I scoured the 'net for an
> answer
> but wasn't able to find exactly what I needed.
>  
> I'm starting to use Log4Net in my web application and I'm quite
> pleased
> with it overall.  I was a user of Log4J when I was programming J2EE
> apps, so obviously Log4Net is a comfortable fit.  
>  
> I've embedded log statements throughout the various tiers of my
> enterprise app and it's outputting useful information to my rolling
> log
> file just fine.  The problem is when the app leaves my development
> machine and moves to a production server with multiple users hitting
> it
> at once.  At that point it becomes very difficult to identify which
> log
> entries pertain to which users.  
>  
> So obviously I want to embed the session ID and/or the request ID in
> my
> log entry.  The first thing that came to mind was to simply log the
> session/request IDs in the Page_Load/Page_Unload event, but that
> doesn't
> work because the other log entries that occur in between Page_Load
> and
> Page_Unload won't have that info.  
>  
> The next thing that came to mind was MDC/NDC.  The problem with that
> is
> that MDC/NDC seems to be thread-based and since a given IIS server
> thread can support multiple sessions at once, the sessionID MDC can
> be
> overwritten.  I realized this fact once I coded the following in my
> global.asax:
>  
> 
> 	Sub Session_Start(ByVal sender As Object, ByVal e As EventArgs)
> 	    ' Fires when the session is started
> 
> 	    log4net.MDC.Set("sessionID", Session.SessionID)
> 
> 	    m_log.Info("Session " & Session.SessionID & " is starting.")
> 	End Sub
> 	
> 	
> 
> 	Sub Session_End(ByVal sender As Object, ByVal e As EventArgs)
> 	    ' Fires when the session ends
> 
> 	    log4net.MDC.Remove("sessionID")
> 
> 	    m_log.Info("Session " & Session.SessionID & " has ended.")
> 	End Sub
> 
> 	
> 
> The last approach that came to mind was making the MDC.Set/Remove
> calls
> in my ASPX page in the Page_Load/Page_Unload events, but that might
> not
> work either given that, once again, multiple sessions are in each
> thread.  Things would get especially confusing if I turned on logging
> in
> not only my presentation tier, but my business tier, my data tier and
> any third party assemblies I'm utilizing.
>  
> So what do I do?  How do I solve this problem?  CAN I solve this
> problem?
>  
>  
> Thanks for your time...
> Leo Hart
>