Drupal watchdog handmatig: severity, type, vier queries

Een Drupal 9-site van een Nederlandse uitgever waar we mee werken gooide al drie weken sporadisch 500's voordat iemand het doorhad. De dblog-adminpagina op /admin/reports/dblog was waardeloos: 50 rijen per pagina, geen aggregatie, een muur van "Notice"-meldingen uit een module waar sinds 2019 niemand meer aan had gezeten. De watchdog-tabel zelf had 1,4 miljoen rijen. De dblog-UI uitlezen was kansloos. De tabel met de hand doornemen was twintig minuten werk.

De watchdog-tabel in vogelvlucht

De watchdog-tabel wordt geschreven door de dblog-module uit Drupal core. Elke variant van Drupal 6 tot en met Drupal 10 draagt dezelfde basiskolommen: wid, uid, type, message, variables, severity, link, location, referer, hostname, timestamp. Het interessante werk zit in drie ervan: type, severity en message. De rest is metadata die je pas nodig hebt als je iets gevonden hebt dat de moeite waard is om uit te pluizen. Op Drupal 8, 9 en 10 is het schema ongewijzigd zolang dblog aanstaat, dus de queries hieronder werken zonder aanpassing op elke ondersteunde versie.

De kolom message bewaart een t()-template met placeholders, niet de gerenderde tekst. De ingevulde waarden zitten in variables, geserialiseerd in PHP. Daarom geeft SELECT message FROM watchdog cryptische strings terug als %type: !message in %function (line %line of %file) in plaats van de leesbare regels die de admin-UI toont. Behandel message als een vingerafdruk, niet als een zin. Twee rijen met dezelfde message zijn hetzelfde soort probleem, ook als de gerenderde output voor een mens anders oogt.

Severity ontcijferd

De severity-kolom van Drupal mapt netjes op de syslog-niveaus uit RFC 5424. Lager nummer, hogere urgentie:

0 Emergency
1 Alert
2 Critical
3 Error
4 Warning
5 Notice
6 Info
7 Debug

Bijna elke Drupal-site die ik heb doorgelicht laat dezelfde verhouding zien: 95% van de rijen zit op severity 5 of 6, 4% op severity 4, en in de resterende 1% zitten de echte problemen. Het eerste dat je doet is alles boven 4 wegfilteren. Alleen daarmee krimpt een watchdog van 1,4 miljoen rijen al tot iets dat op één scherm leesbaar is. De verhouding zelf is ook een datapunt: een site waar severity 4 op 10% zit heeft een ander probleem dan een waar severity 3 op 8% zit, en je wilt voor het schrijven van een fix weten met welk van de twee je te maken hebt.

Vier queries die echte problemen blootleggen

1. Top types in de afgelopen 24 uur, gegroepeerd per severity

SELECT type,
       SUM(severity <= 3) AS errors,
       SUM(severity = 4)  AS warnings,
       COUNT(*)            AS total
FROM watchdog
WHERE timestamp > UNIX_TIMESTAMP() - 86400
GROUP BY type
ORDER BY errors DESC, warnings DESC;

Dit is de oriëntatie-query. Draai die eerst. Levert cron 200 errors per dag op, dan ga je daarheen. Domineert php, dan zit er ergens een fatal in de site. Staat access denied in de top drie, dan loopt er iemand je admin-URL's te fingerprinten. De kolom type bevat precies de string die de aanroepende code aan watchdog() meegaf op Drupal 7, of aan het logger-kanaal op Drupal 8 en later, dus contrib-modules verzinnen soms hun eigen type-strings. Alles wat onbekend voorkomt bovenaan deze lijst is een spoor dat je wilt volgen.

2. Terugkerende PHP-errors, samengeklapt op message-vingerafdruk

SELECT message,
       COUNT(*) AS hits,
       MAX(FROM_UNIXTIME(timestamp)) AS last_seen
FROM watchdog
WHERE type = 'php'
  AND severity <= 3
  AND timestamp > UNIX_TIMESTAMP() - 7 * 86400
GROUP BY message
ORDER BY hits DESC
LIMIT 20;

PHP-errors lenen zich uitstekend voor vingerafdrukken, omdat Drupal de placeholder-template opslaat en niet de gerenderde string. Een regel Trying to access array offset on value of type null in %function() (line %line of %file) die 8.400 keer per week terugkomt, is één bug, in één bestand, op één regel. Eén rij oppakken, variables deserialiseren, en je hebt het bestandspad en regelnummer om te fixen. Het aantal hits zegt hoe hard die fout slaat, en de timestamp last_seen zegt of het na een recente deploy begon. Op de site van de uitgever bleek de bovenste rij een deprecated call in een custom block plugin die niemand onder PHP 8.1 had aangeraakt.

3. De access-denied-patrooncheck

SELECT location,
       COUNT(*) AS hits,
       COUNT(DISTINCT hostname) AS unique_ips
FROM watchdog
WHERE type = 'access denied'
  AND timestamp > UNIX_TIMESTAMP() - 86400
GROUP BY location
ORDER BY hits DESC
LIMIT 20;

Deze verdient zijn plek op elke publieke Drupal-site. Als /user, /user/login, /?q=user en /admin 4.000 keer langskomen vanaf één IP, dan loopt er credential stuffing. Verdeel je hetzelfde volume over 800 hostnames, dan zit je naar een botnet te kijken. Beide patronen zijn aanleiding om vóór de volgende escalatie een .htaccess-regel of een fail2ban-filter toe te voegen. Het type page not found werkt op dezelfde manier: zelfde query, andere filter, en het resultaat is meestal een 404-sweep die op een Drupal-site zoekt naar wp-login.php, wat op zichzelf ook weer een nuttig signaal is.

4. Cron-healthcheck

SELECT type, severity, message, FROM_UNIXTIME(timestamp) AS at
FROM watchdog
WHERE type IN ('cron', 'system')
  AND severity <= 4
  AND timestamp > UNIX_TIMESTAMP() - 7 * 86400
ORDER BY timestamp DESC;

Stille cron-failures zijn het meest voorkomende Drupal-probleem dat niemand opmerkt. Zoekindexen verouderen, queues lopen vol, de sitemap regenereert niet meer, en het statusrapport op /admin/reports/status meldt opgewekt: "Last run 14 weeks ago". Levert deze query warnings of errors op, dan draait cron wel, maar gooit een hook_cron-implementatie er halverwege uit. Levert hij niets op terwijl de statuspagina nog steeds weken geleden zegt, dan wordt cron helemaal niet getriggerd en zit het probleem op de server, niet in de Drupal-code.

De resultaten lezen

Elk van de vier queries beantwoordt een andere vraag, maar het werkpatroon is hetzelfde: draai query 1, pak het type dat het hardst schreeuwt, draai de bijbehorende vervolgquery, en deserialiseer dan één variables-blob om een bestandspad en regelnummer te krijgen. Probeer de watchdog niet lineair uit te lezen. De dblog-adminpagina doet dat al voor je, en dat is precies waarom niemand hem vertrouwt.

Toen we Pier bouwden liepen we hier zelf tegenaan bij het opruimen van een legacy site met zo'n 900.000 watchdog-rijen en een admin-UI die er een time-out op gaf voor de eerste pagina gerenderd was. We hebben het uiteindelijk opgelost door een MySQL editor in hetzelfde venster te zetten als de bestandsboom, zodat de query naast het .module-bestand staat waar de errors uit komen, en elke SQL-wijziging belandt in de version history naast de bestandswijzigingen.

Vandaag: open de watchdog op de Drupal-site die jou het langst aan het mompelen is, en draai query 1. Komt er bovenaan iets anders te staan dan page not found of access denied, dan heb je een middag werk voor de boeg, en waarschijnlijk een kleine overwinning aan het eind.