Als Functioneel Beheerder van een Open Source pakket kun je nog weleens voor uitdagingen komen te staan die je niet verwacht had. Ik noem dit ook wel Moodle bug hunting 1-0-1.
In deze blog neem ik jullie mee in het vinden van een Moodle Bug waar jouw eindgebruikers helemaal niets van merken, maar die je server beheerder wel degelijk op zal vallen.
Moodle bug hunting 1-0-1
backuppen van de database duurt te lang!
Als Functioneel beheerder gebruik ik een monitoringsysteem. Deze geeft mij een melding wanneer een leeromgeving niet binnen een bepaalde tijd reageert op wat we noemen een “ping”.
De insteek is natuurlijk dat je géén meldingen krijgt, maar goed.. een week of twee geleden werd ik midden in de nacht wakker van een melding dat een van de leeromgevingen die ik ondersteun eruit zou liggen.
Het was geen melding waar ik direct voor uit mijn bed zou komen, zeker gezien het tijdstip en de wetenschap dat we op dat moment een back-up maken van de database.
Hetgeen wat mij wel enigszins alert maakte, was toen ik ’s ochtends zag dat dit ruim dertig minuten geduurd heeft. Dit was zeer ongewoon, zeker gezien het gebruik van de omgeving. Ik besloot gauw te overleggen met de hostingpartij.
De hostingpartij wees mij erop dat de database vergeleken met andere omgevingen echt groot was. Okay, dacht ik… deze klant heeft heel veel opdracht activiteiten en daar wordt natuurlijk fanatiek gebruik van gemaakt. Daarnaast was het een drukke periode.
In overleg stelde ik de back-up procedure bij, zodat de klant hier geen last van zou ondervinden.
Het werd niet beter…
Ondanks het bijstellen van de back-up procedure loste het probleem niet op. We zagen ook dat de tijd die nodig was in een rap tempo opliep en toen we op één uur zaten begonnen we ons toch wel zorgen te maken.
Voordat ik verder ga, wil ik wel even zeggen dat ik zeer blij bent met een hostingpartij als Rimote. Ze kijken niet alleen mee, maar denken ook met je mee. Daarnaast zijn ze erg alert op dit soort zaken, waardoor ik als functioneel beheerder op tijd kan ingrijpen.
Het was in ieder geval nu tijd voor onderzoek!
Moodle bug hunting 1-0-1
De rapportage
Een van de zaken die mij opviel als functioneel beheerder was dat de rapportage logs elke dag meer dan 20 duizend pagina’s bevatten. Als je bedenkt dat op elke pagina zo ongeveer vijftig regels staan, dan is dat wel heel veel data.
Het was onmogelijk voor mij om door de pagina’s heen te bladeren. En zelf Excel stuiterde, want die kan maar maximaal 10 duizend regels aan op één pagina.
Ik stelde het tijdstip van bewaren tussen twee momenten bij naar een korter moment. Dat hielp wel iets maar maakte niet direct een wezenlijk verschil.
Het duurde een paar dagen voordat bij mij het kwartje viel en ik het verband begon te zien tussen de enorme rapportage logs en de database die in een rap tempo groter werd.
Wat mij in de rapportage wel vraagtekens gaf, was dat er elke minuut een registratie was dat er een kalenderitem was bijgewerkt.
Het bleek te gaan om kalenderitems die gerelateerd waren aan de activiteit: de opdracht. Het ging met name om de data en tijden rondom het inleveren, de uiterlijke inleverdatum en het beoordelen.
Dat de cron op deze omgeving elke minuut draaide en in de cursus met name deze activiteit gebruikt werd inclusief de instellingen, was voldoende verklaring waarom de database zo ontzettend snel groot geworden was.
Maar… waarom gebeurde dit? Ik begon mijn onderzoek bij de cron.
Moodle bug hunting 1-0-1
De cron
In deze omgeving was ingesteld dat de cron elke minuut draaide. Maar er moet natuurlijk wel een taak of event zijn die zorgt dat de kalenderitems bijgewerkt worden.
Het meest logische leek mij een taak van de kalender zelf, maar dit gaf geen uitsluitsel. Ik keek verder naar een taak die elke minuut draait.
Aangezien het gericht was op de opdracht functie kwam ik als eerste uit bij de cron taak: \mod_assign\task\cron_task en ja, hier bleek iets aan de hand te zijn.
Hier kom je dan ook weer op het punt aan waarom ik soms zo blij ben met de Open Source community van Moodle. Want in 3.8 is het nu mogelijk om als sitebeheerder zelf de taak logs te bekijken zonder dat je naar de server hoeft te gaan.
Moodle bug hunting 1-0-1: Misleiding
Uiteindelijk bleek het een “dwaalspoor” te zijn. Beter gezegd: het bleek om een ander probleem te gaan. Maar goed, nu we toch bezig zijn..
In de log zag ik een drietal meldingen ++ Error: mdb->get_record() found more than one record! ++ . Dan heb je Moodle op zijn best, want om welke activiteit/cursus gaat het nu? Ik heb over de duizend opdrachten modules in deze omgeving!
Via de rapportage log viel mij na een stevige zoektocht op dat er oudere opdrachten modules waren, waar meerdere kalenderitems in stonden. Daar stond dus ook data die al lang niet meer klopte.
Hoewel dit issue niks te maken met het echte probleem, bezorgde het oplossen ervan mij wel de nodige kopzorgen.
In eerste instantie leek het alleen op te lossen zijn door heel drastisch de hele cursus te verwijderen. Gelukkig vond ik uiteindelijk de oplossing binnen de Cursus herstel opties van Moodle.
Let op: dit kun je natuurlijk alleen doen als er niet meer actief gewerkt wordt in de cursus. Ik adviseer je altijd eerst een back-up te maken als het om een productie omgeving gaat.
Moodle bug hunting 1-0-1: de community
Terwijl ik bezig was, vond ik het wel tijd worden om de community van deze problemen op de hoogte te brengen.
Dit heb ik uiteindelijk pas gedaan nadat ik uitgezocht had of iemand anders nog geen melding gemaakt had van dit probleem. Google Search in combinatie met het Moodle Forum geeft je gelukkig een redelijk inzicht of dit het geval is. De Moodle Tracker is een ander verhaal. Hier moet je echt heel specifiek zijn. Na een aantal pogingen kwam ik niet uit op een tracker die er in de buurt kwam.
Opgeven doe ik niet, dus besloot ik het issue te bespreken op het Moodle Community forum en een oproep te plaatsen in de Moodle DEV chat.
Ik kreeg gehoor bij mij grote favoriet: Tim Hunt.
Tim wees mij uiteindelijk in de juiste richting met de twee trackers:
https://tracker.moodle.org/browse/MDL-67204
Deze was specifiek gericht op de opdracht activiteit. Ik reproduceerde de stappen en trok de conclusie dat het probleem inderdaad vrij simpel op te lossen was door een vinkje aan te zetten bij de instellingen van de opdracht.
Met meer dan duizend opdracht activiteiten heb je echt geen zin om dit 1 voor 1 te doen. Ook al kan ik bij de database en kan ik het zo sneller oplossen.
Ik zag ook dat de tracker al op opgelost stond en dat er gemeld was dat de patch bij de volgende minor update in maart al beschikbaar zou zijn.
https://tracker.moodle.org/browse/MDL-66597
De tracker geeft eigenlijk aan dat dit probleem voordoet in meerdere activiteiten. Dus niet specifiek de opdracht activiteit. Het probleem hier is nog niet opgelost, via de DEV channel kreeg ik te horen dat ze er wel druk mee bezig zijn.
Moodle bug hunting 1-0-1: Wat doe je nu?
De afweging is vervolgens of je het laat doorgaan totdat de nieuwe minor release uit is, of dat je bij elke opdracht het vinkje aan gaat zetten.
Ik besloot uiteindelijk eerst om wat anders te doen. Ik moest namelijk eerst de leeromgeving updaten naar de laatste Minor 3.8.1 + release.
Een + release komt wekelijks uit waar kleine aanpassingen direct in staan. Er zijn voor -en nadelen om dit te doen, want elke update (minor of major) brengt risico’s met zich mee.
Opgelost
Voor deze klant was het issue opgelost nadat ik de + release had doorgevoerd. Althans deels… De rapportage maakte geen onnodige meldingen meer aan. We zagen ook al heel snel een stabiliteit op de server ontstaan.
Het probleem is deels opgelost, omdat er nog zeker wel een behoorlijke tijd overheen zal gaan voordat de database weer op een “normale” grootte zal zijn.
We hebben het bewaren van de logs nu zwaar verminderd, zodat dit tijdbestek korter wordt. In een paar dagen tijd zagen we onze database van veertig gb naar twintig gb gaan. We hopen nu binnen een maand op een acceptabel niveau te zitten.
En de klant? Die heeft hier verder niets van gemerkt.
Kun je niet zo lang wachten? zet dan het aantal dagen dat je log bijhoudt omlaag en pas de taak \logstore_standard\task\cleanup_task op elke 10 minuten i.p.v. de standaard waarden.