Drupal 9 502 alleen voor redacteuren: sessions-tabel vol

De Slack-melding kwam op een donderdag om 14:07. Een Nederlands bureau waar we mee samenwerken had een Drupal 9-site die al vier jaar rustig draaide. Plots kreeg het redactieteam, alle twaalf, een 502 Bad Gateway zodra ze een node probeerden op te slaan. Anoniem verkeer ging prima. De homepage rende. Het contactformulier verstuurde. Zoeken werkte. Zodra een redacteur inlogde en iets probeerde, smeet nginx een 502 in hun gezicht. De oorzaak bleek een sessions-tabel die stilletjes uit zijn tablespace was gegroeid, maar het kostte bijna een uur om dat te vinden.

Hun lead developer had veertig minuten besteed aan PHP-FPM herstarten, het aantal workers opschroeven en nginx-errorlogs lezen. De errorlog zei upstream prematurely closed connection while reading response header from upstream. Dat is de meest niets-zeggende regel uit onze branche. Hij vertelt je dat PHP-FPM is gestorven, niet waarom. Hij had ook memory_limit in php.ini verdubbeld en de pool herladen; geen verschil. Hij had MySQL zelf herstart, wat de bureau-lead de stuipen op het lijf joeg en verder niks deed.

Wij sloten om 14:48 aan op het gedeelde scherm. Een uur later draaide de site weer. De oorzaak was een sessions-tabel die rustig uit de InnoDB-systeem-tablespace was gegroeid op een server die sinds 2022 niemand had aangeraakt. Dit is hoe het ging.

De asymmetrie die het probleem benoemt

Het eerste wat we deden was niet naar logs kijken. We laadden de site in een incognitovenster. Homepage: prima. Artikelpagina: prima. Elk gecachet pad: prima. Daarna logden we in als testredacteur en klikten op Bewerken bij een node. 502.

Die asymmetrie is het bruikbaarste signaal in het hele incident. Anonieme bezoekers werden bediend uit Drupals interne pagecache of, in dit geval, een Varnish-laag voor nginx. Hun requests raakten nooit een schrijfbare database-session. Ingelogde gebruikers gaan per design altijd langs de pagecache heen. Elk request van een geauthenticeerde gebruiker schrijft naar de sessions-tabel om sid, timestamp en soms de session-blob zelf te verversen.

Dus de regel die we op het whiteboard schreven was: alles wat alleen kapot gaat voor ingelogde gebruikers is bijna altijd een schrijfpad. Database, bestandssysteem, of een cache die afhankelijk is van een schrijfactie. We hadden drie verdachten. Het bestandssysteem konden we uitsluiten omdat anonieme formulierposts (de contactpagina) wel werkten, dus PHP kon nog naar de tempdir schrijven. User-specifieke caches konden we uitsluiten omdat de fout direct en totaal was, niet de gebruikelijke verwarring van stale data. Bleef over: het schrijfpad naar de database.

Wat de logs werkelijk zeiden

Toen we wisten waar we moesten kijken, gaf de PHP-FPM-errorlog het echte signaal. De site draaide FPM onder een eigen pool waarvan de errorlog op /var/log/php8.1-fpm.log stond, niet op de distropad-default. De lead developer had php-fpm.log zitten tailen vanaf het pad van de package-install, dat al twee jaar leeg was. We tailden het juiste bestand tijdens een mislukte save:

PHP Fatal error:  Uncaught PDOException: SQLSTATE[HY000]: General error:
1114 The table 'sessions' is full in /var/www/drupal/web/core/lib/Drupal/
Core/Database/Statement.php:59

Error 1114 van MySQL betekent niet "de tabel heeft te veel rijen". Hij betekent "de onderliggende opslag kan geen nieuwe schrijfactie meer aan". Op InnoDB betekent dat bijna altijd dat het tablespace-bestand zijn ingestelde maximum heeft geraakt en niet meer kan autoextend'en. De MySQL-referentiehandleiding is hier ongebruikelijk duidelijk over: de systeem-tablespace krimpt niet, en als je hem afkapt, kun je de cap raken.

De site draaide op MySQL 5.7 met innodb_file_per_table op OFF, wat vroeger op sommige oudere Debian-builds de default was. Dat betekent dat elke InnoDB-tabel, inclusief sessions, in één gedeeld bestand woonde: /var/lib/mysql/ibdata1. We bekeken het:

ls -lh /var/lib/mysql/ibdata1
# -rw-r----- 1 mysql mysql 12G Jun 11 14:09 ibdata1

Daarna keken we naar de my.cnf:

innodb_data_file_path = ibdata1:10M:autoextend:max:12288M

Daar zat het. De tablespace was afgekapt op 12 GB. Hij had de cap bereikt. Geen schrijfacties meer. De sessions-tabel was toevallig de meest schrijfintensieve tabel op deze site, dus die kwam als eerste boven, maar elke andere tabel was ook gestopt met inserts accepteren. Cron faalde geruisloos. Watchdog was zes dagen geleden gestopt. Niemand had het gemerkt omdat de publieke site prima las uit de InnoDB-bufferpool, en die heeft alleen leesrechten nodig.

Waarom de sessions-tabel groeide

De sessions-tabel zelf was 4,3 GB. Voor een site met twaalf redacteuren. Dat is absurd, en de uitleg is de moeite waard.

SELECT
  table_name,
  ROUND(data_length / 1024 / 1024, 1) AS data_mb,
  ROUND(index_length / 1024 / 1024, 1) AS index_mb,
  table_rows
FROM information_schema.tables
WHERE table_schema = 'drupal'
ORDER BY data_length DESC
LIMIT 5;

Output:

+--------------------+---------+----------+------------+
| table_name         | data_mb | index_mb | table_rows |
+--------------------+---------+----------+------------+
| sessions           |  4312.0 |    180.4 |   18402231 |
| cache_render       |   904.7 |     12.1 |      44211 |
| watchdog           |   612.0 |     33.0 |    2104883 |
| cachetags          |   188.2 |      9.4 |     412009 |
| cache_dynamic_page |    91.4 |      4.0 |       9802 |
+--------------------+---------+----------+------------+

Achttien miljoen sessierijen. Drupals standaard session garbage collection draait via cron in system_cron(), maar op deze server was cron al maanden stilletjes stuk. De oorzaak was bijna gênant alledaags: een OS-upgrade van een jaar eerder had drush verplaatst van /usr/local/bin/drush naar een Composer-pad onder /var/www/drupal/vendor/bin/drush, maar de root-crontab wees nog steeds naar de oude binary. Cron vuurde keurig op schema, de shell vond de executable niet, de fout ging naar /dev/null, en de regel erboven was een logrotate die altijd met exitcode nul afsluit. De cron-mail-alias stond uit. Niets kwam bovendrijven.

Dus GC had al heel lang niet gedraaid. Elke anonieme bot die een niet-gecachet pad raakte (admin-URL's, zoekopdrachten met querystrings, bepaalde JSON:API-endpoints) schreef een sessierij. Die rijen werden nooit opgeruimd. Ze stapelden zich met honderdduizenden per dag op.

Erger nog: het row format was DYNAMIC en de session-BLOB-kolom werd opgeblazen met extra state door een contrib-module die anonieme form-build-ID's in $_SESSION bewaarde. De gemiddelde rij was 230 bytes, niet de 80 bytes die het schema zou doen vermoeden. De site werd van onderaf vergiftigd, en het enige symptoom dat iemand kon zien, was een keiharde fout op het moment dat de cap werd geraakt. De Drupal session-handling docs gaan ervan uit dat cron gezond is. Is dat niet zo, dan draai je een queue zonder limiet en zonder consumer.

De fix, in twee fases

We deden eerst het meest urgente. De site moest in de lucht.

Fase één: legen en ruimte terugwinnen

TRUNCATE TABLE sessions;

TRUNCATE op InnoDB dropt en herbouwt de tabel. Dat ruimde achttien miljoen rijen op in minder dan een seconde. Elke ingelogde gebruiker, inclusief de redacteuren die in Slack stonden te roepen, werd teruggeschopt naar het inlogscherm. Dat was acceptabel. De site kwam direct terug.

Maar de tablespace was nog steeds 12 GB. TRUNCATE geeft geen ruimte terug aan ibdata1 als file-per-table uitstaat. Je kunt de gedeelde tablespace niet in-place laten krimpen. Je moet dumpen, droppen en importeren, of overstappen op innodb_file_per_table. We deden het laatste, maar later, in het weekend: een volledige mysqldump --single-transaction --routines --triggers, een verse data-directory met innodb_file_per_table = ON, een restore, en een swap. Ongeveer vier uur database-downtime, die het bureau om 06:00 op een zondag inplande. Voor die donderdagmiddag hadden we alleen lucht nodig.

Die lucht kochten we door de cap eraf te halen:

innodb_data_file_path = ibdata1:10M:autoextend

MySQL herstarten. Nu kon het bestand voorbij 12 GB groeien. Geen lange-termijnoplossing, maar genoeg om zes maanden vooruit te kunnen terwijl we de file-per-table-migratie planden.

Fase twee: het bloeden stoppen

We zetten een cron-regel neer die werkte, gericht op de binary die er ook daadwerkelijk is:

*/15 * * * * www-data /var/www/drupal/vendor/bin/drush -r /var/www/drupal/web cron > /dev/null 2>&1

We verlaagden de session-garbage-collection-drempel in settings.php, deels om op PHP's eigen GC te leunen en deels om de lifetime te verkorten zodat de tabel minder hard kon groeien:

$settings['session_write_interval'] = 180;

ini_set('session.gc_maxlifetime', 86400);
ini_set('session.gc_probability', 1);
ini_set('session.gc_divisor', 100);

Dat zet session-GC op PHP's eigen probabilistische schema (1 op de 100 requests triggert een sweep) bovenop Drupals cron. Bretels én een riem.

We voegden ook een Telegraf-check op information_schema.tables toe, zodat we de volgende keer dat sessions de 500 MB passeerde gepiept zouden worden voordat hij voorbij de 4 GB zou gaan. De check is één regel SQL die een Grafana-paneel voedt. Niet glamoureus, en hij had het hele incident voorkomen.

Het ingehouden-adem-moment

Het lastigste deel van het incident was niet de diagnose. Het was het moment, om 14:55, dat we TRUNCATE TABLE sessions op een productiedatabase uitvoerden en onze adem inhielden. We hadden geen back-up van die tabel van eerder die dag. De nachtelijke mysqldump van het bureau was twintig uur oud. Als TRUNCATE iets had gelockt wat niet gelockt had mogen worden, of als een rij in sessions dragend was geweest voor een third-party module waar we niets van wisten (het komt voor; sommige contrib-modules gebruiken de sessions-tabel als kladblok), hadden we twintig uur CMS-werk teruggedraaid.

Dit is het deel van werken aan een legacy site waar zelden over wordt geschreven. De diagnose is afgebakend. Je kunt de MySQL-handleiding lezen. Je kunt door de codebase grepen. De destructieve write is dat niet. Je opereert op een systeem dat je niet zelf hebt gebouwd, met impliciete afhankelijkheden die je niet kunt zien. Senior engineers leren tegelijkertijd heel rustig en heel paranoïde te zijn. De bureau-lead, die al sinds Drupal 6 met Drupal werkte, was zichtbaar opgelucht toen de redacteuren om 14:58 meldden dat saves weer werkten. Wij ook.

Toen we Pier bouwden liepen we hier op genoeg klantsites tegenaan om er een hoofdfunctie van te maken: elke database-write gaat in een version history die je met één klik kunt terugdraaien, en de MySQL editor bewaart een snapshot per tabel van alles wat je de afgelopen zeven dagen hebt aangepast. De middag had dezelfde diagnose gehad, maar de TRUNCATE zou een knop met een Undo ernaast zijn geweest in plaats van een ingehouden adem.

Het kleinste wat je vandaag kunt doen

Open een shell op je grootste verouderde Drupal-bak. Draai:

SELECT table_name, ROUND(data_length/1024/1024, 1) AS mb
FROM information_schema.tables
WHERE table_schema = DATABASE()
ORDER BY data_length DESC LIMIT 10;

Staat sessions, watchdog, cache_render of een cache_*-tabel in de honderden megabytes, dan heb je huiswerk. Zit ibdata1 over de helft van zijn cap, dan zit er een Slack-ping van 14:07 in je toekomst. Zoek het uit voordat het jou vindt.