How to log specific Varnish requests

Use varnishlog to log specific Varnish requests.

I will log 5xx (Server Error) class of status code to the /var/log/varnish/5xx_errors.log log file.

Create logrotate configuration.

$ cat <<EOF | sudo tee /etc/logrotate.d/varnishlog
/var/log/varnish/varnish_5xx.log {
  daily
  rotate 7
  missingok
  compress
  delaycompress
  missingok
 
  postrotate
    /bin/kill -HUP \$(cat /run/varnishlog_5xx/varnishlog_5xx.pid 2>/dev/null) 2>/dev/null || true
  endscript
}
EOF

Create varnishlog_5xx systemd service.

Notice, you need to use RespStatus (HTTP response status code) and BerespStatus (HTTP backend response status code) inside the VSL query to log both requests.

$ cat <<EOF | sudo tee /etc/systemd/system/varnishlog_5xx.service
[Unit]
Description=Varnish HTTP accelerator 5xx log daemon
After=varnish.service
Requires=varnish.service

[Service]
Type=forking
PIDFile=/run/varnishlog_5xx/varnishlog_5xx.pid
RuntimeDirectory=varnishlog_5xx
User=varnishlog
Group=varnish
ExecStart=/usr/bin/varnishlog -a -A -w /var/log/varnish/varnish_5xx.log -D -P /run/varnishlog_5xx/varnishlog_5xx.pid -q "(RespStatus >= 500 and RespStatus <= 599) or (BerespStatus >= 500 and BerespStatus <= 599)"
ExecReload=/bin/kill -HUP \$MAINPID
PrivateDevices=true
PrivateTmp=true
ProtectHome=true
ProtectSystem=full
ExecStartPost=/bin/sleep 1

[Install]
WantedBy=multi-user.target
EOF

Reload the systemd manager configuration.

$ sudo systemctl daemon-reload

Enable and start created service.

$ sudo systemctl enable --now varnishlog_5xx

Inspect service status.

$ systemctl status varnishlog_5xx.service

● varnishlog_5xx.service - Varnish HTTP accelerator 5xx log daemon
   Loaded: loaded (/etc/systemd/system/varnishlog_5xx.service; enabled; vendor preset: enabled)
   Active: active (running) since Sun 2020-09-20 13:52:11 GMT; 3s ago
  Process: 6220 ExecStart=/usr/bin/varnishlog -a -A -w /var/log/varnish/varnish_5xx.log -D -P /run/varnishlog_5xx/varnishlog_5xx.pid -q (RespStatus >= 500 and RespStatus <= 599) or (BerespStatus >= 500 and BerespStatus <= 599) (code=exited, status=0/SUCCESS)
 Main PID: 6221 (varnishlog)
    Tasks: 1 (limit: 1149)
   Memory: 448.0K
   CGroup: /system.slice/varnishlog_5xx.service
           └─6221 /usr/bin/varnishlog -a -A -w /var/log/varnish/varnish_5xx.log -D -P /run/varnishlog_5xx/varnishlog_5xx.pid -q (RespStatus >= 500 and RespStatus <= 599) or (BerespStatus >= 500 and BerespStatus <= 599)

Sample 5xx error.

$ sudo tail -f /var/log/varnish/varnish_5xx.log

[...]
*   << BeReq    >> 19
-   Begin          bereq 18 fetch
-   Timestamp      Start: 1600609944.457551 0.000000 0.000000
-   BereqMethod    GET
-   BereqURL       /
-   BereqProtocol  HTTP/1.1
-   BereqHeader    Host: localhost:6081
-   BereqHeader    User-Agent: curl/7.64.0
-   BereqHeader    Accept: */*
-   BereqHeader    X-Forwarded-For: ::1
-   BereqHeader    Accept-Encoding: gzip
-   BereqHeader    X-Varnish: 19
-   VCL_call       BACKEND_FETCH
-   VCL_return     fetch
-   BackendOpen    26 default 127.0.0.1 80 127.0.0.1 41738
-   BackendStart   127.0.0.1 80
-   Timestamp      Bereq: 1600609944.457668 0.000116 0.000116
-   Timestamp      Beresp: 1600609944.457812 0.000260 0.000144
-   BerespProtocol HTTP/1.1
-   BerespStatus   500
-   BerespReason   Internal Server Error
-   BerespHeader   Server: nginx/1.14.2
-   BerespHeader   Date: Sun, 20 Sep 2020 13:52:24 GMT
-   BerespHeader   Content-Type: text/html
-   BerespHeader   Content-Length: 193
-   BerespHeader   Connection: close
-   TTL            RFC -1 10 0 1600609944 1600609944 1600609944 0 0 cacheable
-   VCL_call       BACKEND_RESPONSE
-   TTL            VCL 120 10 0 1600609944 cacheable
-   TTL            VCL 120 10 0 1600609944 uncacheable
-   VCL_return     deliver
-   Filters
-   Storage        malloc Transient
-   Fetch_Body     3 length stream
-   BackendClose   26 default
-   Timestamp      BerespBody: 1600609944.457889 0.000338 0.000077
-   Length         193
-   BereqAcct      138 0 138 162 193 355
-   End

*   << Request  >> 18
-   Begin          req 17 rxreq
-   Timestamp      Start: 1600609944.457485 0.000000 0.000000
-   Timestamp      Req: 1600609944.457485 0.000000 0.000000
-   ReqStart       ::1 38692 a0
-   ReqMethod      GET
-   ReqURL         /
-   ReqProtocol    HTTP/1.1
-   ReqHeader      Host: localhost:6081
-   ReqHeader      User-Agent: curl/7.64.0
-   ReqHeader      Accept: */*
-   ReqHeader      X-Forwarded-For: ::1
-   VCL_call       RECV
-   VCL_return     hash
-   VCL_call       HASH
-   VCL_return     lookup
-   HitMiss        32788 26.905434
-   VCL_call       MISS
-   VCL_return     fetch
-   Link           bereq 19 fetch
-   Timestamp      Fetch: 1600609944.457956 0.000471 0.000471
-   RespProtocol   HTTP/1.1
-   RespStatus     500
-   RespReason     Internal Server Error
-   RespHeader     Server: nginx/1.14.2
-   RespHeader     Date: Sun, 20 Sep 2020 13:52:24 GMT
-   RespHeader     Content-Type: text/html
-   RespHeader     Content-Length: 193
-   RespHeader     X-Varnish: 18
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish (Varnish/6.1)
-   VCL_call       DELIVER
-   VCL_return     deliver
-   Timestamp      Process: 1600609944.457970 0.000485 0.000013
-   RespHeader     Connection: keep-alive
-   Timestamp      Resp: 1600609944.457989 0.000504 0.000019
-   ReqAcct        78 0 78 222 193 415
-   End
[...]

Additional notes

varnishnsca stores Varnish logs in Apache/NCSA combined log format, but varnishlog provides more detailed information, so it is more useful in case of failure.

Additional notes#

Additional notes