Analysing and troubleshooting Varnish traffic with varnishtop and varnishlog

Written by Claudio Kuenzler - 0 comments

Published on September 13th 2017 - last updated on March 5th 2020 - Listed in Varnish Linux

---

In order to analyze what traffic goes through Varnish and what Varnish exactly does with it, there are mainly two commands available to help you.

varnishtop

The first one is varnishtop which, as the name says (like the "top" command) a real time monitor of the Varnish traffic.

root@varnish:~# varnishtop

list length 4916

 28630.07 ReqHeader      Accept-Encoding: gzip
 21650.78 VCL_return     deliver
 18189.85 ReqProtocol    HTTP/1.1
 10715.35 ReqUnset       Accept-Encoding: gzip
 10682.41 RespProtocol   HTTP/1.1
 10657.09 VCL_call       HASH
 10657.09 VCL_call       RECV
 10657.09 VCL_call       DELIVER
 10657.09 VCL_return     lookup
 10657.09 ReqHeader      X-UA-Device: pc
 10657.09 RespHeader     Via: 1.1 varnish-v4
 10657.09 ReqHeader      Connection: close
 10655.04 RespHeader     Server: nginx/1.10.3 (Ubuntu)
 10649.17 ReqHeader      Host: www.example.com
 10648.83 VCL_return     hash
 10648.83 ReqHeader      Surrogate-Capability: abc=ESI/1.0
 10628.76 RespHeader     X-Forwarded-For:
 10628.76 RespHeader     X-Varnish-Hostname: varnish
 10628.76 RespHeader     Cache-Control: private, max-age=0
 10616.07 ReqMethod      GET
 10596.65 ReqHeader      X-Forwarded-Proto: http
 10563.52 RespHeader     X-Frame-Options: SAMEORIGIN
 10379.00 RespStatus     200
 10379.00 RespReason     OK
 10353.67 RespHeader     Accept-Ranges: bytes
 10219.76 RespHeader     Content-Type: text/html; charset=UTF-8
 10182.13 ReqHeader      Authorization: Basic bmVvOmtsRXdySV9mbzE=
 10180.63 RespHeader     Vary: Accept-Encoding
 10156.50 RespHeader     Content-Encoding: gzip
  9103.57 VCL_call       HIT
  9103.57 RespHeader     X-Cache: HIT
  8730.37 ReqHeader      X-Grace-Debug: hit
  8730.37 RespHeader     X-Grace-Debug: hit
  4739.76 ReqUnset       X-UA-Device: pc
  3984.83 ReqUnset       Accept-Encoding: gzip, deflate
  3597.83 RespHeader     Date: Wed, 13 Sep 2017 11:24:44 GMT
  3452.46 VCL_return     fetch
  2934.02 ReqHeader      Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
  2778.76 ReqHeader      Accept: */*
[...]

It basically counts up the number of times a function (like ReqHeader) was used and sorts it accordingly.

Varnishtop is, like top, an interactive way to see what's going on. To use a non-interactive way (for example running a regular cronjob), the output can be saved in a file:

root@varnish:~# varnishtop -1 -c > /tmp/xxx

Here I told varnishtop to run once (-1) and display only records concerning the client/requester (-c). This works a bit differently because here the full stats (Varnish keeps a kind of log file in memory) are shown (no counting up slowly as in interactive mode):

root@varnish:~# head /tmp/xxx
 50255.00 ReqHeader Accept-Encoding: gzip
 35081.00 VCL_return deliver
 31935.00 ReqProtocol HTTP/1.1
 19200.00 ReqUnset Accept-Encoding: gzip
 19020.00 RespProtocol HTTP/1.1
 18957.00 VCL_call HASH
 18957.00 VCL_call RECV
 18957.00 VCL_call DELIVER
 18957.00 VCL_return lookup
 18957.00 ReqHeader X-UA-Device: pc

Varnishtop can also use filtering. For example if one wants to see a live view of the most requested URL's:

root@varnish:~# varnishtop -i ReqURL

list length 15
     8.17 ReqURL         /
     3.67 ReqURL         /rss.xml
     3.67 ReqURL         /international.rss
     2.67 ReqURL         /blog/733/solving-grokparsefailure-syslog-messages-entries-elk-logstash
     2.67 ReqURL         /monitoring-plugins/
[...]

Or a live view of the client browsers language settings:

root@varnish:~# varnishtop -I ReqHeader:Accept-Language

list length 60

   324.39 ReqHeader      Accept-Language: de-ch
   189.76 ReqHeader      Accept-Language: de,en-US;q=0.7,en;q=0.3
   161.48 ReqHeader      Accept-Language: de-DE,de;q=0.8,en-US;q=0.6,en;q=0.4
   108.58 ReqHeader      Accept-Language: en-US
    95.21 ReqHeader      Accept-Language: de
    79.94 ReqHeader      Accept-Language: de-de
    74.94 ReqHeader      Accept-Language: en-us
    67.58 ReqHeader      Accept-Language: de-CH
    64.30 ReqHeader      Accept-Language: en-US,en;q=0.5
    52.21 ReqHeader      Accept-Language: en-US,en;q=0.8
    36.52 ReqHeader      Accept-Language: en-gb
    23.39 ReqHeader      Accept-Language: de-DE,de,en-US,en
    17.03 ReqHeader      Accept-Language: de-CH,de-DE;q=0.8,de;q=0.6,en-US;q=0.4,en;q=0.2
    16.85 ReqHeader      Accept-Language: en-US,en;q=0.8,de;q=0.6
    16.67 ReqHeader      Accept-Language: de-DE
    15.45 ReqHeader      Accept-Language: de-DE,en-US;q=0.8
    14.61 ReqHeader      Accept-Language: en
    13.67 ReqHeader      Accept-Language: de-CH,de;q=0.8,fr-CH;q=0.7,fr;q=0.5,it-CH;q=0.3,it;q=0.2
    13.00 ReqHeader      Accept-Language: de-CH,de-DE;q=0.8,de;q=0.6,fr-CH;q=0.4,fr;q=0.2
[...]

Note the difference between minor -i and capital -I. If a certain field (in this case Accept-Language) and not just the function (ReqHeader) should be filtered, regular expression (-I) must be applied.

Or to show User-Agents containing the string "Googlebot":

root@varnish:~# varnishtop -I ReqHeader:User-Agent.*Googlebot

list length 5

   190.59 ReqHeader  User-Agent: Mozilla/5.0 (compatible; Googlebot/2.1; startmebot/1.0; +https://start.me/bot)
   119.98 ReqHeader  User-Agent: Mozilla/5.0 (Linux; Android 6.0.1; Nexus 5X Build/MMB29P) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0.2272.96 Mobile Safari/537.36 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)
   107.32 ReqHeader  User-Agent: Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)
    21.12 ReqHeader  User-Agent: SentiBot www.sentibot.eu (compatible with Googlebot)
     1.77 ReqHeader  User-Agent: Googlebot-News

varnishlog

While varnishtop is pretty handy to have a sorted "live" or "monitoring" view of what's going on, it is not very helpful for troubleshooting, like traffic analysis. For this purpose there's varnishlog. If you simply call varnishlog, it will show you a seemingly endless list (if you have high traffic) of the whole HTTP traffic going through Varnish. To be honest, not helpful to troubleshoot if you see the whole traffic from every client. But varnishlog (and varnishtop, too) support so-called VSL queries. With such a query, specific traffic can be analyzed.

Here I analyze traffic coming from my own IP address (10.10.40.40):

root@varnish:~# varnishlog -q "ReqHeader ~ 'X-Forwarded-For: 10.10.40.40'"

Note 1: Varnish runs behind a Reverse Proxy, therefore I'm using the X-Forwarded-For header to find traffic for my client IP.

Note 2: Here I'm using the hyphen (~) operator to make a regular expression query on a string. As you can see in the result below the full request header was "X-Forwarded-For: 10.10.40.40, 127.0.0.1".

On my machine I launch a curl command:

$ curl https://www.example.com/_version

And varnishlog shows me my request:

*   << Request  >> 1739776  
-   Begin          req 1739775 rxreq
-   Timestamp      Start: 1505304166.030111 0.000000 0.000000
-   Timestamp      Req: 1505304166.030111 0.000000 0.000000
-   ReqStart       127.0.0.1 42206
-   ReqMethod      GET
-   ReqURL         /_version
-   ReqProtocol    HTTP/1.0
-   ReqHeader      Host: www.example.com
-   ReqHeader      X-Real-IP: 10.10.40.40
-   ReqHeader      X-Forwarded-For: 10.10.40.40
-   ReqHeader      Connection: close
-   ReqHeader      User-Agent: curl/7.35.0
-   ReqHeader      Accept: */*
-   ReqUnset       X-Forwarded-For: 10.10.40.40
-   ReqHeader      X-Forwarded-For: 10.10.40.40, 127.0.0.1
-   VCL_call       RECV
-   ReqHeader      X-UA-Device: pc
-   ReqHeader      Surrogate-Capability: abc=ESI/1.0
-   VCL_return     hash
-   VCL_call       HASH
-   VCL_return     lookup
-   Debug          "XXXX HIT-FOR-PASS"
-   HitPass        237645
-   VCL_call       PASS
-   VCL_return     fetch
-   Link           bereq 1739777 pass
-   Timestamp      Fetch: 1505304166.052654 0.022543 0.022543
-   RespProtocol   HTTP/1.1
-   RespStatus     200
-   RespReason     OK
-   RespHeader     Server: nginx/1.10.3 (Ubuntu)
-   RespHeader     Content-Type: application/json
-   RespHeader     Vary: Accept-Encoding
-   RespHeader     Cache-Control: private, must-revalidate
-   RespHeader     Date: Wed, 13 Sep 2017 12:02:46 GMT
-   RespHeader     pragma: no-cache
-   RespHeader     expires: -1
-   RespHeader     X-Frame-Options: SAMEORIGIN
-   RespHeader     X-Varnish: 1739776
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish-v4
-   VCL_call       DELIVER
-   RespHeader     X-Cache: MISS
-   RespHeader     X-Grace-Debug:
-   VCL_return     deliver
-   Timestamp      Process: 1505304166.052666 0.022555 0.000012
-   RespHeader     Accept-Ranges: bytes
-   Debug          "RES_MODE 4"
-   RespHeader     Connection: close
-   Timestamp      Resp: 1505304166.052688 0.022577 0.000022
-   ReqAcct        163 0 163 365 135 500
-   End     

The full HTTP traffic is nicely presented from the begin until the end including detailed timestamps.

The query can also be adjusted to use several fields at the same time. In this example I want to see non-cached traffic (X-Cache: MISS) which don't receive a HTTP 200 status as response:

root@varnish:~# varnishlog -q "RespHeader eq 'X-Cache: MISS' and RespStatus != 200"
*   << Request  >> 2747891  
-   Begin          req 2747890 rxreq
-   Timestamp      Start: 1505305067.468814 0.000000 0.000000
-   Timestamp      Req: 1505305067.468814 0.000000 0.000000
-   ReqStart       127.0.0.1 37518
-   ReqMethod      GET
-   ReqURL         /app1/rest/api/v1/run?ID=1111
-   ReqProtocol    HTTP/1.0
-   ReqHeader      Host: www.example.com
-   ReqHeader      X-Real-IP: 10.10.55.55, 127.0.0.1
-   ReqHeader      X-Forwarded-For: 10.10.55.55, 127.0.0.1
-   ReqHeader      Connection: close
-   ReqHeader      X-Forwarded-Proto: http
-   ReqHeader      Authorization: Basic bmVvOmtsRXdySV9mbzE=
-   ReqHeader      C1-Client-Country-Code: US
-   ReqHeader      User-Agent: Mozilla/5.0 (Windows NT 5.1) AppleWebKit/537.31 (KHTML, like Gecko) Chrome/26.0.1410.64 Safari/537.31
-   ReqHeader      Accept-Encoding: gzip,deflate
-   ReqHeader      C1-Tracking-ID: 1578426766423744071
-   ReqUnset       X-Forwarded-For: 10.10.55.55, 127.0.0.1
-   ReqHeader      X-Forwarded-For: 10.10.55.55, 127.0.0.1, 127.0.0.1
-   VCL_call       RECV
-   ReqUnset       Accept-Encoding: gzip,deflate
-   ReqHeader      Accept-Encoding: gzip
-   ReqHeader      X-UA-Device: pc
-   ReqHeader      Surrogate-Capability: abc=ESI/1.0
-   VCL_return     hash
-   VCL_call       HASH
-   VCL_return     lookup
-   VCL_call       MISS
-   VCL_return     fetch
-   Link           bereq 2747892 fetch
-   Timestamp      Fetch: 1505305067.494414 0.025599 0.025599
-   RespProtocol   HTTP/1.1
-   RespStatus     301
-   RespReason     Moved Permanently
-   RespHeader     Server: nginx/1.10.3 (Ubuntu)
-   RespHeader     Content-Type: text/html; charset=UTF-8
-   RespHeader     Cache-Control: no-cache
-   RespHeader     Date: Wed, 13 Sep 2017 12:17:47 GMT
-   RespHeader     Location: http://www.example.com/app1/rest/api/v1/run?ID=1111
-   RespHeader     X-Frame-Options: SAMEORIGIN
-   RespHeader     X-Varnish: 2747891
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish-v4
-   VCL_call       DELIVER
-   RespHeader     X-Cache: MISS
-   RespHeader     X-Grace-Debug:
-   VCL_return     deliver
-   Timestamp      Process: 1505305067.494428 0.025613 0.000014
-   RespHeader     Content-Length: 495
-   Debug          "RES_MODE 2"
-   RespHeader     Connection: close
-   Timestamp      Resp: 1505305067.494519 0.025704 0.000091
-   ReqAcct        500 0 500 404 495 899
-   End           

*   << Request  >> 4490790  
-   Begin          req 4490789 rxreq
-   Timestamp      Start: 1505305068.432932 0.000000 0.000000
-   Timestamp      Req: 1505305068.432932 0.000000 0.000000
-   ReqStart       127.0.0.1 37746
-   ReqMethod      POST
-   ReqURL         /autodiscover/autodiscover.xml
-   ReqProtocol    HTTP/1.0
-   ReqHeader      Host: www.example.com
-   ReqHeader      X-Real-IP: 10.128.50.142, 127.0.0.1
-   ReqHeader      X-Forwarded-For: 10.128.50.142, 127.0.0.1
-   ReqHeader      Connection: close
-   ReqHeader      Content-Length: 389
-   ReqHeader      X-Forwarded-Proto: http
-   ReqHeader      Authorization: Basic bmVvOmtsRXdySV9mbzE=
-   ReqHeader      Cache-Control: no-cache
-   ReqHeader      Pragma: no-cache
-   ReqHeader      Content-Type: text/xml
-   ReqHeader      User-Agent: Microsoft Office/16.0 (Windows NT 6.1; Microsoft Outlook 16.0.4549; Pro)
-   ReqHeader      X-MS-CookieUri-Requested: t
-   ReqHeader      X-FeatureVersion: 1
-   ReqHeader      Client-Request-Id: {9DB2AEBC-D17F-4640-8E3D-29035F67A0F3}
-   ReqHeader      X-MapiHttpCapability: 1
-   ReqHeader      Depth: 0
-   ReqHeader      Cookie: OutlookSession="{638F5EED-5A90-4688-8DE0-032340E18CEA}"; creid=1578407533870507445
-   ReqHeader      C1-Tracking-ID: 1578407533870507445
-   ReqUnset       X-Forwarded-For: 10.128.50.142, 127.0.0.1
-   ReqHeader      X-Forwarded-For: 10.128.50.142, 127.0.0.1, 127.0.0.1
-   VCL_call       RECV
-   ReqHeader      X-UA-Device: pc
-   VCL_return     pass
-   VCL_call       HASH
-   VCL_return     lookup
-   VCL_call       PASS
-   VCL_return     fetch
-   Link           bereq 4490791 pass
-   Timestamp      ReqBody: 1505305068.433025 0.000092 0.000092
-   Timestamp      Fetch: 1505305068.570216 0.137284 0.137192
-   RespProtocol   HTTP/1.1
-   RespStatus     404
-   RespReason     Not Found
-   RespHeader     Server: nginx/1.10.3 (Ubuntu)
-   RespHeader     Content-Type: text/html; charset=UTF-8
-   RespHeader     Vary: Accept-Encoding
-   RespHeader     Date: Wed, 13 Sep 2017 12:17:48 GMT
-   RespHeader     Cache-Control: private, max-age=0
-   RespHeader     X-Forwarded-For:
-   RespHeader     X-Varnish-Hostname: varnish
-   RespHeader     X-Varnish: 4490790
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish-v4
-   VCL_call       DELIVER
-   RespHeader     X-Cache: MISS
-   RespHeader     X-Grace-Debug:
-   VCL_return     deliver
-   Timestamp      Process: 1505305068.570234 0.137301 0.000017
-   Debug          "RES_MODE 4"
-   RespHeader     Connection: close
-   Timestamp      Resp: 1505305068.585268 0.152336 0.015034
-   ReqAcct        828 389 1217 343 178556 178899
-   End           

During the time I interactively ran the command, two results showed up (a 301 and a 404).

What about combining multiple conditions?

Another example is to combine multiple conditions in logical and/or combinations. This can also include a negated condition:

root@varnish:~# varnishlog -q '(ReqHeader ~ "X-Forwarded-For: 10.10.40.40" or BereqHeader ~ "X-Forwarded-For: 10.10.40.40") and ReqURL !~ "/api"'

The first condition is a logical OR: Either the request header (http request from the client to Varnish) has to contain "X-Forwarded-For: 10.10.40.40" or the backend request header (http request from Varnish to the backend) has to contain "X-Forwarded-For: 10.10.40.40". One of them must be true.

The second condition is a logical AND: This condition is a negated condition and checks for the ReqURL (requested URL from the client to Varnish) to NOT be "/api".

The combined conditions result in varnishlog showing only traffic which contain a "X-Forwarded-For: 10.10.40.40" header from either client or to the backend and requests to "/api" are excluded.

Full reference

Full reference on the official varnishtop and varnishlog documentations.

Using these two commands, Varnish's traffic can be analyzed properly. Especially by using the filtering and querying techniques.

Add a comment

Show form to leave a comment

Comments (newest first)

No comments yet.