NetMX & Spring.NET - configure your Apps at runtime

Ever wished you could change some settings of your application during runtime? Easily retrieve runtime information from your components? You tried WMI and Performance Counters?

Well I did and to put it polite: I don't like WMI. Performance Counters are a nice way to retrieve peformance information about an application, but when it comes to changing an application's settings or behavior at runtime, you need another way. WMI is still COM-based, although a WMI.NET binding is available via the System.Management components. Alas this binding is not complete and functions are spread across different namespaces for historical reasons. To put a long story short: It is nothing for the fainthearted.

Brief Introduction to Java Management Extensions (JMX)

In the Java universe for this purpose there is JMX. Basically it allows an application to expose management objects via a JMX server. A monitoring client can then connect to this server and dynamically obtain runtime information about the exposed management objects. In contrast to WMI there is no schema involved, everything is discovered dynamically. For instance the server application could expose the following management bean:

public interface SampleMBean
{
    public String getHello();
    public void setHello(String helloMessage);
    public String sayHello();
}

public class Sample implements SampleMBean {

    private String hello = "Hello World(s)!";

    public Sample() {
    }

    public String getHello() {
        return hello;
    }

    public void setHello(String helloMessage) {
      hello = helloMessage;
    }

    public String sayHello() {
      return hello;
    }
}

Using the JConsole tool, one can easily connect to this application's virtual machine and remotely retrieve/change the properties as well as invoke the exposed method(s):

 

The server application may expose its management objects over a variety of different connectors, as it is shown in this image (copied from the Wikipedia article about JMX)

And Now: .NET Management Extensions

Thanks to the amazing work of Szymon Pobiega, the power of JMX is available for the .NET platform as well. The NetMX implementation is available from CodePlex. The really nice part is, that it also comes with a working implementation of the JSR262 JMX connector, so that it is possible to connect to your .NET application using JConsole (yes, that's true and I'm going to proof that ;-)). Of course NetMX also comes with a .NET version of the console, please check out the project for more. I grabbed the sources and compiled them. After playing around a while, I decided to implement a simple usage scenario.

The Sample Scenario

Every now and then I wanted to increase decrease the logging level of my applications (among other things ...). Using NetMX it should be easy. And - well it was! Using Spring.NET, it was easy to weave a logging advice around my components, using NetMX it was easy to expose a management object for this logging advice, so that the log settings can be changed at runtime. The picture below illustrates the scenario setup I aimed for:

The Logging Advice intercepts every call to the service object and logs the method calls to the log system. By default, logging is turned off, using JConsole I want to change those settings during runtime.

My sample application again is the MovieFinder application. To make the effect visible, the client code retrieves the movielist every second and prints the timestamp + the moviename on the console. Also the logging system is configured to write to the console, but disabled by default.

The Solution

The sources for my experiment can be fetched from my subversion repository. What you also need is the JSR262 enhanced version of JConsole, which is included in the samples of the JSR262 Connector download. Unpack the connector download and checkout $/jsr262-ri-ea4/samples/index.html for more.

So launching the application results in a screen similar to this:

Now launch JConsole and connect to our .NET application using the url "service:jmx:ws://127.0.0.1:9998/jmxws":

Expanding the tree shown in the left pane, you should see this:

  Now let's change some settings. Double-Click into the "Value" column and enter the following:

é voila! Our console has significantly changed now:

We just reconfigured the logging advice on the fly to also log all method calls to our service and also dumps the arguments passed in!

Here's the configuration snipped required to make this happen (using Spring.NET CodeConfig from my last post):

var appContext = new GenericApplicationContext(false);
appContext.Configure()
   .FromConfiguration<MovieFinderConfiguration>()
    .EnableLogging(log =>
    {
       log.TypeFilter = type => type.IsDefined(typeof(ServiceAttribute), true);
       log.Logger.LogLevel = LogLevel.Off;
    })
   .EnableNetMX(netmx =>
   {
     netmx.AddConnector<Jsr262ConnectorServerProvider>(new Uri("http://0.0.0.0:9998/jmxws"));
     netmx.ExportMBean<SimpleLoggingManager>();
   });

Enjoy and again thanks to Szymon for his great work!

Common Logging 2.0 for .NET Released

Last week I released a new version of Common Logging 2.0 for the .NET platform. You can get the distribution as well as online API and User Reference documentation from the project website. For users of previous versions there is also a section about upgrading to 2.0.

What is Common.Logging?

Similar to Java's Apache commons-logging, Common.Logging is an ultra-thin brigde between different .NET logging implementations based on original work done by the iBatis.NET team. A framework or library using Common.Logging can be used with any logging implementation at runtime and thus doesn't lock a user to a specific framework or worse letting him struggle with different frameworks using different logging implementations.

Common.Logging comes with adapters for all popular logging implementations like log4net and Enterprise Library Logging.

Bridging between logging implementations

You might run into the problem, that libraries used by your application use different logging implementations. Common.Logging allows you to route from those implementations into any logging system of your choice:

Please see reference documentation for an example on how to configure such a bridging scenario.

What's new in 2.0?

Several extensions and improvements were made, namly

• Dropped .NET 1.1 Support
• Added support for Enterprise Library 4.1 Logging
• Extended and improved ILog Interface
• Convenience LogManager.GetCurrentClassLogger() Method
• Bi-directional log event routing between logging implementations (see bridging above)
• Improved performance

I already blogged about comparing Common.Logging performance to System.Diagnostics.Trace. According to a thread on stackoverflow, log4net seems even slower than System.Diagnostics.Trace.

Configuring Common.Logging

For examples on how to configure and use Common.Logging and bridge different logging implementations, please see the user refererence guide. The API documentation contains configuration and usage examples on each adapter implementation. Here is an example for configuring Common.Logging to write messages to the console:

<configuration>
<configSections>
 <sectionGroup name="common">
   <section name="logging"
            type="Common.Logging.ConfigurationSectionHandler, Common.Logging"
            requirePermission="false" />
 </sectionGroup>
</configSections>
<common>
 <logging>
   <factoryAdapter type="Common.Logging.Simple.ConsoleOutLoggerFactoryAdapter, Common.Logging">
     <arg key="level" value="ALL" />
   </factoryAdapter>
 </logging>
</common>
</configuration>

Using Common.Logging

Using Common.Logging is as simple as shown below:

ILog log = LogManager.GetCurrentClassLogger();
log.DebugFormat("Hi {0}", "dude");

Hint: When using NET 3.5, you can leverage lambda syntax for logging to avoid any performance penalties:

log.Debug( m=>m("value= {0}", obj.ExpensiveToCalculateInformation()) );

This is the equivalent to writing

if (log.IsDebugEnabled)
{
 log.Debug("value={0}", obj.ExpensiveToCalculateInformation());
}

and ensures that you don't have to pay for calculating the debug information message in case level "Debug" is disabled.

Further Roadmap

The following features and improvements are planned for the next release, some of them already in the works:

• Partial Trust compliance (already in the trunk)
• Support for Windows Azure
• Support for Silverlight
• Logging (aka 'Trace') Context support (in progress) see System.Diagnostics.CorrelationManager and log4net contexts for examples

Of course I would like to invite you to submit any feature request, bug reports or other improvement suggestions to the project's issue tracker.

Happy logging!

Thoughts on System.Diagnostics Trace vs. Common.Logging

While working on the final bits for Common.Logging 2.0 I just looked a bit closer into NET’s trace model and tried to compare it to Common.Logging. I must admit that, being a long-time user of first log4net and then Common.Logging, I never much cared about <system.diagnostics>. Revisiting assumptions from time to time is a good habit, thus I dived into .NET tracing. Here’s what I found…

Configure and use <system.diagnostics>

The .NET trace system basically works by using TraceSources (="Logger" in log4net) to write events to a list of TraceListeners (="Appenders") that decide whether a message to log by consulting a list of TraceFilters. This could be useful, alas there is no "batch" configuration possible, means you need to configure this chain for each TraceSource. Here's a minimum example what one needs to do:

<system.diagnostics>
    <sharedListeners>
        <add name="myListener"
             type="MyTestTraceListener, MyAssembly" />
    </sharedListeners>
    <sources>
        <source name="mySource" switchValue="All">
            <listeners>
                <add name="myListener" />
            </listeners>
        </source>
    </sources>
</system.diagnostics>    

Your code will then look like this:

class MyClass
{
    readonly TraceSource trace = new TraceSource("mySource");
    void Foo(object someArg)
    {
        try
        {
            Bar(someArg);
        }
        catch (Exception ex)
        {
            trace.TraceEvent(TraceEventType.Information, -1,
            "error arg={0}:{1}", someArg, ex);
        }
    }

    void Bar(object someArg) { /* do something */}
}

A nice tutorial on tracing is given in this blog, some criticism is found here.

Performance Considerations

Of course you don’t want to pay much performance costs for your logging infrastructure. Fortunately tracing doesn’t cost you too much. I wrote some tests in Common.Logging to compare both and found Common.Logging twice as fast as Trace. Note, that we are talking about 2s vs. 4s for passing 100.000.000 log entries through the chain. I do not think that this is an issue for anyone except for applications generating an insane number of log entries.

Things get interesting when evaluating a log message becomes expensive. Take for example the line from the example above:

  trace.TraceEvent(TraceEventType.Information, -1,
                           "error arg={0}:{1}", someArg, ex); 

Somewhere within the tracing framework, the passed string and arguments must be evaluated and string.Format() gets called. But you do not want this to happen unless that message *really* gets logged – string.Format() calls both, someArg.ToString() and ex.ToString(), which might be very expensive to calculate!

To be safe, you need to wrap all your calls by

if ( trace.Switch.ShouldTrace(TraceEventType.Information) )
{
 trace.TraceEvent(TraceEventType.Information, -1,
              "error arg={0}:{1}", someArg, ex);
} 

Unfortunately this doesn’t help in all cases. Most often you want all messages from all (or at least most) modules but only the informational ones (not the verbose). You can configure this using a filter:

<system.diagnostics>
    <sharedListeners>
        <add name="myListener"
             type="MyTestTraceListener, MyAssembly">
            <filter type="System.Diagnostics.EventTypeFilter"
                    initializeData="Information"/>
        </add>
    </sharedListeners>
    <sources>
        <source name="mySource" switchValue="All">
            <listeners>
                <add name="myListener" />
            </listeners>
        </source>
    </sources>
</system.diagnostics>

Using the configuration above, all messages will be passed into “myListener”, who’s filter will drop all messages above the information level. Unfortunately there is another issue: The framework automatically adds a DefaultTraceListener to all configured <source>s that will happily log all messages. To avoid this you need to write

<source name="mySource" switchValue="All">
    <listeners>
        <!-- prevent DefaultTraceListener from being added -->
        <clear />
        <add name="myListener" />
    </listeners>
</source>

I wrote some performance tests simulating the case where we only want to log Warnings. Messages are emitted at “Info” level, but the configuration should restrict messages to “Warning”s. On my box this resulted in

Time:00:00:01.9640000 - log.InfoFormat + NoOpLogger
Time:00:00:04.8410000 - traceSource.TraceEvent + unconfigured TraceSource
Time:00:00:03.6140000 - log.InfoFormat
Time:00:00:12.7380000 - traceSource.TraceEvent

As you can see, using tracing gets significant slower using the configuration above. Frankly I could not figure out what causes this. Things become unacceptable as soon as you forget to remove the DefaultTraceLogger:

Time:00:00:00.6670000 - log.InfoFormat + NoOpLogger 
Time:00:00:02.2950000 - traceSource.TraceEvent + unconfigured TraceSource 
Time:00:00:02.2250000 - log.InfoFormat 
Time:01:00:23.8650000 - traceSource.TraceEvent <= not kidding here!

For this reason, Common.Logging introduced a new signature for logging leveraging the power of lambda expressions:

  log.Info( m=>m("some logger info {0}", (object)myObj) )

Using this syntax you will always be on the safe side. Common.Logging will take care, that the message will only be evaluated in case it really gets logged.

Conclusion

What bothers me most is the pain of configuring & using the trace framework. Here are the major pain points I found with the built-in tracing framework:

• It is possible to share listeners, but you need to configure the list of listeners for each TraceSource.
• It is impossible to configure a default listener to be used by all TraceSources
• There is no logging of exception objects possible
• One can instruct a TraceListener to append the current callstack to the message, but this will include the System.Diagnostics stack(!)
• No easy way for "batch" configuring log levels for multiple sources (like in log4net logger hierarchies), each source must be explicitly configured with level+listener
• As soon as one configures the listeners for a TraceSource, a DefaultTraceListener will also be added to the list, causing each message to be logged to OutputDebugString as well (add a <clear/> element to the sample above.
• It is incredible verbose to use, both tracing and configuring

If one insists on avoiding a dependency on Common.Logging or log4net, go with tracing – you’ve been warned.

For all others I recommend grabbing Common.Logging. It allows you to defer the decision of which logging framework to use until the moment you deploy your application. Simply plug in any other logging system you might want to use. If you need to turn off logging at all, configure NoOpLoggerFactoryAdapter and minimize the costs of your log statements to almost zero - guaranteed!