VIP 23: Refactor VSL to support extracting structured data from "binary" log payloads

Synopsis

Instead of formatted log payloads, varnishd writes data into the log in a "raw" format using a relatively small set of data types. This is best illustrated with examples:

• Timestamp: <ASCIIZ><8 byte double><8 byte double><8 byte double>, where ASCIIZ stands for null-terminated ASCII
• (Be)RespStatus: <2 byte uint>
• (Be)ReqAcct: <4 byte uint><4 byte uint><4 byte uint><4 byte uint><4 byte uint><4 byte uint>
• *Header with * in Req, Resp, Bereq, Beresp: <ASCIIZ><ASCIIZ>

The VSL API provides meta-data about the payload contents. This is just suggestive for the purposes of illustration, the actual implementation may end up looking very different:

• Timestamp:
  • label: ASCIIZ
  • t: 8 byte double
  • since_start: 8 byte double
  • since_last: 8 byte double
• RespStatus:
  • value: 2 byte uint
• ReqAcct, BereqAcct:
  • hdr_rx_bytes: 4 byte uint
  • body_rx_bytes: 4 byte uint
  • total_rx_bytes: 4 byte uint
  • hdr_tx_bytes: 4 byte uint
  • body_tx_bytes: 4 byte uint
  • total_tx_bytes: 4 byte uint
• ReqHeader, etc:
  • hdr: ASCIIZ
  • value: ASCIIZ

VSL clients can then make use of this information to extract formatted and possibly structured data from the log, for example in JSON format.

The "legacy" ASCII output for default varnishlog is not changed due to this refactoring. It also does not force any user-visible changes to varnishncsa.

Why?

The proposal results from discussions following the change suggested in PR #2869. The varnishlog -j output suggested there simply moves current ASCII-formatted log payloads into JSON strings, always in a value field. For example:

        {
          "tag": "Timestamp",
          "value": "Fetch: 1542357390.535671 0.000107 0.000107"
        },
        {
          "tag": "RespStatus",
          "value": "200"
        },
        {
          "tag": "ReqAcct",
          "value": "803 0 803 427 4168 4595 803 4595"
        },

But that means that the JSON fields would have to be parsed, for example to get the byte totals from ReqAcct or the epoch time from Timestamp. It also precludes the use of an integer data type for a tag like RespStatus.

The proposed refactoring would:

• make it possible for a VSL client to obtain structured data directly from the log, for example for JSON (but doesn't preclude other structured formats)

• allow foreign language bindings (say a Varnish log reader for Go) to marshal data from the log directly into the other language's native data types

• probably make it possible for VSL clients to interpret log payloads across Varnish versions, when the contents and format change from time to time (if they can consistently read the meta-data across Varnish versions)

• reduce space requirements for the log (8 bytes for a double, for example, are smaller than the 17 bytes + space separator needed to format the epoch time in a Timestamp)

• maybe get varnishd to run a bit faster, since it will do less work to format log payloads

How?

• varnishd log writes will have to be re-written just about everywhere. Some smart macros might help reduce the impact.

  • To avoid a single "monster commit" that changes all log writes at once, the code could support an "intermediate" state that supports both the "old-style" and "new-style" VSL world at the same time. Then it can be a series of smaller commits, changing the code one SLT tag at a time.

• Work out the details of the meta-data interface for VSL.

  • There should be a single "source of truth" for the SLT tags, associated meta-data and docs, from which other sources, include headers and the like are generated. Cf. include/tbl/vsl_tags.h, from which we currently generate the SLT constants and vsl(7) manpage.

• Think about how this affects std.log() and std.timestamp().

• Think about how it affects VMOD use of logging.

  • Consider making it possible for VMOD authors to define their own log meta-data, as is now possible with VSC. Vision: a VMOD defines its own log tags and data structures, and a tool like varnishlog -j will read and format the new record type as specified.

  • But just for the refactoring itself, authors of VSL clients and VMODs will need some guidance for adapting to the change.

  • It's worth keeping in mind that strlen(payload) will not necessarily be the length of the payload after this change (which I believe is always the case now). There won't necessarily be any null-terminated string that can be used appropriately with strlen(), or any of the other str*() functions. Authors of VSL clients and VMODs should be reminded to use VSL_LEN() correctly (although the payload length may become much less relevant, since the meta-data becomes the guide).

• Re-implement varnishlog default output and varnishncsa as the primary proof of concept. All of the vtc tests for the log contents should report no change at all.

• Implement varnishlog -j (JSON output) on this foundation.

Some other considerations:

• Add a new SLT flag, say UNTRUSTED to indicate string log contents that originate either from a client request or a backend response. This is mainly to indicate that we don't know for sure whether a log formatter will need to do additional escaping/quoting.

• Add a BOM byte (inspired by UTF), so that a VSL client can detect the byte order in a binary log file.

• Encapsulate all of the meta-data in a "header" for binary log files, so that clients can read them without having to know the Varnish version with which the log was produced (or be forced to use the identical version of libvarnishapi).

Rationales for these ideas:

• In practice, whether to escape strings from the log is one of the hardest (most annoying) problems for formatting strings from the log for a format like JSON. Notoriously, the User-Agent header may contain double quotes, or any other manner of shlock; and many logging use cases call for extracting User-Agent. IMO it would help a lot if we can tell VSL clients whether or not we know if a string in the log payload is free of such things. If we know for certain that it is (because only varnishd produced the string), then a JSON formatter only has to enclose it in double quotes.

• Byte order issues are only relevant for one rather uncommon situation -- a binary log file is produced on one machine, and read on another machine, not necessarily with the same native byte order. Ordinarily, log contents are read and written on the same machine. So we keep the solution appropriately small -- varnishd writes log contents in native byte order, and a binary log file makes the byte order detectable.

• If binary log files have a header with the meta-data, then VSL clients reading binary log files may have a great deal of independence from the Varnish and API version with which log contents were created.

Discussion

• HTTP Structured Headers suggested as a design basis