roq-logging

Logging is always to stdout and stderr.

Format

The output format is similar to that used by GLOG.

I0812 03:41:59.012292 120952 producer.cpp:405] Write 1048576 byte(s) (consumed=133169712 produced=20410983 ratio=0.15)

  • The first letter indicates

    • I=INFO

    • W=WARNING

    • E=ERROR

    • C=CRITICAL (=FATAL)

  • Next four letters indicate month (08=August) and day of month (12)

  • Then follows the UTC timestamp with microsecond precision

  • Then follows the thread ID

  • Then follows the filename and line number from which the logging originated

    • The filename does not include the path only to keep the log line shorter

  • Then follows the right square bracket to separate informational content from the actual log message

  • Then the log message

Environment Variables

Defining ROQ_v instructs the logger to set the verbosity level.

Setting ROQ_v=0 will report verbosity level 0. Setting ROQ_v=1 will report verbosity level 0 and 1. And so on.

The default verbosity level is 0 (if the variable has not been defined).

The following log types will always be reported: FATAL, ERROR, WARNING and INFO.

Performance and Latency

The logger is synchronous if the program is associated with a terminal.

The logger is asynchronous if the program does not have an associated terminal, e.g. if managed by systemd or Docker.

Asynchronous logging is critical for latency sensitive applications: the unpredictable write operations are completely isolated.

Note

All logging involves extra latency due to formatting of the log message. However, formatting has a mostly predictable latency profile. The most unpredictable part of logging is the interaction with file descriptors; hence the offloading to a secondary thread. Also, using the verbosity level is a way of avoiding even the cost of formatting.

Conventions

These are not strict rules, only guidelines

  • ROQ_v=0 for truly latency sensitive applications with virtually no logging.

  • ROQ_v=1 for a reasonably latency sensitive application with some support for operational investigations.

  • ROQ_v=2, ROQ_v=3, etc. when debugging issues.

Note

Although a human readable log may not be generated for ROQ_v=0, a binary event log is always generated (also on a secondary thread). The event log captures all important events required for operational investigations. However, there is obviously more work involved with extracting the information compared to simply reading a log file. All this to say that operational support is still possible when using ROQ_v=0.

log::critical

log::fatal(...)

Indicative of a violated assumption.

The default action is log a backtrace and abort the program. (A core dump might be generated at this point).

log::warn

log::warn(...)

Useful for e.g. debugging performance issues (could be a warning about latency).

The convention is to log warnings when something unusual happens, e.g. bad data, disconnects, etc.

log::info, log::info<0>

log::info(...)

Indicate normal progress of the program.

The convention is to log relevant information until a latency sensitive program path is running.

These log messages will always be created and should therefore kept to a minimum for any latency sensitive code.

log::info<1>

log::info<1>(...)

Used for important messages, e.g. roq::CreateOrder and roq::OrderUpdate.

It should be possible to turn these off (ROQ_v=0) for truly latency sensitive applications. However, it is normally desirable to log these messages for operational support.

log::info<2>

log::info<2>(...)

Used for non-important messages.

log::info<3>

log::info<3>(...)

Frequent and non-important messages, e.g. roq::MarketByPriceUpdate.

log::info<4>

log::info<4>(...)

Low level debugging, e.g. heartbeat, transport, etc.