Frem til denne uken, når noe gikk galt på denne bloggen, levde bevisene i docker-loggene på serveren, som betyr at de i praksis levde ingen steder. En bruker kunne treffe en feil, fortelle meg om det, og mitt feilsøkingsverktøy var å skrolle gjennom terminalutdata på jakt etter et tidsstempel som omtrent stemte med meldingen deres. På tide å fikse det.
Ideen er enkel: hver gang en tjeneste skriver et feilsvar, skriver den også en rad til en error_log-tabell. Sti, status, feilkode, melding, request-id, brukeren hvis det var en. Adminpanelet får en loggfane som leser fra begge tjenestene og fletter dem til én liste jeg kan filtrere. Bruker sier "det gikk i stykker rundt klokka åtte", jeg filtrerer til det tidsvinduet og ser nøyaktig hva forespørselen deres traff.
Den første designbeslutningen som viste seg feil: jeg logget bare 5xx-feil, med teorien om at 4xx betyr at brukeren gjorde noe feil og 5xx betyr at jeg gjorde det. Men 4xx-svar er ofte selve sporet. En haug med 413-er betyr at noen stadig treffer en opplastingsgrense jeg satte for lavt. En strøm av 403-er betyr enten et angrep eller en tilgangsbug. Så nettet ble utvidet til 5xx pluss noen utvalgte: 403, 413 og 429. Ikke hver eneste 404 fra en bot som skanner etter wordpress.php, det ville bare vært støy med en databaseregning.
Den snikete bugen midt i dette handlet om context. Den opplagte koden sender forespørselens context inn i databaseinnsettingen. Men når feilsvaret skrives, er forespørselen i praksis over, og konteksten kan allerede være kansellert, noe som dreper innsettingen. Loggraden om feilen forsvinner fordi feilen skjedde. Løsningen er å gi innsettingen sin egen frittstående context med en kort timeout:
ctx, cancel := context.WithTimeout(context.Background(), errorLogInsertTimeout)
defer cancel()
if err := q.InsertErrorLog(ctx, db.InsertErrorLogParams{ ... }); err != nil {
log.Printf("error_log insert failed: %v", err)
}Og legg merke til hva som skjer når selve innsettingen feiler: en enkel loggelinje, ingenting mer. Den ene tingen en feillogger aldri må gjøre er å produsere sitt eget feilsvar, fordi den feilen ville blitt logget, som kunne feile, som ville blitt logget. Jeg har lest nok postmortems til å være skikkelig redd for den løkken.
Fanen fikk også en slett-knapp per rad og en tøm-alt, fordi en logg du ikke kan rydde i bare blir en vegg av gammel støy du slutter å lese. Rader eldre enn 90 dager feier seg selv ut sammen med analysehendelsene, samme vaktmester, samme tidsplan.
Er en to-tabells feillogg med en flettning i nettleseren en stor observability-plattform? Nei. Det finnes en skikkelig sentral loggtjeneste skissert for v2, med batching og retry når nettverket faller ut. Men det er et design for senere. Det jeg trengte denne uken var å slutte å feilsøke gjennom docker-logger, og det problemet er nå løst med to tabeller og én adminfane.