Take the 2-minute tour ×
Server Fault is a question and answer site for professional system and network administrators. It's 100% free, no registration required.

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?

share|improve this question

2 Answers 2

up vote 5 down vote accepted

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
share|improve this answer
    
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 '11 at 15:12
    
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 '11 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 '13 at 12:33

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.

share|improve this answer
    
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 '11 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 '11 at 15:07

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.