Setup logging for Varnish – The right way

Initially, logging Varnish didn’t really work that well. Varnish, by default, doesn’t log (varnishncsa can do some logging, but I haven’t figured that out yet.) I’ve been parsing my logs with JAWstats, which reads the Apache logs. However, by default, varnish will replace the IP address of the originating client with the IP address of the proxy server, meaning all traffic will look like it comes from my single server. This is what an entry looks like

173.230.157.240 - - [29/Jul/2010:15:47:47 -0700] "GET / HTTP/1.1" 200 20046 "-" "Pingdom.com_bot_version_1.4_(http://www.pingdom.com/)"
173.230.157.240 - - [29/Jul/2010:15:47:48 -0700] "GET / HTTP/1.1" 200 20046 "-" "Pingdom.com_bot_version_1.4_(http://www.pingdom.com/)"
173.230.157.240 - - [29/Jul/2010:15:47:49 -0700] "GET / HTTP/1.1" 200 20046 "-" "Pingdom.com_bot_version_1.4_(http://www.pingdom.com/)"
173.230.157.240 - - [29/Jul/2010:15:47:50 -0700] "GET / HTTP/1.1" 200 20046 "-" "Pingdom.com_bot_version_1.4_(http://www.pingdom.com/)"
Yeah, I made this up, but you get the idea.

That’s no good. How will I tell that I’m famous in Sweden? I found a way to get the client IP information passed to the backend

sub vcl_recv {
       remove req.http.X-Forwarded-For;
       set    req.http.X-Forwarded-For = client.ip;
}

This is what we get from this.

207.218.231.170, 207.218.231.170 - - [29/Jul/2010:15:47:47 -0700] "GET / HTTP/1.1" 200 20046 "-" "Pingdom.com_bot_version_1.4_(http://www.pingdom.com/)"

Ok, this is better, but the IP address is duplicated. I don’t know if it causes trouble with JAWstats (I assume it does), but I know that it is ugly to me. After much googling, I found this…

sub vcl_recv {
# 	Rename the incoming XFF header to work around a Varnish bug.
  if (req.http.X-Forwarded-For) {
#	Append the client IP
    set req.http.X-Real-Forwarded-For = req.http.X-Forwarded-For ", " regsub(client.ip, ":.*", "");
    unset req.http.X-Forwarded-For;
  }
  else {
    // Simply use the client IP
    set req.http.X-Real-Forwarded-For = regsub(client.ip, ":.*", "");
  }
}

And finally we have a working log file.

This is the first log file from this server

82.103.128.63 - - [04/Jul/2010:03:57:47 -0400] "GET / HTTP/1.0" 200 23301 "-" "Pingdom.com_bot_version_1.4_(http://www.pingdom.com/)"

And this is the last

24.19.50.69 - - [29/Jul/2010:19:44:18 -0700] "POST /wp-admin/admin-ajax.php HTTP/1.1" 200 177 "http://cainmanor.com/wp-admin/post-new.php" "Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_6_4; en-us) AppleWebKit/533.16 (KHTML, like Gecko) Version/5.0 Safari/533.16"