Log4Net Hack: Customizing Log File Paths After Configuration

§ November 28, 2009 04:48 by beefarino |

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.



Facebook Connect Action Filter for ASP.NET MVC

§ November 19, 2009 05:50 by beefarino |

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!



Hacking for Fun and ... more Fun

§ November 12, 2009 16:57 by beefarino |

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!