Forum teuk.org

⏳ Mediabot 3.4dev — Every scheduler hourglass is finally connected to the castle portraits 📊🪄

in Mediabot · started by TeuK · 4w ago

TeuK · 4w ago

Mediabot v3 continues its 3.4 development cycle with the final missing piece of its latency observability work: named Scheduler tasks are now timed, logged and exported to Prometheus.

Previous rounds already covered user commands, partyline activity and event-loop stalls. The internal scheduled jobs were the last silent corridor.

That corridor now has a clock.

🕰️ The last unmeasured path

Mediabot regularly runs internal tasks such as:

channel_cache_refresh
channel_ban_expire

These jobs can perform database work, refresh caches or clean expired state.

Until now, a slow scheduled callback could delay the bot without leaving a task-specific timing trace. The general event-loop stall detector could show that the castle had stopped moving, but not which maintenance round caused it.

Both periodic and calendar-based Scheduler tasks now pass through one shared execution helper:

_run_task_callback

This creates one canonical timing and error path for every registered task.

🧪 Every task duration reaches a histogram

Each callback duration is observed through:

mediabot_scheduler_tick_seconds{task}

The task label comes from Mediabot’s internal Scheduler registry rather than user input, so the metric’s cardinality remains bounded.

Prometheus receives the complete duration distribution, including successful and failed callbacks.

Grafana can then calculate p95 by task and answer practical questions such as:

  • which maintenance task is usually the slowest;
  • whether cache refresh latency is gradually increasing;
  • whether one rare callback caused an event-loop stall;
  • whether a scheduler error also consumed significant time.

The bot no longer merely says that the staircases stopped. It can identify which caretaker was working in the corridor at the time.

🚨 Slow rounds identify themselves

Any scheduled task taking more than one second can now produce a log such as:

SLOW SCHEDULER: task 'channel_cache_refresh' took 2.41s

This completes Mediabot’s four-way user and runtime timing coverage:

SLOW PRIVMSG
event loop stalled
SLOW PARTYLINE
SLOW SCHEDULER

A slow operation should no longer be able to hide simply because it came from a timer instead of a human command.

💥 Errors keep their original cry

The Scheduler refactor preserves the existing failure semantics.

When a callback dies, Mediabot still reports the familiar error:

Scheduler: task 'task_name' error: ...

The duration is observed even on that failed path.

This distinction matters:

  • the error log explains what failed;
  • the histogram records how long the failure path consumed;
  • the event-loop detector shows whether the whole bot was delayed.

No diagnostic replaces another. They reinforce one another.

🏗️ One helper, no hidden execution path

The regression contract also verifies the Scheduler structure.

Periodic and calendar tasks must both call the shared timing helper, and direct callback execution outside that helper is forbidden.

That protects the instrumentation from future drift: a newly added task cannot accidentally bypass the clock by copying the old execution pattern.

The portraits are not optional decorations. Every staircase must pass in front of one.

🔌 The hourglass must be connected after construction

The final review found an important startup-order issue.

The first implementation attempted to inject the Metrics object before the Scheduler had been constructed. The code was syntactically correct and the timing logs worked, but the runtime Scheduler never received the Metrics instance.

The practical result would have been:

SLOW SCHEDULER logs: working
Prometheus histogram: empty
Grafana p95 panel: No data

The wiring has now been moved to the correct location: immediately after Scheduler construction.

This final correction also adds a runtime contract and a startup-order contract so the mistake cannot quietly return.

A painted hourglass is not enough. It must actually be connected to the portrait gallery.

📊 Grafana gains Scheduler p95

The main overview dashboard now includes:

Scheduler task duration p95 (by task)

This panel joins the existing database, event-loop and message-processing views.

Operators can now correlate:

  • database reconnects;
  • slow pings;
  • event-loop stalls;
  • PRIVMSG latency;
  • partyline latency;
  • script-bridge latency;
  • scheduled-task latency.

The result is a much more complete operational picture of Mediabot.

🧹 Clean milestone history

The Scheduler timing round follows the already assigned moderation milestones:

MB554 — kick action and gatekeeper
MB555 — final kick hardening
MB556 — Scheduler task timing
MB557 — final Metrics startup wiring

This keeps tests, changelog entries and future articles unambiguous.

✅ Validation status

Claude’s initial Scheduler implementation reported:

10937/10937 tests passed

That run validated the shared helper, periodic and calendar execution, slow-task logging, error preservation, histogram behavior and dashboard contract.

The final wiring correction adds checks that Metrics is injected only after Scheduler construction.

Before publication, the final gate remains:

full test suite
security audit
startup integrity check
GitHub Actions

No database schema change.
No new mandatory configuration.
Without Metrics, Scheduler logging and execution behavior remain available and safe.

🧙 Summary

This round closes Mediabot’s last silent latency path:

  • periodic and calendar tasks use one timed helper;
  • every callback contributes to a Prometheus histogram;
  • slow tasks identify themselves by name;
  • failed callbacks retain their original error logs;
  • failed durations are still measured;
  • direct untimed execution is guarded against;
  • Grafana gains Scheduler p95 by task;
  • Metrics is connected after Scheduler construction, where it can actually work.

The castle now has no unobserved corridor left.

Whether the delay comes from a wizard, the concierge, Gringotts, the moving staircases or a midnight maintenance round, Mediabot has an hourglass nearby—and every hourglass is finally connected to the portraits. ⏳📊🏰🪄

You must be logged in to reply.