3

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?

Improve this question

3 Answers 3

Reset to default
5

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
Improve this answer
3
  • The TxHeader tag seems to work pretty well, though it does produce thousands of debug lines, all with request ID '0'. Your awk filter removes those requests. Nice!
    – Martijn Heemels
    Nov 22, 2011 at 15:12
  • 1
    However, I see seemingly unrelated entries in the output. They seem to have no relation to the XID or the transaction, that I can determine. Doesn't that happen in your case? I'm using Varnish 3.0.2.
    – Martijn Heemels
    Nov 22, 2011 at 15:18
  • You can also take the XID from the ReqStart line, which might be a bit more reliable match. The "-c" switch will restrict the output to client interaction too, and cut down on the noise.
    – araqnid
    Jan 10, 2013 at 12:33
1

From the man page:

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

In theory negating adding -c or -b should retrieve the entire transaction.

Improve this answer
2
  • Hmm, it does seem to show both, as long as I use a tag that appears in both client and server sides of the transaction. TxHeader:XID seems to work, as @quanta shows. It does however produce thousands of debug lines, all with request ID '0'.
    – Martijn Heemels
    Nov 22, 2011 at 15:05
  • I can't find a way to have varnishlog figure out which front and backend requests belong together, so that I can filter on any tag instead of just tags that appear in both sides of the communication. That still requires multiple commands. One to find the XID of the request, then another to pull the client and server sides of the logs.
    – Martijn Heemels
    Nov 22, 2011 at 15:07
0

Since Varnish 5.1:

varnishlog -d -g session -q 'vxid == 1427305652'

See https://varnish-cache.org/docs/trunk/whats-new/changes-5.1.html#vxid-in-vsl-queries

Improve this answer

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .