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

    • 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 smaller

  • 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, 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(FATAL)

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(WARNING)

LOG(WARNING)(...)

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), VLOG(0)

LOG(INFO)(...)
VLOG(0)(...)

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.

VLOG(1)

VLOG(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.

VLOG(2)

VLOG(2)(...)

Used for non-important messages.

VLOG(3)

VLOG(3)(...)

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

VLOG(4)

VLOG(4)(...)

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