Is passive logging possible in .NET?

Question

I'm frequently frustrated by the amount of logging I have to include in my code and it leads me to wonder if there's a better way of doing things.

I don't know if this has been done or if someone has come up with a better idea but I was wondering is there a way anyone knows of to "inject" a logger into an application such that it passively monitors the thread and quietly logs processes as they occur without having to do things like:

public void MyProcess(int a, string b, object c)
{
  log(
    String.Format(
      "Entering process MyProcess with arguments: [a] = [{0}]; [b] = [{1}]; [c] = [{2}]",
      a.ToString(),
      b,
      c.ToString()
  );

  try
  {
    int d = DoStuff(a)
    log(
      String.Format(
        "DoStuff({0}) returned value {1}",
        a.ToString(),
        d.ToString()
      )
    );
  }
  catch (Exception ex)
  {
    log(
      String.Format("An exception occurred during process DoStuff({0})\nException:\n{1}",
      a.ToString(),
      ex.ToString())
    )
  }
}

What would be great is if I could say to my logger:

Monitor(MyClass.MyMethod)

It would then monitor everything that goes on inside of that method including passed in arguments along with method calls and values passed into those methods, exceptions that occur etc.

Has anyone implemented something like this in the past? Could it even be implemented? Is logging in this fashion just a pipe dream?

I'd love to design something that would do this, but I just don't even know where I'd begin. Of course, I don't want to reinvent the wheel either, if it's already been done, it would be great if someone could point me in the right direction.

Any suggestions would be gratefully received...

Edit: I thought I'd comment on an answer which queried as to the level of detail required in the log. It is frequently required that configurable levels of logging be provided such that if the configuration specifies detailed logging then everything is logged, whereas if critical logging is configured then only certain information is logged along with exceptions. If fatal logging is configured then only information which causes the application to die would be logged. Would something like this be configurable or would AOP require 3 or 4 different builds depending on the number of logging levels?

I frequently use 4 levels: Fatal, Critical, Information, Detailed

Answer 1

You can use PostSharp to log "around" the method. This is exactly the kind of thing AOP is good at. You might want to start with Log4PostSharp - a plugin specifically for logging.

Answer 2

This is the classic example from Aspect Oriented Programming. See PostSharp for a very good CLR-based library.

Answer 3

This is one of the textbook (not sure which textbook has AoP in it but you get the idea) examples of AoP - logging : where you want to stick something before and after a method.

You might want to explore the AoP route, PostSharp is one of the popular ones, along with Microsoft Unity (IoC too), Castle.

One simplistic example of AoP is you add your code before and after methods, instead of adding the method calls inside the actual methods. As you've tagged the question with C# you might want to just look into making an extension method to log it, which is already in this question.

I would take a practical approach: how much actual logging are you doing? Can you get away with just an extension method instead of razzle-dazzle'ing the person reading your code. The logging built into the .NET framework is decent already.

Answer 4

In addition to the logging methods mentioned by Jon, its probably also worth noting another useful feature in VS for tracing program flow, and that is the ability to have non-breaking breakpoints that will simply output a message or run a macro when hit (note you can print variable values as well)

Right click on your breakpoint and choose the When Hit... context menu item.

And of course one other very useful feature is the Trace object and Trace Listners in System.Diagnostics.

Answer 5

I've written a logging library recently that uses the IDisposable interface to wrap regions with logging context. Basically, there's a LogSite disposable object that you use like this:

using(var logger = new LogSite("methodName", new object[] { p1, p2, p3 })
{
    // code that does stuff goes here
}

The LogSite object has a bunch of convenient overloads for the constructor such as MethodBase so you can just use MethodBase.GetCurrentMethod() and use reflection to get the actual name of the method and parameters (instead of a hard-coded strings).

The way it works is this -- In the constructor, it writes to the log with all the trace information to indicate it entered the block. In the Dispose method, it writes an exit entry.

While disposing, it also checks Marshal.GetExceptionCode() for a non-zero value to see if the code inside the using threw an exception or exited normally. It doesn't give you the exception, so that will have to be logged explicitly in the catch handler, but it does indicate "pass/fail" for that region. This allows your logging scope to be more specific than just the method, since you could have lots of these blocks in a single method, and know which one threw the exception exactly.

Also, since there's a "logger" object now available, your catch handler just looks like:

try { ... } 
catch (Exception ex)
{ 
    logger.LogException(ex);
}

The logger already knows the method name, parameter information, and all that, and has internal methods for formating the exception information.

Getting into the architecture below this high-level object, there's a concept of "LogDisposition" which handles the "pass/fail" we determined earlier, and there's a concept of "LogEntryType" which is a filter (implemented with Flags enum) that indicates what kind of log entry is being passed (Error, Trace, etc).

The thing that actually does the logging is just a publisher/listener pattern. The publisher takes the passed in log entry, and much like a multi-cast delegate, keeps a registry of LogListener instances (should be setup at the start of program, or added in dynamically as needed), and passes the log entry to those instances.

The LogListeners in turn, filter out what kind of log entries they care about.. So if you don't want the method entry and exit points for non-error conditions, they don't have to show up in the log. This can be controlled at run-time to allow the user to do things like turn on and off detailed logging at will. Since the publisher can write to a variety of loglisteners, you can hook up something that writes to a file, or writes to the database, or displays error notifications in the GUI... etc.

It's a pretty good system, and requires a relatively small amount of coding to get relatively rich logging.

I could give you a code sample if you wanted... You can contact me through my (nearly completely inactive) blog (see my account profile).

Hope that helps.

Answer 6

I use the opensource Apache log4net in all of my projects. It's a very simple implementation with all kinds of extensions that allow you to log to databases, zip files, rolling log files, RRS feeds, telnet clients, etc. Logging is basically as simple as:

'Will print stack trace after message'
log.err(ex.message,ex)

log.warn("warn")
log.info("info")
log.debug("debug")

Logging parameters such as the output format and log level to output are all read real time while your app is in runtime.