Fix moodle:sync piling up overlapping instances via category-fetch N+1

[Celeo]

Rationale

Exec'd into the live prod api-worker pod and found 4 concurrent moodle:sync processes running simultaneously, none finished, with elapsed times of 11h41m, 8h41m, 5h41m, and 2h41m — i.e. a new instance had started every ~3 hours (its schedule interval) despite the previous ones never completing. Each held ~55-63MB RSS, so roughly 230-290MB of the pod's memory was just stacked duplicate jobs. This was discovered while investigating why api-worker's real CPU/memory usage ran persistently above its Kubernetes resource request (fixed separately via a gitops resource bump, but that only addressed the symptom, not this root cause).

What was wrong

moodle:sync is scheduled in app/Console/Kernel.php:

$schedule->command('moodle:sync')
    ->everyThreeHours(0)
    ->onOneServer()
    ->runInBackground()
    ->withoutOverlapping(120)
    ...

MoodleSync::handle() does a fully sequential User::chunk(1000, ...) loop — one Moodle HTTP call at a time, no concurrency. Once a run's wall-clock time exceeds the 120-minute withoutOverlapping() lock, Laravel's scheduler considers the slot free and starts a new instance on the next 3-hour tick even though the previous one is still alive. Nothing ever kills the stale runs, so they keep stacking.

The dominant contributor to the excess runtime: inside MoodleSync::sync() (called once per user), VATUSAMoodle::getCategoryFromShort() is called 5 times per user (STU/TA/FACCBT/INS role-assignment blocks), and every single call internally calls getCategories() — a full, uncached HTTP round-trip to Moodle's core_course_get_categories, returning the entire category tree. That tree is static for the duration of one run, so this is a severe N+1: for every user in a potentially large table, the same full tree gets re-fetched from Moodle live, sequentially, up to 5 times.

Constraint we had to respect: per api/CLAUDE.md, the 120/60-minute withoutOverlapping() windows on moodle:sync/moodle:competency were deliberately shortened in a prior fix (a324474) specifically so an orphaned lock (pod killed mid-run, before it reaches schedule:finish) self-heals in ~1-2h instead of Laravel's 24h default. Lengthening those windows back would reintroduce that problem, so this fix makes the job's real runtime reliably fit inside the existing window instead of loosening the lock.

What we changed

app/Classes/VATUSAMoodle.php

• getCategories() now memoizes its result for the lifetime of the instance. The same VATUSAMoodle instance is injected once into MoodleSync via its constructor and reused across the entire User::chunk() loop, so this is correctly scoped — it collapses up to 5x live fetches per user down to a single fetch for the whole run, with no change to which categories/roles get assigned. getCategory() and getAllSubcategories() are untouched — both hit Moodle with server-side filtering criteria and must stay live.
• request() is now overridden to bound every Moodle HTTP call to 30s via a save/restore-scoped default_socket_timeout. The vendored llagerlof/moodlerest package's request() uses file_get_contents()/stream contexts with no explicit timeout, so it silently fell back to PHP's 60s ini default (not guaranteed). We scope the ini change tightly around each individual call — not once for the whole process — since default_socket_timeout is process-global and this app's predis (Redis) client also consults it.

app/Console/Kernel.php

• Reworked the before/after scheduler hooks to bridge elapsed time via Cache instead of a shared closure variable. Non-obvious subtlety: both moodle:sync and moodle:competency use ->runInBackground(), and for background events Laravel runs the after hook in a separate, freshly-booted schedule:finish process with no shared memory with the schedule:work process that ran before — a use (&$var) closure wouldn't have worked here.
• Logs a WARN if a run exceeds 75% of its lock window — 90 min for moodle:sync (120min lock), 45 min for moodle:competency (60min lock) — so a future regression surfaces as a log line instead of requiring another live-pod investigation. Other scheduled commands still get a free elapsed-time annotation on their "Finished" log line but no threshold, since picking one for jobs not implicated in this bug would be guessing.

Explicitly out of scope: the withoutOverlapping() window values themselves; MoodleCompetency.php (doesn't call getCategoryFromShort()/getCategories() and wasn't observed stacked); parallelizing the remaining per-user Moodle calls (getUserId, updateUser/createUser, assignCohort, assignRole, etc.) — no production numbers on user-table size or per-call Moodle latency to justify that yet. The new WARN log exists to catch it cheaply if the N+1 fix alone turns out to be insufficient.

How we verified locally

No composer/vendor available outside a container, so verification used compose.dev.yml (MySQL + Redis + artisan serve). Getting that stack running exposed three pre-existing, unrelated gaps in the dev setup (fixed transiently for verification only, not part of this diff — worth their own follow-up):

• bootstrap/cache doesn't exist on a fresh checkout (gitignored) but the bind-mounted container needs it writable.
• The compose command runs composer install (which boots the app via package:discover) before copying .env.example → .env, so it always fails on a truly fresh clone with no APP_KEY.
• config/database.php hardcodes 'scheme' => 'tls' for Redis with no env override, but the dev redis:7-alpine container is plaintext, so Predis hangs on the TLS handshake on every artisan boot.

Once the stack was up:

• php -l on both changed files — no syntax errors.
• ./vendor/bin/phpunit — 3/3 existing smoke tests pass, unaffected.
• php artisan schedule:list — parses cleanly with the new hook signatures; moodle:sync/moodle:competency still show their existing due times and mutex locks.
• php artisan migrate — ran clean against the compose MySQL.
• Tinker check with a counting VATUSAMoodle subclass that intercepts request(): 5 calls across getCategories()/getCategoryFromShort() collapsed to exactly 1 live core_course_get_categories fetch — confirms the N+1 fix.
• Tinker check simulating the before/after hooks across a fake 95-minute run (backdating the Cache marker): elapsed time computed correctly (95 min), Log::warning fired for exceeding the 90-minute moodle:sync threshold, and the cache marker was cleaned up afterward.

How to verify post-deploy

Per api/CLAUDE.md's existing diagnostics, across 2-3 full 3-hour moodle:sync cycles:

kubectl logs -n current deploy/api-worker --since=6h | grep -i "moodle:sync"
kubectl exec -n current deploy/api-worker -- sh -c 'ps -o pid,etime,rss,args | grep -i moodle:sync'

Confirm only one moodle:sync process is ever alive at a time (no more 3h-apart stacking), the "Finished" log line reports a duration comfortably under 120 minutes, RSS stays in the same ~55-63MB range, and no WARN fires. If a WARN does fire, that's a live signal the N+1 fix alone wasn't sufficient and the parallelization follow-up (explicitly deferred above) is needed.

🤖 Generated with Claude Code

[Celeo]

This seems to have not fixed the issue.