How to filter Varnish logs based on XID?
Solution 1
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
Solution 2
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.
Related videos on Youtube
Atulmaharaj
Updated on September 18, 2022Comments
-
Atulmaharaj almost 2 years
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?
-
Atulmaharaj over 12 yearsHmm, 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'.
-
Atulmaharaj over 12 yearsI 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.
-
Atulmaharaj over 12 yearsThe 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!
-
Atulmaharaj over 12 yearsHowever, 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.
-
koti over 11 yearsYou 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.