Diagnosing a Drupal 7 cache generation problem

My company launched their new website recently. When we launched before Christmas we encountered a reoccurring problem that was more difficult than most to diagnose. The problem itself is very specific to our site so I doubt the exact details will help many people, but maybe the troubleshooting steps involved will prove interesting to someone. I'm not particularly proud of the time it took to track down nor our exact thought process (hardly blowing my own horn with this post) but here we go anyway.

The website platform was built for us by a third party, the technology is mostly Drupal 7 with some custom modules written for functionality we required. We wrote our own "Drupal deployment interface" that mirrors the contents of one Drupal site (our Dev server) onto our UAT or Live platform. The Live platform is a simple Apache / Drupal / Varnish stack with a load balancer in front of several web servers, the back-end is several MySQL servers.

When we deployed our final site to launch, we ran into a problem where a specific image on our front page was not displaying. Looking at the HTML source when the image is broken and we see that the image source rather bizarrely contains the hostname 127.0.0.1:

<img alt="" class="media-image" typeof="foaf:Image"
  src="http://127.0.0.1/sites/default/files/LMAX-intro-video.jpg" />

Not being Drupal 7 experts we can't code dive into it's PHP with much confidence so on comes the black box testing and some facts we discovered:

1. We confirm this section of HTML is dynamically generated - it's not a hard coded link to 127.0.0.1 someone's typed into the Drupal interface.
2. No other images are broken, just this one.
3. Looking at other images, the source of the image should be starting with "http://www.lmax.com/...".
4. If we request the correct image link directly it loads fine, so the image file is not missing nor does there appear to be a problem with Apache serving the file.
5. We restart Varnish on all web servers to see if this is problem between Varnish and Drupal but it does not fix the problem.
6. We dump all databases and grep for the offending string and pin the problem to one table.

The bad HTML is being stored in Drupal 7's cache_filter table. We delete the entry from the cache_filter table, refresh our site in a browser and the problem is solved, but unfortunately not for good.

The next day the problem re-occurred - our web developer says that he deployed a new copy of the site onto production and the image is missing again. We investigate again and find the same bad HTML on the database servers. We delete the entry from the cache_filter table again then check our website - the image is still broken. Looking back in the cache_filter table and we see that the same bad HTML has been regenerated, despite us deleting that row. Just to be sure, we truncate the entire cache_filter table on both databases and refresh - still contains 127.0.0.1. What we thought resolved our problem yesterday has not worked a second time and we now have no quick fix way of solving it.

We convey to the business that we can't fix this in five minutes and settle down for some more serious investigation. We now know:

1. The tail end of the problem is the Drupal generated HTML stored in the cache_filter table in our database(s).
2. The problem appears to occur after a deployment of new content from our Dev server to our Live servers.
3. We specifically don't restore any cache table content when doing a deployment to avoid any "stale" cache from Dev reaching Live - so after deployment, the cache tables are empty.
4. Something is continually repopulating the cache with bad HTML.

We have a UAT environment to test deployment specific problems, built for exactly these kinds of problems. We only managed to reproduce the problem once in several test deployments of the same content to our UAT environment - the issue is very intermittent on UAT and practically constant on Live. UAT does not have any load balancing normally, we add some but still cannot reproduce.

We search through the core Drupal 7 PHP code, our custom modules and contributed modules for mention of the host 127.0.0.1. It appears a few times but leads no where relevant. We also spend time playing with Varnish on UAT: we know that each Varnish server's Apache backend is configured over the loopback interface and it's written in the Varnish configuration file with '127.0.0.1'. Our work proves unhelpful there as well.

Trying a different approach, we turn on full query logging on the UAT database, deploy to UAT and browse around our website, looking for "insert into cache_filter" lines. Our thinking is to trace back through the queries for an idea of what occurs before the cache_filter insert and thus hint at what's populating this table. The UAT query log does not help much: we find the insert query but the problem has not occurred after the deployment so the cache_filter contents is correct. Other than witnessing a lot of queries against the domain table, the UAT query log is not very helpful.

We decide to turn on the full query log for one of the production MySQL servers, as we were not happy that our efforts in UAT had exhausted this avenue. We finally have our eureka moment: within seconds of turning on the log we see a queries against the domain table, but these are ever so slightly different:

SELECT domain_id, subdomain, sitename FROM domain WHERE subdomain = '127.0.0.1'

We had a general idea of the domain module and that it works by what hostname someone puts in the browser, so these queries said to us that someone or something was hitting localhost with URL requests and they are getting far enough into our web stack for Drupal to query for it. We immediately revisit Varnish but can't prove it is the cause on UAT yet again. We compare the Apache logs with the Varnish logs, we think on how UAT (unfortunately) differs to production and finally the sack of pennies drops.

The answer was in front of us the entire time - The load balancers use HTTP health checks of "GET /" against the web servers. The load balancer health checks run continuously almost every second and so when a deployment occurs against Live, the load balancers will almost always be the first request to the front page of the website. Since we effectively truncate the cache tables when we deploy, the load balancer health check triggers Drupal to repopulate it's cache. Something about the load balancer's request is causing Drupal to search for a '127.0.0.1' domain, perhaps incomplete HTTP headers, or maybe a REMOTE_HOST header of 127.0.0.1. Since we don't have a domain of 127.0.0.1 the request falls back to our default domain (a feature of the domain module) but somehow content for the front page is being generated incorrectly with details from the original request and cached.

To confirm what was only a theory at this point we changed the load balancer health check to just test the TCP connection rather than a HTTP test, waited for a request to come through and checked the site - the generated content from our request was correct. Rather than keep the TCP health check we found an example Drupal PHP script that does a minimal Drupal bootstrap to check the database health and return HTTP status codes appropriately.

The clarity of hindsight:

• When we had the issue the very first time, after deleting the bad cache_filter entry I must have refreshed the website faster than the load balancers check, hiding the problem until the next day.
• When we added the load balancer to UAT, we mustn't have set up a health check (or if so, only a TCP connection check), as we were unable to reproduce the problem in UAT. Lesson: if trying to mirror production, mirror production.

The vast majority of the problem is now worked around, but it is not solved - the issue still re-occurs every once every couple of weeks, in Live and UAT now as well. There are still several questions that I would like to answer:

1. What is the exact part of the load balancer request that caused Drupal to generate it's cache incorrectly? Is it the REMOTE_HOST header?
2. Is it just the load balancer or was Varnish also a catalyst? If we take Varnish out of the mix and just have the load balancer point to Apache directly, do we still have a problem?
3. What's causing the very infrequent re-occurrences of the problem now? Could it be the Varnish cache expiring and requesting a new copy of the object?

Like all Systems Administration problems though, it will get attention when it annoys someone enough to justify spending the time to fix it permanently. If only computers didn't exist, our lives would be so much simpler...

Sound through HDMI and an nVidia GeForce 210

Continuing on from the previous post about my new HP Microserver, I was mainly interested in seeing how the CPUs did playing a HD movie. Watching the CPU load while playing back a H.264 preview and it wasn't as bad as I expected: both cores sat around 30-60% usage, which includes background system tasks. For the usage I expect of my media server this is sufficient, it's rare that it's playing any video at the same time as anything else. It's also worth mentioning that considering the vast range of formats of most of my media it would be highly unlikely if even the majority would benefit from much offloading to the GPU, however it would be nice to have, so I was still keen on a graphics card with the necessary features.

Considering the space inside the Microserver and the positioning of the PCIe slots, I've got a rather restrictive list of graphics card requirements:

• heat sink cannot be “thicker” than the width of a PCI slot
• low profile
• nVidia (Linux drivers), preferably with a GPU with good PureVideo support
• fanless/passive
• HDMI out, but would settle for DVI

After a bit of searching and lots of squinting at images of cards trying to determine how high the heat sinks were, we found a range of Zotac GeForce 210 cards that fit the bill. The GT210 is one of the first chips to have nVidia's latest PureVideo technology (although now superseded by generation 5 and the GT520). It has a low form factor face plate replacement in the box and the heat sink is the same thickness as the slot. The card also has a HDMI port so can be my sound card as well. The exact model I ended up ordering was the Zotac ZT-20309-10L GT 210 512MB DDR3 LP Silent for £34. I would have preferred a 1GB RAM model but due to availability in the region I settled on the 512MB.

Installing the card was trickier than I thought. There's some annoying bits of metal at the back of the Micro case that the top of the graphics card's face plate was hitting. Had to bend the metal out of the way with a thin screw driver to get the card to slide back properly. Aside from that, the heat sink fits snugly along the side of the case.

HD video play back performance appears unchanged. This could be for several reasons: first off I've only attempted some very basic tuning of Ubuntu and VLC, there's surely many things I haven't tried. Secondly the format of my test MPEG-4 video may not be one that nVidia's PureVideo can offload. More importantly for me at this time is sound: Ubuntu is not playing out of the HDMI audio controller.

Some research and a lot of time later (this project was shelved for a few weeks), I've got Ubuntu playing out the nVidia audio controller. The XBMC wiki and Arch Linux forums contained the necessary tips, namely the installation of the ALSA sound modules, setting the correct options for the snd-hda-intel kernel module and loading the ALSA module into PulseAudio. The probe mask has ALSA using the nVidia codec of the card:

luke@nexus-micro:~$ grep snd-hda-intel /etc/modprobe.d/alsa-base.conf options snd-hda-intel enable_msi=0 probe_mask=0xfff2

Reboot or rmmod / modprobe, then see what device ALSA detects:

luke@nexus-micro:~$ aplay -l **** List of PLAYBACK Hardware Devices **** card 0: NVidia [HDA NVidia], device 3: HDMI 0 [HDMI 0]
Subdevices: 1/1
Subdevice #0: subdevice #0

ALSA says Card 0 Device 3 so that goes into PulseAudio :

luke@nexus-micro:~$ grep alsa /etc/pulse/default.pa load-module module-alsa-sink device=hw:0,3

And done. Next I'll be looking more into video playback performance and maybe doing a disk swap from old media server to new media server.

HP ProLiant Microserver for my new media server

Some months ago a few of us at work bought a HP ProLiant Microserver after HP were advertising a £100 cash back - 4 HDD bays, 1 optical bay, dual core Atholon II 1.3 GHz, 2 RAM slots, 1 PCIe 16x, 1 PCIe 1x and an internal USB socket. The storage potential is huge: convert the optical drive bay into a fifth 3.5” slot or maybe even several 2.5” if you are smart, boot off the internal USB slot and you've got a very cheap system that can hold 5+ HDDs.

I immediately thought of replacing my current media server with something a lot smaller and lighter. There's nothing wrong with the current one at the moment, it's even got newish 2TB disks, but it's getting on 3 years since I built it and I worry about losing my collection of music that I never listen to and the movies and TV that I never watch. Throw a fanless nVidia graphics card in there with a HDMI port and I've got a video and sound card all in one. If only a DVI port was available, a sound card could be put in the PCIe 1x slot, or worst case a USB sound card.

A few of us were stupid (including me) and bought the 160GB HDD version which is probably not covered on the cash back scheme (I don't think anyone's tried yet), but it was still only £189 for a decent amount of hardware.

The little box arrived a few days later and I'm happy with it for the price: sleek and subtle enough case for a living room, four front USB ports and two rear. An on board VGA socket, Gig Ethernet and a large slow-RPM fan at the back for ventilation to the disks. There are some chassis screws in the front door for adding extra disks (thoughtful) and there is also zero disk cable management: the SATA disks plug directly into a SAS backplane that is connected to the motherboard.


Here it is next to a Sony Vaio and 24" BenQ monitor for size comparisons.

There was some discussion at work about the power of the CPUs. The dual core Athlon II is fine for a small office file server, but how would it hold up decoding HD movies? A GPU that supported nVidia's latest PureVideo to offload as much of the decoding as possible would be helpful. Watching movies would then be less affected by other tasks the Micro is doing, in other words there would be no: “Luke, the movie's playing really slow, fix it!”.

So, the first thing I did was put Ubuntu 11.04 on the internal disk to play around with the hardware. It doesn't come standard with an optical drive and there's no PATA port (all my old PCs have PATA optical drives so no chance of salvaging one) so used a USB stick to install off. As I was poking around the optical drive bay I noticed it might prove to be a bit of a mission to get power and data cables up there. I didn't play with it too long though, there might be more avenues for cable management if you disassemble the case further.

First criticism: I'm not super keen on the level of noise at the moment. I've only got the 160GB HDD that it came with plugged in and it is about as noisy as my current media server is now with 4 HDDs. I half expected this though, I built the tower to be silent - lots of rubber feet for the disks and rubber seals on the tower chassis. It remains to be seen how well the Micro chassis holds up noise wise with all four disk bays full. Discussions at work suggest that using low power HDDs will go a way to reducing noise. I've also not looked in to lowering the fan speed. Final solution is to crank up the volume in VLC.

Secondly the internal space is very tight. The motherboard sits on the bottom and the PCIe 16x slot is closest to the side. This means that any card you put into this slot can't be much wider than the width of a PCI slot (about 1.5 cm?) or it will either make contact with the side of the case or physically won't fit at all. Finally the PCI slots are low profile so the card can't be too tall or needs to have an adjustable / replaceable face plate.

Here ends my little review of the HP ProLiant Microserver, I continue on about graphics card purchases, video play back performance and getting sound out of the HDMI port.