Varnish Developer Portal

Generating Varnish access logs with varnishncsa

Tags: ops (28)

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

Customizing logs

To customize your logs, either alter the format of the log lines or only log certain lines.

To alter the log format will, use the -F parameter and specify a format using the fields that were mentioned in the varnishncsa log format section.

To only log certain lines, you’re going to issue a VSL query through the -q parameter. Have a look at the VSL queries section of the varnishlog tutorial, for more information.

Here are a couple of log customization examples:

Extending the log format with a hit/miss marker

If you want to extend the NCSA combined log format and add a hit/miss marker, simply add the %{Varnish:handling}x field.

For Varnish versions 7.5 or more recent, you can simply use the following command and log formatting:

varnishncsa -F "%{Varnish:default_format}x %{Varnish:handling}x"

When you use an older version of Varnish, you’ll have to specificy the complete format instead of referring to %{Varnish:default_format}x, which will look like this:

varnishncsa -F "%h %l %u %t "%r" %s %b \"%{Referer}i\" \"%{User-agent}i\" %{Varnish:handling}x"

Only log errors

To only log for response or backend response status codes above 399, add the below query to your varnishncsa command:

-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 to your varnishncsa command:

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

Limit logs to a certain domain

To only log requests for a certain domain (e.g., example.com), add the following query to your varnishncsa command:

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

Documentation

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