SURFconext storing 28 november: wat ging er mis?

Samenvatting

SURFconext biedt naast standaard authenticaties (inloggen) meer functionaliteit.  Een van die extra functies is het toevoegen van een autorisatiecheck bij het inloggen: tijdens de authenticaties controleren we dan of een gebruiker aan specifieke voorwaarden voldoet. Alleen als dat het geval is mag de gebruiker door naar de dienst.  Deze check kijkt naar de attributen van een gebruiker, en kan bijvoorbeeld alleen medewerkers doorlaten en studenten tegenhouden, of voor bepaalde groepen gebruikers sterkere multifactor-authenticatie afdwingen.

Deze check wordt uitgevoerd door de zogenaamde PDP (Policy Decision Point). Tijdens de authenticatie stelt de login-component een vraag aan de PDP, en deze antwoordt dan of de gebruiker wel of niet geautoriseerd is. 

Het probleem is ontstaan in deze PDP-component. Door een bug antwoordde deze veel trager dan de bedoeling was. Die bug bestond sinds eind 2024, maar was tot nu toe nooit een probleem omdat de PDP snel genoeg was om alle vragen binnen redelijke tijd af te handelen.  Echter, in de loop van 2025 is PDP steeds populairder geworden, waardoor hij het aantal verzoeken op piektijden nog maar net aankon.  

Op vrijdag 28 november wilden we een nieuwe versie van de PDP uitrollen in een reguliere onderhoudsrelease. Zo'n release kunnen we overdag doen zonder onderbrekingen in de dienstverlening door de helft van de nodes af te schakelen, die te upgraden en dan al het verkeer naar de nieuwe nodes te leiden. Dat ging mis: bij het afschakelen van twee van de vier nodes bleek dat de twee overgebleven nodes het toegenomen verkeer niet meer aankonden, en daardoor niet op tijd antwoord konden geven tijdens inlogpogingen. De inlog-engine kan dan niet bepalen of een gebruiker wel naar binnen mag en laat de gebruiker dus niet door.  Na het weer terugzetten van de afgeschakelde nodes was dit probleem opgelost.

Onze aanname op dat moment was dat zolang alle nodes blijven draaien, we rustig op zoek konden naar een extra fix voor het versnellen van de PDP.  Die fix was op maandag 1 december vrij snel gevonden en de bedoeling was om die op donderdag 4 december naar productie te brengen.  Echter, de volgende dag (op 2 december) bleek dat de hoeveelheid verkeer naar de PDP inmiddels tijdens de piektijden (rond 9 uur 's ochtends) zo hoog was, dat zelfs alle nodes samen dit niet aankonden. Dit leidde op die dag tot een korte tweede storing.  Daarna hebben we besloten om snel diezelfde dag de fix uit te rollen.  

Door deze fix is de PDP nu 50 tot 100 maal sneller dan voorheen, en heeft dus geen enkel probleem meer met het afhandelen van het verkeer van SURFconext.  

Ongerelateerde storingen

Een week later zijn er nog twee andere incidenten geweest rondom de PDP.  Deze waren ongerelateerd; hierbij was het probleem dat er door configuratiefouten te weinig of geen vragen meer werden gesteld aan de PDP.  Deze issues beschrijven we hier niet.

Achtergrond

Het reguliere authenticatieproces werkt als volgt:

• Een gebruiker drukt bij een dienst op de loginknop.
• De dienst redirect de gebruiker naar SURFconext (specifiek: naar de Engineblock SAML proxy component).
• De gebruiker kiest diens IdP, en wordt daar weer naartoe doorgestuurd.  Daar logt de gebruiker in met (bijvoorbeeld) username en wachtwoord.
• Bij een succesvolle login stuurt de IdP de gebruiker terug naar Engineblock, die doet een aantal checks (welke attributen moeten worden doorgegeven, moet een informatiescherm worden getoond, moeten er nog externe attributen worden toegevoegd, etc).
• Engineblock stuurt de gebruiker dan met een ondertekend setje attributen en informatie over het loginproces terug naar de dienst. 

Dit zie je hieronder schematisch uitgebeeld aan de rechterkant van het diagram:

Een van de acties die Engineblock bij een succesvolle authenticatie kan doen, is een autorisatiecheck. Aan de hand van voorgedefinieerde autorisatieregels wordt dan gecontroleerd of de gebruiker toegang mag krijgen tot deze dienst. Dit maakt fijnmazige filtering mogelijk, waarmee een instelling bijvoorbeeld kan instellen dat bepaalde dienst alleen voor medewerkers toegankelijk is, alleen voor gebruikers met een specifieke (SURFconext Invite-, SURF-, of instellings-)rol, of alleen voor gebruikers met een specifiek attribuut.  Ook is het mogelijk om op basis van dit soort criteria een bepaald niveau van MFA-middelen af te dwingen, bijvoorbeeld: medewerkers mogen alleen naar binnen na extra authenticatie met een hardwaretoken.

Deze autorisatiechecks worden niet door Engineblock zelf afgehandeld, maar door een andere component van SURFconext, de zogenaamde PDP (Policy Decision Point). In ons centrale beheersysteem Manage slaan we alle informatie op over IdP's en diensten die aan SURFconext zijn gekoppeld. Ook de autorisatieregels staan daar. Manage weet dus voor welke authenticaties (van elke IdP naar welke dienst) er een autorisatiecheck nodig is, en geeft daarvan een lijst door aan Engineblock.  Dit hoeft daardoor dus alleen als er daadwerkelijk een actieve policy bestaat, een aanroep naar de PDP te doen. Dit zie je aan de linkerkant van het diagram hierboven.

De PDP is een XACML-engine gebaseerd op Apache OpenAZ, die zeer complexe autorisatieschema's kan evalueren. OpenAZ verwacht als input XACML-policies. Dat is een tamelijk uitgebreid XML-dialect dat ik hier niet in detail zal bespreken. De echte liefhebber (en ja, die bestaan!) verwijs ik graag naar de specificatie op https://docs.oasis-open.org/xacml/3.0/xacml-3.0-core-spec-os-en.html. Het Wikipedia-artikel geeft ook iets meer context en voorbeelden: https://en.wikipedia.org/wiki/XACML.

In de PDP moeten alle autorisatieregels die we willen gebruiken dus worden opgeschreven als een XACML-policy.  Bijvoorbeeld. als we een autorisatieregel hebben die zegt dat een gebruiker alleen mag inloggen als deze een eduPersonAffiliation-attribuut met de waarde employee  heeft, druk je dat als volgt in XACML uit:

Je ziet hier dat we eerst definiëren op welke IdP en SP de policy van toepassing is. Vervolgens worden er twee regels na elkaar afgewerkt; de eerste die matcht, geldt. Eerst kijken we of de gebruiker een eduPersonAffilation-attribuut heeft met de waarde employee. In dat geval matcht de eerst regel en wordt urn:surfconext:xacml:rule:id:permit  teruggegven aan Engineblock,.  Als deze niet matcht, wordt de volgende regel geëvalueerd. Deze matcht altijd omdat er geen <Match>-element is; iedereen die niet employee is wordt dus tegengehouden. Tevens worden er in dat geval extra "Deny Messages" teruggegeven aan Engineblock, die deze aan de gebruiker kan tonen.

Deze XACML-documenten zijn te complex om handig mee te kunnen werken in de andere omgevingen van SURFconext. We willen graag dat de autorisatieregels-functionaliteit zoveel mogelijk self-service beschikbaar is in SURFconext; onder meer in het SURFconext Dashboard kunnen instellingsbevoegden zelfstandig deze regels te bewerken. Het zou echter behoorlijk bewerkelijk worden als we in alle componenten die policies moeten kunnen tonen en bewerken, ook helemaal XACML-parsing moeten inbouwen. We gebruiken daarom intern een eenvoudiger formaat dat makkelijker te parsen is en dat beter aansluit bij de relatief simpele regels die wij in SURFconext willen aanbieden. Deze versimpelde regels worden opgeslagen in ons centrale beheersysteem, genaamd Manage, waar we ook alle andere informatie over aangesloten instellingen en diensten opslaan. Onze dashboards kunnen de versimpelde policies eenvoudig lezen uit Manage en aanpassingen terugschrijven.

Om de data actief te maken in de PDP, schrijft Manage na een wijziging alle (nog altijd versimpelde) policies naar de PDP.  De PDP converteert die direct bij ontvangst naar volwaardige XACML-documenten en schrijft die in een database weg. Als de XACML-policies zijn gewijzigd, herinitialiseert de PDP zich en leest alle policies opnieuw in.  Dit is een tamelijk tijdrovend proces omdat er enkele honderden XACML-documenten moeten worden geparst.  De tijd die dit kost is grofweg lineair met het aantal gedefinieerde regels. Het duurt momenteel ongeveer 100ms om de PDP-regels van SURFconext opnieuw in te lezen en de PDP-engine te herinitialiseren.

De storing

Op vrijdag 28 november stond een nieuwe release van de PDP op de planning. Zulke updates doen we overdag. Daarvoor hebben we onze servers (die ook al over twee locaties zijn verdeeld, zie het diagram hieronder) in twee groepen verdeeld: de rode en de blauwe servers.  In de loadbalancer kunnen we instellen hoe het verkeer tussen rood en blauw verdeeld moet worden, en kunnen we ook rood of blauw helemaal uitschakelen. Gebruikers merken daar niets van omdat we onze servers zo hebben gedimensioneerd dat al het verkeer in principe door één enkele server kan worden afgehandeld.

De procedure voor zulke updates is dat we de blauwe set uit de loadbalancer halen en daar een nieuwe component op uitrollen. Als die deploy gelukt is, schakelen we de loadbalancer om van rood naar blauw en kunnen we ook de rode servers van een nieuwe versie voorzien. Dit is een reguliere procure die we op productie zo'n 80-100x per jaar uitvoeren.

PDP overbelast

Op de ochtend van 28 november liep het anders. Toen we daar rond kwart voor tien de blauwe server uitschakelden gebeurde dit met de responstijden van de requests naar de PDP (let op de logaritmische schaal!):

Je ziet hier dat de responstijd van de PDP rond de 150ms schommelde; op het moment (~9:44 uur) dat we de blauwe servers uitzetten, explodeert de responstijd direct naar ruim boven de 10 seconden. Als de response zo lang duurt, geeft Engineblock het op en toont een foutmelding aan de gebruiker. Dat gedrag is goed, omdat anders bij een falende PDP (of andere backend-component) Engineblock zelf last gaat krijgen om alle openstaande requests af te handelen, en er helemaal niemand meer kan inloggen. Nu blijven de problemen in ieder geval beperkt tot de diensten en instellingen die daadwerkelijk gebruikmaken van autorisatieregels. 

Verder zie je in de grafiek dat op het moment dat we de PDP op de rode servers weer aanzetten (rond 10:03 uur) de servers het verkeer vrij snel hebben weggewerkt en prima met z'n vieren de load aankunnen. Opvallend is nog dat de blauwe servers (groene en paarse lijn) na de herstart tijdelijk (tot 11:00 uur) heel veel sneller zijn dan de rode servers (rode en blauwe lijn). Dit blijkt later een hint te zijn voor het opsporen van het onderliggende probleem.

Deze grafiek maakt direct duidelijk wat het probleem is. Tijdens de storing zelf bleek dat echter een stuk lastiger te achterhalen. Deze grafieken hadden we van te voren niet kant-en-klaar live ingeregeld, en ook hadden we geen monitoring op de backend-responstijden. Sterker nog, onze monitoring- en logging-systemen zijn zelf ook afgeschermd met SURFconext en autorisatieregels, dus voor het oplossen van de storing hadden we zelf geen toegang tot deze tools. Voor we met de hand achter de oorzaak waren en de rode servers weer aan hadden gezet waren we dus al bijna een half uur verder.

Tijdens de storing verwerkte SURFconext ongeveer 450 logins per minuut, waarvan er per minuut 150 misgingen.

Toegenomen gebruik

De conclusie van dit alles is dat de PDP blijkbaar niet meer genoeg capaciteit heeft om de huidige hoeveelheid requests af te handelen. Tijdens de afhandeling van deze storing bleek ook inderdaad dat inmiddels grofweg een derde van de SURFconext-logins via een autorisatieregel is afgeschermd, en dat er inmiddels bijna 400 regels actief zijn.  

Gedeeltelijk is dit probleem goed te verklaren: sinds we in 2015 autorisatieregels hebben ingevoerd zijn die steeds populairder geworden. We hebben helaas geen historische statistieken waar we de groei van het aantal autorisatieregels bijhouden, maar in dit nieuwsbericht zien we dat we in juni 2020 nog maar 100 regels hadden (https://www.surf.nl/best-practice-hanzehogeschool-groningen-regelt-toegang-tot-faciliteiten-sportopleiding-met), en inmiddels zitten we op bijna 400.  Ook als je kijkt naar het aantal requests naar de PDP, groeit dat flink. Alleen al in de afgelopen 3 maanden is het percentage van de loginverzoeken die een autorisatieregel gebruikt, gegroeid van 31% in de eerste weken van september naar 36% in de eerste week va december. Daarbovenop komt dan nog de totale groei van de logins via SURFconext van 215 miljoen in 2020 naar 275 miljoen vorig jaar. Al met al heeft de PDP dus de afgelopen jaren veel meer te doen gekregen, en de hoeveelheid machines is niet meegegroeid.

De bug

Toch is er meer aan de hand dan alleen simpele groei. In piektijden (bijvoorbeeld maandag- en dinsdagochtend tussen 9 en 10 uur), verwerkt SURFconext maximaal zo'n 3.000 logins per minuut, of 50 per seconde. Met vier PDP-servers kunnen die per seconde dus nooit veel meer dan 12.5 requests per seconde te verwerken krijgen. Als de servers dat niet eens kunnen verwerken, moet er wel meer aan de hand zijn. Merk bovendien op dat de responstijd van de PDP-servers in het grafiekje hierboven rond de 100ms zitten; dat lijkt wel heel erg dezelfde orde van grootte als ~10 requests per seconde.  Het lijkt dus alsof de PDP-servers maar één request tegelijk kunnen afhandelen en daar dan 100ms over doen. Daar klopt iets niet!

En inderdaad: hier zit een vervelende bug. Het blijkt dat in een situatie waar meerdere PDP-servers dezelfde database gebruiken ze uit de pas kunnen gaan lopen. In de database van de PDP wordt een tellertje bijgehouden dat telkens wordt opgehoogd als er regels zijn geüpdatet. De idee is dat zo'n update op één node binnenkomt, dat die het tellertje ophoogt, en dat de andere nodes daardoor weten dat ze de XACML-regels opnieuw moeten inlezen. Het probleem is dat de andere nodes op het moment dat ze die nieuwe XACML-regels gingen inlezen, ook het tellertje ophoogden. Daardoor klopte de versie weer niet met de versie van de andere PDP-servers, die dan ook weer opnieuw de regels ging inlezen, etc...

Het resultaat van dit alles was dat bij elke request van Engineblock naar de PDP, alle XACML-policies opnieuw werden geparsed en ingelezen. Een request dat niet meer dan 1-2ms hoort te duren, duurt daarom opeens meer dan 100ms. 

De duur van het inlezen schaalt met het aantal policies, en ga je dus pas merken bij voldoende gebruik van de PDP. Bovendien treedt het gedrag ook alleen op als je meerdere PDP-nodes draait, en is het dus op onze testomgevingen niet zichtbaar. Al met al een behoorlijk vervelende bug die niet makkelijk te vinden was.

De tweede storing

Terwijl we werkten aan een oplossing voor deze bug, bleek op dinsdag 2 december dat de PDP met bug het aantal requests in reguliere situaties allemaal maar net aankan. Op de betreffende dinsdagochtend tijdens de piektijd tussen 9 en 10 uur kreeg SURFconext bijna 3.000 logins per minuut te verwerken, en dat aantal bleek de PDP niet aan te kunnen. Daardoor ontstond er die dinsdag weer een vergelijkbare storing. Deze keer waren we alerter op precies dit probleem en hadden we die een stuk sneller weer opgelost.

Naar aanleiding hiervan hebben we besloten om nog diezelfde ochtend de definitieve fix van de PDP uit te rollen. In de tussentijd hebben we direct na de storing maatregelen genomen om het wijzigen van PDP-regels te voorkomen. Die wijzigingen in de configuratie waren immers de aanleiding voor het uit sync lopen van de PDP en de triggeren de traagheid van de PDP. Om deze reden hebben we de Dashboards met de self-servicemogelijkheid om regels te wijzigen, ook tijdelijk uitgezet.

Sinds deze uitrol gedraagt de PDP zich weer netjes. Dit is mooi te zien in deze grafieken van de verdeling van de responstijden van de PDP van voor de storing maar met bug (links), tijdens de storing (midden) en na de fix (rechts).  Let op: de horizontale schaal is niet lineair. Het is duidelijk zichtbaar dat voor de fix de responstijden gemiddeld ver boven de 100ms lagen en bovendien ook tussen de server flink varieerden, terwijl ze na de fix meer dan 50x zo snel zijn geworden en tussen servers ook veel minder variëren. Het overgebleven verschil is te verklaren door de verschillende hardware van de servers in Amsterdam (1 en 3) en Utrecht (2 en 4).

Histogram van responstijden van de PDP voor, tijdens, en na storing (let op: non-uniforme horizontale schaal) voor elk van de view nodes.

Vervolg

De belangrijkste les die we uit dit incident hebben geleerd is dat we met hoge prioriteit onze monitoring moeten verbeteren. Dit is voor ons team voor volgend jaar een van de belangrijkste projecten. We willen aan de ene kant de applicaties verbeteren zodat ze zinnigere en nuttigere performancedata en metrics leveren. Aan de andere kant moeten we de systemen die deze logs en metrics in de gaten houden, updaten en aanzienlijk uitbreiden. Momenteel hebben we heel veel text-files met logs. Een deel daarvan is beschikbaar in een Elastic/Kibana-stack, maar die is verre van compleet. Verder hebben we een aantal metrics in een Prometheus/Grafana-systeem, maar ook daar monitoren we niet alles wat we zouden willen.

Als afsluiting zou ik dan ook graag aan jullie willen vragen: wat gebruiken jullie om inzicht te houden in jullie logs en metrics?  Zijn er systemen die we absoluut zouden moeten gebruiken?  Producten die we absoluut moeten vermijden?  We leren graag van jullie ervaringen op dit gebied!