Design of a Logging System

Here is design of a logging system that provides a convenient way to trace the execution of a long running program with arbitrary format strings and data, serialized to a compact binary file.

It needs to store the following information per emitted data record:

• executable image magic which identifies the logdef table used.
• __FILE__ (via logdef table)
• __LINE__
• backtrace() (an array of machine words, looked up via logdef table)
• pthread_self()
• log level
• current time from gettimeofday()
• format string (printf formatted, via logdef table)
• format string arguments (all types accepted by printf, no logdef lookup)

The log will contain the following record types:

• Preamble: stores the full path to the executable image and its content fingerprint (size + {md5 or sha1}) so that corrupted logdefs can be reconstructed. Also stores the magic derived from the fingerprint.
• String logdef: a "log definition" for magic × uintptr_t -> string, for __FILE__ and format string lookup.
• Backtrace logdef: a "log definition" for magic × uintptr_t -> {dli_fname: string, dli_fbase: uintptr_t, dli_sname: string, dli_saddr: uintptr_t} as returned by dladdr(), for backtrace lookup.
• Data record, as described above.

Log files may be arbitrarily concatenated. In that case, the logdef table id which is the same as the executable image fingerprint magic will allow each data record to be interpreted using a different set of logdefs. The preambles may be corrupted also. If both the preamble and logdefs are corrupted, a data record may have missing interpretations.

Logdefs are emitted lazily. The logging system in process maintains a smaller lookup table that tracks whether a logdef has already been emitted. The logdef should immediately precede the data record that references it.

The log serialization format is based on msgpack. A log file consists of frames. Each frame is the sequence:

• 0xc1 | crc32 | 0xc1 | raw_record

Note that 0xc1 is reserved in msgpack, the value between nil (0xc0) and boolean false (0xc2).

The crc32 is the CRC32 for the bytes inside raw_record, as msgpack object uint32_t (0xce).  A raw_record is a msgpack raw object, either fixraw (0xa0—0xbf), raw16 (0xda) or raw32 (0xdb) that frames a record. This structure, along with the reserved 0xc1, can be used to re-sync to frames in case the log file is corrupted.

Each record is simply two msgpack objects concatenated.

• tag | payload

Tag is a simple positive fixnum indicating the record type, preamble (0), string logdef (1), backtrace logdef (2), data (127). The payload depends on the record type. Payloads are maps (fixmap, map16, map32) with field_tag to field_value mapping. Fields are specific to record type, but the payload being a map allows a field to be optional, in a similar vein to protocol buffer messages.