Linux – How to filter Varnish logs based on XID

http-headerslinuxloggingvarnish

I'm running into infrequent 503 errors which appear hard to pinpoint. Varnishlog is driving me mad, since I can't seem to get the information I want out of it.

I'd like to see both the client- and backend-communications as seen by Varnish. I thought the XID number, which is logged on Varnish's default error page, would allow me to filter the exact request out of the logging buffer. However, no combination of varnishlog parameters gives me the output I need.

The following only shows the client-side communication:

varnishlog -d -c -m ReqStart:1427305652

while this only shows the resulting backend communication:

varnishlog -d -b -m TxHeader:1427305652

Is there a one-liner to show the entire request?

Best Answer

Because the XID also appears in the TxHeader tag line when communicating with a client:

   12 SessionOpen  c 127.0.0.1 33829 :80
   12 ReqStart     c 127.0.0.1 33829 1171098618
   12 RxRequest    c GET
   12 RxURL        c /
   12 RxProtocol   c HTTP/1.1
   12 RxHeader     c Host: ganglia.gentoo
   12 RxHeader     c User-Agent: Mozilla/5.0 (X11; Linux i686; rv:5.0) Gecko/20100101 Firefox/5.0
   12 RxHeader     c Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
   12 RxHeader     c Accept-Language: en-us
   12 RxHeader     c Accept-Encoding: gzip, deflate
   12 RxHeader     c Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
   12 RxHeader     c Connection: keep-alive
   12 VCL_call     c recv lookup
   12 VCL_call     c hash
   12 Hash         c /
   12 Hash         c ganglia.gentoo
   12 VCL_return   c hash
   12 HitPass      c 1171098616
   12 VCL_call     c pass pass
   12 Backend      c 13 apache apache
   12 TTL          c 1171098618 RFC 120 -1 -1 1317921851 0 1317921851 0 0
   12 VCL_call     c fetch
   12 TTL          c 1171098618 VCL 120 -1 -1 1317921851 -0
   12 VCL_return   c hit_for_pass
   12 ObjProtocol  c HTTP/1.1
   12 ObjResponse  c OK
   12 ObjHeader    c Date: Thu, 06 Oct 2011 17:24:11 GMT
   12 ObjHeader    c Server: Apache
   12 ObjHeader    c Content-Length: 17
   12 ObjHeader    c Content-Type: text/html
   12 VCL_call     c deliver deliver
   12 TxProtocol   c HTTP/1.1
   12 TxStatus     c 200
   12 TxResponse   c OK
   12 TxHeader     c Server: Apache
   12 TxHeader     c Content-Type: text/html
   12 TxHeader     c Content-Length: 17
   12 TxHeader     c Accept-Ranges: bytes
   12 TxHeader     c Date: Thu, 06 Oct 2011 17:24:11 GMT
   12 TxHeader     c X-Varnish: 1171098618
   12 TxHeader     c Age: 0
   12 TxHeader     c Via: 1.1 varnish
   12 TxHeader     c Connection: keep-alive
   12 Length       c 17
   12 ReqEnd       c 1171098618 1317921851.307137489 1317921851.344322681 0.000065327 0.037110329 0.000074852

and as the @Oneiroi mentioned, according to the man page:

   -b     Include log entries which result from communication with a backend server.  If neither -b  nor  -c
          is specified, varnishlog acts as if they both were.

   -c     Include log entries which result from communication with a client.  If neither -b nor -c is speci‐
          fied, varnishlog acts as if they both were.

so, try this:

varnishlog -d -m TxHeader:XID | awk '$1 !~ /0/ { print $0 }'

A sample results:

varnishlog -d -m TxHeader:1171098618 | awk '$1 !~ /0/ { print $0 }'
   13 BackendOpen  b apache 127.0.0.1 40207 127.0.0.1 8080
   13 TxRequest    b GET
   13 TxURL        b /
   13 TxProtocol   b HTTP/1.1
   13 TxHeader     b Host: ganglia.gentoo
   13 TxHeader     b User-Agent: Mozilla/5.0 (X11; Linux i686; rv:5.0) Gecko/20100101 Firefox/5.0
   13 TxHeader     b Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
   13 TxHeader     b Accept-Language: en-us
   13 TxHeader     b Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
   13 TxHeader     b X-Forwarded-For: 127.0.0.1
   13 TxHeader     b Accept-Encoding: gzip
   13 TxHeader     b X-Varnish: 1171098618
   13 RxProtocol   b HTTP/1.1
   13 RxStatus     b 200
   13 RxResponse   b OK
   13 RxHeader     b Date: Thu, 06 Oct 2011 17:24:11 GMT
   13 RxHeader     b Server: Apache
   13 RxHeader     b Content-Length: 17
   13 RxHeader     b Content-Type: text/html
   13 Fetch_Body   b 4 0 1
   13 Length       b 17
   13 BackendReuse b apache
   12 SessionOpen  c 127.0.0.1 33829 :80
   12 ReqStart     c 127.0.0.1 33829 1171098618
   12 RxRequest    c GET
   12 RxURL        c /
   12 RxProtocol   c HTTP/1.1
   12 RxHeader     c Host: ganglia.gentoo
   12 RxHeader     c User-Agent: Mozilla/5.0 (X11; Linux i686; rv:5.0) Gecko/20100101 Firefox/5.0
   12 RxHeader     c Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
   12 RxHeader     c Accept-Language: en-us
   12 RxHeader     c Accept-Encoding: gzip, deflate
   12 RxHeader     c Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
   12 RxHeader     c Connection: keep-alive
   12 VCL_call     c recv lookup
   12 VCL_call     c hash
   12 Hash         c /
   12 Hash         c ganglia.gentoo
   12 VCL_return   c hash
   12 HitPass      c 1171098616
   12 VCL_call     c pass pass
   12 Backend      c 13 apache apache
   12 TTL          c 1171098618 RFC 120 -1 -1 1317921851 0 1317921851 0 0
   12 VCL_call     c fetch
   12 TTL          c 1171098618 VCL 120 -1 -1 1317921851 -0
   12 VCL_return   c hit_for_pass
   12 ObjProtocol  c HTTP/1.1
   12 ObjResponse  c OK
   12 ObjHeader    c Date: Thu, 06 Oct 2011 17:24:11 GMT
   12 ObjHeader    c Server: Apache
   12 ObjHeader    c Content-Length: 17
   12 ObjHeader    c Content-Type: text/html
   12 VCL_call     c deliver deliver
   12 TxProtocol   c HTTP/1.1
   12 TxStatus     c 200
   12 TxResponse   c OK
   12 TxHeader     c Server: Apache
   12 TxHeader     c Content-Type: text/html
   12 TxHeader     c Content-Length: 17
   12 TxHeader     c Accept-Ranges: bytes
   12 TxHeader     c Date: Thu, 06 Oct 2011 17:24:11 GMT
   12 TxHeader     c X-Varnish: 1171098618
   12 TxHeader     c Age: 0
   12 TxHeader     c Via: 1.1 varnish
   12 TxHeader     c Connection: keep-alive
   12 Length       c 17
   12 ReqEnd       c 1171098618 1317921851.307137489 1317921851.344322681 0.000065327 0.037110329 0.000074852
Related Topic