Obskure feil krever obskure løsninger

I blant dukker det opp bugs i produksjon. Noen ganger er det alvorlige feil som truer en hel organisasjons eksistens, andre ganger har du ved et uhell lagt ut hjelpeteksten i appen din på tysk. For å unngå de mest voldsomme konsekvensene, er det lurt å holde et øye med appene dine, men hva gjør du når alle lamper lyser rødt, og du ikke klarer å finne ut av hvorfor?

Håkon Tørnquist

4. juni 2020

Jeg sitter på et produktteam som eier og drifter rundt 30 JavaScript-applikasjoner. Vi monitorerer dem ved hjelp av et hjemmesnekret bibliotek som logger eventuelle feil til en tjeneste som gjør meldingene søk- og indekserbare i loggverktøyet vårt. I området vi sitter i har vi en skjerm som viser et live-dashboard i form av et rutenett, hvor hver rute viser antall unike brukere som har utløst feil i en gitt applikasjon inneværende døgn. Med opp til 20 000 unike brukere i døgnet er vi sjelden i null på alle rutene, men ved å fargekode dem til å skifte farge - fra grønn, via gul, til rød - etter et visst antall feil, får vi raskt overblikk om feilraten går utover det normale.

Etter en større modernisering av biblioteket vi bruker for å gjøre HTTP-kall begynte vi å legge merke til at en del av applikasjonene logget et mye høyere antall feil enn de pleide. Vi sjekket loggene, og så at en stor andel av feilene hadde oppstått uten at noe hadde gått galt backend. Nettleserne logget dem som en “TypeError”, sammen med en generisk melding om et kall hadde gått galt. Meldingene var attpåtil både nettleser- og lokasjonsspesifikke, så her var det lite å hente.

Vi slet med å reprodusere feilene i testmiljøene våre, og hadde heller ingen tilbakemeldinger fra brukere som sa de opplevde feil, og var på dette tidspunktet litt i villrede. Vi mistenkte at dette ikke var feil som var synlige for sluttbrukerne, men problemet var at de fremdeles ble logget, som gav oss vanskeligheter med å se de faktiske feilene blant alle de røde sildene.

I mangel på informasjon om enkeltfeilene, begynte vi å se mer nøye på brukerne det gjaldt. Det var få mønstre å se når det kom til nettleser eller operativsystem, men det viste seg at når en bruker opplevde feilen, var det ofte det siste de gjorde i en applikasjon, før de enten forsvant fra loggene helt, eller navigerte til en annen applikasjon. Dette er en situasjon hvor nettleserne er beryktet for å kaste generiske feil. Vi forsøkte å reprodusere feilen i den applikasjonen som opplevde den mest, og denne gangen hadde vi mer flaks. Når vi navigerte bort, eller avbrøt lastingen av siden før alle kallene var ferdige, dukket det umiddelbart opp feil i loggene våre.

Nå hadde vi en god anelse om rotårsaken, neste steg var å få fikset problemet. Én løsning er å “hviteliste” disse feilene og ikke logge dem, men det at de kommer i veldig mange forskjellige varianter avhengig av nettleser og språk, gjør dette til en løsning som skalerer dårlig. Vi ville dessuten ikke risikere å la være å logge faktiske feil brukerne opplever. Vi kunne ha forsøkt å bytte ut nettlesernes innebygde fetch-implementasjon med noe annet som gir bedre feilmeldinger, som axios, men det var en større teknisk avgjørelse vi helst ville unngå om vi kunne. Den hovedmistenkte bak feilen ble også opphav til den initielle løsningen: Nettleseren.

En nettside som lastes går gjennom det som kalles en sidesyklus. Denne syklusen eksponerer en haug av events du kan lytte og reagere på, som “load”, som trigges når siden har lastet inn, eller “focus”, som trigges når den aktuelle siden får fokus. Eventene som er sentrale her, er tre events som trigges nær slutten av sidesyklusen; pagehide, beforeunload og unload. En liten advarsel: Hvis du kan unngå det, ikke bruk dem til noe, og iallfall ikke til noe viktig. Oppførselen og timingen deres er notorisk inkonsistent på tvers av nettlesere og enhetstyper, og visse nettlesere støtter dem ikke i det hele tatt. Når det er sagt, kan de hjelpe deg til å gjøre visse antagelser om brukeren. At minst én av dem har blitt utløst, betyr - veldig enkelt forklart - at den aktuelle brukeren er på vei bort fra siden. Det er et par andre forholdsregler man bør ta, som kan leses om her.

Vi la inn lyttere på disse eventene, og registrerte hvilke events brukeren haddde opplevd når en feil oppstod. Vi fant at 90% av feilene ble trigget av brukere som hadde opplevd minst ett av eventene, og valgte å logge disse som “warn”-feil i stedet for “error”. Dashboardet vårt ble umiddelbart grønnere, som igjen gav oss mye bedre mulighet til å se mønstre i de 10 resterende prosentene.

Dette er fremdeles ikke en fullverdig løsning på problemet. Vi plukker ikke opp alle, og det er en form for spesialhåndtering det bør være minst mulig av i et robust system, men gitt de tekniske rammene vi opererer innenfor og verktøy vi har tilgang til, var dette en veldig rask og enkel måte å få ny data om brukeren og forenkle feilsøkingsarbeidet vårt på.