En modern Dr. Watson

Jag tittar på skärmen och tänker att detta är ju helt omöjligt, det kan väl inte finnas någon rationell förklaring till de problem jag har? Inte kan det väl vara så denna gång...?

Sherlock Holmes — bäst på att debugga

Sherlock Holmes är kanske en av de mest kända logikerna i vårt samhälle; genom enbart logik och observation når han snabbt till synes omöjliga slutsatser från den givna faktan. När han skapades så var det brottsfall han tog tag i, men hade han funnits idag hade det nog varit debuggningen av datorproblem han tagit sig an.

Alla som debuggat ett ”omöjligt” problem någon gång förstår nog vad jag menar med att Sherlock Holmes varit rätt man för jobbet med sin logik. Faktum är att han nog hade varit bättre på att debugga än att lösa brott; till skillnad mot människor är datorer deterministiska och logiska varelser. Det är också det som gör datorer så stundtals frustrerande: det är aldrig deras fel.

Som utvecklare har jag lärt mig att det tyvärr aldrig är korrekt att bara skylla ifrån sig på datorn eller andra yttre omständigheter – det är med absolut största sannolikhet mitt eget fel. Datorer är väldigt bra på en sak på det sättet – de gör det väldigt uppenbart vilken idiot du är.

Jag stötte nyligen på ett problem där jag i slutet kände mig som en riktigt idiot. Ett problem där jag kände mig som Dr. Watson utan Sherlock Holmes – förvirrad och med en stark känsla av att det omöjligen fanns rationell lösning på problemet. Låt mig därför presentera en modern variant ett fall för Sherlock så ska vi se hur bra du är, på en skala från mig till Sherlock Holmes.

Faktan

Uppgiften var att skriva en förbokningssida för iPhone 7 till en av de större telekomoperatörerna i Sverige. Sidan i sig är ganska enkel och kör en Angular-frontend med en väldigt enkel PHP-backend, som egentligen bara sparar användarnas information i databasen och ser till att mail kommer iväg till kund och operatör.

Sidan körs på en cloudplattform och finns i två versioner — en dev-version och en prod-version. När jag börjar arbeta med projektets backend kör prod-versionen en sida med rykten om Apples produkter (eftersom iPhone 7 då ej hade släppts), och all utveckling sker därför mot dev-versionen.

Mailen skickas ut via ett PHP-script som går igenom mailkön och skickar iväg alla mail som inte ännu skickats. PHP-skriptet tar en parameter som berättar för det vilken databas det bör gå mot (dev eller prod). Det körs av ett cronjob som en gång i minuten anropar skriptet.

Det jag skulle göra var att ändra mallarna för mailen som skickades; jag skulle lägga till mer information till mailen som gick till operatörerna och mailen till kunderna skulle se annorlunda ut. Slutligen så skulle mailen även komma från en annan mailadress än tidigare.

Problemet

Jag ändrade enkelt mallarna och la till den nya informationen som skulle skickas ut, verifierade att det såg rätt ut och laddade upp det på dev-miljön.

Sedan testade jag att gå igenom flödet från början: jag bokade en telefon och inväntade mailen (både till konsument och operatör). När jag får in dem visar det sig dock att det är den gamla mallen som använts! Dessutom var mailen från den gamla mailen!

De ändringar jag hade gjort i form av ändringar till mallarna verkade alltså inte ha slagit igenom! Jag fortsätter testa och får plötsligt rätt mall, från rätt mail! Fastän jag inte gjort några ändringar! Jag upprepar processen igen direkt — fel mall och mail.

Dags att börja debugga.

Debuggningen

Jag börjar givetvis debuggningen med att likt Dr. Watson tänka ”det är ju helt omöjligt att det blir såhär!”.

Stämmer projektet på servern?

Jag börjar min debuggning med att SSH:a mig in på servern för att kika på projektet och se att allt står rätt till. Jag kollar igenom mallarna och dubbelkollar att de ser rätt ut och matchar de jag har skrivit lokalt, det gör de.

Efter det testar jag att göra ändringar i PHP-filen som tar emot kundens uppgifter och sparar det och ser att ändringarna har gått igenom.

Slutsats: projektet är uppdaterat och det är det som körs.

Finns mallarna och mailen ens skrivet någonstans på servern?

Finns då mallarna eller mailen nedskriven någonstans på servern? Först söker jag igenom hela mitt projekt lokalt — ingenstans står mailen eller delar av mallen nedskriven. Jag kör ”grep” för att rekursiv söka igenom alla filer på servern efter strängarna. Ingenting.

Slutsats: ingenstans på hela servern står texterna som sedan mailas ut.

Mailtjänsten kanske cachar någon slags mall?

Kanske är det då mailtjänsten vi använder som på något sätt cachar mallarna eller liknande? Jag kikar igenom dokumentationen och ser att det verkar finnas möjlighet att skapa templates som används vid mailutskick. Jag letar igenom vårt konto efter mallar — inga.

Fast! Det visar sig att vi inte använder det kontot för att skicka ut mailen, så jag skapar en API-nyckel för inloggningen och byter till den nya nyckeln. Ingen skillnad — mailen är fortfarande fel.

Slutsats: felet har inget med mailtjänsten vi använder att göra.

Är det något fel med cronjobbet?

Är det något knasigt med cronjobbet? Cloudtjänsten använder sig av shards och virtualisering och såna där coola saker, kanske är det något som blivit fel med vilken användare som kör cronjobbet?

Jag SSH:ar in på servern och börjar leta runt bland alla cronjob. Tyvärr verkar det bara vara ett cronjob som körs, och det körs som samma användare som jag är inne som.

För att dubbelkolla så testar jag att sätta några mail i mailkön till att de inte blivit skickad och sedan manuellt anropa PHP-scriptet som skickar ut mail.

Mailen är rätt.

Slutsats: om man manuellt kör PHP-scriptet är mailen rätt.

Är det verkligen inte något fel med cronjobbet?

Jag har redan innan konstaterat att cronjobbet körs som rätt användare och när jag manuellt kör exakt samma kommando som cronjobbet, blir det rätt. Om jag däremot väntar så blir det fel mail som skickas.

Hur mycket jag än försöker hittar jag inget fel på det cronjobb som finns.

Slutsats: det är verkligen inte något fel på cronjobbet.

Så... vad är felet?

Innan jag ger dig svaret vill jag att du tänker igenom det hela. Lösningen går att se med hjälp av den fakta som finns och de steg i debuggningen som leder upp till detta steg. Faktum är att Sherlock Holmes nog att hade löst problemet redan vid faktan.

Har du tänkt klart?

Problemet var som så ofta är fallet en copy-paste. PHP-skriptet tar som sagt en parameter som bestämmer mot vilken av databaserna det ska hämta datan. Felet var att prod-servern hade ett cronjob som var copy-paste:at från dev-servern utan att ha ändrat parametern från dev till prod.

Det som skedde var alltså att prod-servern, som inte har uppdaterats med nya mallar och mail, går upp mot dev-serverns databas och skickar ut dess mail och sätter sedan dessa som skickade. Eftersom båda scripten går mot samma databas och körs någorlunda parallelt blir det stundtals korrekt — om prod-servern är lite för seg med att skicka mail hinner dev-servern få iväg några stycken (det vill säga, ett väldigt klassiskt race condition).

När felet är löst och jag ser hur trivial lösningen är och hur uppenbar den ter sig såhär i efterhand känner jag mig som en riktig idiot. Fastän problemet gått fortare att lösa om Sherlock Holmes varit med känner mig också lite glad att han inte fanns där för att påpeka vilken idiot jag är som inte direkt ser lösningen.

Jag tänker tillbaka på alla de problem som varit riktigt svårdebuggade och det slår mig att varje gång har jag börjat med att tänka ”det är ju omöjligt!” och slutat med att stirra på något helt trivialt (och fullständigt möjligt). De problem vi ställs inför när vi debuggar skulle passa bra för en modern Sherlock Holmes: de ser till en början helt omöjliga ut, men visar sig till slut alltid ha en rationell och ofta tämligen enkel lösning.