#2782

Linq DataContext Logging with the Logging Application Block

The System.Data.Linq.DataContext class exposes a TextWriter as the Log property allowing you to monitor the SQL that’s getting executed under the covers. The trivial usage of this is to simply set the property to Console.Out and watch the results.

Given that I was adding the Enterprise Library 4.0 Logging Block to my web application I wanted to catch the DataContext output and manage it along with all my other logging using the logging block configuration.

I need my own TextWriter that takes anything written to it and passes it on to the logging block Logger. Turns out that this isn’t so hard…

(You can download the source code here)

  public class LoggingTextWriter : TextWriter
  {
    private LogEntry _entryTemplate = new LogEntry();

    public LoggingTextWriter()
    {
    }

    public LoggingTextWriter(ICollection<string> categories,
      int priority,
      int eventId,
      TraceEventType severity,
      string title,
      IDictionary<string, object> properties)
    {
      _entryTemplate = new LogEntry("EMPTY", categories, priority, eventId,
          severity, title, properties);
    }

    public LoggingTextWriter(string category,
      int priority,
      int eventId,
      TraceEventType severity,
      string title,
      IDictionary<string, object> properties)
    {
      _entryTemplate = new LogEntry("EMPTY", category, priority, eventId,
          severity, title, properties);
    }

    public LoggingTextWriter(LogEntry entryTemplate)
    {
      if (entryTemplate == null)
        throw new ArgumentNullException("entryTemplate");

      _entryTemplate = entryTemplate;
    }

    public override void Write(string value)
    {
      value = Regex.Replace(value, "[ \t\r\n \t]+", " ",
          RegexOptions.Compiled);

      LogEntry entry = new LogEntry();
      entry.Categories = _entryTemplate.Categories;
      entry.Priority = _entryTemplate.Priority;
      entry.EventId = _entryTemplate.EventId;
      entry.Severity = _entryTemplate.Severity;
      entry.Title = _entryTemplate.Title;
      entry.ExtendedProperties = _entryTemplate.ExtendedProperties;

      entry.Message = value;

      Logger.Write(entry);
    }

    public override void WriteLine(string value)
    {
      this.Write(value);
    }

    public override System.Text.Encoding Encoding
    {
      get { return System.Text.Encoding.Unicode; }
    }
  }

Set this on the DataContext.Log (instead of Console.Out) and you’re good to go. The LoggingTextWriter strips out carriage returns and line feeds from the data context log output so SQL statements appear on a single line. You can also specify the other LogEntry properties for every entry.

Couple of points to note. In a real application this will generate lots of output and could impact performance. I’m not expecting to log all SQL output in production and I wrote a new text formatter that outputs a subset of the log entry to a single line, giving me something like this:

SQL: [p-1 / Information] SELECT [t0].[pkid], [t0].[Name], [t0].[Id] FROM [dbo].[Users] AS [t0] WHERE [t0].[pkid] = @p0
SQL: [p-1 / Information] — @p0: Input BigInt (Size = 0; Prec = 0; Scale = 0) [1]
SQL: [p-1 / Information] — Context: SqlProvider(Sql2005) Model: AttributedMetaModel Build: 3.5.30428.1
SQL: [p-1 / Information] UPDATE [dbo].[Users] SET [Name] = @p3 WHERE ([pkid] = @p0) AND ([Name] = @p1) AND ([Id] = @p2)
SQL: [p-1 / Information] — @p0: Input BigInt (Size = 0; Prec = 0; Scale = 0) [1]
SQL: [p-1 / Information] — @p1: Input VarChar (Size = 10; Prec = 0; Scale = 0) [John Doe 3]
SQL: [p-1 / Information] — @p2: Input VarChar (Size = 12; Prec = 0; Scale = 0) [john@doe.com]
SQL: [p-1 / Information] — @p3: Input VarChar (Size = 8; Prec = 0; Scale = 0) [John Doe]
SQL: [p-1 / Information] — Context: SqlProvider(Sql2005) Model: AttributedMetaModel Build: 3.5.30428.1
SQL: [p-1 / Information] SELECT [t0].[pkid], [t0].[Name], [t0].[Id] FROM [dbo].[Users] AS [t0] WHERE [t0].[pkid] = @p0
SQL: [p-1 / Information] — @p0: Input BigInt (Size = 0; Prec = 0; Scale = 0) [1]
SQL: [p-1 / Information] — Context: SqlProvider(Sql2005) Model: AttributedMetaModel Build: 3.5.30428.1

Each log line contains the log entry category, priority, severity and message fields but no more. This is configurable using the Enterprise Library configuration tool.

If you’re interested there are unit tests for the LoggingTextWriter. I wrote them using xUnit.net and in the process discovered that Brad has shipped an xUnit [Fact] code snippet, which makes TDD that much quicker.