Log4Net Hack: Customizing Log File Paths After Configuration

I get a lot of log4net questions through my blog because of the tutorials I've written up.  One item that comes up frequently is how to configure a FileAppender to be able to write a single log file from multiple instances of the same application.  The truth is, you can't do it.  Or more precisely, there is no way to do it and expect not to lose log events and have your application performance suffer greatly.

First let me show you how to allow multiple applications access to a single log file.  It's actually quite easy:

 <?xml version="1.0" encoding="utf-8" ?>
 <configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>  
  </configSections>
  <log4net>
    <appender name="FileAppender" type="log4net.Appender.FileAppender">
      <file value="log-file.txt" />
      <appendToFile value="true" />
      <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
      <layout type="log4net.Layout.SimpleLayout" />         
    </appender>
    <root>
      <level value="DEBUG" />
      <appender-ref ref="FileAppender" />      
    </root>    
  </log4net>
  
</configuration> 

Since I discuss the parameters and pitfalls of the FileAppender elsewhere, I will leave it to you to read up on them more if you want to.  The locking mode being used here is causing log4net to acquire the file handle before each log event, then close the handle after the log event is written.  Doing this allows other applications to get write access to the file when no one else is currently logging, but the technique has a few serious flaws that should prevent you from using it:

  1. All of that file opening and closing seriously hampers performance;
  2. The log file will be shared, but access conflicts will still occur between applications attempting to log events at the same time, resulting in more performance degredation and "dropped" log events.

You may be able to address some of the performance issues using a BufferingForwardingAppender that sends large chunks of events to the minimally-locking FileAppender; however this will not resolve the contention over the single log file that is at the root of the issue.

The simplest solution to this problem is to use a different type of appender that is designed for concurrent use.  For instance, the EventLogAppender or AdoNetAppender use technologies that will manage concurrency issues for you.  If you're dead set on using the filesystem, the next simplest solution is to have each application log to a unique file, thus removing any log file contention at runtime.  The separate log files can be collated once the run is over using a tool like LogParser.  The drawback to this approach is that you have to hack it in: there is no direct way to modify the filename in the FileAppender based on the runtime environment.

That said, it's not hard.  Check out this simple console application:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using log4net;
using log4net.Appender;
namespace log4netPostConfig
{
    class Program
    {       
        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            var filePostfix = "_" + Guid.NewGuid().ToString( "N" );
            
            var fileAppenders = from appender in log4net.LogManager.GetRepository().GetAppenders()
                                where appender is FileAppender
                                select appender;
            fileAppenders.Cast<FileAppender>()
                .ToList()
                .ForEach(
                    fa =>
                    {
                        fa.File += filePostfix;
                        fa.ActivateOptions();
                    }
                );
            ILog Log = log4net.LogManager.GetLogger( System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );
            Log.InfoFormat( "this process is using log file postfix [{0}]", filePostfix );
        }
    }
} 

This example loads the logging configuration from the app.config (line 14).  The log4net configuration is searched for instances of FileAppenders (line 16), which have their filename parameters handrolled with some process-specific information (line 25) - a GUID in this case, the current process identifier may be another good choice.  Calling the ActivateOptions on each modified appender is vital (line 26), as it recreates each file handle using the new filename configuration parameter set in the code.

The app.config for this example is just a plain vanilla logging configuration:

<?xml version="1.0" encoding="utf-8" ?>
 <configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>  
  </configSections>
  <log4net>
    <appender name="FileAppender" type="log4net.Appender.FileAppender">
      <file value="log-file.txt" />
      <appendToFile value="true" />
      <encoding value="utf-8" />
      <layout type="log4net.Layout.SimpleLayout" />         
    </appender>
    <root>
      <level value="DEBUG" />
      <appender-ref ref="FileAppender" />      
    </root>    
  </log4net>
  
</configuration>

Note that the log-file.txt specified in the app.config will be created when the XML logging configuration is loaded (line 13 in my code example above), but it will never be written to.

Edit Notes

I just noticed after publishing this that a very similar example was written almost 2 months ago by Wil Peck.

kick it on DotNetKicks.com
E-mail • Permalink • Comments (0)

Facebook Connect Action Filter for ASP.NET MVC

I've got a few ASP.NET MVC projects burning that will be leveraging Facebook Connect for user identity and profile data.  I was impressed with how quickly I could get things running using the Facebook Developer Toolkit.  Well-documented, good examples, and the API makes sense. 

One of Connect's basic features is to provide user identity to other web applications via the "Connect Button".    Adding this feature to your ASP.NET site is already well documented by Clarity Consulting and others; here I will show you how I'm seamlessly folding this feature into the ASP.NET MVC request-handling pipeline using a custom Facebook Connect ActionFilterAttribute. 

The code for the Action Filter is pretty thin:

using System;
using System.Web;
using System.Web.Mvc;
using Facebook.Rest;
using Facebook.Session;
namespace MyWebSite.Filters
{
    public class FacebookConnectAttribute : ActionFilterAttribute
    {
        // obviously, you need to fill these in with your own application's values
        const string myFacebookApiKey = "...";
        const string myFacebookSecret = "...";
        public override void OnResultExecuting(ResultExecutingContext filterContext)
        {
            var connectSession = new ConnectSession( myFacebookApiKey, myFacebookSecret );
            if( connectSession.IsConnected())
            {
                filterContext.Controller.ViewData["FBConnected"] = true;
                var api = new Api(connectSession);
                filterContext.Controller.ViewData["FBUser"] = api.Users.GetInfo();
            }
            else
            {
                filterContext.Controller.ViewData["FBConnected"] = false;
            }
        }
    }
}

In my case, I'm making use of Facebook Connect before the controller's result is executed; e.g., before any view is resolved and rendered.  I could just as easily executed this filter before the action is executed by overriding the OnActionExecuting method.  Lines 11 and 12 contain my site's Facebook API key and secret (no prizes for guessing why I left those out of this example), which are used in line 15 to create the toolkit ConnectSession instance.  The filter can use this instance to check if the user has connected with my site and, if they have chosen to connect, fetch some of their profile data (line 20).

To place this filter into the request processing pipeline, just decorate the controller class definition with the filter attribute:

namespace MyWebSite.Controllers
{
    [HandleError]
    [MyWebSite.Filters.FacebookConnect]
    public class HomeController : Controller
    {
        public ActionResult Index()
        {
            return View();
        }
        // ... 

With the attribute in place, my Facebook Connect filter will be used during every request that invokes this controller, and the dynamic view data will contain the user's connected status and identity information:

<!-- 
    ... 
-->
<div id="logindisplay">
    <%
        if ((bool) ViewData["FBConnected"] == false) 
        {
    %>
    <fb:login-button v="2" size="xlarge" onlogin="window.location.reload();">Connect</fb:login-button>
    <%
        }
        else
        {
            var user = (user) ViewData["FBUser"];
            Response.Write("Welcome, " + user.first_name + "!");
        }
    %>
</div> 
<!-- 
    ... 
-->

The net result of this minimal effort: the entire site now has access to the user's Facebook identity and profile information once they choose to connect.

I'm still playing with the toolkit, and will hopefully have more to post soon!

kick it on DotNetKicks.com
E-mail • Permalink • Comments (5)

Hacking for Fun and ... more Fun

We had big fun tonight at the first Charlotte ALT.NET user group hack night.  Special thanks to Mike Linnen and Xpient for hosting the event.

The theme of the evening was taken from the recent Raleigh and Carolina Code Camps: Rock Paper Scissors.  Teams coded modules to play rounds of RPS, uploaded their assembles to a server, and duked it out over three rounds of riveting RPS action.

I was a bit apprehensive about the event, mostly afraid of looking like an idiot in front of some really smart people.  But once the hacking started we all fell into a groove and it turned out to be a lot of fun.  I chose to try and predict my opponent's actions using a bit of fuzzy logic and some statistics.  It worked fairly well through the first two rounds of the tournament, but I was given a resounding spanking in the final round by @micahlmartin and @DeveloperInfra.  In the end, a three-way tie for first place was resolved with a fourth round, where  @micahlmartin edged us out with a perfect score!

I may blog about my approach to the puzzle some other time, but I wanted to jot down some things I noticed this evening.

When I'm under a time contraint, I can get a lot of work done quickly.  I don't know why this surprises me, but after tonight I'm considering adding stricter timeboxes to my daily GTD routine.

Hacking is fun.  Lately coding has started to feel monotonous.  A lot of the projects I've got going on are hitting non-techcnial walls, and moving forward is proving to be difficult.  It was a blast to hammer out some code without those pesky business boundaries to bring it all down.  I think scheduling some regular geek time to work on things like Project Euler or some code katas would be a good idea - no expectations past my own enjoyment.

Overall a very positive experience, thanks everyone!

kick it on DotNetKicks.com
E-mail • Permalink • Comments (0)

it's been noticed...

Just ignore this post, I just need to release some steam...

We just had an emergency team meeting.  The topic: it's been noticed by the executives that we're not always around when they are.  Someone needed something and one of us wasn't there to oblige.  That must have really chapped their hide.  

Well, I've noticed some things too.  Here's what I've noticed:

  • I'm VPN'ed into work at midnight fixing the build someone else broke;
  • I'm constantly tweaking our unit tests to keep them working as the rest of the team gets to plod on to greenfield pastures;
  • I'm responding to support emails at 2am;
  • I'm answering the support phone at 4am;
  • I still make the 9:30am scrum;
  • I bust my hump as a principal developer on a project, only to hear the executives single-out my superiors to praise for my work;
  • After four rounds of layoffs, I've taken on so many roles here I've lost track;
  • I haven't dropped the ball on any of my responsibilities (or if I have, no one has let me know about it);
  • I've been willing to drop my life for days at a stretch to make emergency trips to fix client issues;
  • I'm frequently the last one out the door at the end of the day;
  • I see my kids for maybe 90 minutes a day;

... and more thing I noticed: the people I work for only notice me when I'm not around.

 

kick it on DotNetKicks.com
E-mail • Permalink • Comments (7)