Search

Enabling logging with varnishncsa Tutorial

Introduction

By default any installation of varnishd will not write any request logs to disk. Instead Varnish has an in-memory log, and supplies tools to tap into this log and write to disk.

Prerequisites

In order to complete this guide, you will need a Linux based server, with either a privileged account, or an account with sudo capabilities. You will need to have varnish packages installed, either Varnish Cache Plus or Varnish Cache. You can use your distribution supplied packages, or head over to the official site for installation instructions. This guide was written and tested with Varnish version 4.1.x, but should work fine with Varnish 5.x as well.

Enable varnishncsa logging

Enabling Varnishncsa to be run as a service is done differently based on the distribution type. See the below table to decide what type of distribution you are on:

Distribution Version Type
CentOS 6 Non-systemd
Red Hat EL 6 Non-systemd
CentOS 7 Systemd
Red Hat EL 7 Systemd
Debian 8 (Jessie) Systemd
Debian 9 (Stretch) Systemd
Ubuntu 14.04 (Trusty) Non-systemd
Ubuntu 16.04 (Xenial) Systemd

Non-systemd based distributions

Step 1 - Enable the service

On CentOS6/RHEL6, use chkconfig to enable the service on boot:

chkconfig --level 345 varnishncsa on

On Debian/Ubuntu, edit /etc/default/varnishncsa and uncomment the line below (by removing the # at the start of the line):

VARNISHNCSA_ENABLED=1

Step 2 - Check status

Check the status, the service should not be running yet:

service varnishncsa status
* varnishncsa is not running

Step 3 - Customise options

You can add custom options to the startup by adding a DAEMON_OPTS line to either /etc/sysconfig/varnishncsa (CentOS6/RHEL6) or /etc/default/varnishncsa (Debian/Ubuntu), below is an example of adding -c to the defaults.

DAEMON_OPTS="-a -w ${LOGFILE} -D -P ${PIDFILE} -c"

For how to escape the output log format string see the note in Step 3 - Customise options of the systemd based distro section.

Step 4 - Start the service

Start the service (output might differ based on distribution):

service varnishncsa start
 * Starting Varnish Cache Plus NCSA logging daemon varnishncsa

Step 5 - Verify

Confirm it is running:

ps aux | grep varnishncsa
varnish+  1844  0.3  0.0  99208   176 ?        Ss   09:33   0:00 /usr/bin/varnishncsa -a -w /var/log/varnish/varnishncsa.log -D -P /var/run/varnishncsa/varnishncsa.pid

Systemd based distributions

Step 1 - Enable the service

Enable the systemd varnishncsa.service so that it will autostart on boot:

systemctl enable varnishncsa

Step 2 - Check status

Check the status of the service, should not be started:

systemctl status varnishncsa
● varnishncsa.service - Varnish Cache Plus HTTP accelerator log daemon
   Loaded: loaded (/lib/systemd/system/varnishncsa.service; enabled; vendor preset: enabled)
   Active: inactive (dead)

Step 3 - Customise options

You can edit the options passed to varnishncsa by editing ExecStart in the varnishncsa.service file. In systemd use the edit command like so:

systemctl edit varnishncsa

This will open a blank file allowing you to enter overrides for the service. Below is an example, adding -c to the defaults:

[Service]
ExecStart=
ExecStart=/usr/bin/varnishncsa -a -w /var/log/varnish/varnishncsa.log -D -c

To use a customized output log format string simply read the string from a file via the -f <formatfile> option:

[Service]
ExecStart=
ExecStart=/usr/bin/varnishncsa -a -w /var/log/varnish/varnishncsa.log -D -c -F -f /my_custom_format

With example formatfile contents being:

$ cat /my_custom_format
%{Host}i %h %l %u %t "%r" %s %b "%{Referer}i" "%{User-agent}i"
$

To use a customized output log format string in the systemd unit file you will need to escape percent signs, %, and double quotes, ". An example of using a custom output log format string on the command line requires no escaping:

$ /usr/bin/varnishncsa -F '%{Host}i %h %l %u %t "%r" %s %b "%{Referer}i" "%{User-agent}i"'

From the systemd unit file however the escaped string will look like this:

[Service]
ExecStart=
ExecStart=/usr/bin/varnishncsa -a -w /var/log/varnish/varnishncsa.log -D -c -F "%%{Host}i %%h %%l %%u %%t \\\"%%r\\\" %%s %%b \\\"%%{Referer}i\\\" \\\"%%{User-agent}i\\\" "

Step 4 - Start the service

Start the service:

systemctl start varnishncsa

Step 5 - Verify

Confirm it is running with the status command (output will differ slightly on different distros):

systemctl status varnishncsa
● varnishncsa.service - Varnish Cache Plus HTTP accelerator log daemon
   Loaded: loaded (/usr/lib/systemd/system/varnishncsa.service; enabled; vendor preset: disabled)
   Active: active (running) since Fri 2017-12-15 10:18:22 UTC; 2s ago
  Process: 8476 ExecStart=/usr/bin/varnishncsa -a -w /var/log/varnish/varnishncsa.log -D -P /var/run/varnishncsa/varnishncsa.pid (code=exited, status=0/SUCCESS)
 Main PID: 8477 (varnishncsa)
   CGroup: /system.slice/varnishncsa.service
           └─8477 /usr/bin/varnishncsa -a -w /var/log/varnish/varnishncsa.log -D -P /var/run/varnishncsa/varnishncsa.pid

Dec 15 10:18:22 centos-7-amd64.local systemd[1]: Starting Varnish Cache Plus HTTP accelerator log daemon...
Dec 15 10:18:22 centos-7-amd64.local systemd[1]: Started Varnish Cache Plus HTTP accelerator log daemon.

Customising logs

If you want to customise the logging, either the format of the loglines, or only log certain lines. Go back to step 3 from the above instructions, and edit the startup options for varnishncsa.

For more information on the available options, see the varnishncsa documentation.

Below are a couple of examples that might prove useful.

Only log errors

In order to only log for response or backend response status codes above 399, add the below query:

-q "RespStatus >= 400 or BerespStatus >= 400"

Log problem requests

To log all requests that took more than two seconds to be delivered, or with a non 200 response status add the below query:

-q "Timestamp:Resp[3] > 2.0 or RespStatus != 200"

Limit log to a certain domain

To only log requests for a certain domain (example.com in this case), add the following:

-q "ReqHeader ~ '^Host: .*\.example.com'"

Restarting varnishncsa

After customizing the logs restart varnishncsa. These steps are for restarting varnishncsa on Systemd based distributions. For an in depth systemd tutorial see Configuring systemd services.

Stop the varnishncsa daemon and kill any varnishncsa processes:

$ sudo systemctl stop varnishncsa
$ ps auxww | grep -e PID -e varnishncsa
$ kill pid_of_running_varnishncsa_process

Check for unused override files and comment varnishncsa if necessary:

$ systemctl cat varnishncsa
$ sudo vi override_file_from_previous_command

A customized log format can be present in /etc/rc.local, /etc/default/varnishncsa (Non-systemd CentOS6/RHEL6), and /etc/sysconfig/varnishncsa (Non-systemd Debian/Ubuntu). In Non-systemd based distributions these files are used. In Systemd based distributions however these files are not used and any varnishncsa override present in them should be commented to avoid confusion.

Confirm the updates made to varnishncsa are present, reload systemctl, and start varnishncsa:

$ sudo systemctl cat varnishncsa
$ sudo systemctl daemon-reload
$ sudo systemctl start varnishncsa

Tail the varnishncsa log to view the updated output. This is the argument to the -w option which is typically /var/log/varnish/varnishncsa.log:

$ tail -f /var/log/varnish/varnishncsa.log

Rotating logs

On a high volume system, logging to disk will quickly eat up disk, and it is imperative that you set up proper logrotation. Most varnish packages that supply a varnishncsa service will also supply a base config for logrotate, but configuring this depends heavily on your setup and traffic, and is out of the scope of this tutorial. See man logrotate or this DigitalOcean logrotate tutorial for more information, and see /etc/logrotate.d/varnish for the default.

Conclusion

After completing the step by step guide above, you should now get requests logged into /var/log/varnish/varnishncsa.log on your host.