vslparser - a Varnish Log Parser

David Čepelík

Backendgoopensourcevarnish

Robert Larsson

We just released vslparser, a simple yet efficient parser of Varnish logs written in Go.

What it is and how we use it

At Showmax, we rely heavily on caching. In fact, only a small portion of customer traffic ever hits our back-end services. Varnish does the heavy lifting for us by caching the responses of our microservices. We also trace every request, and use a lot of information from the Varnish logs. Stuff like:

Complete set of request/response headers
Request/response timing
Client and back-end identification

The Varnish logs are available through a shared memory buffer. A binary called varnishlog can display those logs in a suitable form:

*   << BeReq	>> 53584999
-   Begin      	bereq 53584998 fetch
-   Timestamp  	Start: 1554382167.163438 0.000000 0.000000
-   BereqMethod	GET
-   BereqURL   	/foo/bar
-   BereqProtocol  HTTP/1.1
-   BereqHeader	X-Foo: bar
-   BereqHeader	X-Foobar: baz
...
-   End.

The vslparser module, written in Go, parses these so-called “log entries” (error handling omitted):

cmd := exec.Command("varnishlog") // Add "-b" to only process back-end requests.
stdout, _ := cmd.StdoutPipe()
scanner := bufio.NewScanner(stdout)
for {
    entry, _ := vslparser.Parse(scanner)
}

To get the vslparser.Entry, you just need to do some line splitting and basic sanity checks. For example, the entry does not understand the time-stamps or headers yet. In fact, it’s a simple map:

// Entry holds a single log entry. An entry consists mostly of a collection
// of log fields.

type Entry struct {
    Kind   string
    VXID   int
    Fields Fields
}

// Fields are a collection of log fields. A single log field consists of a key
// and a list of values which appeared with this key. Consider this fragment of
// varnishlog output:
//
// - Foo    Bar Baz
// - Foo    Foobar
// - Bar
//
// There are two fields, "Foo" with values "Bar Baz" and "Foobar" and the field
// "Bar" with an empty string as a sole value.
type Fields map[string][]string

The vslparser.Entry then provides various convenient methods to further parse the entry, such as:

ts, _ := entry.Timestamp("Bereq")

This gives you a vslparser.Timestamp structure that contains all data contained in the original string, but sanitized and converted to suitable types:

// Timestamp represents a parsed time-stamp.
type Timestamp struct {
    AbsTime 	time.Time // Absolute time component.
    UsSinceUnit int   	// Number of microseconds since the start of work unit.
    UsSincePrev int   	// Number of microseconds since previous stamp.
}