Drupal 9 read-only om 16:08: een /tmp-inode-verhaal

De 16:08-melding

De Loom kwam binnen om 16:08 op een dinsdag. Een lead bij een Nederlands bureau waar we mee samenwerken had een Drupal 9-corporate site die, in zijn woorden, "online stond maar kapot was op een manier die ik niet herken". De homepage renderde. Ingelogde redacteuren konden de admin nog laden. Maar elke poging om iets op te slaan eindigde in een wit scherm, elke webform-submissie faalde stilletjes, en elke vers geüploade afbeelding gaf de tweede keer dat hij werd opgevraagd een 500.

Hij had de voor de hand liggende dingen al gedaan voordat hij de Loom opnam. Drupal's cache geleegd met drush cr, wat zelf halverwege een fout gooide. php-fpm herstart. nginx herladen. Watchdog getailed: geen nieuwe entries in de laatste veertig minuten. Dat was eigenlijk al de eerste echte aanwijzing, als je het wist te lezen. Een CMS dat niet meer naar zijn eigen logtabel schrijft, is geen gezond CMS.

Het hostingdashboard liet 39 procent schijfgebruik zien. Memory zag er prima uit. Load average stond op 0.42. Er stond niets opvallends in de nginx-access log, alleen een rustig stroompje bots. In de PHP-error log stond een zee aan identieke regels:

PHP Warning:  file_put_contents(/tmp/...): failed to open stream: No space left on device

No space left on device. Op een schijf die 39 procent vol zat.

Die melding is de aanwijzing, maar alleen als je er eerder mee bent gebeten. Linux geeft ENOSPC terug bij twee verschillende situaties: het block device is door zijn data blocks heen, of het filesystem is door zijn inodes heen. De error string is hetzelfde. De fix niet.

Inodes lezen, geen bytes

Drie commando's regelden de diagnose binnen een minuut.

df -h /tmp
# Filesystem      Size  Used Avail Use% Mounted on
# /dev/vda1        80G   30G   46G  39% /

df -i /tmp
# Filesystem     Inodes  IUsed IFree IUse% Mounted on
# /dev/vda1        5.0M   5.0M     0  100% /

ls /tmp | wc -l
# 4128911

Vijf miljoen inodes gealloceerd toen het filesystem werd aangemaakt. Vier komma één miljoen bestanden op dit moment in /tmp. Niets anders op de partitie had nog ruimte om ook maar één nieuw bestand weg te schrijven, en dus faalde alles wat de temp directory raakte.

Inodes zijn een structuur van vaste grootte die ext4 alloceert tijdens het formatteren, één per bestand of directory. De standaardverhouding op de meeste distributies is één inode per 16 KB. Eenmaal op, zijn ze op, totdat je herformatteert of extra opslag toevoegt. De ext4-designnotes zijn er duidelijk over: het inode-aantal is een eigenschap van het filesystem op het moment van mkfs, geen runtime-tunable. Dat de schijf 39 procent vol was, was irrelevant. De site kon geen enkele session opslaan, geen enkele cache-entry wegschrijven, geen enkele upload accepteren.

Wat dit zo lang verborgen heeft gehouden, is dat vrijwel elk hostingdashboard, elke "disk usage"-alert en elke goedkope monitoring-agent bytes meet, geen inodes. De percentagemeter in het controlepaneel kroop al een jaar lang met tienden van procenten omhoog en niemand had reden om te kijken. Een inode-meter staat in de meeste panels gewoon niet. Als die er wel was, was deze melding in maart als waarschuwing binnengekomen, niet als brand in oktober.

De temp directory tellen

Een uitsplitsing van /tmp op bestandspatroon vertelde ons waar we moesten graven.

find /tmp -maxdepth 1 -type f -name 'sess_*'   | wc -l
# 4112740

find /tmp -maxdepth 1 -type f -name 'twig_*'   | wc -l
# 8

find /tmp -maxdepth 1 -type f -name 'phpinfo*' | wc -l
# 0

find /tmp -maxdepth 1 -type f -name 'image_*'  | wc -l
# 14

Vier komma één miljoen PHP-sessionbestanden. Geen enkele jonger dan negen maanden. Het nieuwste sess_*-bestand in de directory was ouder dan de laatste Drupal core-update van het bureau. Wat dan ook geacht werd ze op te ruimen, had bijna een jaar lang niet gedraaid.

De oorzaak bleek een combinatie van twee bekende maar makkelijk over het hoofd geziene defaults. Debian en Ubuntu leveren php.ini met session.gc_probability = 0, waarmee PHP's eigen session garbage collector bewust wordt uitgeschakeld. De verwachting is dat /etc/cron.d/php elke dertig minuten sessionclean draait om oude sessions op te ruimen. Dat cron-bestand wordt met het php-common-pakket meegeleverd. Op deze server stond het bestand er, maar een eerdere admin had php-fpm met de hand aangepast naar session.save_path = /tmp in plaats van Debian's default /var/lib/php/sessions. De cron-job kijkt naar het default pad. Hij heeft een jaar lang elke dertig minuten een lege directory geveegd, terwijl /tmp ernaast vol liep.

Dit is zo'n config-drift die heel lang niets doet en dan in één middag alles sloopt. Er staat een korte opmerking over precies deze valkuil in de Debian PHP-wiki waarvan ik wou dat meer overdrachtsdocumenten ernaar verwezen.

De fix die bleef plakken

Een werkende session cleanup was de directe fix. Een nieuw /tmp-beleid was de blijvende.

Eerst hebben we de backlog opgeruimd. rm -rf /tmp/* is de verkeerde reflex, want dat sloopt screen-sockets, X11-sockets, systemd-private directories en actieve sessionbestanden van iedereen die toevallig is ingelogd. Gericht werken is beter.

find /tmp -maxdepth 1 -type f -name 'sess_*' -mtime +1 -delete

Dat draaide ongeveer negentig seconden en gaf zo'n 4,1 miljoen inodes vrij. df -i zakte naar 2 procent gebruik. De site sloeg alweer op voordat het find-commando klaar was.

Daarna hebben we de session-opslag teruggezet waar de Debian-cron hem verwachtte.

; /etc/php/8.2/fpm/php.ini
session.save_path = /var/lib/php/sessions
session.gc_maxlifetime = 1440

Toen we de config toch openhadden, hebben we ook Drupal's eigen temp directory weggehaald bij /tmp. Drupal 9 leest $settings['file_temp_path'] uit settings.php en valt terug op PHP's sys_get_temp_dir() als die niet gezet is. Door die fallback ging elk geüpload bestand, elke image-style-afgeleide en elk geaggregeerd CSS-bestand via /tmp op weg naar zijn uiteindelijke plek in public://. Een vast pad houdt Drupal's verkeer volledig uit de system temp directory.

// sites/default/settings.php
$settings['file_temp_path'] = '/var/www/example.com/private/tmp';

Tot slot hebben we een extra cron toegevoegd die alles in /tmp dat ouder is dan een dag opveegt, plus een monitoring-check die alarmeert zodra het inode-gebruik boven de 70 procent komt.

# /etc/cron.d/tmp-sweep
17 4 * * * root find /tmp -maxdepth 1 -type f -mtime +1 -delete

# Inode check for the monitoring agent
df -i / | awk 'NR==2 {gsub("%",""); if ($5+0 > 70) exit 2; else exit 0}'

Om de nieuwe opstelling te verifiëren wachtten we een uur, logden een verse redacteur in en zagen de sessionbestanden onder /var/lib/php/sessions verschijnen met de juiste ownership en mode. We draaiden sessionclean van de distro met de hand om te bevestigen dat hij nu een echte directory had om naar te kijken. Het uploadveld, het luidste symptoom, hebben we getest met een afbeelding van 4 MB; de afgeleide landde op de plek waar file_temp_path naar wees en werd zonder /tmp aan te raken naar public:// verplaatst. Die verificatie van vijf minuten is wat "het werkt nu" onderscheidt van "het werkt ook nog voor de volgende admin die dit erft".

Dat soort check verdient zichzelf eens in de twee jaar terug en lijkt de rest van de tijd ruis. De moeite waard.

De stille faalmodi van Drupal

De onderliggende oorzaak was een verkeerd geroute PHP-sessionpad, wat niets met Drupal te maken heeft. Dat een bureau-lead er twintig minuten over deed om het probleem terug te brengen tot "iets in de filesystem-hoek", is wel degelijk een Drupal-verhaal.

Drupal 9 verbergt verrassend veel storingen achter een generieke witte error of een stille webform-500. De image-module zet een afgeleide in de wachtrij en vertelt je niet dat hij niet weggeschreven kon worden. De file-module accepteert een upload en klaagt pas bij de uiteindelijke move. De cache-backends slikken een schrijfprobleem en serveren een stale pagina. Dat is geen defect. Het is de prijs van een CMS dat probeert om alles wat het kan tóch te blijven renderen. Maar het betekent ook dat zodra een site in de toestand "online maar kapot op een manier die ik niet herken" belandt, de symptomen naar de symptomen wijzen, niet naar de oorzaak.

Je leert om eerst de oninteressante dingen te checken: disk, inodes, file permissions, de PHP-error log, de cron-log, het systemd-journal. De system requirements-pagina van Drupal zelf is nuchter over het feit dat de temp directory schrijfbaar moet zijn, maar niets in core waarschuwt wanneer de temp directory die uiteindelijk gebruikt wordt het system /tmp is, of wanneer die directory over de helft van zijn inode-budget heen is. Daar is ruimte voor een kleine status report-check. Tot die er is, schrijf je hem zelf.

De volgende site dichttimmeren

De checklist die we bij de post-mortem hebben opgeleverd is kort en het waard om in elk Drupal-overdrachtsdocument te plakken.

• Zet $settings['file_temp_path'] expliciet in elke omgeving. Laat het nooit terugvallen op sys_get_temp_dir().
• Zet session.save_path vast in php-fpm en controleer of de session cleanup-cron van de distro naar hetzelfde pad wijst. cat /etc/cron.d/php is de bron van waarheid.
• Alerteer op inode-gebruik, niet alleen op schijfgebruik. df -i en df -h kunnen flink van elkaar afwijken.
• Voeg periodiek find /tmp -maxdepth 1 -type f -mtime +N -delete toe als vangnet, ook als de applicatie denkt dat hij zelf opruimt.
• Als een Drupal-site kapot is op een manier die niemand herkent, lees dan de PHP-error log voor watchdog. Watchdog heeft een schrijfbare database-connectie en een schrijfbare temp directory nodig om überhaupt een bericht vast te leggen.

Toen we Pier bouwden, hadden we tooling voor precies dit soort forensisch rondspitten in een verouderde site in gedachten. De chat dockt met de live FTP en MySQL, dus het inode-aantal checken, de temp directory op bestandspatroon scannen of file_temp_path vastzetten in settings.php gebeurt allemaal tegen de draaiende site zonder SSH-sessie. Elke bewerking landt met versiegeschiedenis eraan vast, en de MySQL-editor is één tab verderop als de volgende vraag is "is de variable-tabel daadwerkelijk geüpdatet?"

Het kleinste wat vandaag de moeite waard is, op elke Drupal-site die je onderhoudt, is één commando: df -i. Zit een partitie boven de 60 procent, dan heb je weken, geen maanden, voordat er stilletjes iets sneuvelt. Zet de temp-paden vast en zet de sweep-cron nu klaar, nu er nog niets in de fik staat.