Serilog.Assert 0.5.0-pre1

Log.Assert( less is "More. More useful logging with less code.")

Log.Assert and Serilog.Assert add assertion-style application logging to ILogger.

public string GoBang(string target, int guess)
{
    log.Me();
    log.PreconditionNotNull(target);

    var graphemes = new StringInfo(target??"");
    log.Assert(graphemes.LengthInTextElements > 0);
    log.Precondition(0 <= guess && guess <= graphemes.LengthInTextElements);

    log.ExceptionAndThrowIf(
        graphemes.SubstringByTextElements(guess,1) is "💥",
        new ApplicationException("bang!"));

    var remainder = Remove(graphemes,guess);
   
    log.DebugIf(remainder.Length == 0,"TBC:is this permitted?");
    log.If(graphemes.LengthInTextElements > 0,
              usefulState: (target,guess,graphemes.LengthInTextElements),
              label: "Remaining after Removal");

    log.PreconditionNotNull(target);
    log.Postcondition(remainder.Length < target.Length);
    log.Me(remainder);
    return remainder;
}

What is Logged?

• All methods log the current method or member name.
• Assertions, Pre-, and Post-Conditions log nothing at all if they pass.
• Assertions, Pre-, and Post-Conditions log the literal failed expression if they fail.
• log.If() methods log nothing at all if the condition is false
• log.If() methods log the literal condition expression if it is true
• All methods can log additional information, either auto-labelled or explicitly labelled.

Do log.Assertions throw?

No, they log. Traditionally, assertions are stripped out for release, and take effect only when code is compiled in debug mode. Log.Assert strongly encourages you to instead keep the assertions and log the failures. (We do also provide log.AssertElseThrow() methods, which throw on failure).

Do I have to use pre- and post-conditions everywhere now?

No, you don't.

Example output

Depending on your logger configuration, the default templates output something like:

INF] GoBang
ERR] GoBang:Precondition Not Null Failed:target
ERR] GoBang:Assertion Failed:graphemes.LengthInTextElements > 0:
ERR] GoBang:Precondition Failed:0 <= guess && guess <= graphemes.LengthInTextElements
INF] GoBang:graphemes.LengthInTextElements > 0:Remaining after Removal:(12🍾4💥, 1, 5)
ERR] GoBang:Postcondition Failed:0 <= guess && guess <= graphemes.LengthInTextElements
INF] GoBang(remainder=1🍾4💥)

Structured Logging Properties

The default properties sent to structured logging are:

• All methods log the current method or member name as a string {Action}.
• Assertions, Pre-, and Post-Conditions log their {Assertion} as a literal code string, and the value of their {Subject}.
• log.If() and log.IfNot() methods log their {Condition} as a literal code string
• All methods log optional usefulState as an object {State} and a string {Label}
• Exceptions log {Exception} just as the frameworks normally do.

{Subject} and {State} are the only complex properties, everything else is a string.

Automatic {Action} and {Label} values can be overridden inline:

log.Me(state, label:"Not the auto-generated label", action:"Not the method name")

Log Multiple Additional Structured Properties by Passing an Anonymous Object

If you pass an anonymous object as usefulState, each of its properties is logged as a separate named structured logging property.searchable and filterable in your log aggregator:

log.If(orderReady, new { OrderId = order.Id, CustomerId = customer.Id });
// Structured properties: {Action}, {Condition}, {OrderId}, {CustomerId}

log.Assert(balance >= 0, new { AccountId = id, Balance = balance });
// On failure, structured properties: {Action}, {Assertion}, {AccountId}, {Balance}

log.Me(new { RequestId = correlationId, Elapsed = sw.ElapsedMilliseconds });
// Structured properties: {Action}, {RequestId}, {Elapsed}

Example output:

INF] ProcessOrder:orderReady:OrderId=ORD-123, CustomerId=42
ERR] Withdraw:Assertion Failed:balance >= 0:AccountId=acct-7, Balance=-5
INF] HandleRequest(RequestId=corr-abc, Elapsed=47)

Otherwise, if usefulState is anything but an anonymous object, it will be logged as a single property with the name State, and the label will be logged as a string property with the name Label.

Changing the Template Strings and Structured Property Names

To change the message templates, and the property names used for structured logging, set the properties of the static class TemplateStrings to the strings and property names you want.

For instance if you set

TemplateStrings.Me = "{MethodName}({Title}{Info})";

Then log.Me(param1) will result in structured logging properties:

{MethodName} = "<Method or member name>"
{Title} = "param1"
{Info} = <value of param1>

instead of the default {Action},{Label},{State}.

The default template strings are stored as constants in TemplateStrings.Defaults.

Log Level

• Assertions, Pre-, and Post-Conditions log at level Error.
• Other methods default to logging at level Information, with named methods for other log levels (see the full list below).
• Exceptions log at level Error by default.

All Methods

All methods accept an optional additonal usefulState parameter, and an optional label for it.

log.Me()
log.MeDebug()
log.MeTrace()   //Log.Assert
log.MeVerbose() //Serilog.Assert
log.MeWarning()
log.MeError()

log.Assert()
log.AssertNotNull()
log.AssertNotNullOrEmpty()
log.AssertNotNullOrWhitespace()

log.Precondition()
log.PreconditionNotNull()
log.PreconditionNotNullOrEmpty()
log.PreconditionNotNullOrWhitespace()

log.Postcondition()
log.PostconditionNotNull()
log.PostconditionNotNullOrEmpty()
log.PostconditionNotNullOrWhitespace()

log.AssertElseThrow()
log.AssertNotNullElseThrow()

log.PreconditionElseThrow()
log.PreconditionNotNullElseThrow()

log.PostconditionElseThrow()
log.PostconditionNotNullElseThrow()

log.If()
log.InformationIf()
log.DebugIf()
log.TraceIf()   //Log.Assert
log.VerboseIf() //Serilog.Assert
log.WarnIf()
log.ErrorIf()
log.CriticalIf() //Log.Assert
log.FatalIf()    //Serilog.Assert

log.IfNot()
log.InformationIfNot()
log.DebugIfNot()
log.TraceIfNot()    //Log.Assert
log.VerboseIfNot()  //Serilog.Assert
log.WarnIfNot()
log.ErrorIfNot()
log.CriticalIfNot() //Log.Assert
log.FatalIfNot()    //Serilog.Assert

log.Exception()
log.ExceptionIf()
log.ExceptionAndThrow()
log.ExceptionAndThrowIf()
log.CriticalThenThrow()                       //Log.Assert
log.CriticalExceptionThenExitProcessWithCode() //Log.Assert
log.FatalThenThrow()                          //Serilog.Assert
log.FatalExceptionThenExitProcessWithCode()   //Serilog.Assert

Logging additional usefulState

//Use a ValueTuple or anonymous object to log multiple items of additional state 
log.Me( (this,that,other) );

// By default the log line will auto-label the state:
"MethodName:(this,that,other)=(value1,value2,value3)"

// You can explicitly label the state:
log.Me( (this,that,other), "Checkpoints 1 to 3")
"MethodName:Checkpoints 1 to 3=(value1,value2,value3)"

// additional state can be just a comment:
log.Me("Comment ...")
"MethodName:Comment ..."

What about performance?

For applications where the billionths of a second it takes to compute an assertion success are more critical than visibility of assertion failures, then you will not want to use logging assertions, you can use traditional assertions instead. Programs running on shared virtual infrastructure or making a network call do not fall into this category.

Billionth of a second?

I reckon a typical boolean assertion in a hotspot in a running program won't go beyond your processor's L2 cache, so we're talking clock cycles — nanoseconds, not milliseconds.

Reference and Inspiration

Logging production assertion failures can be an eye-opener. Jim Coplien made this point some years ago in his paper, Most Unit Testing is Waste. Why would you test only in a unit test run? Test in production too, it's what the pros do. (I offer no opinion on whether his title is statistically true. Obviously none of my unit tests are waste, because I deleted the pointless ones).

Proofs of program correctness have not been as fashionable as automated testing for the past thirty years. Now is your chance to join the trendsetters before everyone is doing it.