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.
}

We use vslparser to process loads of logs and, in addition to using the data for distributed tracing, we also use it for performance monitoring.

Contributing

The project is hosted on GitHub. Be sure to report all bugs and send us a PR if you miss any features! We’ll be glad to help.

Please check the original version of this article at