Vai al contenuto

Il bug count(null) su PHP 8.4: trovato in 6 ore di blameless postmortem

Il bug count(null) su PHP 8.4: trovato in 6 ore di blameless postmortem

Il bug count(null) su PHP 8.4: trovato in 6 ore di blameless postmortem

Martedì 17 giugno, 9:14. Alert PagerDuty: spike di HTTP 500 sul sito di un cliente WordPress, frequenza intermittente, circa 1 request su 100. Niente di catastrofico in valore assoluto, ma un pattern non deterministico che è la cosa peggiore: non puoi dare al dev una request da riprodurre, e gli alert non scalano in modo lineare con l’utenza, salgono e poi calano da soli. Sei ore dopo, alle 15:30, il fix temporaneo era in produzione e l’error rate sotto lo 0,1%. Tre settimane dopo, il fix definitivo era una pull request mergiata upstream sul plugin colpevole. In mezzo, un postmortem blameless con un dev senior in screen share, che racconto qui per intero. Vedi anche gli altri post di questa rubrica: Production.

Il contesto: PHP 8.4 da pochi mesi

Il sito girava su PHP 8.4 da circa due mesi. La migrazione l’avevamo pianificata seguendo lo stesso schema che avevamo applicato sull’upgrade a 8.0 nei primi mesi del 2024: staging clone, smoke test sui template principali, deprecation log abilitato per intercettare i warning, due settimane di canary su un sotto-traffico, poi promote. La 8.4 era passata pulita, deprecation count quasi a zero, smoke test verde. Il sito stava sotto i 200ms di TTFB mediano, error rate sotto lo 0,01%. Niente di sospetto fino al 17 giugno.

L’endpoint che tirava 500 era una pagina pubblica, lato frontend, con un’integrazione che chiamava un plugin di image optimization molto diffuso nell’ecosistema WordPress. Il plugin lavorava su get_post_meta per leggere metadata associati ai media, e in determinate condizioni il valore restituito era trattato come array. Le condizioni esatte erano la parte difficile da identificare.

Triage: dal log nginx a xdebug in produzione

La prima ora è stata pura disciplina di triage, in ordine di costo crescente.

Step 1 (5 minuti). nginx error log. tail -F sull’error.log del vhost. Il messaggio era generico: FastCGI sent in stderr: PHP message: PHP Fatal error: Uncaught TypeError. Path della richiesta variabile, ma il template hit era sempre lo stesso. Buon segnale: il bug è in un componente che viene caricato su quel template, non in un middleware globale.

Step 2 (15 minuti). PHP-FPM slow log. Configurato con slowlog_timeout = 5s. Niente di rilevante: lo slow log mostrava solo qualche query lenta sporadica, niente correlato con i 500. Significa che il fatal arrivava in fretta, prima del timeout. Fatal sincrono, non timeout in attesa.

Step 3 (20 minuti). MariaDB query log. Abilitato in modalità general_log per 60 secondi su una replica. Le query erano regolari, nessuna anomalia. Anche qui: il problema non è a database. È in PHP, e succede prima ancora che il template arrivi a fare query rilevanti.

Step 4 (45 minuti). PHP error log dettagliato. Aumentato log_level su PHP-FPM, attivato display_errors = On solo per un IP whitelistato (il mio). Riprodurre il bug a comando era impossibile (1 su 100), ma con request automatizzate lato CLI ho intercettato il messaggio per esteso:

TypeError: count(): Argument #1 ($value) must be of type Countable|array, null given

E lo stack trace puntava a un file dentro il plugin di image optimization, riga count($meta_values). Bingo sul tipo di errore, ancora da capire perché $meta_values è null.

Step 5 (60 minuti). xdebug in produzione, una volta sola. Decisione consapevole: xdebug in produzione è caro come performance, e ha implicazioni di sicurezza serie se rimane attivo. L’ho abilitato solo sul container del web tier che avevamo isolato per il debug, su una request riprodotta tramite un cookie speciale che il plugin firmava. Breakpoint sulla riga incriminata. Variabili in scope al momento del fatal: $post_id valido, $meta_key valido, $meta_values = null. Il count arrivava sul ritorno di get_post_meta($post_id, $meta_key, false), che documentation alla mano dovrebbe restituire un array (anche vuoto), mai null.

Il sospetto: PHP 7.4 vs 8.0+ e il caso edge non documentato

A questo punto la pista era abbastanza chiara, ma andava confermata. La firma di get_post_meta in WordPress restituisce array nella stragrande maggioranza dei casi. Tuttavia, leggendo il sorgente del plugin, ho trovato che il chiamante non passava direttamente l’output di get_post_meta: lo passava attraverso un filtro custom, registrato dal plugin stesso, che in certi rami di codice restituiva null esplicitamente per segnalare “metadata non disponibile, salta il blocco”. Era un pattern interno del plugin, non un comportamento di WordPress.

In PHP 7.4 quella count(null) era un E_WARNING silenziato dal log handler del plugin, e il valore restituito era 0. Il flusso continuava come “zero metadata, salta il blocco”. In PHP 8.0+ il warning è diventato TypeError fatale. Per due mesi nessuno se n’era accorto perché il filtro custom in questione veniva invocato solo in un edge case specifico del frontend, dipendente dalla combinazione di tassonomia + un certo tipo di media allegato. Non un caso comune, ma non rarissimo: spiegava bene il “1 su 100”.

La prova del nove: simulato il caso edge in staging, riprodotto il fatal al primo colpo. Tre ore dal primo alert.

Fix temporaneo: monkey-patch nel functions.php

Il fix immediato doveva essere reversibile, isolato dal codice del plugin (che si aggiorna automaticamente), e applicabile senza riavviare nulla di critico. La soluzione canonica in WordPress è un filtro nel functions.php del tema custom (figlio), che intercetta il valore prima che il plugin lo passi a count.

add_filter( 'plugin_image_optimization_meta_values', function( $value, $post_id, $meta_key ) {
    if ( null === $value || ! is_array( $value ) ) {
        return array();
    }
    return $value;
}, 10, 3 );

Questo è sicuro perché:

  • Non modifica il plugin (che si aggiorna senza che il fix venga sovrascritto).
  • Riallinea il contratto al comportamento documentato (array, anche vuoto).
  • È idempotente: se il plugin lo correggerà upstream, il filtro continua a essere innocuo.

Deploy del fix tramite il pipeline standard, niente roba a mano via SSH. Cinque minuti per pushare, due minuti per il deploy CI/CD, monitoring per altri trenta minuti per confermare che l’error rate scendeva. Alle 15:30 era sotto lo 0,1%, dove è restato.

Fix definitivo: pull request upstream

Una toppa nel functions.php è ottima per chiudere l’incident, ma è debito tecnico se la lasci lì. La forma corretta del fix doveva andare nel plugin, e da lì propagarsi a tutti quelli che usavano lo stesso pattern. Quella sera ho aperto la repo del plugin, scritto un repro test (un PHPUnit su una fixture WordPress che riproduceva il filtro custom restituendo null), e mandato una pull request. Tre cose concrete:

  1. Repro test: il PR partiva con un test che falliva sulla codebase corrente. Importante: senza repro test, una PR su un plugin maturo viene chiusa o ignorata.
  2. Fix minimale: due righe, il count veniva sostituito con is_array($value) ? count($value) : 0. Niente refactoring del filtro, niente cambio di firma pubblica. La PR doveva avere superficie minima.
  3. Note sul changelog: spiegazione del comportamento PHP 7.4 vs 8.0+, con link al manual PHP. Era stata già una migrazione obbligata, ma serviva contestualizzare per il maintainer.

Tre settimane di review, una richiesta di rename della variabile in test, mergiata. Il fix è uscito nella versione successiva del plugin, e ho rimosso il monkey-patch dal functions.php due settimane dopo l’update, mantenendolo come failsafe per i tenant che non avevano ancora aggiornato.

Il postmortem blameless: cosa abbiamo imparato sul processo

La parte importante non è stata trovare il bug. È stata la conversazione di postmortem il giorno dopo, in screen share con il dev senior. Una regola, dichiarata all’inizio: niente nomi, niente colpa, focus sul “cosa abbiamo imparato che possiamo cambiare nel processo”. Le conclusioni operative:

Una. Il deprecation log su staging non basta. Il bug non era un deprecation, era un errore già E_WARNING in 7.4 che è diventato fatal in 8.0+. Per intercettare questa classe di problemi serve un canary più aggressivo: idealmente, un job che fa 1000 request casuali su tutti gli URL pubblici noti (sitemap.xml + tutti gli articoli pubblicati negli ultimi 90 giorni) prima di promuovere PHP 8.x in produzione. Costo: una decina di minuti di esecuzione, una task in CI/CD.

Due. Gli edge case nei filtri custom dei plugin sono invisibili al testing standard, perché dipendono da combinazioni di dati di produzione che lo staging non sempre ha. La soluzione non è “fare più test in staging”, ma “tenere uno staging più simile a produzione” (snapshot dati periodico, anonimizzato dove serve, automazione del refresh).

Tre. Il monitoring sull’error rate va guardato con un baseline p95 e non solo media. La media è scesa rapidamente sotto soglia perché 1 su 100 si annega nel volume delle altre request. Il p95 di error rate per template, invece, era saltato bene visibile. Aggiunto un alert specifico per template error rate p95 > 1% sostenuto su 5 minuti. Da quel giorno, gli alert arrivano prima.

Quattro. La regola “xdebug in produzione mai” è una regola con eccezioni. L’eccezione qui è stata gestita bene: container isolato, cookie speciale firmato, finestra di tempo chiusa, audit log di chi ha attivato la modalità debug. Ho documentato la procedura nel runbook interno: prima di poterla rifare, qualcuno deve firmarla.

Cinque. La PR upstream è sempre la via giusta, anche quando costa tre settimane in più. Il monkey-patch nel functions.php è debito; restituirlo all’ecosistema chiude il debito e aiuta gli altri tenant che usano lo stesso plugin senza saperlo.

I numeri dell’incident

Metrica Valore
Tempo da primo alert a fix in produzione 6h 16m
Tempo sopra error rate 1% sostenuto 23 minuti
Error rate post-fix temporaneo sotto 0,1%
Error rate post-fix definitivo (3 settimane dopo) 0,00% sul template colpito
PR upstream: review time 3 settimane
Linee di codice modificate (fix definitivo) 2
Linee di codice del repro test 38
Persone coinvolte nel postmortem 2 (io + dev senior in screen share)

Il dato che mi ha sorpreso di più è il rapporto tra le due righe di fix definitivo e le 38 del test che lo accompagnava. È il rapporto tipico di un fix maturo: il codice da cambiare è poco, il codice che dimostra perché va cambiato è molto di più. Senza quel rapporto, le PR upstream non vengono mergiate.

Cosa rifarei

Prima. Il canary su PHP 8.x non era abbastanza aggressivo. Aggiunto in pipeline subito dopo, con un set di URL randomizzato pescato dalla sitemap. Il primo run dopo la modifica ha intercettato due casi simili in altri plugin del network, prima che arrivassero in produzione.

Seconda. L’attivazione di xdebug in produzione l’ho gestita ad-hoc, decidendo sul momento perché era l’unica via per catturare il caso. Ho documentato la procedura solo dopo. La prossima volta voglio averla documentata prima, con criteri espliciti su quando si può fare e quando no, e un ticket di tracking obbligatorio.

Terza. Il display_errors = On per IP whitelistato è un trucco che ho usato per anni. Funziona, ma è un’arma carica: se sbaglio l’IP o se il filtro middleware si rompe, esponi stack trace al mondo. Voglio sostituirlo con un endpoint di debug separato, dietro VPN, che serva solo a quel sotto-traffico. La differenza è significativa in termini di blast radius.

Quarta. Il postmortem blameless ha funzionato. Tre persone in screen share, una regola “no colpa” detta all’inizio, e un documento di output con cinque action items operativi. Il dev senior che ha lavorato con me su quell’incident è poi stato la persona che ha ridisegnato il canary in CI/CD: il valore di un postmortem si misura sulle cose che cambiano dopo, non sulle cose che si dicono durante.

Quinta. Il filtro che ho usato come monkey-patch va lasciato in tema custom finché non scompare l’ultima versione del plugin che ha il bug. Ho impostato un alert sul plugin update tracking del cliente: quando il plugin sale alla versione fixata, il filtro diventa innocuo (ridondante), ma fino a quel momento lavora come failsafe. Toglierlo subito dopo il merge upstream era una tentazione: la risposta corretta è “lo tolgo quando l’ho visto vivere a vuoto per 30 giorni in produzione”.

Quello che mi sono portato a casa

Le migrazioni di major PHP sono ormai routine, ma il bug della migrazione PHP 7 → 8 non è morto. Vive nei plugin di terze parti, nei filtri custom, nei rami di codice che vengono invocati una volta su cento, su una combinazione di dati che lo staging non ha. La differenza tra un team che subisce queste cose e un team che le intercetta non è nella configurazione di OPcache o nelle regole di linting. È nella pipeline di canary, nel monitoring per template, nella disciplina di postmortem che chiude il loop con azioni concrete.

E c’è un’osservazione di processo che vale al di là di PHP. Sei ore di postmortem in screen share con un dev senior costano molto, in termini di tempo di persone qualificate. Sono sempre soldi spesi bene. Le partnership tecniche lunghe (intese come “lavorare di fianco a sviluppatori che conoscono il codice cliente”) sono la cosa che ti permette di chiudere un incident senza panico, e di estrarne lezioni che durano. Una richiesta di troubleshooting una tantum non ti porta lì: ti porta ad aprire un ticket, applicare la toppa più veloce, e perdere l’occasione di imparare il sistema.

Articoli correlati