chris-peterson/spiffy

A structured logging framework for .NET that supports log aggregation, e.g. Splunk

Overview

A structured logging framework for .NET that supports log analysis (e.g. Splunk) and metrics gathering (e.g. Prometheus).

Battle-tested in high-volume production environments for more than 10 years, handling over 1,000,0000,000,000 (1 trillion) requests.

Status

Package	Latest Release
Spiffy.Monitoring
Spiffy.Monitoring.Aws
Spiffy.Monitoring.NLog
Spiffy.Monitoring.Prometheus
Spiffy.Monitoring.Splunk

Setup

PM> Install-Package Spiffy.Monitoring

Built-In Logging Providers

Spiffy.Monitoring includes "built-in" logging mechanisms (Trace and Console).

There is no default logging behavior, you must initialize provider(s) by calling Spiffy.Monitoring.Configuration.Initialize.

Until initialized, any published EventContext will not be observable, so it is recommended that initialization be as early as possible when your application is starting (i.e. in the entry point).

Example

  Configuration.Initialize(spiffy => { spiffy.Providers.Console(); });

Extended Providers

For extended functionality, you'll need to install a "provider package".

NOTE: the provider package need only be installed for your application's entry point assembly, it need not be installed in library packages.

NLog Provider

PM> Install-Package Spiffy.Monitoring.NLog

Example

    static void Main() {
        // this should be the first line of your application
        Spiffy.Monitoring.Configuration.Initialize(spiffy => {
            spiffy.Providers
                .NLog(nlog => nlog.Targets(t => t.File()));
        });
    }

Multiple Providers

Multiple providers can be provied, for example, this application uses both Console (built-in), as well as File (NLog)

Example

    Spiffy.Monitoring.Configuration.Initialize(spiffy => {
        spiffy.Providers
            .Console()
            .NLog(nlog => nlog.Targets(t => t.File()));
    });

Log

Example Program

        // key-value-pairs set here appear in every event message
        GlobalEventContext.Instance
            .Set("Application", "MyApplication");

        using (var context = new EventContext()) {
            context["Key"] = "Value";

            using (context.Time("LongRunning")) {
                DoSomethingLongRunning();
            }

            try {
                DoSomethingDangerous();
            }
            catch (Exception ex) {
                context.IncludeException(ex);
            }
        }

Normal Entry

[2014-06-13 00:05:17.634Z] Application=MyApplication Level=Info Component=Program Operation=Main TimeElapsed=1004.2 Key=Value TimeElapsed_LongRunning=1000.2

Exception Entry

[2014-06-13 00:12:52.038Z] Application=MyApplication Level=Error Component=Program Operation=Main TimeElapsed=1027.0 Key=Value ErrorReason="An exception has ocurred" Exception_Type=ApplicationException Exception_Message="you were unlucky!" Exception_StackTrace=" at TestConsoleApp.Program.DoSomethingDangerous() in c:\src\git\github\chris-peterson\Spiffy\src\Tests\TestConsoleApp\Program.cs:line 47 at TestConsoleApp.Program.Main() in c:\src\git\github\chris-peterson\Spiffy\src\Tests\TestConsoleApp\Program.cs:line 29" InnermostException_Type=NullReferenceException InnermostException_Message="Object reference not set to an instance of an object." Exception="See Exception_* and InnermostException_* for more details" TimeElapsed_LongRunning=1000.0

Hosting Frameworks

Spiffy.Monitoring is designed to be easy to use in any context.

The most basic usage is to instrument a specific method. This can be achieved by "newing up" an EventContext. This usage mode results in Component being set to the containing code's class name, and Operation is set to the containing code's method name

There are times when you may want to instrument something that's not a specific method. One such example is an API -- in this context, you might want to have 1 log event per request. Consider setting Component to be the controller name, and Operation the action name. To acheive this, add middleware that calls EventContext.Initialize with the desired labels.

spiffy's Issues

Planning Version 7

Potential Changes in v7.0

Breaking Changes

• default to shorter, snake_case field names. Provide configuration options to retain existing behavior and/or further customize field naming
• changes to default behavior: RemoveNewLines: true
• don't log Count_ automatically when using Time/Timers.Accumulate -- require some sort of opt-in
• default precision for ms is whole numbers only. can opt-in for fractional values

Enhancements

• Add ability to control precision for timings -- with this provide a minimum threshold under which fields are automatically suppressed
• Ensure non-standard SI units are explicit in field names, e.g. ms in TimeElapsed
• Add Warn/Error methods that default to appending. Consider removing SetToX methods
• Introduce a concept of "essential fields". This set can be extended by callers and is used by a new Summarize() method that will shrink a logged message to just the essential fields. This is useful to manage logging volumes, e.g. for a web request that is fast and successful, don't log a ton of granular timings, etc; but rather, the "essential fields"

Feature: IncludeJson

Add an IncludeJson method

While JSON is a pretty human-infriendly representation of log data, there are times when you might want to emit JSON as part of a log entry (e.g. debugging corner cases)

Default behavior of Console is strange for the library usecase

Scenario

A library package Foo periodically does something "notable". The application developers for Foo want to generate event messages to provide visibility to code that would otherwise be invisible. Spiffy.Monitoring seems like a good fit.

An application named Bar discovers Foo. The application developers for Bar are too busy (reckless?) to be concerned with "logging". When running Bar, they are confused by periodic log emission as Foo performs its duties.

Proposed Change

Remove default publishing behavior, require application entry-point to Initialize either a provider assembly, or one of the built-ins ("trace" / "console").

Support "informational" exceptions

Problem

EventContext.IncludeException automatically sets Level=Error. Most of the time, this is desirable, but there are times when it is not (e.g. you've handled an exception, but still want to log details).

Implementation Suggestion

EventContext.IncludeInformationalException that would require a string key, and exception value.

Update NLog 5 to release version

Currently on latest (5.0.0-beta11). Shadowing their version numbering until it is released.

Console logging behavior question

Should the Console logging behavior use Console.Error.WriteLine(…) if the level is Level.Error?

Splunk wants comma separted field in quotes.

It looks like only the Message field surrounds the value with double quotes. That can be a problem on multi-value fields in splunk.

For example
context["ImportantStuff"] = string.Join(",", arrayOfGoodies) ;

For splunk, I have to change this to
context["ImportantStuff"] = "\"" + string.Join(",", arrayOfGoodies) + "\"";

Don't forget NOT to add quotes if they're already there.

Sorry I couldn't do this myself.

Feature: Add ability to suppress logging of individual properties

When using IncludeStructure, it would be nice to be able to deny certain fields from getting logged. e.g.

class Customer
{
   public string Name { get; set; }
   
   [NeverLog]
   public CreditCardNumber { get; set; }
}

Use "duck" typing to allow client to define the attribute in their own code base.

Allow sub-classification of Operation

Sometimes, a given method will have need to create EventContext in different circumstances, e.g. error handling.

Provide a convenience method EventContext.AppendOperation.

Example:

   void DoStuff() {
     using (var normalContext = new EventContext()) {
       // do normal stuff
     }

     if (errorsDetected) {   
        using (var errorContext = new EventContext()) {
          errorContext.AppendOperation(":HandleErrors");
      }
   }
}

errorContext would publish an event with Operation=DoStuff:HandleErrors

NLog.Config file ignored

I created an NLog.config file for an app, but it is completely ignored. The only way to configure spiffy appears to be the Initialize(Action<NLogConfigurationApi>) method.

Difference between step method and `Step` class

Method steps support overloads while subclasses of Kekiri.Step do not support constructor overloads. It would be nice if both types of steps worked the same way (either neither supporting overloads, or both supporting overloads). I'd vote for both supporting overloads. What do you think @chris-peterson ?

Include option for serializing a structure

This can currently be achieved by:

    {
        public static EventContext IncludeStructure(this EventContext eventContext, object structure, string keyPrefix = null, bool includeNullValues = true)
        {
            if (structure != null)
            {
                foreach (var property in from property in structure.GetType().GetProperties().Where(p => p.CanRead)
                                         let sensitiveDataAttribyte = property
                                                                          .GetCustomAttributes(typeof (SensitiveDataAttribute), false)
                                                                          .FirstOrDefault() as SensitiveDataAttribute
                                         where sensitiveDataAttribyte == null
                                         select property)
                {
                    try
                    {
                        var val = property.GetValue(structure, null);
                        if (val == null && !includeNullValues)
                        {
                            continue;
                        }
                        string key = string.IsNullOrEmpty(keyPrefix)
                                         ? property.Name
                                         : string.Format("{0}_{1}", keyPrefix, property.Name);
                        eventContext[key] = val;
                    }
                    catch // intentionally squashed
                    {
                    }
                }
            }

            return eventContext;
        }
    }```

6.1

Proposed feature-set for 6.1:

• Set(key, val, Condition.IfNotExists)
• Ditch custom synchronization code in favor of built-in concurrent collections

Introduce prioritization for short log values

In a situation where a log is overlong and the underlying log capture ssystem is forced to cut off the log, prioritizing "short" values in favor of "long" ones will maximize the count of KV pairs that are included in the log message.

Addressed by #26

NLog provider package can target lower version of net standard

NLog targets 1.3, can probably match this. This would make the project more universally compatible (i.e. not require .NET 4.6)