Sånn fiksa VG-utviklerne valg­trøbbelet: – Det skar seg så voldsomt!

På et tidspunkt jobbet over 20 ansatte og to cache-guruer fra Varnish på spreng for å fikse nedetiden.

Utviklerne i VG jobbet på spreng valgkvelden for å finne årsaken til at nettsidene gikk ned. 📸: VG
Utviklerne i VG jobbet på spreng valgkvelden for å finne årsaken til at nettsidene gikk ned. 📸: VG Vis mer

Enhver utviklers verste mareritt er antagelig når viktige tjenester som mange er avhengige av går ned. Og slike har gjerne en tendens til å gå ned nettopp når de absolutt ikke må gå ned.

Det skjedde med VG.no på selveste valgkvelden, 11. september, da nettsidene knelet på grunn av for høy belastning.

– Cache-serverne våre leverer vg.no og mange andre domener pålitelig dag etter dag. Valgspesial-koden var også battle-testet i flere valg før. Vi hadde høy tillit til at begge deler fungerte bra, sier DevOps Engineer Nicolai Langfeldt til kode24.

– Men så skar det seg så voldsomt.

«Når røyken hadde lagt seg kunne vi konstatere at det var et falskt spor.»

Automatiske alarmer

Til tross for at VG.no er vant til å håndtere til tider svært mye trafikk, gikk det galt. Med en gang valgresultatene ble offentliggjort, så fikk cache-serverne for mye å gjøre.

– Vi satt i beredskap og merket det fort. Automatiske alarmer gikk av i løpet av to minutter. I den første tiden var det ikke mulig å lese nye artikler.

Langfeldt forteller at de bruker cache-servere fra Varnish, som hadde en "load average på over 1.000". Det var vanskelig å se hva som foregikk og vanskelig å få respons på noe som helst.

– Forskjellige kollegaer hadde forskjellige teorier og fikk etter hvert ut query-logger. En av de første teoriene var at det så ut som det var manglende caching av 307- og 308-redirecter generert av Next.js.

  • Teorien var at manglende caching vil gjøre at backend/origin-tjenesten får forespørslene som resulterer i redirect hele tiden, svært mange ganger i sekundet.
  • Det kan gi en overbelastning, og forespørslene til cache-laget fører til at cachens tilgjengelige tråder brukes opp på å vente på forespørsler fra en backend som svarer langsommere og langsommere.
  • Dermed får man en snøballeffekt med overbelastning i mange ledd.

– Når røyken hadde lagt seg kunne vi konstatere at det var et falskt spor og det passet ikke helt med symptomene heller. Det var ledige tråder og null ledig CPU, sier Langfeldt.

Bilde fra feilsøkingen kl. 23:36. På skjermen sees cache-loggen, som snart skulle hjelpe VG med å identifisere at komprimering tar for lang tid. 📸: VG
Bilde fra feilsøkingen kl. 23:36. På skjermen sees cache-loggen, som snart skulle hjelpe VG med å identifisere at komprimering tar for lang tid. 📸: VG Vis mer

Måtte kalle inn Varnish-guruer

Etter en halvtime til tre kvarter så det ut som de fleste kunne lese artikler og få opp VG-forsiden ganske pålitelig. Men overvåkningen fortsatte å varsle om at noe var nede ganske ofte.

– Det var nok en del som fikk feilmeldings-siden vår, men det skjedde ikke konstant.

– Vi fulgte flere falske spor og etterhvert kom to guruer fra Varnish Software med i videokonferansen. Siden valgspesialen uansett ikke virket for leserne våre, startet vi å eksperimentere med å generere 418-feilmeldinger direkte i produksjons-Varnishen på en av serverne. Det fikk lasten til å falle drastisk!

Det var da en av Varnish-guruene foreslo at de kanskje komprimerte svarene for mye.

Det fikk Langfeldt og utviklerteamet til å innse at valgspesialen leverte fra seg gzip-ede filer og at cachen transkodet alle forespørslene med Brotli-algoritmen med høyeste kvalitetsinnstilling og med bare 10 sekunder cache-TTL. Den største filen tok rundt 2 sekunder å rekode.

– Dermed var det flere tusen filer som måtte transkodes på nytt hvert 10. sekund. Det ble for mye. Da vi deaktiverte Brotli-rekoding på valgspesialen, circa en halvtime etter midnatt, løsnet alt. Vi har aldri sett lasten på servere falle så fort før.

Tre av dem som jobbet på spreng for å fikse problemene valgkvelden: Nicolai Langfeldt (DevOps Engineer), Ole Halvor Lindtveit Bergan (lærling i IT-drift) og Martin Pedersen (utvikler). Bildet av sistnevnte er ikke helt nytt. 📸: Privat
Tre av dem som jobbet på spreng for å fikse problemene valgkvelden: Nicolai Langfeldt (DevOps Engineer), Ole Halvor Lindtveit Bergan (lærling i IT-drift) og Martin Pedersen (utvikler). Bildet av sistnevnte er ikke helt nytt. 📸: Privat Vis mer
«Det var da en av Varnish-guruene foreslo at de kanskje komprimerte svarene for mye.»

Valgspesial i Next.js

Martin Pedersen er en av de andre utviklerne som jobbet med å få VG.no på beina igjen den hektiske valgkvelden.

Han kan fortelle at valgspesialen ble utviklet i React med Next.js-rammeverket. Datahenting ble implementert ved hjelp av Next.js getInitialProps.

Når man bruker serverside-rendring og getInitialProps, vil dataene som er nødvendig for å rendre siden i praksis bli duplisert tre ganger. Først finner man den i HTML-koden, deretter i JSON i script-taggen med id-en "__NEXT_DATA__", og til slutt under URL-en "/_next", som blir brukt under påfølgende navigering i spesialen, forklarer Pedersen.

Han forteller at videre undersøkelser av frontend-koden avslørte at en fullstendig statisk eksport ved hjelp av "next export"-kommandoen resulterte i en mappe på hele 2GB. Med en cache-TTL (Time-To-Live) på kun 10 sekunder, og med ytterligere duplisering basert på omtrent fem forskjellige cache-nøkler knyttet til brukeragent-typer som PC, mobil, nettbrett og apper, måtte Varnish-serverne håndtere en betydelig belastning.

– Jeg har forsøkt å Brotli-komprimere hele valgspesialen én gang på min egen maskin. Det tok fem minutter med q=11, og to sekunder med q=1.

Moroa gikk fort over

Ole Halvor Lindtveit Bergan er lærling i IT-drift. Noen av kode24s lesere kjenner kanskje igjen navnet – han fikk nemlig jobb i VG etter at de hadde lest om Ole Halvors passvarsel-app på kode24.no:

Han kan fortelle om en stressende kveld der det på et tidspunkt var over 20 ansatte som jobbet på spreng for å få fikset problemene.

– Selv om alle team var forberedt og parat, så kan ting gå galt. Vi ønsker jo å fikse problemene så fort som mulig slik at vi får levert innholdet til brukerne våre.

– Valg er ett av høydepunktene i løpet av et år, og det er ikke da vi ønsker at problemer skal oppstå. Vi jobbet aktivt over flere timer for å stabilisere alle tjenestene våre, sier Lindtveit Bergan, til kode24

– De første ti minuttene var det moro å ha så mye trafikk at VG.no gikk ned, men moroa gikk fort over da vi slet med å finne rotårsaken, legger Martin Pedersen til.

Graf som viser CPU-belastningen før og etter feilfiks. Blått er user space-last på CPU. Grønt er idle CPU. 📸: VG
Graf som viser CPU-belastningen før og etter feilfiks. Blått er user space-last på CPU. Grønt er idle CPU. 📸: VG Vis mer

Har lært av problemene

– Hva gjør dere for å unngå at noe lignende skjer igjen?

– Vi har såkalte “post mortem” hvor vi går gjennom hva som gikk galt, og hva vi kan lære fra det. Vi justerer komprimeringen slik at den ikke vil overbelaste serverene våre når vi får mye trafikk, og vi jobber aktivt for å vurdere hvor komprimering er nødvendig, sier Lindtveit Bergan.

Han forteller videre at VG jobber med å finne bedre løsninger for å simulere høy trafikk slik at de kan oppdage problemer tidligere.

– Det er viktig at vi lærer av feilene slik at de ikke skjer igjen.

Lindtveit Bergan sier at selv om dette kanskje var en litt trist dag for alle som jobbet hardt med å forberede seg til valget, så synes han det var fantastisk å se hvordan alle løper til for å hjelpe når noe først går galt.

– Alle strekker seg virkelig langt for å hjelpe uansett hvor de befinner seg. Det synes jeg er veldig rørende.

Nicolai Langfeldt legger til at valgspesialen var nede frem til rundt klokken 00:40 valgkvelden, da de fikk ut en fikset cachekode til alle serverne.

– Journalistene skrev og publiserte artikler med innsikt og bilder fra spesialen, som var tilgjengelig internt, men uten de interaktive elementene som redaksjonell utvikling hadde jobbet med å tilrettelegge for gjennom valgspesialen, sier Langfeldt.