Hoe één foutje 100k records veranderde in 56M records, waardoor meerdere delen van een productieomgeving urenlang uitvielen en wat we ervan geleerd hebben.

Serverloze applicaties zijn de laatste jaren sterk in opkomst. Bij Levarne zijn we ook voorstanders van serverless, omdat we de grote voordelen uit eerste hand hebben ervaren. Aangezien het een veld is dat zich blijft ontwikkelen, valt er nog elke dag veel te leren. En soms zul je het op de harde manier moeten leren. Dat is precies wat ons een paar weken geleden is overkomen.
Hoewel het op het moment zelf erg pijnlijk was, hebben we veel geleerd van een bepaalde case die we hebben meegemaakt op het gebied van architectonisch ontwerp en enkele van de innerlijke werkingen van een paar AWS services. In deze driedelige serie zullen we je vertellen welke problemen we tegenkwamen, wat de oorzaken waren, hoe we de problemen hebben opgelost en wat we van deze case hebben geleerd. Als je tot het einde doorleest, leer je dezelfde dingen als wij, maar zonder dat je datzelfde pijnlijke moment hoeft mee te maken.
In dit eerste deel gaan we dieper in op de problemen waarmee we te maken kregen, leggen we uit hoe we de problemen hebben aangepakt en leggen we enkele interessante technologische aspecten van AWS Lambda invocaties uit.

• Your Worst-case Serverless Scenario Part I: Invocation Hell
• Your Worst-case Serverless Scenario Part II: Magic With Numbers
• Your Worst-case Serverless Scenario Part III: The Invisible Process

"Houston, we hebben een probleem..."

Dit verhaal begon een paar weken geleden, begin maart 2020, toen we een telefoontje kregen van een van onze klanten. Volgens hen waren meerdere onderdelen van de applicatie plotseling gestopt met werken. Ze gaven een aantal voorbeelden van dingen die fout waren gegaan om ons te helpen met het onderzoek. Omdat de fouten bedrijfskritisch waren, zijn we meteen op zoek gegaan naar wat er precies aan de hand was. Eerst zijn we de beweringen van de klant gaan verifiëren door te kijken naar diensten als AWS CloudWatch, X-Ray, Lambda en DynamoDB. Tijdens het proces van het oplossen van de problemen, vonden we nog een aantal problemen die verband hielden met dezelfde hoofdoorzaak. Hieronder hebben we al deze problemen samengevat om u een compleet beeld te geven van alles waar we tegenaan liepen.

Problemen die we aanvankelijk vonden

• Eén deel van de applicatie faalde altijd. Dit had te maken met een DynamoDB tabel die niet meer gelezen kon worden. Aangezien deze tabel normaal gesproken niet veel gelezen wordt, zou het vinden van de oorzaak van dit probleem eenvoudig zijn via X-Ray en CloudWatch.
• Meerdere delen van de applicatie faalden soms. We konden niet direct zien waarom dit gebeurde of een verband vinden tussen de diensten die faalden. Het vinden van de hoofdoorzaak van dit probleem zou waarschijnlijk meer tijd kosten.

Problemen die we later vonden

• Eén DynamoDB tabel, laten we het de origin tabel noemen, zou ongeveer 100k records moeten bevatten, maar bestond op de een of andere manier uit bijna 56 miljoen records! Het is een duizelingwekkende hoeveelheid vergeleken met wat het zou moeten zijn. Hoewel we het stukje code dat de vorige problemen veroorzaakte al hadden gevonden en wisten dat het ook dit getal veroorzaakte, begrepen we dit niet meteen. Een meer grondige blik op de kwaadaardige code en discussie onder onze ingenieurs was nodig.
• Dezelfde origin tabel was leesbaar nadat alles afgekoeld was, maar was niet meer beschrijfbaar. We hadden dit gedrag al eerder gezien op een DynamoDB tabel, maar normaal gesproken was het veel eerder opgelost. Maar, vanwege de enorme hoeveelheid van bijna 56 miljoen records, was dit hoogstwaarschijnlijk de oorzaak van de extra vertraging.

Laten we rustig beginnen: een simpele codeerfout

Gelukkig voor ons hadden we een goed startpunt met het eerste probleem dat we beschreven: Eén onderdeel van de applicatie faalde steeds. Omdat we al hadden waargenomen dat dit werd veroorzaakt door een DynamoDB-tabel die veel meer reads kreeg dan normaal, konden we via X-Ray opzoeken welke Lambda-functie deze reads uitvoerde. Deze Lambda functie was in principe verantwoordelijk voor het invoegen van een x-aantal items in een database, gebaseerd op de input van een gebruiker (dit kan 1 item zijn, maar het kan oplopen tot +- 250k items). Omdat deze Lambda kan worden aangeroepen via API Gateway en langer kan duren dan 30 seconden, wat de maximale runtime is via API Gateway, hadden we gekozen voor een ontwerp waarbij deze Lambda zichzelf kan aanroepen indien nodig. Echter, bij het opstarten, moest het een aantal gegevens uit een DynamoDB tabel lezen. Dit lezen was niet nodig na het aanroepen van zichzelf, maar door een coderingsfout werd het lezen hier toch uitgevoerd. En, misschien denk je nu al: "maar hey, slechts één extra read? Is dit echt zo'n groot probleem?" Nee, dat doet het niet, maar het bleek dat de functie veel te vaak werd aangeroepen dan nodig was. We zullen hier in de volgende sectie dieper op ingaan, maar voor nu is het goed om te weten dat dit gebeurde.
Om dit probleem op te lossen hebben we de geconstateerde codeerfout hersteld door te controleren op een event path, dat alleen beschikbaar is als het wordt aangeroepen via API Gateway, die op zijn beurt altijd de eerste aanroep is in dit geval.

Voor het geval je het je afvraagt, voor onze DynamoDB tabel gebruikten we voorziene capaciteit met automatische schaling, maar door het veel te grote aantal aanroepen van deze functie, bereikte hij vrij snel zijn maximale voorziene capaciteit.

(Concurrent) Invocation Hell

Door het eerste probleem aan te pakken, kregen we meteen een goed beeld van wat de oorzaak was van al deze problemen. Herinner je dat ons tweede probleem was dat meerdere delen van de applicatie soms faalden en dat we geen relatie konden vinden tussen deze delen. Nu we wisten dat dezelfde Lambda functie die het vorige probleem veroorzaakte veel vaker werd aangeroepen dan zou moeten, vermoedden we dat dit problemen veroorzaakte bij het aanroepen van andere Lambda functies, omdat die hoogstwaarschijnlijk de concurrent Lambda invocation limit. Omdat deze limiet regionaal en per AWS account is, betekent het dat als het eenmaal is bereikt, er geen Lambda uitvoeringscontexten meer kunnen worden opgestart, tenzij reeds bestaande uitvoeringscontexten worden verwijderd. Het bleek dat deze limiet op deze dag inderdaad was bereikt, omdat deze Lambda-functie niet alleen vaker werd aangeroepen, maar ook zijn uitvoeringscontexten langer openhield dan normaal, vanwege DynamoDB-time-outs. Op de vraag waarom de timeouts optraden, gaan we in de volgende secties in meer detail in.

Verwarring en afkoeling

Oké, goed, dus we hebben de oorzaak gevonden. Hoe lossen we het op? Nou, in eerste instantie waren we nogal in de war, want zelfs als deze Lambda's meer zijn aangeroepen dan zou moeten, raken ze nu een limiet, wat een fout veroorzaakt, dus volgens onze code zou het de keten moeten stoppen. Maar dit gebeurde duidelijk niet, want we zagen meer aanroepen voor deze functie en volgens de logs werden ze niet direct door een gebruiker aangeroepen. Omdat het bedrijf geld verloor met elke minuut dat dit probleem aanhield en deze functie niet bedrijfskritisch was, dachten we eraan om hem volledig uit de stack te verwijderen en hem opnieuw te implementeren. Kort daarna koelde het aantal aanroepen echter af en leek het alsof de keten van aanroepen tot een einde was gekomen.

Meer verwarring en opwarming (opnieuw)

Na een telefoontje met de klant leek alles weer normaal te worden, dus in ieder geval was de druk van de klant om geld te verliezen weg en konden wij ons concentreren op waarom precies de functie meer werd aangeroepen dan wij dachten en vervolgens deze functie op een betere manier herontwerpen. Desalniettemin kregen we niet veel later weer een telefoontje van onze klant, dat ze weer dezelfde problemen ondervonden. Maar wacht... de functie werd niet opnieuw aangeroepen door de klant, maar hij werd op de een of andere manier herhaaldelijk door zichzelf aangeroepen in hogere eisen!

Oké, dus... hoe was dit mogelijk? De keten leek eerst te zijn afgekoeld, maar nu leek het alsof er een andere keten was gestart, terwijl de logs duidelijk laten zien dat er geen gebruikersactie was ondernomen. Na een gesprek met Levarne's meest ervaren Cloud Architect, kon hij ons erop wijzen dat de functie zichzelf aanriep met het Event InvocationType en dat dit type aanroep betekent dat in plaats van te wachten op een reactie, Lambda deze aanroepingen zelf regelt. Als er een fout wordt gegooid tijdens het aanroepen, zal het de aanroep in een wachtrij zetten en het na een tijdje tot 2 keer toe opnieuw proberen. En natuurlijk, omdat de herhalingen na enige tijd plaatsvinden en de functies tijdens de eerste golf ongeveer op hetzelfde moment een fout maakten, werd de tweede golf veroorzaakt doordat al deze herhalingen bijna gelijktijdig plaatsvonden. Dit realiserend, hadden we geen andere optie dan de Lambda functie van de stack te verwijderen totdat we een lange-termijn oplossing voor dit probleem hadden gevonden.

Dat is genoeg informatie voor nu. In deel II zullen we uitleggen hoe 100k records veranderden in 56 miljoen records, waarbij we dieper zullen ingaan op de Event InvocationType en Retry patronen uit dit artikel en ook wat intrigerend gedrag van DynamoDB zullen toevoegen.

Visuals in deze post zijn gemaakt door David Kempenaar.