Adding unique IDs to log messages

Coordinator
Dec 9, 2009 at 11:33 AM

I have been involved in a few projects in the past where the IT support team have requested that each logged message (above DEBUG) has some form of unique ID. This has always proved to be a tedious requirement to meet. Typically this involves creating an enumeration of log IDs. Often you find people re-cycling inappropriate IDs, or simply avoiding logging altgother.

I am wondering if there is anything SLF could do to help in this context?

Colin E.

 

Dec 10, 2009 at 6:37 AM

Perhaps there is. You could let the all Log methods return an object that describes the ID. Then adapters to the logging frameworks can than return the ID generated by the framework or return null if an ID is inappropriate or not supported. I would be happy with this, because this is exactly what CuttingEdge.Loggging supports. Some of the loggers (SqlLoggingProvider and AspNetSqlLoggingProvider) return an integer ID, while for others (such as the MailLoggingProvider) returning an ID is inappropriate and null is returned.

When changing the API is not an option you could implement some sort of 'logging scope' that has a thread affinity. I could imagine you implement something like this:

using (var scope = new LoggingScope())
{
    LoggerService.GetLogger().Log("message");

    object id = scope.LastLoggedId;
}

The implementation of the LoggingScope could look like this:

public sealed class LoggingScope : IDisposable
{
    [ThreadStatic]
    private static LoggingScope current;
    private object lastLoggedId;

    public LoggingScope()
    {
        if (current != null)
        {
            throw new InvalidOperationException(
                "LoggingScope already in scope.");
        }
        current = this;
    }

    // Returns the LoggingScope that's currently in scope or null.
    public static LoggingScope Current
    {
        get { return current; }
    }

    public void Dispose()
    {
        current = null;
    }

    //Get the last logged id or null.
    public object LastLoggedId
    {
        get { return this.lastLoggedId; }
    }

    // This method is called by framework adapters.
    // Usuage: LoggingScope.Current.SetLastLoggedId(id)
    public void SetLastLoggedId(object id)
    {
        this.lastLoggedId = id;
    }
}
Cheers

Aug 23, 2010 at 4:30 PM
Edited Aug 23, 2010 at 4:33 PM

It depends on what you mean by this comment "IT support team have requested that each logged message (above DEBUG) has some form of unique ID".  Do you mean that every message that is logged by tagged with, essentially, an sequentially increasing id?  So, the logged messages would have a field that would go like 1, 2, 3, etc as statements are logged?  Judging by the rest of your comment (about defining an enum of log IDs), it sounds like you are asking about something like "event id" which helps describe the actual message being logged.  So, you could define "log ids" or "event ids" like this (enum or const, or whatever you prefer):

public class AppEventId
{
  public int Startup = 0,
  public int Initialize = 1,
  public int Shutdown = 2,  
  public int Enter = 3,  
  public int Exit = 4,
  public int DatabaseLoginFailed = 5,
  public int FooServiceNotAvailable = 6,
  public int BarServiceNotAvailable = 7,
  public int LoginFailedOnce = 8,
  public int LoginFailedTwice = 9,
  public int LoginFailedThriceUserLockedOut = 10
};

With these ids, and with an api that accepts ids (like System.Diagnostics TraceSource.TraceEvent), you can write code that gives logging messages some additional context.

int maxAttempts = 3;

TraceSource ts = new TraceSource("MyTraceSource");
ts.TraceEvent(TraceEventType.Information, AppEventIds.Enter, "Enterning XYZ");

bool userLoggedIn = false;
int attempts = 0;

while (!userLoggedIn && attempts < maxAttempts)
{
  userLoggedIn = GetUserLoginInfo();
  if (!userLoggedIn)
  {
    int id = 0;
    switch (maxAttempts)
    {
      case 0:
        id = AppEventId.LoginFailedOnce;
      break;
      case 1:
        id = AppEventId.LoginFailedTwice;
      break;
      case 2:
        id = AppEventId.LoginFailedThriceUserLockedOut;
      break;
    }
    ts.TraceEvent(TraceEventType.Warning, id, "Login attempt failed");
    throw new Exception("Login failed");
  }
  attempts++;
}
ts.TraceEvent(TraceEventType.Information, AppEventId.Exit, "Login successful");

Here is a question from StackOverflow that seems to be asking about event ids in the same context and meaning that you are asking:

http://stackoverflow.com/questions/1637464/what-are-best-practices-for-event-id-management

Some time ago I saw another post on StackOverflow where someone made a comment about defining event ids in a manner similar to the "theory of reply codes" used in SMTP.

http://stackoverflow.com/questions/576185/logging-best-practices

See the "Other recommendations" under the first answer (the answer by "Sly", just in case the answers are ever reordered) for a brief discussion of how one might structure event ids.

I think that there are a couple of issues regarding the event id:

1.  If an organization/product wants to use event ids, then they have to define the ids and manage them somehow.  This seems to be part of the problem you are describing.  Some ids get defined. They are used in logging messages.  Someone writes more code and wants to log a message and should make a new id, but is to lazy to do so.  Instead, they use an existing id that might be misleading to someone reading the log.

2.  If an organization/product wants to use event ids, it is more awkward to log them using popular logging frameworks like log4net and NLog.  The "normal" logging functions (Logger.Info, ILog.Info, etc) don't accept an id parameter.  Also, the more generic "Log" functions also don't seem to accept an "event id" parameter (in the same sense as the EventID accepted by TraceSource.TraceEvent).  It looks like the only way to get an EventID logged is to use either the MDC, NDC, GlobalContext, or ThreadContext objects (whichever one is appropriate) on the logger/manager. 

See this StackOverflow question/answer for one example of how to get an "event id" to show up in a log4net log:

http://stackoverflow.com/questions/2290102/log4net-eventlogappender-log-event-id

(In this question they seem to be asking about the EventLogAppender, but I see no reason why someone might not want to log event ids in other logging targets like files, etc).

(Note that I have not actually used either of these logging platforms, except for recently trying out NLog).  Anyway, the EventID could be stored in the appropriate dictionary and then could be referenced in the formatting string so that the output contains the ID.

So, what to do?  I'm not sure what SLF can do to help with problem 1.  It seems that the ids have to be defined and managed somewhow.  Once that is solved, it should be straightforward enough for a developer that wants to log a message to determine what the appropriate id is.  If there is not an appropriate, he/she should probably define a new one (depending on local standards/procedures).  I suppose that SLF could have some sort of event id validation facility where an application/library can "register" "valid" event ids with SLF and then any time an event id is passed to SLF via an "event id" parameter in a logging call, SLF could verify that the id is a valid one.  This would give a development shop the ability to catch the use of nonexistent event ids, but would not help in the case of "wrong" event id being used in the wrong place.  I would say leave the event id definition and management up to the development organization.  Maybe SLF should only provide a way to explicitly pass the event id parameter and get it logged?

It seems like SLF could help with problem 2.  Maybe by providing some overloads that allow the specification of an event id in the logging calls (ILogger.Info(), ILogger.Warn(), etc).  With that in place, there is now a uniform way for people to use SLF and to be able to log event ids.  For TraceSources (if natively supported by SLF), the implementation would be simple enough.  Simply pass the event id to TraceSource.TraceEvent via the event id parameter.  Done.  For log4net and NLog, the problem is trickier.  Since there is (from what I can tell) not an explicit "event id" parameter available in the logging functions for those platforms, then the event id would have to be passed by convention, perhaps by adding a key/value pair to the appropriate dictionary (maybe called "EventID"??) containing the parameter name ("EventID") and value (the event id itself).  If the person using log4net or NLog as their underlying platform wants to use the event id parameter, he/she would have to configure the formatting string(s) to reference the "EventID" parameter.

Another issue with adding the ability to log event ids is that now you need a lot more overloads of the logging functions.  I suppose you could choose to restrict the use of the "event id" parameter to a limited set of functions or you could make the event id parameter optional or have a default value.  I do notice that SLF.ILogger does have a "Log" function that takes a LogItem structure that has an event id member.  This means that people using SLF today could program to the Log function and populate the LogItem structure explicitly.  Maybe it is not so bad if you don't have a large number of logging statements that want to log the event id?  That is ok, I guess, but it suddenly makes the application's logging code more verbose:

// Using ILogger.Log and LogItem makes this look more like old LAB logging examples.
ILogger logger = SLF.GetLogger("HelloWorldLogger");

LogItem item = new LogItem();
item.Message = "Hello World!";
item.LogLevel = LogLevel.Warn;
item.EventId = 1001; //Let's just hardcode the event id for now
item.LoggerName = logger.Name;

logger.Log(item);

//Compare with being able to pass event id explicitly:
ILogger logger = SLF.GetLogger("HelloWorldLogger");

logger.Warn("Hello World!", 1001);

If I had to vote, I would say that adding a common way to log event ids across the logging platforms supported by SLF (or custom factories/loggers implemented by users of SLF) would be useful.

Sorry for the long (and late) post, hope it is helpful.

Sep 10, 2010 at 6:11 PM
Edited Sep 13, 2010 at 2:54 PM

You can go to the log4net source repository here to find a log4net extension that shows how to extend log4net to include an event id parameter.  Essentially they define an interface that is the same as (or similar to) ILog, with an additional eventId parameter.  The implementation wraps a regular log4net logger.  Each logging call creates a log4net LoggingEvent structure/class and adds an "EventID" property to the LoggingEvent's Properties dictionary.  It then uses the regular log4net logger's Log method (which takes a LoggingEvent sturcture/class).  To get the EventID to show up in the  output, I guess you would just have to add the appropriate properties reference in the format string.

If SLF wanted to support the ability to log "event id" natively, one approach might be to declare an interface that is parallel to SLF.ILogger.  It might be SLF.IEventIdLogger.  It would have the same parameters as ILogger, with the addition of an event id, maybe as the first parameter like log4net did.  Now, if someone wants to log event ids, they would request IEventIdLoggers (maybe you would need a parallel LogManager like log4net implemented in their extension) and log away.  A similar technique could probably be used for NLog (put the EventId in the appropriate NLog context dictionary).