Menu

A co-worker started getting the following error on her Mac running Mac OS X 10.7.5:

For some reason, the SSL certificate chain was no longer valid. After checking to make sure there were no Apple software updates, Chrome was up to date, no proxying, and the date / time was correct, I took a look at the certificate chain. It claimed that the root certificate had expired, but there wasn’t an update for it.

I figure this might be due to a lack of vendor updates around this version of Mac (10.7.x may be out of cycle now), so think she probably will need an update to Mavericks. In the mean time, she’s unblocked!

Varnish is an excellent page cache / web accelerator program that is well worth a look. Quick, where does varnish log by default? Trick question – by default Varnish doesn’t log anywhere. Let’s explore this a little bit.

Using varnishncsa for live logging

The first place you might look is just looking at the live data. Varnish provides the utility varnishncsa to view logs live in NCSA common log format. To fire it up in a console, just run varnishncsa. You can change the format, log it to a file, daemonize it…check the documentation for more.

Running varnishncsa on boot

Running Ubuntu 12.04 or newer? Piece of cake. Just edit /etc/default/varnishncsa, and set VARNISHNCSA_ENABLED=1. Then run: sudo /etc/init.d/varnishncsa start

Going Deeper: Logging X-Forwarded-For and Change Log Directory

Now is when we get to the hacky part. What if we want to change the logging format or change the log directory? Alas – the only way to do this is to edit the init script. Here are a few things I want to edit:

Log X-Forwarded-For

Custom Logging

Change log directory

Log X-Forwarded-For

Running behind a reverse proxy? Using an Elastic Load Balancer? The IP address in the log will not be of the end user, but of the reverse proxy or ELB. The end user IP will be in an HTTP header called “X-Forwarded-For”. If you’ve looked at the varnishncsa documentation, you know you can set this in two ways: use -f to “prefer X-Forwarded-For HTTP header over client.ip in the log output”, or use -F and specify a custom log format. If doing the former, this is really easy. Edit /etc/init.d/varnishncsa, and look for this line:

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

Change this by appending -f:

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

Custom Logging

Don’t like the NCSA custom log format? Want to add a field? Create your own format. However, this is a little non-intuitive. Create the format at the top of the init script, say, after defining the USER. You can get a list of the formatting options from the varnishncsa documentation.

For instance, let’s say we want to add the time before the first byte is received from the backend. This will help track how much time it takes to get a response from the backend, which could explain latencies. I’ll also want to keep the X-Forwarded-For IP instead of client IP.

I’ll just append it to the default format. So, my format string would be:

Change log directory

The first part of this is relatively straightforward. Let’s say we have a separate partition for logging, at say, /mnt/logs. We want to log to /mnt/logs/varnish instead of the default /var/log/varnish. Edit /etc/init.d/varnishncsa and set the LOGFILE variable:

This way, if the log directory and its contents are not owned by varnishlog, it’ll fix this. Note that placement here is after checking VARNISHNCSA_ENABLED and that the DAEMON exists, so it’ll only run if we’ve passed those checks.

Almost there! One other snag is that log rotation will not rotate this log. Edit /etc/logrotate.d/varnish and add the path:

Conclusion

Varnish logging isn’t the most straightforward and obvious. The above works, but is kind of kludgy: we’ve dumped a lot of stuff into the init script, and it’s highly custom to this particular installation. I created a modified version of the above that stuffs the configuration information into /etc/default/varnishncsa, but that also doesn’t feel quite right. I’d ideally like to edit, say, /etc/varnish/varnishncsa.cfg or something, but this will do. Though it’s somewhat non-intuitive, varnish is worth the effort.

Ta da! Power screen kill! I find this example interesting in the sense of the right way to approach problems: don’t necessarily just do work by hand; give a little thought to how to do things better.

The irony that the effort I saved is lost on creating this blog post is not lost on me. However, it emphasizes a good secondary skill: document what you do. Though it may take even more time, it’ll pay off in the future. It might not for the particular thing you’re documenting, but as a habit, it’s invaluable.

For whatever reason, you may have gotten collections in MongoDB that you cannot access or delete, due to their name. Maybe you led the collection name with a number, instead of a letter. Your collection name may be illegal or inaccessible for any of a variety of reasons. In my case, I had collections with names like the following: tmp.mr.mapreduce_1368742878_ec2-123-456-789-012.compute-1.awesomecloud.host_20534

In this case, it’s likely the dashes are causing issues. That’s a mouthful, so I’ll just refer to that string as ILLEGALLYNAMEDCOLLECTION. However, what’s more interesting is how you access that data. You can’t count it like so:

The ping summary stats themselves were the same, just the overall time was longer. What’s going on here? I little net research, and I had my answer: reverse DNS. I hadn’t mapped up the reverse DNS for this yet, so when I pinged by hostname, it tried to reverse map the IP in the results for each ping. You can disable this with the -n flag, and results become normal again: