Friday, December 25, 2009

Logging, part 2. Architecture & configuration

The main goal was: how to make logging and its configuration easy for simple scenarios and in the meantime highly adaptable for complex ones.

In order to achieve the required level of flexibility most logging frameworks have the following components:

  • Loggers (named instances of some public class or interface (usually ILog) that provides developers with functionality to write diagnostic messages to).
  • Appenders (output destinations of above-mentioned loggers).
  • Log manager or log provider (usually a central access point of a framework. It resolves loggers by their names).

DataObjects.Net logging system follows exactly this pattern but bearing in mind that it must provide the possibility to plug-in any logging framework it introduces its own set of abstract components (actually loggers & log manager, but not appenders) which in fact just wrap up the plugged-in ones and simply redirect diagnostic messages to them. Moreover, in case when none of standalone logging frameworks is plugged-in, DataObjects.Net contains its own simple implementation of those components.

The main access point is the public static LogProvider class with one method LogProvider.GetLog(string logName), which is used to resolve a required ILog instance by its name. Once instance of ILog is obtained, it can be used to log Debug, Info, Warning, Error & FatalError messages through the corresponding methods.

It could be considered as a good practice when members from one namespace log their messages into the same logging space. This namespace-based approach is quite useful as usually a namespace contains a set of classes that are closely coupled and execute some shared piece of programming logic, therefore the idea to merge their diagnostic output in one log seems to be rather sensible. Due to this approach DataObjects.Net contains a set of predefined loggers for most frequently used namespaces, such as: Xtensive.Core, Xtensive.Storage, Xtensive.Storage.Building and so on. Each of these loggers has name which corresponds to its namespace except "Xtensive." prefix. Say, logger for Xtensive.Core namespace is named as "Core".

For usability reasons the above-mentioned namespaces contain public static class named Log which exposes the same set of logging methods as ILog interface. As you might understand, each of these static Log classes is no more than a connector between its consumers (classes which use it as a logger) and corresponding ILog instance that is transparently constructed on demand.

Configuring internal DataObjects.Net's log output

Internal logging subsystem is not as powerful as some well-known logging monsters but rather flexible and doesn't require any additional components. Configuration of DataObjects.Net's logging is made in application configuration file (app.config or web.config).

First of all, include Xtensive.Core.Diagnostics section into configSections section:

    <section name="Xtensive.Core.Diagnostics" type="Xtensive.Core.Diagnostics.Configuration.ConfigurationSection, Xtensive.Core" />

The second step is to configure logs (appenders in terms of log4net):

    <!-- Use these settings for Xtensive.Storage.* logs -->
    <log name="Storage" events="Warning,Error,FatalError" provider="File" fileName="Storage.log" />

Note that each log has a name which is equal to the namespace where it is located except "Xtensive." prefix. This is true for logs from DataObjects.Net only and might not be true for logs from your own application.

Types of events: Debug, Info, Warning, Error, FatalError.

Types of providers: File (you need to provide file name as well), Debug, Console, Null (no logs at all, analogue of /dev/null), Error.

The example of log:

2009-12-17 00:00:02,052 DEBUG Storage.Providers.Sql - Session 'Default, #9'. Creating connection 'sqlserver://*****'.
2009-12-17 00:00:02,052 DEBUG Storage.Providers.Sql - Session 'Default, #9'. Opening connection 'sqlserver://*****'.
2009-12-17 00:00:02,052 DEBUG Storage.Providers.Sql - Session 'Default, #9'. Beginning transaction @ ReadCommitted.
2009-12-17 00:00:02,068 DEBUG Storage.Providers.Sql - Session 'Default, #9'. SQL batch: 
SELECT [a].[Id], [a].[TypeId], [a].[Name], [a].[Code], [a].[Description], [a].[LongDescription],
 [a].[IsForChildren], [a].[BasePrice], [a].[Price], [a].[SizeString], [a].[HasNoInnerCover]
 FROM [dbo].[Product] [a] ORDER BY [a].[Id] ASC
2009-12-17 00:00:02,068 DEBUG Storage.Providers.Sql - Session 'Default, #9'. Commit transaction.
2009-12-17 00:00:02,068 DEBUG Storage.Providers.Sql - Session 'Default, #9'. Closing connection 'sqlserver://*****'.

Looks pretty good, right?

In the next post I’ll describe how to use external logging framework with DataObjects.Net.


  1. Great info, Dmitri.

    One suggestion (of course low priority given you have so many high priority things to do)... for debug purposes, it would be nice not to substitute table names with aliases (e.g. dbo.Product [a])... so that we can review the generated SQL more easily.

    Btw, when is disconnected state being released?

  2. Hello Mr. Anonymous,

    Thanks for your comment.

    The suggestion is quite valuable, I'm sure it won't take much time to implement this. Unfortunately, there is no option to avoid substitution at all because of nested queries (Select something From Select something) and APPLY construct, although we can make aliases more human-readable, for example, if there are several references to dbo.Product table in a query we could named them not as [a], [b], [c] but as Product, Product1, Product2, etc.

    What do you think? Will it help?

    Speaking about disconnected state, it is almost ready, but is not rock solid, so we want to postpone its release until 4.1.1 version which is planned to be released in early January. If you want to play with it right now, I'd recommend you to take a look at WPF sample from the latest nightly build, or it can be found in our public repository