.Net Core Documentation

Reading time: 12 minutes

An example

Suppose you're measuring values coming from a car. This is what that could look like:

module Bicycle.SupervisorProcess
open Logary
open Logary.Message

// "the sensor"
let logger = Log.create "Car.SupervisorProcess"

let tyreTick () =
  // "the event is triggered, e.g. via a polling supervisor"
  logger.info (
    eventX "Tyres"
    >> addGauge "front" (Gauge (Float 79.2421, Units.Pascal)))
    >> addGauge "back" (Gauge (Float 90.159, Units.Pascal)))

Passing values around

Context is generally classified into these categories: (you can try these code on test.fsx in Logary.Tests)

Fields

prefix with "_fields."

Fields are the structured data when you use structure logging like (https://messagetemplates.org/), there are mainly two style to achieve this.

open Logary
open Logary.Message

type SomeInfo() =
  member x.PropA =
    45
  member x.PropB =
    raise (Exception ("Oh noes, no referential transparency here"))
with
  interface IFormattable with
    member x.ToString (format, provider) = "PropA is 45 and PropB raise exn"

let oneObj = SomeInfo ()

eventFormat (Info, "Hey {userName}, here is a default {info} and stringify {$info} and destructure {@info}", "You", oneObj)
  |> setSimpleName "Company.APIModule.calculateTotals"
  |> MessageWriter.levelDatetimeMessagePath.format

// alternative style:

event Info "user write some info"
  |> setField "userName" "You"
  |> setField "data" oneObj
  |> setSimpleName "Company.APIModule.calculateTotals"
  |> MessageWriter.levelDatetimeMessagePath.format

Results in:

val it : string =
  "I 2018-01-26T09:08:21.6590074+00:00: Hey "You", here is a default "PropA is 45 and PropB raise exn" and stringify "FSI_0002+SomeInfo" and destructure SomeInfo { PropB: "The property (PropB) accessor threw an (TargetInvocationException): Oh noes, no referential transparency here", PropA: 45 } [Company.APIModule.calculateTotals]
  fields:
    info =>
      SomeInfo {
        PropB => "The property (PropB) accessor threw an (TargetInvocationException): Oh noes, no referential transparency here"
        PropA => 45}
    userName => "You""

Gauges

prefix with "_logary.gauge."

which value is Gauge(float, units). An instantaneous value. Imagine the needle showing the speed your car is going or a digital display showing the same instantaneous metric value of your car's speed.

you can add gauges with one message, or use gauge as the message. The difference between them is, if you use gauges as the message, the value in message are auto generate by gauges when formatting them :

type User =
  {
    id      : int
    name    : string
    created : DateTime
  }

let date20171111 =  DateTime.Parse("2017-11-11")
let foo () = { id = 999; name = "whatever"; created = date20171111}


let ex = exn "exception with data in it"
ex.Data.Add ("data 1 in exn", 1)
ex.Data.Add ("data foo in exn", foo ())
ex.Data.Add (foo(), foo())

Message.event Error "ouch"
|> Message.addExn ex
|> Message.addExn (exn "another exception")
|> Message.setSimpleName "somewhere.this.message.happened"
|> MessageWriter.levelDatetimeMessagePathNewLine.format

val it : string =
  "E 2018-01-26T09:30:37.7648557+00:00: ouch [somewhere.this.message.happened]
  others:
    _logary.errors =>
      -
        System.Exception {
          Message => "another exception"
          HResult => -2146233088}
      -
        System.Exception {
          Message => "exception with data in it"
          Data =>
            "data 1 in exn" => 1
            "data foo in exn" =>
              User {
                name => "whatever"
                id => 999
                created => 11/11/2017 12:00:00 AM}
            - key =>
                User {
                  name => "whatever"
                  id => 999
                  created => 11/11/2017 12:00:00 AM}
              value =>
                User {
                  name => "whatever"
                  id => 999
                  created => 11/11/2017 12:00:00 AM}
          HResult => -2146233088}
"

SinkTargetNames

prefix with "_logary.sink.targets"

They are generally are set by Events Processing, you can define which targets (sinks) your message will go. if not set, message will go to all targets and let the targets themself to decide whether or not to accept it.

let pipeLine =
   Events.events
   |> Events.tag "queue"
   |> Pipe.map (fun msg -> {msg with value = "https://github.com/alexandrnikitin/MPMCQueue.NET"})
   |> Events.sink ["nice console"]

let logm =
  Config.create "svc" "localhost"
  |> Config.target (Targets.Console.create Targets.Console.empty "my console target")
  |> Config.target (Targets.LiterateConsole.create Targets.LiterateConsole.empty "nice console")
  |> Config.processing pipeLine
  |> Config.build
  |> run

let lg = logm.getLogger (PointName.parse "give.some.example.here")

Message.event Info "MPMCQueue"
|> Message.tag "queue"
|> Message.tag "high-performance"
|> Message.tag "lock-free"
|> Message.tag "multiple-consumers"
|> lg.logSimple

this will only show on LiterateConsole, not normal Console.

SinkTargetNames

things you don't want to show on the message value, but show on the backstore. e.g: some structured data not belong the message template or data you can use in the EventProcessing Pipeline.

Message.eventFormat (Info, "{userId} create an shopping list at {createdTime}", "9999", DateTime.Now )
|> Message.setContext "user name" ":)"
|> Message.setContext "shopping list" ["cat";"cat food";"books";"drinks"]
|> Message.setSimpleName "somewhere.this.message.happened"
|> MessageWriter.levelDatetimeMessagePath.format

val it : string =
  "I 2018-01-26T10:11:54.5221326+00:00: "9999" create an shopping list at 1/26/2018 6:11:54 PM [somewhere.this.message.happened]
  fields:
    userId => "9999"
    createdTime => 1/26/2018 6:11:54 PM
  others:
    user name => ":)"
    shopping list => ["cat", "cat food", "books", "drinks"]"

Filtering logs

A logger have a minimum level which message's level below it is not processed when logging these message. Can give us Low overhead logging – evaluate your Message only if a level is switched on. Especially when you use logging api with message factory.

A logger's minimum level are config through Config.loggerMinLevel "a.b.*" LogLevel.Fatal on logary conf (usually globally) use a specific name or some hierarchy path. And can be switch on fly logm.switchLoggerLevel ("a.b.*", LogLevel.Info),this will only affect the loggers (its name, not its instance) which have been created beafore. e.g. the default level is Error on prod, use a pipe line detect an error message, switch to Info for 5 mins then change it back. can be use for auto collecting more useful info when things goes wrong.

let someRuleOnTarget =
  Rule.empty
  |> Rule.setMinLevel LogLevel.Error // this target will only get message about error level (inclusive)
  |> Rule.setPath (System.Text.RegularExpressions.Regex("a.b.c.*")) // only accept message name under a.b.cxxxxx
  |> Rule.setAcceptIf (fun msg -> msg |> Message.hasTag "emergency")

let tconf =
  Targets.LiterateConsole.create Targets.LiterateConsole.empty "nice console"
  |> TargetConf.addRule someRuleOnTarget
let logm =
  Config.create "svc" "localhost"
  |> Config.target tconf
  |> Config.loggerMinLevel "a.b.*" LogLevel.Fatal  // logger under a.bxxxx path only process Fatal message
  |> Config.loggerMinLevel "a.b.c.*" LogLevel.Info // logger under a.b.cxxxx path can process message above Info
  |> Config.build
  |> run

let abc = logm.getLogger (PointName.parse "a.b.cxxx")
let ab = logm.getLogger (PointName.parse "a.bxxx")

abc.verbose (Message.eventX "abc.Info" >> fun msg -> printfn "invoke %s" msg.value; msg) // no invoke
abc.error (Message.eventX "abc.Error" >> fun msg -> printfn "invoke %s" msg.value; msg) // invoke, but will not go to target
abc.error (Message.eventX "abc.Error with emergency tag" >> (fun msg -> printfn "invoke%s" msg.value; msg) >> Message.tag "emergency") // hurray

ab.error (Message.eventX "ab.Error" >> (fun msg -> printfn "invoke %s" msg.value; msg) >> Message.tag "emergency") // no invoke
ab.fatal (Message.eventX "ab.Fatal" >> (fun msg -> printfn "invoke %s" msg.value; msg) >> Message.tag "emergency") // hurray

> abc.verbose (Message.eventX "abc.Info" >> fun msg -> printfn "invoke %s" msg.value; msg) // no invoke
- ;;
val it : unit = ()

> abc.error (Message.eventX "abc.Error" >> fun msg -> printfn "invoke %s" msg.value; msg) // invoke, but will not go to target
- ;;
invoke abc.Error
val it : unit = ()

> abc.error (Message.eventX "abc.Error with emergency tag" >> (fun msg -> printfn "invoke%s" msg.value; msg) >> Message.tag "emergency") // hurray
- ;;
invokeabc.Error with emergency tag
val it : unit = ()

> [19:06:33 ERR] abc.Error with emergency tag <a.b.cxxx>
  others:
    _logary.host => "localhost"
    _logary.service => "svc"
    _logary.tags => ["emergency"]

> ab.error (Message.eventX "ab.Error" >> (fun msg -> printfn "invoke %s" msg.value; msg) >> Message.tag "emergency") // no invoke
- ;;
val it : unit = ()

> ab.fatal (Message.eventX "ab.Fatal" >> (fun msg -> printfn "invoke %s" msg.value; msg) >> Message.tag "emergency") // hurray
- ;;
invoke ab.Fatal
[val19:07:45  FTLit]  ab.Fatal:  unit<a.bxxx>
  others:
    _logary.host => "localhost"
    =_logary.service => "svc"
    _logary.tags  => ["emergency"]

Log levels

The highest log level is Fatal, which should be reserved for things that make your service/process crash. Things like; "my disk is full and I'm a database trying to start", or "I'm a 2-tier service built with a database, that I cannot do any work without" warrant the Fatal level.

The next level is Error, which should be reserved for what you consider to be edge-cases. E.g. if the data received from a socket is corrupt, or there was an unhandled exception that you as a programmer did not have in your mental model while writing the code. These events should be logged at the Error level.

At this level human beings are normally directly alerted.

Warn is for things like 100 failed password attempts within 5 minutes, for one of your users, or a temporary network glitch while communicating with a "resource" such as your database.

If these events for an anomaly persist over time, humans may be alerted.

At Info level, I like to put events and gauges that measure company-relevant stuff, like when users sign in, sign up, an integration has to perform a retry or a service was started/restarted.

Debug level is the default level and the work-horse. You normally log all metrics at this level.

Verbose is the level when you want that little extra. Not normally enabled.

Logging from modules

Let's say you have a module in your F# code that you want to log from. You can either get a logger like shown in Hello World, or you can do something like this:

module MyCompany.Sub.MyModule

open Logary

let logger = Logging.getCurrentLogger ()

let logInUser () =
  // do something
  Message.event Info "User logged in" |> Logger.logSimple logger
  // do more stuff

If you want to name your logger with a specific name, you can use Logging.getLoggerByName instead. (This is different for the Facade file)

Logging from classes

Similarly, sometimes you want to log from a class, and perhaps log some metrics too.

namespace MyCompany.Sub

open Logary

type Worker() =
  let logger =
    Logging.getLoggerByName "MyCompany.Sub.Worker"

  let workName =
    PointName [| "MyCompany"; "Sub"; "Worker"; "workDone" |]

  let getAnswers (amount : float) =
    // work work work
    42 * amount

  member x.Work (amount : float) =
    // Initially, log how much work is to be done
    // the only "supported" metric is a gauge (a value at an instant)
    Message.gauge workName amount |> Logger.logSimple logger

    // do some work, logging how long it takes:
    let everything = Logger.time logger (fun () -> getAnswers amount)

    // return result
    everything

In this example you learnt how to send arbitrary metrics to Logary (the gauge) and also how to time how long certain method calls take in your system.

Make it a habit to log these sort of gauges all over your code base while you write your code, to make it much easier to understand the system as it develops.

In fact, the more you do this, the more use you will have of Logary and of the dashboard you put up in Kibana (via Logstash) or Grafana (via InfluxDb). Put it up on a big TV in your office and you'll develop a second sense of whether the system is doing well or not, just from looking at the graphs.

Structured logging and interpolation

The templates syntax can be found here:

Message Templates are a superset of standard .NET format strings, so any format string acceptable to string.Format() will also be correctly processed by logary.

Property names are written between and braces
Formats that use numeric property names, like 0 and 1 exclusively, will be matched with the Format method's parameters by treating the property names as indexes; this is identical to string.Format()'s behaviour
If any of the property names are non-numeric, then all property names will be matched from left-to-right with the Format method's parameters
Property names may be prefixed with an optional operator, @ or $, to control how the property is serialised
Property names may be suffixed with an optional format, e.g. :000, to control how the property is rendered; these format strings behave exactly as their counterparts within the string.Format() syntax

Per-process event processing

Sometimes you need a metric that runs continuously over time. A Ticker can be seems as a metric, it can be auto triggered or by manually. A ticker can be chained in an pipe line (EventProcessing).

We have some windows performance counter metrics that you can use.

But you sometimes want to chain metrics from events or gauges happening inside your own application.

We have some windows performance counter metrics that you can use.

module Program

open System
open System.Threading
open Hopac
open Logary
open Logary.Configuration
open NodaTime
open Logary.Targets
open Logary.Metrics.WinPerfCounters
open Logary.EventProcessing

module Sample =

  let randomWalk pn =
    let reducer state = function
      | _ ->
        state

    let ticker (rnd : Random, prevValue) =
      let value =
        let v = (rnd.NextDouble() - 0.5) * 0.3
        if abs v < 0.03 then rnd.NextDouble() - 0.5
        elif v + prevValue < -1. || v + prevValue > 1. then -v + prevValue
        else v + prevValue

      let msg = Message.gauge pn value

      (rnd, value), msg

    let state =
      let rnd = Random()
      rnd, rnd.NextDouble()

    Ticker.create state reducer ticker

[<EntryPoint>]
let main argv =
  let inline ms v = Duration.FromMilliseconds (int64 v)
  let pn name = PointName [| "Logary"; "Samples"; name |]
  use mre = new ManualResetEventSlim(false)
  use sub = Console.CancelKeyPress.Subscribe (fun _ -> mre.Set())
  let clock = SystemClock.Instance
  let tenSecondsEWMATicker = EWMATicker (Duration.FromSeconds 1L, Duration.FromSeconds 10L, clock)
  let randomWalk = Sample.randomWalk "randomWalk"
  let walkPipe =  Events.events |> Pipe.tickTimer randomWalk (TimeSpan.FromMilliseconds 500.)
  let systemMetrics = Events.events |> Pipe.tickTimer (systemMetrics (PointName.parse "sys")) (TimeSpan.FromSeconds 10.)
  let processing =
    Events.compose [
       walkPipe
       |> Events.sink ["WalkFile";]

       walkPipe
       |> Pipe.choose (Message.tryGetGauge "randomWalk")
       |> Pipe.counter (fun _ -> 1L) (TimeSpan.FromSeconds 2.)
       |> Pipe.map (fun counted -> Message.eventFormat (Info, "There are {totalNumbers} randomWalk within 2s", [|counted|]))
       |> Events.sink ["Console";]

       walkPipe
       |> Pipe.choose (Message.tryGetGauge "randomWalk")
       |> Pipe.map (fun _ -> 1L) // think of randomWalk as an event, mapping to 1
       |> Pipe.tickTimer tenSecondsEWMATicker (TimeSpan.FromSeconds 5.)
       |> Pipe.map (fun rate -> Message.eventFormat (Info, "tenSecondsEWMA of randomWalk's rate is {rateInSec}", [|rate|]))
       |> Events.sink ["Console";]

       systemMetrics
       |> Pipe.map Array.toSeq
       |> Events.flattenToProcessing
       |> Events.sink ["LiterateConsole"; "WPCMetricFile";]
    ]

  let console = Console.create Console.empty "Console"
  let literalConsole = LiterateConsole.create LiterateConsole.empty "LiterateConsole"
  let randomWalkFileName = File.Naming ("{service}-RandomWalk-{date}", "log")
  let wpcFileName = File.Naming ("{service}-wpc-{date}", "log")
  let randomWalkTarget = File.create (File.FileConf.create Environment.CurrentDirectory randomWalkFileName) "WalkFile"
  let wpcFileTarget = File.create (File.FileConf.create Environment.CurrentDirectory wpcFileName) "WPCMetricFile"
  let logary =
    Config.create "Logary.Examples.MetricsWriter" "localhost"
    |> Config.targets [console; literalConsole; randomWalkTarget; wpcFileTarget;]
    |> Config.ilogger (ILogger.Console Verbose)
    |> Config.processing processing
    |> Config.build
    |> run

  mre.Wait()
  0

By wrapping it up like this, you can drastically reduce the amount of code a given service sends by pre-computing much of it.

It's also a good sample of reservoir usage; a fancy name of saying that it's an algorithm that works on more than one gauge at a time, to produce a derived metric.

LogaryAnalytics

.Net Core Documentation

An example

Passing values around

Fields

Gauges

Tags

SinkTargetNames

SinkTargetNames

Filtering logs

Log levels

Logging from modules

Logging from classes

Structured logging and interpolation

Per-process event processing