Varnish - Makes Websites Fly !

mail

Looks like some entries are duplicated across logfiles

Situation

  1. I have split logs per virtualhost for AWStats
  2. In /var/log/varnish/, I expect log files like :
    • virtualhostA.myDomain.tld.log for everything about the website virtualhostA.myDomain.tld
    • virtualhostB.myDomain.tld.log for everything about the website virtualhostB.myDomain.tld
    • varnishncsa.log for everything else
  3. I see "similar" (?) entries when viewing virtualhostA.myDomain.tld.log and varnishncsa.log
Are all logs written to varnishncsa.log by default, then duplicated into specific files because of the way I setup this ?

Details

Long story short, I ended with this command :
logfileForVirtualhost='virtualhostA.myDomain.tld.log'; logfileForEverythingElse='varnishncsa.log'; cd '/var/log/varnish'; randomLineNumber=$(shuf -i 1-$(wc -l "$logfileForVirtualhost" | cut -d' ' -f1) -n 1); regEx=$(awk -v lineNumber="$randomLineNumber" 'BEGIN{OFS=".*"} NR==lineNumber {print $1,$4,$7,$9,$11}' "$logfileForVirtualhost" | tr -d '[]'); grep -E "$regEx" "$logfileForVirtualhost" "$logfileForEverythingElse" | column -s ' ' -t
which shows that every entry of virtualhostA.myDomain.tld.log can be found in varnishncsa.log.

Solution

As long as this does not f*ck things up for AWStats analyzes, I'm probably only wasting CPU and disk storage...
fix this (some day)
mail

Varnish logs : varnishncsa

Usage

  • varnishd doesn't log the hits it receives into logfiles but into a shared memory segment called the VSL (this is for speed and to avoid eating storage space, source)
  • if you want "regular" logfiles (i.e. stuff written into /var/log/varnish/whatever.log), this is handled by varnishncsa

Flags

Flag Usage
-a append to file specified with -w instead of overwriting it (the default)
-D Daemonize
-F formatString Write the output log in the Format specified by formatString
-P pidFile write the process's PID into pidFile
-q myQuery Run the specified VSL query myQuery to extract logs
-w outputFile write output to outputFile

Example

To setup logs (sources : stackoverflow.com, Varnish documentation, Varnishncsa documentation) :

  • logs are in /var/log/varnish/varnishncsa.log
  • varnishncsa configuration is in :
    • for pre-systemd systems :
      /etc/default/varnishncsa
    • for modern systems (post-systemd) :
      /etc/default/varnishncsa states :
      
      # Note: If systemd is installed, this file is obsolete and ignored.  You will
      # need to copy /lib/systemd/system/varnishncsa.service to /etc/systemd/system/
      # and edit that file.
      
      See /etc/systemd/system/varnishncsa.service

If logging is setup fine and stopped working :

"Stopped working" means you get :
ll /var/log/varnish/varnishncsa.log
-rw-r--r-- 1 varnishlog varnishlog 0 Sep 9 02:16 /var/log/varnish/varnishncsa.log	empty file
In such case :
  1. Make sure everything's working fine :
    systemctl status varnishncsa
     varnishncsa.service - Varnish Cache HTTP accelerator NCSA logging daemon
       Loaded: loaded (/etc/systemd/system/varnishncsa.service; enabled; vendor preset: enabled)
       Active: failed (Result: exit-code) since Wed 2018-01-10 22:53:40 CET; 7 months 28 days ago
    • This has been down for almost 8 months, SHAME ON ME !!!
    • There's no need to check varnish itself because, should it have any problem, I'd have received some more obvious alerts way earlier (like my website being down )
  2. restart it :
    systemctl restart varnishncsa && systemctl status varnishncsa
     varnishncsa.service - Varnish Cache HTTP accelerator NCSA logging daemon
       Loaded: loaded (/etc/systemd/system/varnishncsa.service; enabled; vendor preset: enabled)
       Active: active (running) since Sun 2018-09-09 18:56:47 CEST; 1s ago
      Process: 32169 ExecStart=/usr/bin/varnishncsa -a -w /var/log/varnish/varnishncsa.log -D -P /run/varnishncsa/varnishncsa.pid (code=exited,
     Main PID: 32170 (varnishncsa)
       CGroup: /system.slice/varnishncsa.service
               └─32170 /usr/bin/varnishncsa -a -w /var/log/varnish/varnishncsa.log -D -P /run/varnishncsa/varnishncsa.pid
mail

After upgrading to Debian Jessie (8.x), Varnish won't listen anymore on port 80

This article is NOT about changing the default port Varnish is listening on. It is about a change in Varnish behavior after upgrading Debian on a server where Varnish was already running fine and listening on port 80.
For more information about the initial setup of Varnish, and about changing its default port, please read my Varnish setup article.

Situation

I have a server running Debian Wheezy (7.x) and Varnish 4.x, listening on port 80 and everything is going extremely well. I upgrade it to Debian Jessie (8.x), then upgrade Varnish itself following this procedure, but after restarting Varnish, I can only see my website is not online anymore .

Details

The reason is that Varnish is not listening on port 80 anymore, but on its default port : 6081, as reported by netstat -laputen
Proto	Recv-Q	Send-Q	Local Address		Foreign Address		State	User	Inode		PID/Program name
tcp	0	0	0.0.0.0:6081		0.0.0.0:*		LISTEN	0	833790406	5785/varnishd
tcp	0	0	127.0.0.1:6082		0.0.0.0:*		LISTEN	0	833790425	5785/varnishd
Has /etc/default/varnish been altered during the upgrade ? Let's check this with :
grep -E "^DAEMON_OPTS" /etc/default/varnish
DAEMON_OPTS="-a :80 \
Nope, no change. So what ?

The root cause is that Debian Jessie doesn't use init.d as the init system anymore, but systemd instead. And /etc/default/varnish is only read by the /etc/init.d/varnish script, not by the systemd init script (/lib/systemd/system/varnish.service).

Solution

  1. backup /etc/systemd/system/varnish.service (should be a symlink, but just in case ...)
  2. cp /lib/systemd/system/varnish.service /etc/systemd/system/
  3. open /etc/systemd/system/varnish.service with your favorite text editor :
    [Unit]
    Description=Varnish Cache, a high-performance HTTP accelerator
    
    [Service]
    Type=forking
    LimitNOFILE=131072
    LimitMEMLOCK=82000
    ExecStartPre=/usr/sbin/varnishd -C -f /etc/varnish/default.vcl
    ExecStart=/usr/sbin/varnishd -a :6081 -T localhost:6082 -f /etc/varnish/default.vcl -S /etc/varnish/secret -s malloc,256m
    ExecReload=/usr/share/varnish/reload-vcl
    
    [Install]
    WantedBy=multi-user.target
  4. change that 6081 into 80
  5. save, exit and restart Varnish : service varnish restart

    The good ol' /etc/init.d/varnish restart has no effect here (varnishd still listening on 6081). SysVinit vs systemd styles, I guess...

  6. check : service varnish status
     varnish.service - Varnish Cache, a high-performance HTTP accelerator
    	Loaded: loaded (/lib/systemd/system/varnish.service; linked)
    	Active: active (running) since Tue 2016-01-05 21:17:24 CET; 4s ago
    Process: 7835 ExecStart=/usr/sbin/varnishd -a :80 -T localhost:6082 -f /etc/varnish/default.vcl -S /etc/varnish/secret -s malloc,256m (code=exited, status=0/SUCCESS)
    Process: 7824 ExecStartPre=/usr/sbin/varnishd -C -f /etc/varnish/default.vcl (code=exited, status=0/SUCCESS)
    Main PID: 7846 (varnishd)
    	CGroup: /system.slice/varnish.service
    		├─7846 /usr/sbin/varnishd -a :80 -T localhost:6082 -f /etc/varnish/default.vcl -S /etc/varnish/secret -s malloc,256m
    		└─7848 /usr/sbin/varnishd -a :80 -T localhost:6082 -f /etc/varnish/default.vcl -S /etc/varnish/secret -s malloc,256m
    You can see there not only the port it's listening to, but also the configuration file read at startup.
  7. Confirm : netstat -laputen :
    Proto	Recv-Q	Send-Q	Local Address		Foreign Address		State	User	Inode		PID/Program name
    tcp	0	0	0.0.0.0:80		0.0.0.0:*		LISTEN	0	834168483	7846/varnishd
    tcp	0	0	127.0.0.1:6082		0.0.0.0:*		LISTEN	0	834168504	7846/varnishd
mail

Varnish cache : RAM or disk ?

Whether the Varnish cache is in memory or on a disk is defined in /etc/default/varnish :

1GB on disk fixed-size cache file :

DAEMON_OPTS="-a :6081 \
	     -T localhost:6082 \
	     -b localhost:8080 \
	     -u varnish \
	     -g varnish \
	     -S /etc/varnish/secret \
	     -s file,/var/lib/varnish/$INSTANCE/varnish_storage.bin,1G"

256MB memory-based cache :

DAEMON_OPTS="-a :80 \
	     -T localhost:6082 \
	     -f /etc/varnish/default.vcl \
	     -S /etc/varnish/secret \
	     -s malloc,256m"
mail

Varnish setup

Installation on Debian Wheezy (source) :

  1. apt-get install apt-transport-https curl
  2. curl https://repo.varnish-cache.org/debian/GPG-key.txt | apt-key add -
  3. echo 'deb https://repo.varnish-cache.org/debian/ wheezy varnish-4.0' >> /etc/apt/sources.list.d/varnish-cache.list
  4. apt-get update && apt-get install varnish

Installation ok, is it already listening ?

netstat -laputen
Active Internet connections (servers and established)
Proto	Recv-Q	Send-Q	Local Address	Foreign Address	State	User	Inode		PID/Program name

tcp	0	0	0.0.0.0:6081	0.0.0.0:*	LISTEN	0	148492344	8519/varnishd
tcp	0	0	127.0.0.1:6082	0.0.0.0:*	LISTEN	0	148492320	8495/varnishd

tcp6	0	0	:::6081		:::*		LISTEN	0	148492345	8519/varnishd
tcp6	0	0	::1:6082	:::*		LISTEN	0	148492319	8495/varnishd
or : ss -ltp
State	Recv-Q	Send-Q	Local Address:Port	Peer Address:Port	(user/PID/?)
LISTEN	0	0	*:6081			*:*			users:(("varnishd",8519,7))
LISTEN	0	0	127.0.0.1:6082		*:*			users:(("varnishd",8495,6))
...
LISTEN	0	0	:::6081			:::*			users:(("varnishd",8519,8))
LISTEN	0	0	::1:6082		:::*			users:(("varnishd",8495,5))
So yes, Varnish is already listening on TCP ports 6081 and 6082. Good news : it didn't try to automatically use the HTTP port upon install, and my web server is still working normally .

More on ports :

  • 6081 : the default port Varnish is listening to. It is expected to be changed to 80 once both Varnish and the web server are properly configured. (source)
  • 6082 : management interface (source)
  • Ports are defined in /etc/default/varnish

What happens if we query those ports ?

wget -S -O /dev/null http://ipAddressOfMyServer:6081
HTTP request sent, awaiting response...
	HTTP/1.1 503 Backend fetch failed
	Date: Mon, 20 Oct 2014 13:53:36 GMT
	Server: Varnish
	Content-Type: text/html; charset=utf-8
	Retry-After: 5
	X-Varnish: 32770
	Age: 0
	Via: 1.1 varnish-v4
	Content-Length: 282
	Connection: keep-alive
2014-10-20 15:53:36 ERROR 503: Backend fetch failed.
I did get a response from Varnish, but it sounds like "Halp, I'm not configured !"
wget -S -O /dev/null http://ipAddressOfMyServer:6082
Connecting to ipAddressOfMyServer:6082... failed: Connection refused.
Knocking on the wrong door ? (This is for administration, actually. We'll see this later.)

Configuration :

This procedure applies to a live webserver running Lighttpd, which is why all restarts occur and the end of the configurations.

Listen on port 80 (source) :

This is all in /etc/default/varnish, which says :
## Alternative 2, Configuration with VCL
#
# Listen on port 6081, administration on localhost:6082, and forward to
# one content server selected by the vcl file, based on the request.
# Use a 256MB memory based cache.
#
DAEMON_OPTS="-a :6081 \
	     -T localhost:6082 \
	     -f /etc/varnish/default.vcl \
	     -S /etc/varnish/secret \
	     -s malloc,256m"
Update -a :6081 to -a :80.

Declare the backend server(s) (source) :

This takes place in /etc/varnish/default.vcl. For a very basic setup :
# Default backend definition. Set this to point to your content server.
backend default {
	.host = "127.0.0.1";
	.port = "8080";
	}

Don't forget to instruct the webserver (here : Lighttpd) to listen on port 8080 :

In /etc/lighttpd/lighttpd.conf, change server.port = 80 into server.port = 8080

Check Varnish configuration, restart daemons, and check Varnish responds :

varnishd -C -f /etc/varnish/default.vcl && service lighttpd restart && service varnish restart
The Varnish configuration check will return :
  • if success : the compiled configuration + a Unix success return code
  • if failure : a Unix failure return code +
    Message from VCC-compiler:
    (details of error encountered and line)
    #
    Running VCC-compiler failed, exited with 2
    VCL compilation failed
And check : wget -S -O /dev/null http://ipAddressOfMyServer
HTTP request sent, awaiting response...
	HTTP/1.1 200 OK
	Cache-Control: public, max-age=600
	Expires: Mon, 20 Oct 2014 15:10:29 GMT
	X-Powered-By: PHP/5.5.17-1~dotdeb.1
	Vary: Accept-Encoding
	Content-type: text/html
	Date: Mon, 20 Oct 2014 15:00:30 GMT
	Server: lighttpd/1.4.31
	X-Varnish: 32872
	Age: 0
	Via: 1.1 varnish-v4
	Transfer-Encoding: chunked
	Connection: keep-alive
	Accept-Ranges: bytes
Looks good !

Varnish administration :

This can be done with varnishadm (your future favorite command : help)
No logs written to disk, view logs in realtime with varnishlog.
mail

VCL subroutines

vcl_deliver
Called before a response object (from the cache or the web server) is sent to the requesting client.
vcl_fetch
Called when the request has been sent to the backend and a response has been received from the backend. Normal tasks here are to alter the response headers, trigger ESI processing, try alternate backend servers in case the request failed.
The request object req is still available. And there's also the backend response object beresp, containing HTTP headers from the backend. (details)
vcl_recv
Called after a request is received from the client, but before it is processed. Its purpose is to decide whether or not to serve the request, how to do it, and, if applicable, which backend to use. It also allows to alter the request (alter cookies, add / remove request headers).
Only the request object req is available.(details)
vcl_synth
Called to deliver a synthetic object, i.e. an object that is generated in VCL, not fetched from the backend. Its body may be constructed using the synthetic() function.

VCL workflow seen as a finite state machine (source) :

mail

VCL actions

hit
Content is served from cache.
miss
Content has been searched in cache, not found, then requested to the backend, stored in cache and served.
pass
The request and subsequent response will be passed to and from the backend server. It won't be cached. pass can be called in both vcl_recv and vcl_fetch.