Walkthrough

Before we get started...

Here are a couple of very simple classes that we'll use through many of the examples to demonstrate the power and concepts of Its.Log. Feel free to skip and refer back if necessary as you learn from the examples.

public class Movie
{
    public string Title { get; set; }

    public IEnumerable<Person> Stars { get; set; }

    public Person Director { get; set; }

    public int Year { get; set; }

    public static readonly Movie StarWars = new Movie
    {
        Title = "Star Wars: Episode IV - A New Hope",
        Director = Person.GeorgeLucas,
        Stars =
            new[]
            {
                Person.CarrieFisher, 
                Person.HarrisonFord,
                Person.MarkHamill
            },
        Year = 1977,
        FullCast = new[]
        {
            new Person { Name = "Mark Hamill" },
            new Person { Name = "Harrison Ford" },
            new Person { Name = "Carrie Fisher" },
            new Person { Name = "Peter Cushing" },
            new Person { Name = "Alec Guinness" },
            new Person { Name = "Anthony Daniels" },
            new Person { Name = "Kenny Baker" },
            new Person { Name = "Peter Mayhew" },
            new Person { Name = "David Prowse" },
            new Person { Name = "James Earl Jones" },
            new Person { Name = "Phil Brown" },
            new Person { Name = "Shelagh Fraser" },
            new Person { Name = "Jack Purvis" },
            new Person { Name = "Alex McCrindle" },
            new Person { Name = "Eddie Byrne" },
            new Person { Name = "Drewe Henley" },
            new Person { Name = "Denis Lawson" },
            new Person { Name = "Garrick Hagon" },
            new Person { Name = "Jack Klaff" },
            new Person { Name = "William Hootkins" },
            new Person { Name = "Angus MacInnes" },
            new Person { Name = "Jeremy Sinden" },
            new Person { Name = "Graham Ashley" },
            new Person { Name = "Don Henderson" },
            new Person { Name = "Richard LeParmentier" },
            new Person { Name = "Leslie Schofield" },
            new Person { Name = "David Ankrum" },
            new Person { Name = "Mark Austin" },
            new Person { Name = "Scott Beach" },
            new Person { Name = "Lightning Bear" },
            new Person { Name = "Jon Berg" },
            new Person { Name = "Doug Beswick" },
            new Person { Name = "Paul Blake" },
            new Person { Name = "Janice Burchette" },
            new Person { Name = "Ted Burnett" },
            new Person { Name = "John Chapman" },
            new Person { Name = "Gilda Cohen" },
            new Person { Name = "Tim Condren" },
            new Person { Name = "Barry Copping" },
            new Person { Name = "Alfie Curtis" },
            new Person { Name = "Robert Davies" },
            new Person { Name = "Maria De Aragon" },
            new Person { Name = "Robert A. Denham" },
            new Person { Name = "Frazer Diamond" },
            new Person { Name = "Peter Diamond" },
            new Person { Name = "Warwick Diamond" },
            new Person { Name = "Sadie Eden" },
            new Person { Name = "Kim Falkinburg" },
            new Person { Name = "Harry Fielder" },
            new Person { Name = "Ted Gagliano" },
            new Person { Name = "Salo Gardner" },
            new Person { Name = "Steve Gawley" },
            new Person { Name = "Barry Gnome" },
            new Person { Name = "Rusty Goffe" },
            new Person { Name = "Isaac Grand" },
            new Person { Name = "Nelson Hall" },
            new Person { Name = "Reg Harding" },
            new Person { Name = "Alan Harris" },
            new Person { Name = "Frank Henson" },
            new Person { Name = "Christine Hewett" },
            new Person { Name = "Arthur Howell" },
            new Person { Name = "Tommy Ilsley" },
            new Person { Name = "Joe Johnston" },
            new Person { Name = "Annette Jones" },
            new Person { Name = "Linda Jones" },
            new Person { Name = "Joe Kaye" },
            new Person { Name = "Colin Michael Kitchens" },
            new Person { Name = "Melissa Kurtz" },
            new Person { Name = "Tiffany L. Kurtz" },
            new Person { Name = "Al Lampert" },
            new Person { Name = "Anthony Lang" },
            new Person { Name = "Laine Liska" },
            new Person { Name = "Derek Lyons" },
            new Person { Name = "Mahjoub" },
            new Person { Name = "Alf Mangan" },
            new Person { Name = "Rick McCallum" },
            new Person { Name = "Grant McCune" },
            new Person { Name = "Jeff Moon" },
            new Person { Name = "Mandy Morton" },
            new Person { Name = "Lorne Peterson" },
            new Person { Name = "Marcus Powell" },
            new Person { Name = "Shane Rimmer" },
            new Person { Name = "Pam Rose" },
            new Person { Name = "George Roubicek" },
            new Person { Name = "Erica Simmons" },
            new Person { Name = "Angela Staines" },
            new Person { Name = "George Stock" },
            new Person { Name = "Roy Straite" },
            new Person { Name = "Peter Sturgeon" },
            new Person { Name = "Peter Sumner" },
            new Person { Name = "John Sylla" },
            new Person { Name = "Tom Sylla" },
            new Person { Name = "Malcolm Tierney" },
            new Person { Name = "Phil Tippett" },
            new Person { Name = "Burnell Tucker" },
            new Person { Name = "Morgan Upton" },
            new Person { Name = "Jerry Walter" },
            new Person { Name = "Hal Wamsley" },
            new Person { Name = "Larry Ward" },
            new Person { Name = "Diana Sadley Way" },
            new Person { Name = "Harold Weed" },
            new Person { Name = "Bill Weston" },
            new Person { Name = "Steve 'Spaz' Williams" },
            new Person { Name = "Fred Wood" }
        },
    };

    public IEnumerable<Person> FullCast { get; set; }
}

public class Person
{
    public string Name { get; set; }

    public DateTime DateOfBirth { get; set; }

    public IEnumerable<Movie> Movies { get; set; }

    public static readonly Person GeorgeLucas = new Person
    {
        Name = "George Lucas",
        DateOfBirth = new DateTime(1944, 5, 14)
    };

    public static readonly Person CarrieFisher = new Person
    {
        Name = "Carrie Fisher",
        DateOfBirth = new DateTime(1956, 10, 21)
    };

    public static readonly Person HarrisonFord = new Person
    {
        Name = "Harrison Ford",
        DateOfBirth = new DateTime(1942, 7, 13)
    };

    public static readonly Person MarkHamill = new Person
    {
        Name = "Mark Hamill",
        DateOfBirth = new DateTime(1951, 9, 25)
    };
}

##Basic usage

An important concept to understand early is that an Its.Log statement does not actually log anything.

"What? A logging library that doesn't log? Then why bother?"

Its.Log separates the concern of sending notifications that something should be logged from the concern of pushing the data to a store. It concentrates on how you instrument your code with logging statements and gives you a powerful separation of concerns so you can create effective centralized policies for handling different situations including the ability to dial up or down your logging requirements dynamically if necessary. It allows you to use your favorite logging library to handle serializing your data to disk or sending it over the network. It will become clearer what this means with some examples so let's jump in.

// the simplest log statement looks like this
// it fires an event and until you subscribe to that event, nothing will get logged here
Log.Write(Movie.StarWars);

// subscribe to the event like this
Log.EntryPosted += (sender, e) => { Console.WriteLine(e.LogEntry.ToLogString()); };

// now the first statement will write this to the console:
// { Information: CallingType = [null] | CallingMethod =  | Subject = Playground.Movie | TimeStamp = 2015-07-09 15:49:05Z | Params = {  } }

We will refer to this event handler as the "log policy." It is in the policy where you configure your logging rules. The Write statements are embedded with your logic and are technically instrumentation but it is still common to refer to these statements as "logging". Just keep in mind that it is not technically logging to disk even though that is typically the end result.

// Compare the output of this with the next statement
Log.Write(Movie.StarWars);
// { Information: CallingType = [null] | CallingMethod =  | Subject = Playground.Movie | TimeStamp = 2015-07-09 15:49:05Z | Params = {  } }

// Extra data is added about the calling method and type
Log.Write(() => Movie.StarWars);
// { Information: CallingType = ItsLogDemo | CallingMethod = BasicLogging | Subject = Playground.Movie | TimeStamp = 2015-07-09 15:49:05Z | Params = {  } }

Its.Log is optimized for performance. Reflecting to determine the caller is both slow and unreliable in optimized builds. Using the lambda expression allows Its.Log to efficiently gather the caller information so you should prefer it to the first example.

Notice that Log.Write accepts any type of object, not just strings. Inside the EntryPosted event, the event contains a member LogEntry which is an Its.Log type for all events logged via Log.Write (or other Logging methods). LogEntry contains all the members you see in the log output above: CallingType, CallingMethod, Subject, TimeStamp, Params. Subject refers to the object that was just logged. The default output for an object is its .ToString() method so subject above shows the default implementation of .NET's ToString() - i.e. namespace (Playground) and class (Movie).

Add formatting to types

While you could modify output by overriding ToString(), Its.Log provides a simple decoupled way to format your logs without imposing any requirements on the logic. By adding formatters you can configure the output for each type independently:

// often the log policy will live with the top-most app level code (like in Global.asax in a web application)
Log.EntryPosted += (sender, e) => Console.WriteLine(e.LogEntry.ToLogString());

// this code will normally live alongside the log policy
Formatter<Movie>.RegisterForAllMembers();
Formatter<Person>.RegisterForAllMembers();

// whereas this line is embedded with your logic
Log.Write(() => Movie.StarWars);
// { Information: CallingType = ItsLogDemo | CallingMethod = AddFormatting | Subject = { Movie: Title = Star Wars: Episode IV - A New Hope | Stars = { { Person: Name = Carrie Fisher | DateOfBirth = 1956-10-21 00:00:00Z | Movies = [null] }, { Person: Name = Harrison Ford | DateOfBirth = 1942-07-13 00:00:00Z | Movies = [null] }, { Person: Name = Mark Hamill | DateOfBirth = 1951-09-25 00:00:00Z | Movies = [null] } } | Director = { Person: Name = George Lucas | DateOfBirth = 1944-05-14 00:00:00Z | Movies = [null] } | Year = 1977 | FullCast = { { Person: Name = Mark Hamill | DateOfBirth = 0001-01-01 00:00:00Z | Movies = [null] }, { Person: Name = Harrison Ford | DateOfBirth = 0001-01-01 00:00:00Z | Movies = [null] }, { Person: Name = Carrie Fisher | DateOfBirth = 0001-01-01 00:00:00Z | Movies = [null] }, { Person: Name = Peter Cushing |  DateOfBirth = 0001-01-01 00:00:00Z | Movies = [null] }, { Person: Name = Alec Guinness | DateOfBirth = 0001-01-01 00:00:00Z | Movies = [null] }, { Person: Name = Anthony Daniels | DateOfBirth = 0001-01-01 00:00:00Z | Movies = [null] }, { Person: Name = Kenny Baker | DateOfBirth = 0001-01-01 00:00:00Z | Movies = [null] }, { Person: Name = Peter Mayhew | DateOfBirth = 0001-01-01 00:00:00Z | Movies = [null] }, { Person : Name = David Prowse | DateOfBirth = 0001-01-01 00:00:00Z | Movies = [null] }, { Person: Name = James Earl Jones | DateOfBirth = 0001-01-01 00:00:00Z | Movies = [null] } ... (94 more) } } | TimeStamp = 2015-07-09 18:45:52Z | Params = {  } }

Notice how all the properties on the type are automatically reported on for each type logged now.

Perhaps this is too much detail and you would like to be more precise in what properties are logged. No problem.

Log.EntryPosted += (sender, e) => Console.WriteLine(e.LogEntry.ToLogString());

// only certain properties...
Formatter<Movie>.RegisterForMembers(m => m.Title, m => m.Stars);

// or specify your own function...
Formatter<Person>.Register(p => string.Format("{0} (born: {1})", p.Name, p.DateOfBirth));

Log.Write(() => Movie.StarWars);
// { Information: CallingType = ItsLogDemo | CallingMethod = BeingMorePreciseWithFormatting | Subject = { Movie: Title = Star Wars: Episode IV - A New Hope | Stars = { Carrie Fisher (born: 10/21/1956 12:00:00 AM), Harrison Ford (born: 7/13/1942 12:00:00 AM), Mark Hamill (born: 9/25/1951 12:00:00 AM) } } | TimeStamp = 2015-07-09 18:52:16Z | Params = {  } }

Exceptions are descriptive by default

No need to register a custom formatter when errors are involved. Even nested exceptions are expanded.

Log.EntryPosted += (sender, e) => Console.WriteLine(e.LogEntry.ToLogString());

var dataException = new DataException("oops!");
dataException.Data["why?"] = "because";
var outerException = new ReflectionTypeLoadException(new[] { typeof(ItsLogDemo) }, new[] { dataException });

try
{
    throw outerException;
}
catch (Exception ex)
{
    Log.Write(() => ex);
}
// { Error: CallingType = ItsLogDemo | CallingMethod = ExceptionsAreDescriptiveByDefault | ExceptionId = 89e3aa8c-0426-4df5-8250-7647c35bf522 | Subject = { ReflectionTypeLoadException: Types = { ItsLogDemo } | LoaderExceptions = { { DataException: Message = oops! | Data = { [why?, because] } | InnerException = [null] | TargetSite = [null] | StackTrace = [null] | HelpLink = [null] | Source = [null] | HResult = -2146232032 } } | Message = Exception of type 'System.Reflection.ReflectionTypeLoadException' was thrown. | Data = {  } | InnerException = [null] | TargetSite = Void ExceptionsAreDescriptiveByDefault() | StackTrace =    at Playground.ItsLogDemo.ExceptionsAreDescriptiveByDefault() in c:\Source\Git\CoMetrics\Playground\Playground\ItsLog\ItsLogDemo.cs:line 97 | HelpLink = [null] | Source = Playground | HResult = -2146232830 } | TimeStamp = 2015-07-09 19:00:35Z | Params = {  } }

Only the outer exception has a stack trace since it was the only one thrown from the code. Note that a unique exception id is generated for each exception thrown which can be useful when parsing logs to disambiguate one exception stack from another.

Simple .NET TraceListener log policy

Here is a naive log policy configuration for a console app with notes on how this would be applied inside a web app.

// Web app: global.asax Application_Start would initialize the trace listener and store a static reference
using (var traceListener = new TextWriterTraceListener("MyApp.log"))
{
    Trace.Listeners.Add(traceListener);

    // Should be first thing executed to ensure no log events are missed
    Log.EntryPosted += (sender, e) =>
    {
        var logEntry = e.LogEntry;

        if (logEntry.Subject is Exception)
        {
            Trace.TraceError(logEntry.ToLogString());
        }
        else
        {
            Trace.TraceInformation(logEntry.ToLogString());
        }
    };

    // The rest of the app records its activity
    Log.Write(() => "hello");
    // In MyApp.log: Playground.exe Information: 0 : { Information: CallingType = ItsLogDemo | CallingMethod = ControllingHowDifferentTypesAreLogged | Message = hello | Subject = hello | TimeStamp = 2015-07-08 17:12:45Z | Params = {  } }
    Log.Write(() => new Exception("oops"));
    // In MyApp.log: Playground.exe Error: 0 : { Error: CallingType = ItsLogDemo | CallingMethod = ControllingHowDifferentTypesAreLogged | ExceptionId = 2e60cb74-87ea-44ba-b90a-bb68c7db4347 | Subject = { Exception: Message = oops | Data = {  } | InnerException = [null] | TargetSite = [null] | StackTrace = [null] | HelpLink = [null] | Source = [null] | HResult = -2146233088 } | TimeStamp = 2015-07-08 17:12:45Z | Params = {  } }
} // Web app: Global.asax Application_End would dispose of the stored trace listener

One point of interest here is how the policy is using the type of the subject to make decisions. One can imagine a very rich set of rules governing how to respond to different types that are logged, logging to different places depending on context, using multiple loggers, etc. You could easily replace the .NET Trace Listener with NLog, log4net, or your favorite logging library here.

Where is Log.Error, Log.Warn, etc.?

The trouble with writing these statements throughout your code is that you're coupling the core logic with how its information should be logged. This makes it very awkward to dial up or down your logging level based on policy or context. Since an Its.Log policy is just C# code, you can react to the environment and log messages differently or dial logging up or down dynamically. Its.Log protects you from this coupling, but you have the freedom to react in your log policy in any way you see fit including calling a Log.Error or Log.Warning in some other system.

Its.Log also includes conventions that all exceptions are Errors by default. Some particularly problematic exceptions like OutOfMemoryException are Critical, handled exceptions are Warnings, other messages are Information, and some messages which may or may not get logged are Verbose (you'll see this a bit later). If you scan some of the prior output you'll notice it begins with Error for exceptions and Information for other messages. So chances are you can stick with the Its.Log conventions and never worry about log levels at all.

What happens when logging a long list?

You can customize how many elements of a list that are included in the log via ListExpansionLimit:

Log.EntryPosted += (sender, e) => Console.WriteLine(e.LogEntry.ToLogString());

// limit the detail so its easier to see the results
Formatter<Movie>.RegisterForMembers(m => m.Title, m => m.FullCast);
Formatter<Person>.Register(p => string.Format("{0} (born: {1})", p.Name, p.DateOfBirth));

Formatter.ListExpansionLimit = 3;
Log.Write(() => Movie.StarWars);
// { Information: CallingType = ItsLogDemo | CallingMethod = ListExpansionLimits | Subject = { Movie: Title = Star Wars: Episode IV - A New Hope | FullCast = { Mark Hamill (born: 1/1/0001 12:00:00 AM), Harrison Ford (born: 1/1/0001 12:00:00 AM), Carrie Fisher (born: 1/1/0001 12:00:00 AM) ... (101 more) } } | TimeStamp = 2015-07-09 19:51:59Z | Params = {  } }

Formatter.ListExpansionLimit = 10;
Log.Write(() => Movie.StarWars);
// { Information: CallingType = ItsLogDemo | CallingMethod = ListExpansionLimits | Subject = { Movie: Title = Star Wars: Episode IV - A New Hope | FullCast = { Mark Hamill (born: 1/1/0001 12:00:00 AM), Harrison Ford (born: 1/1/0001 12:00:00 AM), Carrie Fisher (born: 1/1/0001 12:00:00 AM), Peter Cushing (born: 1/1/0001 12:00:00 AM), Alec Guinness (born: 1/1/0001 12:00:00 AM), Anthony Daniels (born: 1/1/0001 12:00:00 AM), Kenny Baker (born: 1/1/0001 12:00:00 AM), Peter Mayhew (born: 1/1/0001 12:00:00 AM), David Prowse (born: 1/1/0001 12:00:00 AM), James Earl Jones (born: 1/1/0001 12:00:00 AM) ... (94 more) } } | TimeStamp = 2015-07-09 19:51:59Z | Params = {  } }

Take note of the FullCast member and how it ends as well "(101 more)" and "(94 more)"

What about recursive types?

Glad you asked. Its.Log has a RecursionLimit and thus protects from infinite loops.

Log.EntryPosted += (sender, e) => Console.WriteLine(e.LogEntry.ToLogString());

// limit the detail so its easier to see the results
Formatter<Movie>.RegisterForMembers(m => m.Title, m => m.Director);
Formatter<Person>.RegisterForMembers(p => p.Name, p => p.Movies);

// set up a recursive relationship that the above properties formatters will traverse
Person.GeorgeLucas.Movies = new[] { Movie.StarWars };

// default depth is 6 (objectLevel1.level2.level3.level4.level5.level6)
Log.Write(() => Person.GeorgeLucas);
// { Information: CallingType = ItsLogDemo | CallingMethod = HandlingRecursionInLoggedObjects | Subject = { Person: Name = George Lucas | Movies = { { Movie: Title = Star Wars: Episode IV - A New Hope | Director = { Person: Name = George Lucas | Movies = { Playground.Movie } } } } } | TimeStamp = 2015-07-09 19:59:27Z | Params = {  } }

Formatter.RecursionLimit = 3;
Log.Write(() => Person.GeorgeLucas);
// { Information: CallingType = ItsLogDemo | CallingMethod = HandlingRecursionInLoggedObjects | Subject = { Person: Name = George Lucas | Movies = { Playground.Movie } } | TimeStamp = 2015-07-09 19:59:27Z | Params = {  } }

Formatter.RecursionLimit = 10;
Log.Write(() => Person.GeorgeLucas);
// { Information: CallingType = ItsLogDemo | CallingMethod = HandlingRecursionInLoggedObjects | Subject = { Person: Name = George Lucas | Movies = { { Movie: Title = Star Wars: Episode IV - A New Hope | Director = { Person: Name = George Lucas | Movies = { { Movie: Title = Star Wars: Episode IV - A New Hope | Director = { Person: Name = George Lucas | Movies = { Playground.Movie } } } } } } } } | TimeStamp = 2015-07-09 19:59:27Z | Params = {  } }

Is Log.Write all you've got to offer?

Its.Log also has the ability to include contextual information in its logs and log boundaries around code quite easily.

Log.EntryPosted += (sender, e) => Console.WriteLine(e.LogEntry.ToLogString());

// limit the detail so its easier to see the results
Formatter<LogEntry>.RegisterForMembers(
    e => e.Message,
    e => e.Subject,
    e => e.ElapsedMilliseconds);

var birthdays = new List<DateTime>();
var test = "test";

// the entrance is logged
using (var activity = Log.Enter(() => new { birthdays, test }))
// { Start: Subject = { birthdays = {  } | test = test } |  }
{
    birthdays.Add(Person.MarkHamill.DateOfBirth);
    test = "test 2";

    // standard write does not include context
    Log.Write(() => new { value = "adding a birthday..." });
    // { Information: Subject = { value = adding a birthday... } |  }

    // but this one includes all the context data
    activity.Trace(() => new { value = "adding a birthday..." });
    // { Verbose: Subject = { birthdays = { 1951-09-25 00:00:00Z } | test = test 2 } | ElapsedMilliseconds = 9 }

    birthdays.Add(Person.CarrieFisher.DateOfBirth);
    test = "test 3";

    // and the exit is logged
}
// { Stop: Subject = { birthdays = { 1951-09-25 00:00:00Z, 1956-10-21 00:00:00Z } | test = test 3 } | ElapsedMilliseconds = 12 }

Notice how the state of each object reference (birthdays and test) is correctly captured at the point in time of each log statement.

What about conditional logging?

Rather than placing lots of if/else statements around Log.Write calls, Log.Enter enables conditional logging by optionally requiring confirmation before committing log events:

Log.EntryPosted += (sender, e) => Console.WriteLine(e.LogEntry.ToLogString());

// limit the detail so its easier to see the results
Formatter<LogEntry>.RegisterForMembers(
    e => e.Message,
    e => e.Subject,
    e => e.ElapsedMilliseconds);

var test = "test";
// because this block requires confirmation...
using (var activity = Log.Enter(() => new { test }, requireConfirm: true))
{
    test = "test 2";
    activity.Trace("does this write?");
    test = "test 3";

    // ...and non is given...
}
// ...no logs are written at any of the usual points

// this block receives a confirmation so all logs get written
using (var activity = Log.Enter(() => new { test }, requireConfirm: true))
// { Start: Subject = { test = test 3 } |  }
{
    test = "test 4";
    activity.Trace("how about this?");
    // { Verbose: Message = how about this? | Subject = { test = test 4 } | ElapsedMilliseconds = 13 }
    test = "test 5";

    // this confirmation could be inside a condition of some sort
    // when a certain thing happens log all the details of this block
    // otherwise when not confirmed then ignore logging the entire set of details
    activity.Confirm();
}
//{ Stop: Subject = { test = test 5 } | ElapsedMilliseconds = 13 }

Aggregating confirmations

You can use confirm to aggregate details.

// this time we won't limit the output
Log.EntryPosted += (sender, e) => Console.WriteLine(e.LogEntry.ToLogString());

using (var activity = Log.Enter(() => { }))
// { Start: CallingType = ItsLogDemo | CallingMethod = TrackingCheckpointsWithConfirm | TimeStamp = 2015-07-14 15:11:35Z | Params = {  } }
{
    activity.Confirm(() => "Getting started");
    for (var i = 0; i < 10; i++)
    {
        activity.Confirm(() => new { processed = i });
    }

    activity.Confirm(() => "Finished");
}
// { Stop: CallingType = ItsLogDemo | CallingMethod = TrackingCheckpointsWithConfirm | ElapsedMilliseconds = 4 | TimeStamp = 2015-07-14 15:11:35Z | Params = { { Confirmed = { Getting started, { processed = 10 }, Finished } } } }

Notice in the 'Stop' log message 'Confirmed' results are aggregated.

Handling Exceptions

Its.Log includes some extension methods on Exceptions that allow more robust log reporting. While unrealistic, the following example demonstrates how you can flavor your exceptions when logging.

// provide some custom handling of posted log entries
Log.EntryPosted += (sender, e) =>
{
    var logEntry = e.LogEntry;
    var exception = logEntry.Subject as Exception;

    // anytime we get an unhandled exception
    if (exception != null && !exception.HasBeenHandled())
    {
        // in a more realistic example this might trigger a red flag in your monitoring dashboard
        Console.WriteLine("\nUNEXPECTED ERROR: " + logEntry.ToLogString() + "\n");
    }
    else
    {
        // everything else include handled exceptions
        Console.WriteLine(logEntry.ToLogString());
    }
};

// now the app is running and this try/catch represents some top-most level error handling
try
{
    // lots of code runs here, but somewhere deeper in the call stack we encounter an
    // exception we know how to handle, but want to flag it in the logs just in case
    try
    {
        throw new InvalidOperationException("Something happened");
    }
    catch (InvalidOperationException ex)
    {
        // here we indicate the exception has been handled
        ex.MarkAsHandled();
        Log.Write(() => ex);
        // { Warning: CallingType = ItsLogDemo | CallingMethod = MarkExceptionAsHandled | ExceptionId = 1d9c561f-a1ad-4ba1-ab76-82c4ec4555d9 | Subject = { InvalidOperationException: Message = Something happened | Data = { [Handled, True] } | InnerException = [null] | TargetSite = Void MarkExceptionAsHandled() | StackTrace =    at Playground.ItsLogDemo.MarkExceptionAsHandled() in c:\Source\Playground\ItsLog\ItsLogDemo.cs:line 258 | HelpLink = [null] | Source = Playground | HResult = -2146233079 } | TimeStamp = 2015-07-14 15:21:59Z | Params = {  } }
    }

    // somewhere else the code hits something it doesn't know how to handle
    // (btw: this should be a type derived Exception)
    throw new Exception("Something really bad happened!");
}
catch (Exception ex)
{
    Log.Write(() => ex);
    // UNEXPECTED ERROR: { Error: CallingType = ItsLogDemo | CallingMethod = MarkExceptionAsHandled | ExceptionId = 4eebfd79-4b5f-4551-8b2e-15a2df72959c | Subject = { Exception: Message = Something really bad happened! | Data = {  } | InnerException = [null] | TargetSite = Void MarkExceptionAsHandled() | StackTrace =    at Playground.ItsLogDemo.MarkExceptionAsHandled() in c:\Source\Playground\ItsLog\ItsLogDemo.cs:line 266 | HelpLink = [null] | Source = Playground | HResult = -2146233088 } | TimeStamp = 2015-07-14 15:21:59Z | Params = {  } }
}

Automatic message leveling

Notice above how the first message automatically was marked as a Warning and the second as an Error. Its.Log includes a set of conventions for how messages will be leveled when logging. These are as follows:

Critical - These are exceptions your app should probably crash on if it ever sees it. They are: ThreadAbortException, AccessViolationException, and OutOfMemoryException (except if InsufficentMemoryException - you can potentially try again with this one)
Error - All exceptions that were not marked as handled
Warning - All exceptions that were marked as handled
Information - All Log.Write messages
Verbose - Activity.Trace messages
Start - Log.Enter messages
Stop - When the Log.Enter return value is disposed of
Suspend, Resume, Transfer - In async/threading code

Can I add context to exceptions?

You bet, using:

exception.WithData()

This example should be pretty easy to follow:

Log.EntryPosted += (sender, e) => Console.WriteLine(e.LogEntry.ToLogString());

var someContext = new
{
    data1 = "test",
    data2 = 55,
    data3 = DateTime.Now
};

try
{
    throw new Exception("Something bad happened");
}
catch (Exception ex)
{
    ex.WithData(new { Context = someContext, SomeOtherInfo = "Hello there" });
    Log.Write(() => ex);
}

// { Error: CallingType = ItsLogDemo | CallingMethod = AddingDataToExceptions | ExceptionId = 4ec9f058-ae99-49fc-98b1-745bb1987c41 | Subject = { Exception: Message = Something bad happened | Data = { [ItsLog_ExceptionData_, { Context = { data1 = test | data2 = 55 | data3 = 2015-07-14 11:45:30Z } | SomeOtherInfo = Hello there }] } | InnerException = [null] | TargetSite = Void AddingDataToExceptions() | StackTrace =    at Playground.ItsLogDemo.AddingDataToExceptions() in c:\Source\Playground\ItsLog\ItsLogDemo.cs:line 287 | HelpLink = [null] | Source = Playground | HResult = -2146233088 } | TimeStamp = 2015-07-14 15:45:31Z | Params = {  } }

We could have just pass someContext to WithData if we wanted, it will accept any type. Passing a known type allows log policies to more easily figure out what it can do with messages.

Can I give additional context with regular logging?

Yup... try:

Log.WithParams()

This example shows you how:

// let's create a simple type that will hold some context
class SimpleType
{
    // add any context data you want on this type
    public string Name { get; set; }
}

// somewhere else...
Log.EntryPosted += (sender, e) => Console.WriteLine(e.LogEntry.ToLogString());

// and in the code...
var o = new SimpleType
{
    Name = "Hello"
};

// you can pass any type you want, but you have to give WithParams<T> the
// type or give it something an object it can use to infer the type
var log = Log.WithParams(() => o);

// now anytime we use log we'll get the extra context

log.Write("Now what?");
//{ Information: CallingType = ItsLogDemo | CallingMethod = UsingWithParams | Message = Now what? | Subject = Now what? | TimeStamp = 2015-07-14 16:05:37Z | Params = { { SimpleType: Name = Hello } } }

using (log.Enter(() => new { Test = "Yeah!" }))
// { Start: CallingType = ItsLogDemo | CallingMethod = UsingWithParams | Subject = { Test = Yeah! } | TimeStamp = 2015-07-14 16:05:37Z | Params = { { SimpleType: Name = Hello } } }
{
}
// { Stop: CallingType = ItsLogDemo | CallingMethod = UsingWithParams | ElapsedMilliseconds = 2 | Subject = { Test = Yeah! } | TimeStamp = 2015-07-14 16:05:37Z | Params = { { SimpleType: Name = Hello } } }

SimpleType and its data are added to all log statements issued from the log instance.

Using .With()

In this example, we'll use the SimpleType class again, but this time we'll use With instead of WithParams. With is cool because when you receive the log entry in your EntryPosted event you can detect which 'extension' type was used by the executing code. An example should make it clear.

Log.EntryPosted += (s, e) =>
{
    if (e.LogEntry.HasExtension<SimpleType>())
    {
        var simpleType = e.LogEntry.GetExtension<SimpleType>();
        Console.WriteLine("Metadata: {{ Name: {0} }}", simpleType.Name);
    }

    Console.WriteLine(e.LogEntry.ToLogString());
};

var log = Log.With<SimpleType>(simpleType => simpleType.Name = "oh yeah");

using (log.Enter(() => { }))
// Metadata: { Name: oh yeah }
// { Start: CallingType = ItsLogDemo | CallingMethod = UsingJustWith | TimeStamp = 2015-07-14 21:43:54Z | Params = {  } }
{
    // do something
    log.Write("Hello world");
    // Metadata: { Name: oh yeah }
    // { Information: CallingType = [null] | CallingMethod =  | Message = Hello world | Subject = Hello world | TimeStamp = 2015-07-14 21:43:54Z | Params = {  } }

}
// Metadata: { Name: oh yeah }
// { Stop: CallingType = ItsLogDemo | CallingMethod = UsingJustWith | ElapsedMilliseconds = 4 | TimeStamp = 2015-07-14 21:43:54Z | Params = {  } }

Here's another naive example of using .With() to give you better idea of how it could be used.

class MyPerformanceCounter
{
    public string Name { get; set; }

    public void Write(long milliseconds)
    {
        Console.WriteLine("Performance counter {0} recorded {1}ms", this.Name, milliseconds);
    }
}

Log.EntryPosted += (s, e) =>
{
    // only output extra detail when exiting (Stopping) an Enter block
    if (e.LogEntry.EventType == TraceEventType.Stop &&
        e.LogEntry.HasExtension<MyPerformanceCounter>())
    {
        e.LogEntry.GetExtension<MyPerformanceCounter>().Write(e.LogEntry.ElapsedMilliseconds.Value);
    }

    Console.WriteLine(e.LogEntry.ToLogString());
};

using (Log.With<MyPerformanceCounter>(counter => counter.Name = "MyCounter").Enter(() => { }))
// { Start: CallingType = ItsLogDemo | CallingMethod = MoreUsingWith | TimeStamp = 2015-07-14 21:49:42Z | Params = {  } }
{
    var randomSleepTime = new Random().Next(10, 300);
    Thread.Sleep(randomSleepTime);
}
// Performance counter MyCounter recorded 169ms
// { Stop: CallingType = ItsLogDemo | CallingMethod = MoreUsingWith | ElapsedMilliseconds = 169 | TimeStamp = 2015-07-14 21:49:42Z | Params = {  } }

Reactive logging

Okay... now that you've got the basics let's try our hand at integrating Its.Log with the Microsoft's Reactive framework Rx. Add a using System.Reactive.Linq to your code for these examples. Reactive is quite powerful and many examples are possible here so we'll just give you a few to whet your taste-buds. Take a look at Rx to get a better idea of what's possible at https://github.com/Reactive-Extensions/Rx.NET and https://msdn.microsoft.com/en-us/data/gg577609.aspx

Separate your log policy handlers based on type

This is a completely different way to think about your log policies. You can do this in addition to or instead of the approaches laid out earlier. Log.Events() is of type IObservable so you can quickly peek into the log stream and react appropriately

// log policy for exceptions
using (Log.Events()
    .Select(e => e.Subject as Exception)
    .Where(ex => ex != null)
    .Subscribe(ex => Console.WriteLine(ex.StackTrace)))
// log policy for strings
using (Log.Events()
    .Select(e => e.Subject as string)
    .Where(s => !string.IsNullOrWhiteSpace(s))
    .Subscribe(s => Console.WriteLine(s)))
{
    try
    {
        throw new Exception("Test");
    }
    catch (Exception ex)
    {
        Log.Write(() => ex);
        //   at Playground.ItsLogDemo.ReactiveLogging() in c:\Source\Playground\ItsLog\ItsLogDemo.cs:line 386
    }
    Log.Write(() => "Hello world");
    // Hello world
}
// both policies get disposed of here

The using (Log.Events()... ) statements would normally run as part of app startup (like in Application_Start in Global.asax.cs of an asp.net app) and the references created would be disposed of when the app terminates (such as in Application_End() of Global.asax.cs of an asp.net app).

Throttling events

In this example, we use Its.Log and Rx to throttle all the events down to one every second.

using (Log.Events()
    .Sample(TimeSpan.FromSeconds(1))
    .Subscribe(e => Console.WriteLine(e.Subject.ToLogString())))
{
    foreach (var i in Enumerable.Range(1, 2000000))
    {
        Log.Write(() => i);
    }

    Thread.Sleep(TimeSpan.FromSeconds(1.1));

    Log.Write(() => "one more");

    Thread.Sleep(TimeSpan.FromSeconds(1.1));
}

// Output (1 line per second)
// 1093053
// 2000000
// one more

Log event counts

// generate a bunch of exceptions
var _404s = Observable.Interval(TimeSpan.FromSeconds(.011))
    .Select(_ => new HttpException(404, "Not found"))
    .Publish();

// don't clog the logs with 404s, just log a count
var countOf404s = Log.Events()
    .Where(e => e.SubjectIs<HttpException>())
    .Where(e => e.GetSubject<HttpException>().GetHttpCode() == 404)
    .Buffer(TimeSpan.FromSeconds(1))
    .Select(es => es.Count());

using (_404s.Connect())
using (_404s.Subscribe(Log.Write))
using (countOf404s.Subscribe(count => Console.WriteLine("Received {0} Not found (404) exceptions", count)))
{
    Thread.Sleep(TimeSpan.FromSeconds(10));
}

// Output (1 line per second)
// Received 65 Not found (404) exceptions
// Received 63 Not found (404) exceptions
// Received 65 Not found (404) exceptions
// Received 64 Not found (404) exceptions
// Received 65 Not found (404) exceptions
// Received 64 Not found (404) exceptions
// Received 63 Not found (404) exceptions
// Received 65 Not found (404) exceptions
// Received 64 Not found (404) exceptions

Start logging after threshold is reached

var problems = Log.Events().SkipUntil(
    Log.Events().Where(e => e.Subject is Exception));

using (problems.Subscribe(e => Console.WriteLine(e.ToLogString())))
{
    var thread = new Thread(
        () =>
        {
            for (var i = 0; i <= 5000; i++)
            {
                // this won't appear in the log until the exceptions start happening:
                Log.Write(() => "Message " + i);

                if (i > 4995)
                {
                    Log.Write(() => new InvalidOperationException());
                }
            }
        });
    thread.Start();
    Thread.Sleep(1000);
    thread.Abort();
}

// Output:
// { Information: CallingType = ItsLogDemo | CallingMethod = EnableLoggingOnlyAfterThresholdIsReached | Message = Message 4997 | Subject = Message 4997 | TimeStamp = 2015-07-14 22:22:21Z | Params = {  } }
// { Error: CallingType = ItsLogDemo | CallingMethod = EnableLoggingOnlyAfterThresholdIsReached | ExceptionId = 8b87631d-2121-441a-a622-74905cc24d57 | Subject = { InvalidOperationException: Message = Operation is not valid due to the current state of the object. | Data = {  } | InnerException = [null] | TargetSite = [null] | StackTrace = [null] | HelpLink = [null] | Source = [null] | HResult = -2146233079 } | TimeStamp = 2015-07-14 22:22:21Z | Params = {  } }
// { Information: CallingType = ItsLogDemo | CallingMethod = EnableLoggingOnlyAfterThresholdIsReached | Message = Message 4998 | Subject = Message 4998 | TimeStamp = 2015-07-14 22:22:21Z | Params = {  } }
// { Error: CallingType = ItsLogDemo | CallingMethod = EnableLoggingOnlyAfterThresholdIsReached | ExceptionId = 8fea1b8c-05df-4cc1-93e9-e5b8ffc418db | Subject = { InvalidOperationException: Message = Operation is not valid due to the current state of the object. | Data = {  } | InnerException = [null] | TargetSite = [null] | StackTrace = [null] | HelpLink = [null] | Source = [null] | HResult = -2146233079 } | TimeStamp = 2015-07-14 22:22:21Z | Params = {  } }
// { Information: CallingType = ItsLogDemo | CallingMethod = EnableLoggingOnlyAfterThresholdIsReached | Message = Message 4999 | Subject = Message 4999 | TimeStamp = 2015-07-14 22:22:21Z | Params = {  } }
// { Error: CallingType = ItsLogDemo | CallingMethod = EnableLoggingOnlyAfterThresholdIsReached | ExceptionId = 8174dfec-59dc-459e-b57d-e41ecb9e1cdf | Subject = { InvalidOperationException: Message = Operation is not valid due to the current state of the object. | Data = {  } | InnerException = [null] | TargetSite = [null] | StackTrace = [null] | HelpLink = [null] | Source = [null] | HResult = -2146233079 } | TimeStamp = 2015-07-14 22:22:21Z | Params = {  } }
// { Information: CallingType = ItsLogDemo | CallingMethod = EnableLoggingOnlyAfterThresholdIsReached | Message = Message 5000 | Subject = Message 5000 | TimeStamp = 2015-07-14 22:22:21Z | Params = {  } }
// { Error: CallingType = ItsLogDemo | CallingMethod = EnableLoggingOnlyAfterThresholdIsReached | ExceptionId = 7a3a9f1e-ec45-4eb9-8a75-14a823dd9973 | Subject = { InvalidOperationException: Message = Operation is not valid due to the current state of the object. | Data = {  } | InnerException = [null] | TargetSite = [null] | StackTrace = [null] | HelpLink = [null] | Source = [null] | HResult = -2146233079 } | TimeStamp = 2015-07-14 22:22:21Z | Params = {  } }

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Walkthrough

Walkthrough

Before we get started...

Add formatting to types

Exceptions are descriptive by default

Simple .NET TraceListener log policy

Where is Log.Error, Log.Warn, etc.?

What happens when logging a long list?

What about recursive types?

Is Log.Write all you've got to offer?

What about conditional logging?

Aggregating confirmations

Handling Exceptions

Automatic message leveling

Can I add context to exceptions?

exception.WithData()

Can I give additional context with regular logging?

Log.WithParams()

Using .With()

Reactive logging

Separate your log policy handlers based on type

Throttling events

Log event counts

Start logging after threshold is reached

Clone this wiki locally