on-demand requests are ignored for up to an hour: _poll_on_demand_requests inherits max_age=3600 as its in-memory TTL

[ChuckBuilds]

Summary

_poll_on_demand_requests reads the request through cache_manager.get('display_on_demand_request', max_age=3600). get_cached_data defaults the in-memory TTL to max_age, so the first request read is pinned in the display service's memory for an hour. Every later poll gets that stale entry, short-circuits on the already-processed check, and never re-reads the file the web service just wrote.

Net effect: after the first on-demand request, no further on-demand request is honoured for up to an hour, unless the display service restarts. /api/v3/display/on-demand/start still returns HTTP 200 with a request_id, so there is no sign of failure at the caller.

Why it's usually invisible

on-demand/start defaults to start_service: true, which restarts the display service and wipes the memory cache as a side effect. Passing start_service: false — the sensible choice when the service is already running, to avoid the ~40s boot splash — is what exposes it.

Reproduction

LEDMatrix v3.3.0-4-g0730d952, 256x64 rig, display service running throughout.

# request 1 — 17:45:47
POST /api/v3/display/on-demand/start {"plugin_id":"7-segment-clock","duration":90,"pinned":true,"start_service":false}
-> 200, request_id 179dfa66-...
journal: Received on-demand request 179dfa66-...: start
         Requested on-demand mode '7-segment-clock' is not available     # separate race, see below

# request 2 — 17:53:50, same session, no restart
POST /api/v3/display/on-demand/start {"plugin_id":"7-segment-clock","mode":"7-segment-clock","duration":75,"pinned":true,"start_service":false}
-> 200, request_id 80103dfb-...

Two and a half minutes later the second request had never been seen:

disk  /var/cache/ledmatrix/display_on_demand_request.json     -> request_id 80103dfb-...   (17:53)
disk  /var/cache/ledmatrix/display_on_demand_processed_id.json -> 179dfa66-...              (17:45)
GET /api/v3/display/on-demand/status                          -> {"active": false, "status": "idle"}
journal: no mention of 80103dfb at all

Restarting the display service — changing nothing else — picked it up in 2 seconds and it activated fine:

$ sudo systemctl restart ledmatrix
17:56:23 INFO Received on-demand request 80103dfb-...: start (plugin_id=7-segment-clock, mode=7-segment-clock)
17:56:23 INFO Processing on-demand start request for plugin: 7-segment-clock
17:56:23 INFO Activated on-demand for plugin '7-segment-clock' with 1 modes: ['7-segment-clock']
17:56:38 INFO Rotating to next on-demand mode: 7-segment-clock (index 0/1)

processed_id.json -> 80103dfb-...

So the request itself was valid the whole time; only the stale in-memory copy stood between it and the controller.

Cause

src/display_controller.py:1270-1276:

def _poll_on_demand_requests(self) -> None:
    """Poll cache for new on-demand requests from external controllers."""
    try:
        # Use a long max_age (1 hour) to ensure requests aren't expired before processing
        # The request_id check prevents duplicate processing
        request = self.cache_manager.get('display_on_demand_request', max_age=3600)

src/cache_manager.py:299-320:

def get_cached_data(self, key: str, max_age: int = 300, memory_ttl: Optional[int] = None):
    in_memory_ttl = memory_ttl if memory_ttl is not None else max_age
    # 1) Memory cache
    cached = self._memory_cache_component.get(key, max_age=in_memory_ttl)
    if cached is not None:
        return cached
    # 2) Disk cache
    ...

The comment above the call explains that max_age=3600 is there so a disk record isn't considered expired before it's processed — a good reason. What it doesn't account for is that the same number silently becomes the memory TTL, which is the opposite of what a poll loop wants: this key is a mailbox written by another process, so it must be read from disk every time.

Suggested fix

Pass an explicit, short memory TTL (or zero) at the call site:

request = self.cache_manager.get('display_on_demand_request', max_age=3600, memory_ttl=0)

memory_ttl=0 should make _memory_cache_component.get(key, max_age=0) always miss; worth confirming that's how it behaves, otherwise bypass the memory layer for this key explicitly. The same question applies to any other cross-process mailbox key read through cache_manager.

It would also help if /display/on-demand/start didn't report success for a request that hasn't been accepted yet — the caller currently cannot distinguish "queued", "rejected", and "will be silently ignored for an hour".

Secondary, noticed alongside

Enabling a plugin and immediately issuing an on-demand request for it fails with Requested on-demand mode '<id>' is not available, because the display controller reconciles plugins on its own cadence — in this run the toggle landed at 17:45:4x and the reconcile at 17:46:36, ~49s later. The API returns 200 and the failure only surfaces as {"status": "error", "error": "invalid-mode"} in /on-demand/status. Not the same bug, but the same reporting gap.

Environment

LEDMatrix v3.3.0-4-g0730d952, Raspberry Pi, 256x64 panel, ledmatrix.service as root and ledmatrix-web.service as a normal user. Found while validating plugins on real hardware.

[ChuckBuilds]

A cleaner reproduction of the secondary issue mentioned at the end of the original report — the on-demand request being dropped while the API reports success. It is a startup race, and it is easy to hit because start_service: true is the default.

When start_service: true, the restart it triggers means the freshly-started controller reads the request before it has loaded plugins, so the mode legitimately isn't available yet:

19:55:12  INFO  Received on-demand request dafaca75-...: start (plugin_id=of-the-day, mode=of_the_day)
19:55:12  INFO  Processing on-demand start request for plugin: of-the-day
19:55:12  ERROR Requested on-demand mode 'of_the_day' is not available

But the mode is genuinely valid — it appears in the controller's own Available modes list both before and after that moment:

19:54:02  INFO  Available modes: [... 'web_ui_info', 'of_the_day', 'geochron', 'text_display', ...]
19:56:22  INFO  Loaded plugin: of-the-day
19:56:23  INFO  Available modes: [... 'web_ui_info', 'of_the_day', 'geochron', 'text_display', ...]

So the request was valid, arrived ~70s before the plugin finished loading, and was discarded. POST /api/v3/display/on-demand/start returned 200 with a request_id, and /on-demand/status reported status=active active=True error=null — the panel simply carried on showing the previous plugin.

The working sequence is to restart first, wait until the controller lists the mode, and only then send the request with start_service: false:

sudo systemctl restart ledmatrix
until journalctl -u ledmatrix --since '-2min' | grep -q "Available modes:.*'$mode'"; do sleep 3; done
curl -X POST .../on-demand/start -d '{"plugin_id":"...","mode":"...","start_service":false}'

Two suggestions, both small:

• When start_service triggers a restart, hold the request until plugin loading completes rather than letting the new controller consume it early — the request already persists in display_on_demand_request.json, so re-reading it after load would be enough.
• Reflect the rejection in /on-demand/status. It currently reports active: true for a request the controller has already logged as not available, which is what makes this hard to notice: the only evidence is a line in the journal.

Unrelated to the caching bug in the title, but it shares the property that a dropped request looks like a successful one to every caller.

[ChuckBuilds]

Worth noting that restarting the service is not a reliable workaround, because the restart spends its one request on whatever is still sitting in display_on_demand_request.json from last time.

Sequence, driving two plugins onto the panel back to back with a restart in between:

20:04:13  INFO  Received on-demand request 8b1a1234-...: start (plugin_id=christmas-countdown, ...)
20:04:13  INFO  Activated on-demand for plugin 'christmas-countdown'
          <- then a request for pomodoro-timer is POSTed, 200 + request_id 776be714-...
          <- no journal line for 776be714 ever appears

State afterwards:

request on disk : pomodoro-timer  776be714
processed_id    : christmas-countdown 8b1a1234

The controller came up, read the previous run's request off disk, activated it, cached it, and from then on ignored the file — so the new request never ran and the panel kept showing christmas-countdown. /on-demand/start returned 200 and /on-demand/status reported no error.

So the practical rule is one on-demand request per service lifetime and the restart itself consumes one, which means a caller that restarts to "clear" the state actually replays the stale request instead. Clearing or invalidating display_on_demand_request.json once it has been processed would fix that half of it independently of the memory-TTL change.