Varnish Logging – Log Timestamps with Varnish Health Probes

linuxloggingvarnish

I'm using Varnish 3.0.3 on RHEL 6 as a caching load balancer in front of several Apache web servers and want to keep a log of when Varnish sees the back-ends change from healthy to sick and back again.

From the command line I can run varnishlog -O -I "Back healthy|Went sick" and see lines like the following:

0 Backend_health - webserver1 Went sick 4--X--- 2 3 5 0.000000 0.000679 
0 Backend_health - webserver1 Back healthy 4--X-RH 3 3 5 0.000622 0.000679 HTTP/1.1 200 OK

I'd love to write these sick/healthy state changes to a log file, but they are useless without having timestamps associated with them. How can I write these lines to a log file and include timestamps for each line?

Best Answer

The output of varnishlog can be piped to awk and reformatted to put the date at the beginning of each line. The tricky part is that varnishlog buffers the output which causes it only to be sent to awk after a number of lines have been generated, resulting in all of the lines getting the same timestamp as the last one that tops off the buffer. To get around this, the unbuffer command can be used to pipe the output of varnishlog to awk straight away so that each line gets an appropriate timestamp.

unbuffer varnishlog -O -I 'Back healthy|Went sick' 2>&1 | awk '{ print strftime(), $0; fflush() }'

This results in output like the following, which can then be appended to a log file.

Wed Feb 20 15:20:58 EST 2013     0 Backend_health - webserver1 Went sick 4--X--- 2 3 5 0.000000 0.000679
Wed Feb 20 15:28:03 EST 2013     0 Backend_health - webserver1 Back healthy 4--X-RH 3 3 5 0.000622 0.000679 HTTP/1.1 200 OK

Note: Thanks to this answer Kieron and this answer by Mark Harrison for the pieces needed to figure this out.

Related Topic