Friday 31 August 2012

Dynamic log level with log4net

Out of all the features of log4net, the most useful and the least known at the same time is the possibility for the logger to dynamically change the logging level based on future events. Yes, future! Nothing like a little clairvoyance to produce clean and usable log files.

log4net can buffer incoming events and, when an error occurs, write out the sequence of actions that lead to it - and if nothing wrong happens, then the excessive messages are dropped. The class that allows for that is BufferingForwardingAppender. It wraps around another log appender (e.g. file or console or smtp or database or eventlog or whatever else you would like log4net to write to) and uses an evaluator to decide when to flush buffered data. Let's have a look at a sample configuration (app.config file):

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
  </configSections>
  <log4net>
    <!-- see http://logging.apache.org/log4net/release/config-examples.html for more examples -->
    <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
      <threshold value="WARN" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%-4timestamp [%thread] %-5level %logger %ndc - %message%newline" />
      </layout>
    </appender>
    <!-- you should use a RollingFileAppender instead in most cases -->
    <appender name="FileAppender" type="log4net.Appender.FileAppender">
      <file value="my_application.log" />
      <!-- pattern is required or nothing will be logged -->
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%-4timestamp [%thread] %-5level %logger %ndc - %message%newline" />
      </layout>
    </appender>
    <appender name="BufferingForwardingAppender" type="log4net.Appender.BufferingForwardingAppender" >
      <evaluator type="log4net.Core.LevelEvaluator">
        <threshold value="ERROR" />
      </evaluator>
      <bufferSize value="50" />
      <lossy value="true" />
      <appender-ref ref="FileAppender" />
    </appender>
    <!-- root is the main logger -->
    <root>
      <!-- default is INFO, this performs initial filtering -->
      <level value="DEBUG"/>
      <!-- messages are sent to every appender listed here -->
      <appender-ref ref="BufferingForwardingAppender"/>
      <appender-ref ref="ConsoleAppender" />
    </root>
  </log4net>
</configuration>

Now this is a wall of text. What is going on here?

  • configSections is a standard .NET configuration section declaration
  • then we declare a ConsoleAppender that will print everything of level WARN or above to console - you can configure a ColoredConsoleAppender instead to have prettier output
  • following that is a FileAppender, which simply outputs everything to a file
  • next one is the magical BufferingForwardingAppender, containing an evaluator that triggers for every message of level ERROR or above, a lossy buffer of size 50 (that means that when more messages are buffered, the first ones are being discarded) and a target appender that will receive messages when they are flushed
  • last element is the root logger, which is the default sink for all the messages - it contains referenced to our appenders and will feed messages to them

So far so good. log4net now needs to be instructed to parse this configuration - my preferred way is with an assembly attribute:

[assembly: log4net.Config.XmlConfigurator (Watch = true)]

You can specify a file path in this attribute if you don't want to store your configuration inside app.config. A simple way to create a logger is just

private static readonly log4net.ILog log = log4net.LogManager.GetLogger ( System.Reflection.MethodBase.GetCurrentMethod ().DeclaringType );

and we're good to go. Now all that remains is dumping some log messages into our log.

for (int i = 0; i < 1025; i++)
{
  log.DebugFormat("I'm just being chatty, {0}", i);
  if(i%2 ==0)
    log.InfoFormat("I'm just being informative, {0}", i);
  if(i%20 == 0)
    log.WarnFormat("This is a warning, {0}", i);
  if(i%512==0)
    log.ErrorFormat("Error! Error! {0}", i);
}

When you execute this sample code you will see every warning and error printed to console. Contents of my_application.log, however, will look differently: they will contain only errors and 50 messages that were logged before the error. Now that's much easier to debug, isn't it?

Please also take a look at how I include parameters in the logging calls: using the DebugFormat() form overloads means that the strings are not formatted until this is necessary - so if a log message is suppressed, no new string will be allocated and no ToString() will be called. This might not change your applications performance a lot, but it's a good practice that is worth following. And one last thing to remember: log4net, by default, does not do anything. In order to get any output, you need to explicitly request it - most likely through configuration.

Wednesday 1 August 2012

NuGet proxy settings

This post is based on code present in NuGet 2.0.

NuGet reads web proxy settings from three distinct sources, in order:

  • configuration files
  • environment variables
  • current user's Internet Options

While the layout of IE's Connection Settings is probably familiar to you if you are behind a corporate firewall and require proxy configuration to access the Internet, first two options require a bit of explanation.

For configuration files, NuGet first considers .nuget\NuGet.config and then falls back to %APPDATA%\NuGet\NuGet.config. Relevant configuration entries are http_proxy, http_proxy.user and http_proxy.password. You can either edit them manually, by adding a line under <settings> node:

<add key="http_proxy" value="http://company-squid:3128" />

or you can add them from NuGet command line:

nuget.exe config -set http_proxy=http://company-squid:3128

If those variables aren't found in the configuration files, NuGet will fall back to checking standard environment variables for proxy configuration. By pure concidence, the variables have the same names as the configuration options ;-) . Names are not case-sensitive, but you might have to experiment a bit until you get NuGet to properly parse your settings if you have a space where it wouldn't expect one (e.g. in your user name).

Finally, if you are running NuGet in your user account, not using a service account (e.g. on a continuous build server), it will simply pick up whatever you have configured in the Control Panel as the system proxy server. All credentials configured there (including Active Directory single sign-on mechanism) should work without any work on your part.