Sunday, January 13, 2008

Highlight: Logging

If you design a solid framework, obviously there should be logging. .Net Framework doesn't offer much here - just logging to Windows logs. Certainly this isn't a good option, especially if you want to log some diagnostics-related events.

After spending some time on studying third-party logging libraries, we came to a conclusion there are two primary options:
- Either to use Logging Application Block from Microsoft Enterprise Library. Flexible, but slower (by some reports - much slower).
- Or stop on Apache log4net. Port of log4java (from my point of view "port" is disadvantage, since it isn't natively designed for .Net), but pretty good.

Other pros and cons can be found e.g. here, here and here.

And what was may be the most important, both frameworks doesn't provide few quite desirable features:
- A good approach for binding some default log to any type \ method automatically. This means that ideally we want to write something like Log.Info(...) anywhere to write a message to the default log for the place where such call happens.
- Log capturing. Ideally, we want to be able to create something that will listen all the events logged to a certain set of logs, capture them and allow to browse them further. This was quite important for e.g. storage builder - this class inspects all the registered types and builds storage model for them. This involves activities of many other classes, which should log all warnings and errors to some log(s). Ideally, storage builder should just capture all such logging events from other logs, and if at least one error is found, it throws an exception showing all errors and warnings.
- Log indentation. It would be nice to have an ability to temporary increase the indent in some log(s) to produce more readable output.

Finally we came to a conclusion which seems quite regular for us in such cases: we shouldn't rely or strictly bind ourselves on either ;) But building our own logging framework isn't a cheap solution as well. So we decided to provide a set of generic interfaces for logging in Xtensive.Core.Diagnostics, and implement them in wrappers for log4.net - that was pretty easy.

But in addition we should solve mentioned problems. And as I see now, we've solved them gracefully:

1. Default logs.

First of all, it's necessary to define what's "default log". We decided that default log is either a log bound to the current assembly (i.e. the assembly from which logging method is called), or a log bound to the current namespace (i.e. the namespace of class from which logging method is called). If there is no default log bound to the current namespace, we should use the default log for above one.

And as I've mentioned, the preferable way of logging for us is to write something like Log.Error(...) anywhere where this is necessary - it seems it's the shortest possible form of getting something logged at all ;)

What we definitely didn't want to have is:
- Necessity to use construction like LogProvider.FindLog("Xtensive.Core").Debug(...) - since in this case we specify assembly \ namespace name, which may lead to logging to a wrong log - e.g. on moving a class to another namespace \ assembly.
- Necessary to declare a static ILog-like member in each of our classes (e.g. as log4net recommends) - of course this would solve the problem (i.e. we could write log.Debug(...) in any method of such class), but even declaring such a property in any class (+ probably, static constructor!) seems too much.
- Of course we could try to make PostSharp to do this, but it is also not so easy - PostSharp can make any of such classes to implement some interface (e.g. ILogProvider), but in this case it would be anyway complex to log: to prevent compile-time errors, we should use something like ((ILogProvider)(object)this).Log.Error(...) - again, too much code. Moreover, this approach doesn't allow to access the log from static members.

Finally we've found the solution. There is the following class in Xtensive.Core.Diagnostics:

  /// <summary>
/// Log template - simplifies logging,
/// provides support for <see cref="LogCaptureScope"/>.
/// </summary>
/// <typeparam name="T">Should always be the type of descendant.</typeparam>
public class LogTemplate<T>
{
private static ILog instance = null;

/// <summary>
/// Gets the <see cref="ILog"/> this type logs to.
/// </summary>
public static ILog Instance {
get {
return instance; }
protected set
{
ArgumentValidator.EnsureArgumentNotNull(value,
"value");
instance = value;
}
}

#region ILog-like static methods

public static bool IsEnabled(LogEventTypes eventType)
{
return Instance.IsLogged(eventType);
}

[Conditional(
"DEBUG")]
public static void Debug(object message, Exception exception)
{
Instance.Debug(message, exception);
}

[Conditional(
"DEBUG")]
public static void Debug(string format, params object[] args)
{
Instance.Debug(format, args);
}

[Conditional(
"DEBUG")]
public static void Debug(IFormatProvider provider, string format, params object[] args)
{
Instance.Debug(provider, format, args);
}

public static void Info(object message, Exception exception)
{
Instance.Info(message, exception);
}

public static void Info(string format, params object[] args)
{
Instance.Info(format, args);
}

public static void Info(IFormatProvider provider, string format, params object[] args)
{
Instance.Info(provider, format, args);
}

public static void Warning(object message, Exception exception)
{
Instance.Warning(message, exception);
}

public static void Warning(string format, params object[] args)
{
Instance.Warning(format, args);
}

public static void Warning(IFormatProvider provider, string format, params object[] args)
{
Instance.Warning(provider, format, args);
}

public static void Error(object message, Exception exception)
{
Instance.Error(message, exception);
}

public static void Error(string format, params object[] args)
{
Instance.Error(format, args);
}

public static void Error(IFormatProvider provider, string format, params object[] args)
{
Instance.Error(provider, format, args);
}

public static void FatalError(object message, Exception exception)
{
Instance.FatalError(message, exception);
}

public static void FatalError(string format, params object[] args)
{
Instance.FatalError(format, args);
}

public static void FatalError(IFormatProvider provider, string format, params object[] args)
{
Instance.FatalError(provider, format, args);
}

#endregion


// Static constructor

static LogTemplate()
{
Type t =
typeof (T);
string logName = "Unnamed";
logName = (
string)t.GetField("Name", BindingFlags.Public | BindingFlags.Static).GetValue(null);
string skipPrefix = "Xtensive.";
if (logName.StartsWith(skipPrefix))
logName = logName.Substring(skipPrefix.Length);
Instance = LogProvider.GetLog(logName);
Diagnostics.Log.Info(
"{0} log initialized.", Instance);
}
}

It is base generic type for any default log. It's quite easy to create a default log based on this type:
using System.Reflection;
using Xtensive.Core.Diagnostics;

namespace Xtensive.Core
{
/// <summary>
/// Log for this namespace.
/// </summary>
public sealed class Log: LogTemplate<Log>
{
// Copy-paste this code!
public static readonly string Name;

static Log()
{
string className = MethodInfo.GetCurrentMethod().DeclaringType.FullName;
Name = className.Substring(0, className.LastIndexOf(
'.'));
}
}
}

So to get default log in some namespace, you should just copy-paste the last piece of code, and set appropriate namespace in it!

Why this approach works? C# resolves type name by the following pattern:
- It searches the current namespace (i.e. namespace of the type where reference to class is found) for the type with the name it resolves
- If no type with specified name is found, it searches the above namespace, and so on
- Finally, it searches the namespaces listed in using directives in the current file.
So if you declare such Log in some namespace, type Log will be resolved to it in this namespace and all above ones (of course if above namespace doesn't declare another Log). That's exactly the behavior we want to get!

Funny trick: have you noted what's the ancestor of Log? It is LogTemplate<Log> - i.e. a LogTemplate< <ThisType> >. LogTemplate class should be generic (i.e. have at least one generic parameter) - to ensure its static instance member will be created for each of its non-generic instances. But on the other hand we should ensure that each instance of this generic will have different type of T parameter (if it will be the same, there will be shared static member). And Log type (i.e. <ThisType>) perfectly suits here!

So now we have Log.Info(...) - like calls everywhere - and doesn't worry about moving the classes or methods. Copy-paste once, use everywhere in assembly or namespace. Perfect!

2. Log capturing.

This problem is actually much less tricky to solve - i.e. just coding is necessary here. There is LogCaptureScope type allowing to capture an output from a set of ILogs into another ILog - i.e. exactly what we need. Just an example, and nothing more:
using (new LogCaptureScope(LogProvider.ConsoleLog)) {
Log.Info(
"This message will be written twice on console.");
}

3. Log indentation.

Again, rather simple problem, so let's show its solution on one more small example:
Log.Info("Not indented");
using (new LogIndentScope()) {
using (new LogCaptureScope(LogProvider.ConsoleLog)) {
Log.Info(
"Indented (1)");
using (new LogIndentScope()) {
Log.Info(
"Indented (2)");
}
}
}

7 comments:

  1. The examples are available here (as NUnit tests).

    ReplyDelete
  2. You guys really need to take a step back and ask yourselves if what you are working on is worthwhile. You are re-inventing every wheel that is currently already out there -- indexes, logging, network messaging, the list goes on? What are you guys doing that is so special that it warrants writing so much code? You are falling deep, deep into the "not invented here" syndrome, and 4.0 will keep slipping into the future as you bring on more and more of a burden by building all this cruft.

    You should be building novel things like your security system and OR/M. This other stuff is just nonsense and is re-inventing the wheel (messaging, logs) and premature optimization (b+ tree indexes)

    ReplyDelete
  3. FYI - I left the company that was using DO.NET 3 more than a year and a half ago.. to think that 4.0 is still vaporware at this point to your customers is mindblowing. I personally think x-tensive has gone down the wrong path and you guys need to step back and prioritize features (ie, CUT a ton of features) and add value instead of writing logging code.

    ReplyDelete
  4. Ok, partially you're correct - probably we are doing a lot of things that are implemented somewhere else. But:
    - We actually avoid to do something that is already done well. E.g. we use PostSharp, log4net and NUnit.
    - Concerning logging: as I wrote, we just implemented wrappers implementing our own logging interfaces around log4net classes. So this is really better then bind ourselves to log4net. So all our logging-related code is ~ 30Kb in total - good price for flexibility & features we wanted.
    - Concerning indexing: I anyway planned to publish a special post explaining our attention to them. This really seems rather in OR\M context (e.g. you consider indexing as some king of optimization, but actually this isn't true - it's one of key components of our storage platform). We're dealing with them because currently our context is not just an OR\M context.

    > You should be building novel things like your security system and OR/M.

    Building a security system on the top of flexible storage engine is probably just 5% of total work. Building it on less flexible engine can be a hell... E.g. currently there are some problems in v3.9 security system, that could take a lot of time to be solved. Moreover, they anyway couldn't be solved ideally - permission queries and support for permission updates in offlines are examples of such tasks.

    > You guys need to step back and prioritize features (ie, CUT a ton of features) and add value instead of writing logging code.

    It isn't quite attractive for us to be just a pretty good player in this niche. We want to be the best one. In wide range of tasks DO 4.0 can be the only good option. Yes, it ate a lot of time, and probably will a lot further - on CTP-to-release path. But it should be #1, otherwise it doesn't worth to spend so much time on it.

    Finally, it seems I should explain why I post such topics here - my primary intention is to show some non-trivial approaches to well-known problems we've faced - a lot of people face the same ones, but as far as I know, we're the first company using e.g. such a nice approach for dealing with generic relatively well-known concept as context-scope-activation. Usually it isn't solved in such general & fast fashion. I shown how we're logging everything by the same reason - tons of applications \ frameworks log something, but compare the approach ;) Again, we have quite simple, blazingly fast context-bound logging. Other approaches we know can provide just 2 of these 3 features.

    ReplyDelete
  5. > This really seems rather in OR\M context
    "Rather strange", I mean ;)

    ReplyDelete
  6. > will a lot further
    "will eat a lot further"

    ReplyDelete
  7. Ok, done ;) See one more post I just published.

    ReplyDelete