Generating Varnish access logs with varnishncsa

Because Varnish sits in front of the web server and caches its output, the access logs of the web server no longer give the full picture of your site’s traffic. Only cache misses and bypassed requests will end up in the log.

To ensure that these logs still get generated in spite of the cache, the varnishncsa program can be used.

The Varnish Shared Memory Log#

The varnishd process reserves shared memory for logging by creating and mapping files in a tmpfs memory file system. The files are subsequently mapped by log consumers like varnishlog, varnishncsa, and varnishstat in read-only mode, allowing them to get information and logs from varnishd without affecting the caching process. These files are collectively know as Varnish Shared Memory (VSM). The part of the VSM responsible for communicating information about the traffic flowing through Varnish is called the Varnish Shared Memory Log (VSL).

The VSL is a circular buffer with a default size of 80 MB, but the size can be changed through the vsl_space runtime parameter.

Because Varnish is positioned on the edge of web content delivery platforms, it receives all the incoming requests. Therefore Varnish is in an excellent position to generate access logs through the VSL mechanism.

The varnishncsa program#

The varnishncsa program is a utility that comes with any Varnish installation. It reads from the varnishd shared memory logs and presents the output in a NCSA combined log format.

The NCSA combined log format#

The NCSA combined log format is the conventional web server log format and contains the following fields:

%h %l %u %t "%r" %s %b "%{Referer}i" "%{User-agent}i"

• %h: the client hostname or IP address
• %l: the client identifier or - if none is set
• %u: the username used by the client for authentication or - if none is set
• %t: the date and time of the HTTP request
• %r: the first line of the HTTP request
• %s: the status code of the HTTP response
• %b: the byte size of the HTTP response
• %{Referer}i: the URL that linked to the requested page or - if none is set
• %{User-agent}i: the web browser and platform used by the client

Here’s an example of such a log line that was generated by varnishncsa

172.17.0.1 - - [18/May/2022:11:57:56 +0000] "GET / HTTP/1.1" 200 45 "-" "curl"

The varnishncsa systemd service#

When Varnish is installed using the official Linux packages, a varnishncsa.service systemd service is automatically created.

The contents of this service can be viewed by running the following command:

sudo systemctl cat varnishncsa

This is the output:

[Unit]
Description=Varnish Cache HTTP accelerator NCSA logging daemon
After=varnish.service

[Service]
RuntimeDirectory=varnishncsa
Type=forking
User=varnishlog
Group=varnish

# Beware of custom formats! If you wish to use a different format using the
# -F option for varnishncsa, please note that systemd also uses percent '%'
# expansion in unit files: you need to double the percent signs in your
# format string.
#
# For example the default format would look like this:
#
#     -F '%%h %%l %%u %%t "%%r" %%s %%b "%%{Referer}i" "%%{User-agent}i"'
#
# Alternatively you can read the ncsa format from a file using the -f
# option in your varnishncsa command line.

ExecStart=/usr/bin/varnishncsa -a -w /var/log/varnish/varnishncsa.log -D
ExecReload=/bin/kill -HUP $MAINPID

[Install]
WantedBy=multi-user.target

This service runs the following command:

/usr/bin/varnishncsa -a -w /var/log/varnish/varnishncsa.log -D

This command continuously appends the output from varnishncsa to /var/log/varnish/varnishncsa.log. This command is daemonized through the -D option.

Enabling the varnishncsa service#

The varnishncsa.service systemd service is not enabled by default. Because Varnish is so powerful and can handle so many concurrent requests, the sheer number of log lines written to the varnishncsa.log file can potentially overwhelm the system.

Enabling varnishncsa.service means starting the service, but also ensuring it automatically gets started after a reboot.

Please run the following commands to enable and start the varnishncsa.service:

sudo systemctl enable varnishncsa
sudo systemctl start varnishncsa

Any new request that is received by Varnish will now end up in /var/log/varnish/varnishncsa.log.

Log rotation#

The Varnish installation also comes with a logrotate configuration. This configuration ensures that /var/log/varnish/varnishncsa.log is rotated daily to ensure that the logs don’t fill the disk.

The logrotate configuration is located in /etc/logrotate.d/varnishand looks like this:

/var/log/varnish/varnishncsa.log {
  daily
  rotate 7
  compress
  delaycompress
  missingok
  postrotate
    systemctl -q is-active varnishncsa.service || exit 0
    systemctl reload varnishncsa.service
  endscript
}

Based on this configuration, logrotate inspects the log on a daily basis, copies it to another file and eventually compresses the output into a gzip file.

Only seven log files are kept on the disk and are rotated on a daily basis.

These are the filenames of the logs:

/var/log/varnishncsa.log
/var/log/varnishncsa.log.1
/var/log/varnishncsa.log.2.gz
/var/log/varnishncsa.log.3.gz
/var/log/varnishncsa.log.4.gz
/var/log/varnishncsa.log.5.gz
/var/log/varnishncsa.log.6.gz
/var/log/varnishncsa.log.7.gz

Rate limiting#

If the varnishncsa.service has too much of an impact on your disk or the performance of your system, you can reduce the output of varnishncsa by adding rate limiting.

Rate limiting suppresses VSL transactions that exceed the limit. The -R option allows you to set the limit for a given duration.

Here’s an example where we only log one line every ten seconds:

varnishncsa -R 1/10s

To integrate rate limiting into your varnishncsa.service, run the following command:

sudo systemctl edit --full varnishncsa

This will open up an editor for the varnishncsa.service. Please add the -R option as illustrated below:

[Unit]
Description=Varnish Cache HTTP accelerator NCSA logging daemon
After=varnish.service

[Service]
RuntimeDirectory=varnishncsa
Type=forking
User=varnishlog
Group=varnish

# Beware of custom formats! If you wish to use a different format using the
# -F option for varnishncsa, please note that systemd also uses percent '%'
# expansion in unit files: you need to double the percent signs in your
# format string.
#
# For example the default format would look like this:
#
#     -F '%%h %%l %%u %%t "%%r" %%s %%b "%%{Referer}i" "%%{User-agent}i"'
#
# Alternatively you can read the ncsa format from a file using the -f
# option in your varnishncsa command line.

ExecStart=/usr/bin/varnishncsa -a -w /var/log/varnish/varnishncsa.log -D -R 1/10s
ExecReload=/bin/kill -HUP $MAINPID

[Install]
WantedBy=multi-user.target

After saving the file and closing the editor, run the following command to activate these changes:

sudo systemctl restart varnishncsa

Documentation#

Fore more information about the varnishncsa program and VSL, you can consult the official documentation on varnish-cache.org.

• The varnishncsa documentation for Varnish Cache 6.0 LTS
• The VSL documentation for Varnish Cache 6.0 LTS
• The varnishncsa documentation for the latest fresh version of Varnish Cache
• The VSL documentation for the latest fresh version of Varnish Cache