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.

Regex for IP addresses

I was lazy and went looking for an example regex to match a dotted quad IP address and was a bit surprised at how wrong some of them are.

Here's one I'm using to validate input on a web form. I'm writing it here so I can find it again easy enough.

my $IPregex = '^([1-9]|[1-9]\d|[1]\d\d|2[0-4]\d|25[0-5])\.(\d|[1-9]\d|[1]\d\d|2[0-4]\d|25[0-5])\.(\d|[1-9]\d|[1]\d\d|2[0-4]\d|25[0-5])\.(\d|[1-9]\d|[1]\d\d|2[0-4]\d|25[0-5])$';

This will match between 1.0.0.0 and 255.255.255.255, which suits my requirements.

Fedora Directory Server and Solaris 10

Now something more meaty: configuring Solaris 10 to use Fedora Directory Server as an LDAP source of users, groups and authentication. This information is sourced from the FDS Project and Sun documentation.

In order for PAM authentication to work, the Solaris 10 server needs to be recently patched. I'm not sure which patch it is specifically, but patch level 138889-07 (from 'uname -a') will be enough.

Create Fedora Directory Server profile

This step should only need to be done once per FDS cluster, multiple Solaris 10 machines can use the same profile.

Solaris takes the stance that everything should be stored in the directory server, including how to talk to the directory server. Only a minimal amount of information is stored on the Solaris host, namely which LDAP server to talk to and any proxy username and password to use to connect to the LDAP server.

A blank FDS install won't have the necessary structure or schema to support Solaris. The FDS install requires the DUAConfigProfile schema, which is available from the Fedora Project.

Once this schema is imported, there's a script on Solaris 10 that can be used to create the base directory structure that Solaris uses for LDAP. A lot of what this script creates is not used, the most important thing is the ou=profiles addition which stores instructions on how Solaris machines connect to the LDAP servers.

The script also adds a mandatory nisDomain attribute to the base of the directory. Fedora Directory Server should have a schema for the objectClass nisDomainObject, but if not, you'll have to go looking for one.

dn: dc=somedomain,dc=com,dc=au
nisDomain: somedomain.com.au
objectClass: nisDomainObject

The script is located at /usr/lib/ldap/idsconfig, it needs one slight modification to make sure it executes correctly. Here is a patch to change the allowed IDS_MAJVER to match what Fedora Directory Server presents (version 1 in this case). If after applying this patch it still complains about the wrong version, just edit the 'if' statement to allow the major version number that your version of FDS is quoting.

--- idsconfig.backup    Tue Jan 13 12:14:50 2009
+++ idsconfig   Tue Jan 13 12:18:45 2009
@@ -1191,8 +1191,8 @@
IDS_VER=`cat ${TMPDIR}/checkDSver`
IDS_MAJVER=`${ECHO} ${IDS_VER} | cut -f1 -d.`
IDS_MINVER=`${ECHO} ${IDS_VER} | cut -f2 -d.`
-    if [ "${IDS_MAJVER}" != "5" ] && [ "${IDS_MAJVER}" != "6" ]; then
-       ${ECHO} "ERROR: $PROG only works with JES DS version 5.x and 6.x, not ${IDS_VER}."
+    if [ "${IDS_MAJVER}" != "5" ] && [ "${IDS_MAJVER}" != "6" ] && [ ${IDS_MAJVER}" != "1" ]; then
+       ${ECHO} "ERROR: $PROG only works with JES DS version 5.x and 6.x and FDS 1.1.3, not ${IDS_VER}."
exit 1
fi
if [ $DEBUG -eq 1 ]; then 

Execute this script and answer a series of questions to create the default profile. You can edit these on the Fedora Directory Server later, or rerun the script as necessary. Questions you want to pay particular attention to are:

1. Default server list - space separated list of LDAP servers, you may have more than one.
2. Credential level - can you do user/group searches anonymously or do you need to bind first?
3. Setup Service Authentication Method - you'll probably want to create a 'pam_ldap' auth method of type 'simple' while you're here.
4. Setup Service Search Descriptors - you may want to setup search descriptors for different services if your LDAP directory is large.

Once the changes are committed, the script will execute a series of ldapmodify's to create the base structure and default profile. Run an ldapsearch for the newly created profile and sanity check what you've entered. The profile name will change depending on what you answered to the question:

[root@solaris10]$ ldapsearch -h ldap.somedomain.com.au -p 389 -b "cn=default,ou=profile,dc=somedomain,dc=com,dc=au" "objectClass=*"

version: 1
dn: cn=default,ou=profile,dc=somedomain,dc=com,dc=au
credentialLevel: anonymous
defaultServerList: 1.2.3.4 5.6.7.8
authenticationMethod: simple
serviceAuthenticationMethod: pam_ldap:simple
defaultSearchBase: ou=Staff,dc=somedomain,dc=com,dc=au
serviceSearchDescriptor: passwd:ou=Users,dc=somedomain,dc=com,dc=au?sub
serviceSearchDescriptor: shadow:ou=Users,dc=somedomain,dc=com,dc=au?sub
serviceSearchDescriptor: group:ou=Groups,dc=somedomain,dc=com,dc=au?sub
objectClass: top
objectClass: DUAConfigProfile
followReferrals: FALSE
defaultSearchScope: sub
searchTimeLimit: 10
profileTTL: 43200
cn: default
bindTimeLimit: 10

Configure Solaris 10 for LDAP

Once you have a profile you can tell Solaris 10 servers to use this profile to configure themselves for LDAP. The /usr/sbin/ldapclient command does this. It requires only enough information to find the profile, namely the LDAP server, profile name, plus any proxy credentials that are needed to search for the profile (if you can't ldapsearch it anonymously):

ldapclient -v init -a profileName=default -a domainname=somedomain.com.au ldap.somedomain.com.au

Watch the output of this command to make sure it succeeds. If all is good so far you will be able to run /usr/bin/ldaplist group and /usr/bin/ldaplist passwd, as well as id username and groups username, which will all query LDAP.

Fix Domain Name Resolution

The ldapclient command replaces /etc/nsswitch.conf with a very heavy LDAP configuration, which may not be what you're after. I always correct the hosts line in nsswitch.conf as we don't store host information in LDAP, you can remove a lot more if you wish:

hosts:      ldap [NOTFOUND=continue] files dns

PAM authentication with LDAP

With user and group lookups working, you'll want to be able to authenticate as your LDAP users. Here is a sample PAM configuration that adds the pam_ldap module to several services:

#
# Authentication management
#
# login service (explicit because of pam_dial_auth)
#
login auth requisite pam_authtok_get.so.1
login auth required pam_dhkeys.so.1
login auth required pam_unix_cred.so.1
login auth required pam_dial_auth.so.1
login auth binding pam_unix_auth.so.1 server_policy
login auth required pam_ldap.so.1
#
# rlogin service (explicit because of pam_rhost_auth)
#
rlogin auth sufficient pam_rhosts_auth.so.1
rlogin auth requisite pam_authtok_get.so.1
rlogin auth required pam_dhkeys.so.1
rlogin auth required pam_unix_cred.so.1
rlogin auth binding pam_unix_auth.so.1 server_policy
rlogin auth required pam_ldap.so.1
#
# rsh service (explicit because of pam_rhost_auth,
# and pam_unix_auth for meaningful pam_setcred)
#
rsh auth sufficient pam_rhosts_auth.so.1
rsh auth required pam_unix_cred.so.1
rsh auth binding pam_unix_auth.so.1 server_policy
rsh auth required pam_ldap.so.1
#
# PPP service (explicit because of pam_dial_auth)
#
ppp auth requisite pam_authtok_get.so.1
ppp auth required pam_dhkeys.so.1
ppp auth required pam_dial_auth.so.1
ppp auth binding pam_unix_auth.so.1 server_policy
ppp auth required pam_ldap.so.1
#
# Default definitions for Authentication management
# Used when service name is not explicitly mentioned for authentication
#
other auth requisite pam_authtok_get.so.1
other auth required pam_dhkeys.so.1
other auth required pam_unix_cred.so.1
other auth binding pam_unix_auth.so.1 server_policy
other auth required pam_ldap.so.1
#
# passwd command (explicit because of a different authentication module)
#
passwd auth binding pam_passwd_auth.so.1 server_policy
passwd auth required pam_ldap.so.1
#
# cron service (explicit because of non-usage of pam_roles.so.1)
#
cron account required pam_unix_account.so.1
#
# Default definition for Account management
# Used when service name is not explicitly mentioned for account management
#
other account requisite pam_roles.so.1
other account binding pam_unix_account.so.1 server_policy
other account required pam_ldap.so.1
#
# Default definition for Session management
# Used when service name is not explicitly mentioned for session management
#
other session required pam_unix_session.so.1
#
# Default definition for Password management
# Used when service name is not explicitly mentioned for password management
#
other password required pam_dhkeys.so.1
other password requisite pam_authtok_get.so.1
other password requisite pam_authtok_check.so.1
other password required pam_authtok_store.so.1 server_policy
#
# Support for Kerberos V5 authentication and example configurations can
# be found in the pam_krb5(5) man page under the "EXAMPLES" section.
# 

Limit Login Access

By default the ldapclient command will have modified the passwd and shadow to use LDAP:

passwd:        files ldap
group:         files ldap

This will allow all users with a valid login shell access to the Solaris host, which may not be what you desire. You could limit the scope of the user search in the profile using a service search descriptor like:

serviceSearchDescriptor: passwd:ou=IT,ou=Users,dc=somedomain,dc=com,dc=au?sub

However it's probably more flexible to limit login access through other Solaris means. A very quick way is to put NSS passwd lookups into NIS compatability mode so you can use the old style +/- notations in the passwd file. To avoid any hassles later on, disable nscd from caching anything for us:

svcadm disable svc:/system/name-service-cache:default

Edit /etc/nsswitch.conf and put the passwd file into NIS compatabillity mode:

passwd: files compat
group: files ldap
passwd_compat: ldap

We can then modify /etc/passwd and /etc/shadow to allow and deny users. To add a user, the +username notation is used. You can override any fields in the passwd file, for example you could force everyone's shells to be /bin/sh. The first two lines below in the passwd and shadow files add user1 and user2 without any modifications. The third line adds all users but modifies their shell to something invalid so they cannot log in. You could simply omit the 'all users' include, however there may be situations where you want the UID lookups to occur without allowing everyone to login.

/etc/passwd
...
+user1::::::
+user2::::::
+::::::/usr/bin/false

/etc/shadow
...
+user1::::::::
+user2::::::::
+::::::::

To make sure only the users you really want to log in have valid shells, use getent passwd to list passwd file entries. If you use the 'all users' include above, the same user will be listed multiple times with different shells. Remember that the first username key found is what is used.

Don't forget to re-enable nscsd when you're done:

svcadm enable svc:/system/name-service-cache:default

A better method would be to implement Linux's pam_access.so module instead of using the dated NIS compatability mode, but this module is not in Solaris 10 by default. Hopefully I can find a package for pam_access some time in the near future, otherwise I'll be building it myself.

SSH SOCKS5 tunnel with PuTTY in Windows

First post, very simple, but something that took me longer than I thought it would to find an answer to online. In Linux it's very easy to use ssh to create a SOCKS5 proxy tunnel through your SSH target. You then point a browser at localhost and some arbitrary port you specify, thus masquerading your local browser as the machine you're SSHed into:

ssh -D 12345 username@remotehost.com.au

The same can be done on Windows just as easily with PuTTY. Download it if you haven't already and put a copy in %SYSTEMROOT% (C:\Windows\). In the Run dialog or search box, enter:

putty -D 12345 username@remotehost.com.au

Login to the remote host. Change Firefox's SOCKS proxy setting to be 'localhost' and whatever port you specify (12345) and browse away.