PHP session race: de verkeerde factuur-PDF in de mail

De Loom kwam binnen om 23:41. Een Nederlands bureau waar we mee samenwerken had de avond doorgebracht met het uitleggen aan hun klant waarom hun factuurportaal een PDF had gemaild die gericht was aan een heel ander bedrijf. Hetzelfde sjabloon, verkeerd logo, verkeerd btw-nummer, verkeerde regels. De klant had de mail gescreenshot en beleefd gevraagd of ze zich zorgen moesten maken over hun gegevens.

Ze draaiden een custom-PHP factuurportaal dat sinds 2014 in productie stond. PHP 7.4, kale MySQL, geen framework, drie include-bestanden bovenaan elk script. Het type legacy site dat jarenlang vlekkeloos draait en dan, op een dinsdagavond, iets doet waardoor je voor het slapengaan de OWASP top tien er nog eens bij pakt.

We hebben de volgende zes uur session_start() de schuld gegeven. De bug zat ergens anders.

De drie verdachte includes

Elke pagina in het portaal begon met dezelfde boilerplate:

<?php
require __DIR__ . '/inc/config.php';
require __DIR__ . '/inc/session.php';
require __DIR__ . '/inc/auth.php';

config.php zette de PDO-connectie op plus een paar constanten. session.php riep session_name('PORTAL') aan en daarna session_start() met session.use_strict_mode aan. auth.php las $_SESSION['uid'], zocht de gebruiker op en stuurde door naar de loginpagina als er iets niet klopte. Niets exotisch. Dezelfde bootstrap die we hebben gelezen in pakweg tweehonderd legacy PHP-projecten.

Het download-endpoint, /invoice.php?id=123, deed vervolgens dit:

$id  = (int) $_GET['id'];
$inv = $db->invoice($id, $_SESSION['uid']);
if (!$inv) { http_response_code(404); exit; }

header('Content-Type: application/pdf');
header('Content-Disposition: attachment; filename="' . $inv['number'] . '.pdf"');
echo render_pdf($inv);

Die query was afgebakend op de sessie-gebruiker. We hebben hem met de hand opnieuw gedraaid tegen de database met het getroffen factuur-ID en het getroffen gebruikers-ID, en hij gaf netjes NULL terug. De PHP-code weigerde dus die factuur aan die gebruiker te sturen. En toch had de gebruiker hem ontvangen. Twee keer.

Zes uur binnen session_start()

De eerste hypothese was de voor de hand liggende: een session_start()-race. Eerder dat jaar had iemand een "factuur opnieuw versturen"-cron in elkaar geschroefd, en we hadden een vage herinnering aan CLI-code die $_SESSION aanraakte op manieren waar niemand trots op was. We hebben het gecheckt. De cron raakte sessies niet aan. Hij bouwde zijn eigen auth-context op uit een service-account-token.

De volgende hypothese was session locking. PHP serialiseert standaard requests op hetzelfde session-bestand. Twee AJAX-calls die uit dezelfde browser vertrekken, gaan in de wachtrij, de een achter de ander, omdat session_start() een exclusief lock neemt op het session-bestand en dat vasthoudt tot session_write_close() of het einde van het script. De php.net-toelichting bij session_write_close legt de lock-semantiek in drie regels uit, mocht je hem een tijd niet meer hebben gelezen. We hebben de access logs nageplozen op overlappende requests op dezelfde sessie. Niets binnen vijf seconden van de verkeerde PDF.

Daarna hebben we de custom session handler ondersteboven gekeerd. Het portaal sloeg sessies op in MySQL in plaats van op disk, waardoor we even hoopten dat een bug in de read- of write-callback de verwisseling kon verklaren. We hebben de sessions-tabel gedumpt op het moment van een getroffen download en de rij met de hand geïnspecteerd. De session_data-blob deserialiseerde netjes. Elk veld kwam overeen met het audit log van recente klantactiviteit. De handler loog niet.

Toen werden we serieus. We hebben een logregel toegevoegd aan session.php, direct na session_start():

error_log(sprintf(
    '[sess] pid=%d sid=%s uid=%s uri=%s',
    getmypid(),
    session_id(),
    $_SESSION['uid'] ?? 'none',
    $_SERVER['REQUEST_URI']
));

De logs waren saai. Elke request had een session-ID. Elke session-ID mapte naar één en slechts één gebruiker. We hebben de log getailed op de productiebak en de getroffen klant gevraagd een factuur opnieuw te downloaden. De regel die we zagen klopte. Hun session-ID. Hun gebruikers-ID. Het juiste factuurnummer in de URL. En vervolgens hoorde de PDF die terugkwam bij iemand anders.

Tegen het vierde uur waren we in de fase van debuggen aanbeland waarin iedereen in de kamer akkoord gaat met het ding dat ze hadden willen vermijden. We draaiden strace -f op de PHP-FPM workerpool tijdens een reproductiepoging. De worker die de getroffen request afhandelde, opende het PDF-bestand van de factuur nooit. Hij raakte de database niet aan. Voor zover het syscall-log betrof, deed dat PHP-proces helemaal geen werk voor de request die een PDF teruggaf.

Dat was het moment dat de vloer bewoog.

Waar de verwisseling echt plaatsvond

Het portaal stond achter nginx. De vorige ops-contractor van het bureau had ergens in 2022 fastcgi_cache aangezet om PHP-FPM te ontlasten tijdens de factuurronde aan het einde van de maand. De config zag er, met vermoeide ogen, zo uit:

fastcgi_cache_path /var/cache/nginx/portal levels=1:2
    keys_zone=PORTAL:50m max_size=2g inactive=30m;

location ~ \.php$ {
    fastcgi_cache       PORTAL;
    fastcgi_cache_key   "$scheme$request_method$host$request_uri";
    fastcgi_cache_valid 200 10m;
    fastcgi_pass        unix:/run/php/php7.4-fpm.sock;
    include             fastcgi_params;
}

Lees de regel met fastcgi_cache_key langzaam. Hij is opgebouwd uit scheme, method, host en URI. Hij bevat niet de PORTAL-sessiecookie. Hij bevat niet de Authorization-header. Hij bevat helemaal niets dat de aanvragende gebruiker identificeert.

Het download-endpoint was /invoice.php?id=123. De eerste gebruiker die die URL aansprak nadat de cache koud was, kreeg zijn PDF gerenderd, teruggestuurd en opgeslagen in /var/cache/nginx/portal onder een sleutel die puur uit de URI was afgeleid. Elke andere geauthenticeerde gebruiker die de tien minuten daarop een factuur met hetzelfde numerieke ID downloadde, kreeg de PDF van die eerste gebruiker, byte voor byte, zonder dat er PHP werd uitgevoerd. De session-logregel die we hadden toegevoegd, vuurde voor die requests nooit. nginx serveerde de gecachte response en de request bereikte PHP-FPM nooit.

De reden dat het ons zes uur kostte: factuur-ID's zijn meestal opeenvolgend en per klant afgebakend, dus botsingen op hetzelfde ID tussen klanten zijn zeldzaam. De reden dat het deze week brak: het bureau had die dag drie klanten gemigreerd vanuit een verouderde tabel naar het portaal, en de geïmporteerde facturen behielden hun oude ID's. Twee van de geïmporteerde ID's botsten met bestaande ID's van een andere klant. Dat was de trigger. Al het andere was nginx die precies deed wat wij hem opgedragen hadden.

We bevestigden het met één extra regel in de nginx-config. add_header X-Cache-Status $upstream_cache_status always;, reloaden, de klant vragen opnieuw een factuur te downloaden, de response bekijken. De header kwam terug als HIT. Dat was het bewijs dat we nodig hadden. De PHP-code had niet gefaald. Hij was simpelweg niet aangesproken. nginx had de vraag zelf beantwoord, vanuit een stale entry, met een sleutel die niet wist wie er vroeg.

De fix, en wat we onderweg nog tegenkwamen

De minimale patch was drie regels. Vertel nginx om niets te cachen van geauthenticeerde gebruikers, en vertel PHP om de headers mee te sturen die elke toekomstige cachelaag dat laten respecteren.

location ~ \.php$ {
    fastcgi_cache       PORTAL;
    fastcgi_cache_key   "$scheme$request_method$host$request_uri$http_cookie";
    fastcgi_cache_bypass $cookie_PORTAL;
    fastcgi_no_cache    $cookie_PORTAL;
    fastcgi_pass        unix:/run/php/php7.4-fpm.sock;
    include             fastcgi_params;
}

En in invoice.php, de headers die we vanaf dag één hadden moeten meesturen:

header('Cache-Control: private, no-store, max-age=0');
header('Pragma: no-cache');

De MDN-referentie over Cache-Control is het waard om opnieuw te lezen elke keer dat je een download-endpoint bouwt. private alleen is niet genoeg als je reverse proxy zo geconfigureerd is dat hij Cache-Control volledig negeert, en dat doet fastcgi_cache standaard, tenzij je er expliciet voor kiest via fastcgi_ignore_headers. Beide lagen moeten het eens zijn. De nginx fastcgi_cache-documentatie zegt dit verspreid over ongeveer zeven alinea's.

Terwijl we daar toch bezig waren, hebben we ook een harde ownership-check toegevoegd aan de factuurquery, niet alleen een fetch die op de sessie was afgebakend:

$inv = $db->invoice($id);
if (!$inv || $inv['user_id'] !== $_SESSION['uid']) {
    http_response_code(404);
    exit;
}

De oorspronkelijke query was "correct" in de zin dat hij in de WHERE-clausule op gebruiker filterde, maar defensieve ownership-checks op applicatieniveau maken de volgende bug van deze soort vanzelfsprekend zichtbaar in code review. Een query die op ID ophaalt en daarna ownership controleert, is makkelijker te auditen dan een query die ownership in een JOIN verstopt.

Verificatie was eenvoudig en traag. We hebben /invoice.php aangesproken vanuit twee browsers die als twee verschillende gebruikers waren ingelogd, tien seconden uit elkaar, met hetzelfde factuur-ID in de URL. Beide responses kwamen terug met X-Cache-Status: BYPASS. We hebben uitgelogd, een niet-geauthenticeerde marketingpagina op dezelfde vhost aangesproken en gekeken hoe de cache normaal werkte op een publieke asset. We hebben X-Cache-Status permanent in de response-headers laten staan. Het is één regel extra en het beantwoordt een vraag waar we vijf uur lang het antwoord niet op kregen.

Wat we daarna lieten draaien

Toen de directe brand geblust was, hebben we drie kleine monitoring-stukjes toegevoegd die het portaal zes jaar lang had moeten missen.

Het eerste was een synthetische check. Een speciale test-gebruiker logt elke vijftien minuten in, downloadt een bekende factuur, en het script verifieert dat de SHA-256 van de response overeenkomt met een vastgelegde baseline. Als een tweede test-gebruiker onder een andere tenant ooit dezelfde SHA krijgt voor een ander factuur-ID, gaat het alert af voordat een echte klant het merkt.

Het tweede was een dagelijkse grep over het nginx access log naar elke HIT op een pad dat begint met /invoice of /account. Op die paden hoort nooit een cache hit te staan. Als er toch een opduikt, is er iets in de cache-config geregresseerd en willen we dat op maandagochtend weten, niet op een vrijdagavond als de klant aan het screenshotten is.

Het derde was een jaarlijkse kalenderafspraak in de gedeelde agenda van het bureau om de nginx-config van boven tot onder opnieuw te lezen. Caching-regels schuiven. Commentaar veroudert. De volgende contractor weet niet meer waarom fastcgi_no_cache op de sessiecookie is gezet, en zal in de verleiding komen om het op te ruimen.

De audit die niemand wilde schrijven

Het zwaarste deel van het incident was niet de fix. De fix was drie regels nginx en twee regels PHP. Het zware deel was de vraag beantwoorden die om 09:00 de volgende ochtend kwam: welke facturen, precies, zijn naar welke klanten gegaan? Het bureau moest aan drie van zijn eigen klanten vertellen of hun btw-nummer, bankgegevens en factuurregels door een ander bedrijf waren gezien.

We hadden nginx access logs van negentig dagen terug. We hadden de cache-directory op disk. We hadden geen registratie van welke response-body uit de cache was geserveerd versus live gerenderd, en geen registratie van welk bestand in de cache-directory op het moment van elke hit aan welke URI was gekoppeld. nginx schrijft dat niet op. Je kunt het meeste reconstrueren uit log-timestamps en de KEY:-header in het cache-bestand, maar "het meeste" is niet het woord dat een compliance-officer wil horen.

Uiteindelijk hebben we de melding aan de drie getroffen klanten op woensdagmiddag verstuurd. Twee reageerden binnen een uur, stelden een of twee verduidelijkende vragen over welke velden zichtbaar waren geweest, accepteerden de uitleg. De derde wilde een geschreven incidentrapport op briefpapier, wat de versie van dit gesprek is die een week kost om af te sluiten. Geen van hen vertrok. De eigenaar van het bureau vertelde ons achteraf dat de excuusmail langer duurde om op te stellen dan de patch om te schrijven, en dat voelde ongeveer juist.

Toen we Pier bouwden liepen we van de andere kant tegen exact dit soort probleem aan. Pier schrijft version history voor elk bestand dat via de app wordt aangeraakt en elke rij die via de MySQL editor wordt geschreven, zodat het antwoord op de vraag "wat heeft deze server nou echt geserveerd, en wie heeft daarvoor wat aangepast" in de log staat in plaats van in je geheugen.

Het kleinste ding dat vandaag de moeite waard is: open de nginx-config van de oudste PHP-site die je beheert, grep op fastcgi_cache_key en controleer of de sleutel iets bevat dat de aanvragende gebruiker identificeert. Zo niet, en de site authenticeert wie dan ook, dan heb je dezelfde bug als wij. Je hebt er alleen nog geen rekening voor gepresenteerd gekregen.