Werkplaats / 01
Soms zit de bug helemaal niet in je code
Een hardnekkig probleem met Google Calendar en Meet dat uiteindelijk veel meer lagen bleek te hebben dan alleen mijn eigen applicatie.
Het probleem
Het systeem werkte. Tot de Meet-link ineens verdween.
Onlangs liep ik tegen een behoorlijk hardnekkig probleem aan in het bookingsysteem dat ik zelf heb ontwikkeld. Ik gebruik het binnen Buro Creatixx voor mijn eigen afspraken, maar het systeem is ook beschikbaar voor klanten. Na het bevestigen van een afspraak worden achter de schermen automatisch verschillende stappen uitgevoerd.
Er wordt een event aangemaakt in Google Calendar, Google Meet genereert een link en vervolgens ontvangt de bezoeker een bevestigingsmail met de gegevens van de afspraak.
Die hele keten werkte zoals bedoeld, totdat er ineens geen Google Meet-link meer verscheen. De afspraak zelf kwam nog gewoon binnen en kon ook worden bevestigd, maar vanaf dat punt liep de rest van de flow niet meer zoals het hoorde.
De eerste verdachte
Dan kijk je als eerste naar je eigen code.
De logging gaf daar ook alle reden toe. Op verschillende momenten kreeg ik meldingen dat de Google-koppeling verlopen of ingetrokken was, terwijl andere fouten wezen op ontbrekende toegang tot Google Calendar.
Vanuit Google zelf verscheen daarnaast deze melding:
insufficient authentication scopesDat wijst behoorlijk nadrukkelijk naar OAuth. In deze koppeling is OAuth het mechanisme waarmee mijn bookingsysteem toestemming krijgt om namens mij handelingen uit te voeren in Google Calendar.
Daarbij worden zogenaamde scopes gebruikt. Die bepalen precies welke rechten een applicatie krijgt. Mijn eerste onderzoek richtte zich daarom op de vraag of Google daadwerkelijk dezelfde Calendar-rechten verleende als waar mijn applicatie vanuit ging.
De OAuth-flow
De koppeling kon strenger controleren.
Ik heb de OAuth-flow vervolgens behoorlijk grondig doorgelopen. De applicatie controleert nu niet meer alleen of een koppeling technisch is gelukt, maar ook welke rechten Google daadwerkelijk aan het token heeft gekoppeld.
Die scope-informatie wordt opgeslagen, waardoor ook bestaande koppelingen waarvan die gegevens nog ontbreken alsnog gecontroleerd kunnen worden wanneer ze opnieuw worden gebruikt.
Ook de refresh-logica is aangescherpt. Een bestaand refresh token wordt niet meer zonder verdere controle hergebruikt wanneer niet duidelijk is of de benodigde Calendar-rechten daarbij horen.
Nog een fout
Tijdens dat onderzoek kwam een tweede probleem boven water.
De OAuth-callback bleek onder bepaalde omstandigheden te kunnen crashen bij het verwerken van de informatie over het verlopen van een token.
Invalid time valueGoogle levert informatie mee over wanneer een token verloopt, maar die informatie bleek niet altijd bruikbaar aanwezig te zijn. Mijn systeem probeerde daar vervolgens alsnog een geldige datum van te maken, waardoor de callback kon vastlopen.
Ook dat probleem is aangepast. De expiry-informatie wordt nu eerst gevalideerd en wanneer er geen bruikbare waarde aanwezig is, probeert het systeem niet langer geforceerd een datum te construeren.
Tegelijkertijd heb ik de foutdiagnostiek uitgebreid. Wanneer Google Calendar iets weigert, wordt nu veel specifieker vastgelegd tijdens welke handeling dat gebeurt, welke HTTP-status Google teruggeeft en welke reden daarbij hoort.
Daarbij worden gevoelige gegevens zoals tokens, e-mailadressen en Meet-links bewust buiten de logging gehouden.
Opnieuw testen
Na die aanpassingen werkte de hele keten weer.
Ik heb de volledige flow opnieuw doorlopen en alle onderdelen reageerden weer zoals bedoeld.
Op dat moment leek het probleem opgelost. De code was robuuster geworden, de foutafhandeling was beter en de Google-koppeling deed weer precies wat hij moest doen.
Een paar dagen later
Toen kwam hetzelfde probleem terug.
Een paar dagen later testte ik opnieuw. Ook nu kon ik de afspraak gewoon bevestigen, maar de Google Meet-link verscheen opnieuw niet.
Google koppeling is verlopen of ingetrokken. Koppel het Google-account opnieuw.Dat veranderde de aard van het onderzoek. Inmiddels waren er namelijk verschillende echte problemen in de applicatie gevonden en opgelost, terwijl de fout desondanks terugkwam.
Daarmee werd het steeds waarschijnlijker dat het laatste ontbrekende puzzelstuk niet meer in mijn eigen code zat. De volgende laag om te onderzoeken was daarom de configuratie van Google Cloud zelf.
Google Cloud
Daar zat het laatste ontbrekende puzzelstuk.
In Google Cloud kwamen uiteindelijk twee dingen naar boven. De OAuth-app stond nog in Testing. Voor een productie-integratie was dat niet de gewenste configuratie, dus die is correct ingericht en naar In production gezet.
Daarna kwam het belangrijkere probleem aan het licht. Onder Google Auth Platform → Data Access stond de benodigde Google Calendar-scope helemaal niet geregistreerd.
Mijn applicatie vroeg tijdens de OAuth-flow wel om toegang tot Google Calendar en controleerde daarna ook netjes of Google die rechten daadwerkelijk had verleend. Alleen ontbrak dezelfde Calendar-toegang in de configuratie van de OAuth-app zelf.
https://www.googleapis.com/auth/calendarNadat die scope expliciet onder Data Access was toegevoegd, heb ik Google opnieuw gekoppeld en de Calendar-toestemming opnieuw geaccepteerd.
Vervolgens heb ik opnieuw de volledige keten getest. De afspraak werd bevestigd, het Calendar-event werd aangemaakt, Google Meet genereerde de link en de bevestigingsmail werd verstuurd.
Dit keer bleef de koppeling ook na nieuwe tests correct werken.
Wat hier interessant aan was
Uiteindelijk was er niet één bug.
Achteraf zou het verleidelijk zijn om de ontbrekende Calendar-scope in Google Cloud simpelweg als de oorzaak van het hele probleem aan te wijzen. Dat zou alleen geen volledig beeld geven van wat er werkelijk gebeurde.
Tijdens het onderzoek kwamen namelijk ook echte problemen in mijn eigen applicatie naar voren. De verwerking van expiry-informatie kon fout gaan, de controle op scopes kon beter, de refresh-logica kon veiliger en de foutdiagnostiek gaf nog onvoldoende inzicht.
Die aanpassingen waren dus geen nutteloze omweg. Ze losten alleen niet het laatste probleem in de keten op, omdat dat probleem zich een laag verderop bevond.
Digitale systemen
Je eigen code is maar één laag van het systeem.
Moderne digitale systemen bestaan zelden uit alleen de applicatie die je zelf bouwt. Er zitten externe API's aan vast, authenticatielagen, tokens, rechten, cloudconfiguraties en beveiligingsregels van andere partijen.
Wanneer ergens in die keten iets misgaat, wordt het effect vaak zichtbaar in je eigen applicatie. Daarom is het logisch dat het onderzoek daar begint, maar dat betekent nog niet automatisch dat de oorzaak zich daar bevindt.
Juist bij hardnekkige problemen wordt het daarom belangrijk om niet alleen naar individuele fouten te kijken, maar naar de hele keten waarin die fout ontstaat.
Uiteindelijk
De koppeling is er beter van geworden.
Het ironische is dat ik behoorlijk lang naar mijn eigen code heb gekeken voor een probleem waarvan het laatste ontbrekende puzzelstuk buiten die code bleek te liggen.
Juist dat onderzoek heeft de koppeling uiteindelijk veel robuuster gemaakt. Het systeem controleert beter welke rechten Google werkelijk heeft verleend, gaat zorgvuldiger om met tokens en ontbrekende metadata en geeft veel specifiekere informatie wanneer er iets misgaat.
Al dat zoeken was dus bepaald niet voor niets. Alleen het laatste ontbrekende puzzelstuk zat op een plek waar ik met geen regel code iets aan kon veranderen.
Je kunt behoorlijk lang om een probleem heen programmeren wanneer je blijft zoeken in de laag waar de fout zichtbaar wordt, terwijl de oorzaak ergens anders in de keten zit.