package logs

Logging.

Logs provides a basic logging infrastructure. Logging is performed on sources whose reporting level can be set independently. Log message report is decoupled from logging and handled by a reporter.

See the basics, a few usage conventions to respect and a note on synchronous logging.

v0.6.2 - homepage

Reporting levels

Log sources

Log functions

Logging result value Errors

Source specific log functions

Reporters

Logs monitoring

Basics

Logging

In order to minimize the overhead whenever a log message is not reported, message formatting only occurs on actual message report via the message formatting function you provide to log functions. This leads to the following logging structure:

let k, v = ... in
Logs.err (fun m -> m "invalid kv (%a,%a)" pp_key k pp_val v);
Logs.err (fun m -> m "NO CARRIER");

The pattern is quite simple: it is as if you were formatting with a printf-like function except you get this function in the m argument of the function you give to the logging function.

If you want to abstract a repeated log report it is better to keep the message formatting function structure for the arguments of the messages. Here's how the above examples can be abstracted and invoked:

let err_invalid_kv args =
  Logs.err @@ fun m ->
  args (fun k v -> m "invalid kv (%a,%a)" pp_key k pp_val v)

let err_no_carrier args =
  Logs.err @@ fun m -> args (m "NO CARRIER")

let () =
  err_invalid_kv (fun args -> args "key" "value");
  err_no_carrier (fun () -> ());
  ()

Note that log messages are formatted and hit the reporter only if they have not been filtered out by the current reporting level of the source you log on. See also the log source and reporting level usage conventions.

Reporter setup

If you are writing an application you must remember to set the reporter before any logging operation takes place otherwise no messages will be reported. For example if you are using the formatter reporter, logging can be setup as follows:

let main () =
  Logs.set_reporter (Logs_fmt.reporter ());
  ...
  exit (if Logs.err_count > 0 then 1 else 0);
  ()

If you have logging code that is performed in the toplevel initialization code of modules (not a good idea) or you depend on (bad) libraries that do so, you must call and link the reporter install code before these initialization bits are being executed otherwise you will miss these messages.

The documentation of Logs_cli module has a full setup example that includes command line options to control color and log reporting level.

If you are writing a library you should neither install reporters, nor set the reporting level of sources, nor log on the default source or at the App level; follow the the usage conventions. A library should simply log on an another existing source or define its own source like in the example below:

let src = Logs.Src.create "mylib.network" ~doc:"logs mylib's network events"
module Log = (val Logs.src_log src : Logs.LOG)

The Log module defines logging functions that are specific to the source src.

Usage conventions

A library should never log on the default source or at the App level these are reserved for use by the application. It should either create a source for itself or log on the source defined by one of its dependencies. It should also never set the reporting level of the sources it deals with or install reporters since control over this must be left to the application.

The semantics of reporting levels should be understood as follows:

• App, this level can be used for the standard output or console of an application. It should never be used by libraries.
• Error, error condition that prevent the program from running normally.
• Warning, suspicious condition that does not prevent the program from running normally but may eventually lead to an error condition.
• Info, condition that allows the program user to get a better understanding of what the program is doing.
• Debug, condition that allows the program developer to get a better undersanding of what the program is doing.

Note on synchronous logging

In synchronous logging, a client call to a log function proceeds only once the reporter has finished the report operation. In Logs this depends both on the reporter and the log functions that the client uses.

Whenever the client uses a log function that results in a report, it gives the reporter a continuation that defines the result type of the log function and a callback to be called whenever the log operation is over from the reporter's perspective (see reporter). The typical use of the callback is to unblock the continuation given to the reporter. This is used by Logs_lwt's log functions to make sure that the threads they return proceed only once the report is over. In the functions of Logs however the callback does nothing as there is no way to block the polymorphic continuation.

Now considering reporters, at the extreme we have:

• A completely asynchronous reporter. This reporter formats the message in memory and immediately invoke the callback followed by the continuation. This provides no guarantee of persistency in case a crash occurs. All log functions behave asynchronously and return as soon as possible.
• A completely synchronous reporter. This reporter formats the message, persist it, invoke the client callback followed by the continuation. All log functions behave synchronously. An example of such a reporter is reporter with formatters baked by channels: when formatting returns the message has been written on the channel.

However a purely synchronous reporter like reporter acting on channels does not play well with Lwt's cooperative runtime system. It is possible to reuse reporter to define a cooperative reporter, see this example. However while this reporter makes Logs_lwt's log functions synchronous, those of Logs behave asynchronously. For now it seems it that this is unfortunately the best we can do if we want to preserve the ability to use Logs with or without cooperative concurency.

Example with custom reporter and tags

This example uses a tag to attach Mtime time spans in log messages. The custom reporter uses these time spans to format relative timings for runs of a given function. Note that as done below the timings do include logging time.

let stamp_tag : Mtime.span Logs.Tag.def =
  Logs.Tag.def "stamp" ~doc:"Relative monotonic time stamp" Mtime.pp_span

let stamp c = Logs.Tag.(empty |> add stamp_tag (Mtime.count c))

let run () =
  let rec wait n = if n = 0 then () else wait (n - 1) in
  let c = Mtime.counter () in
  Logs.info (fun m -> m "Starting run");
  let delay1, delay2, delay3 = 10_000, 20_000, 40_000 in
  Logs.info (fun m -> m "Start action 1 (%d)." delay1 ~tags:(stamp c));
  wait delay1;
  Logs.info (fun m -> m "Start action 2 (%d)." delay2 ~tags:(stamp c));
  wait delay2;
  Logs.info (fun m -> m "Start action 3 (%d)." delay3 ~tags:(stamp c));
  wait delay3;
  Logs.info (fun m -> m "Done." ?header:None ~tags:(stamp c));
  ()

let reporter ppf =
  let report src level ~over k msgf =
    let k _ = over (); k () in
    let with_stamp h tags k ppf fmt =
      let stamp = match tags with
      | None -> None
      | Some tags -> Logs.Tag.find stamp_tag tags
      in
      let dt = match stamp with None -> 0. | Some s -> (Mtime.to_us s) in
      Format.kfprintf k ppf ("%a[%0+04.0fus] @[" ^^ fmt ^^ "@]@.") dt
        Logs.pp_header (level, h) dt
    in
    msgf @@ fun ?header ?tags fmt -> with_stamp header tags k ppf fmt
  in
  { Logs.report = report }

let main () =
  Logs.set_reporter (reporter (Format.std_formatter));
  Logs.set_level (Some Logs.Info);
  run ();
  run ();
  ()

let () = main ()

Here is the standard output of a sample run of the program:

[INFO][+000us] Starting run
[INFO][+168us] Start action 1 (10000).
[INFO][+206us] Start action 2 (20000).
[INFO][+243us] Start action 3 (40000).
[INFO][+303us] Done.
[INFO][+000us] Starting run
[INFO][+012us] Start action 1 (10000).
[INFO][+038us] Start action 2 (20000).
[INFO][+074us] Start action 3 (40000).
[INFO][+133us] Done.