diff --git a/CHANGELOG.md b/CHANGELOG.md index 4ff4225a..f8a48122 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,80 @@ All notable changes to this project will be documented in this file. The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.1.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). +## [2.6.8] - 2026-10-01 + +### Fixed +- **A healthy sandboxed worker was killed after 10 cumulative CPU-seconds, then the plugin went `FAILED`**: `RLIMIT_CPU` counts the process's *total* CPU time since it started, but the worker set it once at startup (soft 10 s / hard 15 s, from a hardcoded `_SANDBOX_MAX_CPU_SEC=10`). The kernel's default `SIGXCPU` action terminates the process, and no handler exists (`signal` is forbidden to plugins) — so any plugin doing real work was killed after a few minutes of ordinary requests, restarted, killed again, and marked `FAILED` after `max_restarts` (3). Since `sandboxed` is the default execution mode (2.6.2), this hit every plugin that doesn't declare `execution_mode`. The limit is now two-level: + - **soft limit = CPU budget per request** (`SandboxConfig.max_cpu_seconds`, default 10): the worker re-arms it to "CPU already consumed + budget" before every call (`_arm_cpu_budget`, `resource` is imported before the import guards go up). A request that burns more than its budget is still killed by `SIGXCPU`. + - **hard limit = lifetime ceiling of a worker generation** (`SandboxConfig.max_cpu_lifetime_seconds`, default 3600, +5 s grace). A hard limit can never be raised without privilege, so it stays a kernel-enforced backstop a plugin cannot lift. Before reaching it the worker **recycles itself** between two requests (exit code `RECYCLE_EXIT_CODE`, 75) instead of being killed mid-request; `SandboxProcessManager` restarts it without counting a crash. + Verified end-to-end with the real worker process: 8 requests of 0.5 s CPU each under a 1 s per-request budget all succeed (4 s cumulative — the old behavior killed the worker after the first couple); with a 4 s lifetime ceiling the worker exits with code 75 after 3 requests, not `-24` (`SIGXCPU`). + **Behavior change to be aware of**: the kernel-enforced CPU backstop moves from 15 CPU-seconds per worker to 3600 per worker generation. Runaway requests are still bounded by the 10 s per-request soft limit and by the manager's wall-clock IPC timeout (`resources.timeout_seconds`, which kills and restarts a stuck worker); both settings are configurable. +- **A sandboxed plugin that crashed rarely still ended up `FAILED` for good**: `SandboxProcessManager._restarts` was only reset in `start()`, so three crashes spread over weeks exhausted `max_restarts`. If the subprocess ran at least `SandboxConfig.restart_reset_after` (60 s) before crashing, the restart sequence now starts over; a crash loop is still capped. + +### Added +- **The event loop being frozen by synchronous plugin code is now visible and attributable.** A Trusted plugin runs on the application's single event-loop thread: CPU work, `time.sleep()` or a blocking call between two `await`s suspends every request, `asyncio.wait_for(timeout=...)` cannot interrupt it (measured: a `handle()` burning 1 s of CPU with `timeout_seconds: 0.2` returned `status: ok` after 1000 ms), and under the GIL threads do not help CPU-bound work. `LifecycleManager.call()` now times each synchronous *step* of `handle()` (`xcore.kernel.observability.blocking.watch_blocking`, transparent to results, exceptions, cancellation and timeouts) and logs `plugin blocked the event loop` with the plugin, the action and the blocked time when a step exceeds `plugins.loop_block_warn_ms` (default `250`, `0` disables; one warning per plugin per 10 s). `status()` gains `max_loop_block_ms`. +- Same detection for scheduler jobs (`scheduler job blocked the event loop` — a synchronous job runs entirely on the loop) and for synchronous hooks that exceed their `timeout` (`sync hook timed out, its worker thread keeps running`: `wait_for` stops waiting, not the thread). +- `SandboxConfig.max_cpu_seconds`, `max_cpu_lifetime_seconds`, `restart_reset_after`; `plugins.loop_block_warn_ms`. + +### Documentation +- `doc/plugins/trusted-plugins.md`: why `timeout_seconds` cannot interrupt synchronous code and what the new warning means; a "Reload, Unload and Memory" section (`ctx.spawn_task` vs bare `asyncio.create_task`, what the kernel releases, `plugin instance still referenced after unload`, namespaced scheduler job ids); and the known limitation that **a reload only affects the server worker that handled the request** — there is no cross-worker reload broadcast yet. +- `CLAUDE.md`: version synced (it still said 2.5.3) and the plugin lifecycle/reload pitfalls fixed in 2.6.4–2.6.8 recorded. + +### Not changed (deliberately) +- Synchronous scheduler jobs are **not** moved to `asyncio.to_thread` here: it would silently change the threading model for existing jobs (no running loop in the thread, non-thread-safe state). They are reported instead; moving them is a decision for a minor release. + +## [2.6.7] - 2026-10-01 + +### Fixed +- **A plugin's HTTP routes were never removed on unload or reload — the old code kept serving**: `Xcore._unmount_plugin_router()` did `app.routes = [...]`, but `routes` is a read-only property in Starlette (`AttributeError: property 'routes' ... has no setter`, swallowed by the `EventBus` as an `event handler error`), and even with a working setter it filtered on `route.path`, an attribute FastAPI ≥ 0.14x's `_IncludedRouter` does not have. A reload therefore kept the previous router mounted (the old closures served requests and pinned the old plugin generation in memory) and `unload`/`disable` left a disabled plugin's endpoints reachable. Mounting now goes through a single `_mount_plugin_router()` that records the route objects `include_router()` added; unmounting removes exactly those (in place, invalidating FastAPI's route cache) plus any route whose `path` is the plugin prefix or below it. The prefix match is now segment-exact: unmounting `/plugins/shop` no longer removes `/plugins/shop2`. Boot and reload now share the same mount logic — the reload path used to always wrap the router in a second `/plugins/` prefix while boot only did so when the router wasn't already prefixed — and the "plugin routes mounted" log no longer reads an undefined `wrapper` for a router that is already prefixed. +- **Unloading one instance of an Ephemeral plugin broke its sibling instances and unregistered the plugin**: every pooled instance of the same manifest shared one `sys.modules` namespace (`xcore_plugin_`), and every instance's unload purged it and called `registry.unregister()`. Unloading or evicting one warm-pool instance made the others' lazy relative imports fail with `ModuleNotFoundError: No module named 'xcore_plugin_'`, and removed the still-active plugin from the registry until the next instance happened to re-register it. Pooled instances (`LifecycleManager(..., pooled=True)`, used by `WarmPool` and `EphemeralHandler`) now get their own module namespace and leave the registry alone; `EphemeralHandler.stop()` unregisters the plugin once, when the plugin itself stops. +- **A plugin that exports a service could not be reloaded after boot**: `PluginSupervisor.boot()` step 5 registered the entire `ServiceContainer` as kernel-protected services — including the services plugins had just propagated into it — so the exporting plugin's next reload failed with `Impossible d'écraser le service protégé '' (propriétaire actuel: kernel)`. Services already owned by a plugin in the registry (`PluginRegistry.service_owner()`) are now left with their owner. + +### Added +- **Forced garbage collection after unload/reload, with a leak report**: a plugin instance lives in reference cycles (class, module, context, tasks), so reference counting never frees it and Python's automatic collector only reaches it after a full collection — measured on 3.14.7: a dead cycle promoted to the old generation was still alive after 11.5 million allocations on a 3-million-object heap (0 full collections ran), and the old generation of a reloaded plugin (module, state, buffers) stayed resident all that time. `LifecycleManager` now schedules one `gc.collect()` shortly after a persistent plugin is unloaded or reloaded (`_GC_DELAY_S`, 1 s; several unloads within the window share a single collection), then checks via a `weakref` that the old instance is gone. If it is not, it logs `plugin instance still referenced after unload` with the types of its referrers — the signature of a raw `asyncio.create_task`, a callback registered outside `ctx`, or a service held elsewhere. Ephemeral pool instances are exempt (short-lived young cycles; a full collection per call would cost more than it frees). + A full collection is stop-the-world: ~15 ms on a 300 000-object heap, ~850 ms on 3 million. It happens once per unload/reload burst, never on the request path. Opt out with `plugins.gc_after_unload: false` in `integration.yaml` (default `true`). +- `PluginRegistry.service_owner(name)`; `LifecycleManager(..., pooled=...)`. +- Regression tests: `tests/unit/test_xcore_plugin_routes.py` (mount/unmount/remount against a real FastAPI app), `tests/unit/kernel/test_ephemeral_isolation.py`, `tests/unit/kernel/test_supervisor_exported_services.py` (real supervisor boot + reload), `tests/unit/kernel/test_plugin_release_watcher.py`. + +## [2.6.6] - 2026-10-01 + +### Fixed +- **Unloading a plugin left its exported services callable in the shared container**: `PluginRegistry.unregister()` only cleans the registry, but `propagate_services()` also writes a plugin's exported services into the `ServiceContainer`'s shared dict — where they stayed after unload, reachable by every other plugin through `ctx.services` and pinning the dead plugin (instance, module, state) in memory. `LifecycleManager` now remembers what *it* wrote and removes exactly those entries at unload — never one that another plugin has since replaced. +- **A plugin's HTTP router and middlewares survived unload and reload**: `plugin_router`/`plugin_middlewares` were never reset in `_do_unload()`, so an unloaded handler kept the old router (and, through its closures, the old module), and a reload whose new code no longer exposed a router kept serving the previous one. `_collect_middlewares()` also *merged* the new `add_state()` result into the old dict (`.update`), so removed middlewares lived on. Both are now cleared at unload and replaced, not merged, on load. +- **Cancelled background tasks were not awaited before the plugin's module was dropped**: `_do_unload()` called `task.cancel()` and moved on, so the tasks' `finally` blocks ran *after* `sys.modules` had been purged. Tasks created with `ctx.spawn_task()` are now awaited after cancellation (bounded by `_TASK_CANCEL_TIMEOUT_S`, 2 s; a task that swallows `CancelledError` is logged and no longer blocks the unload). An unload triggered from inside one of those tasks no longer cancels itself. +- **`ctx.spawn_task()` leaked every finished task**: the tracking list only ever grew for the lifetime of the plugin. Finished tasks are now dropped as they complete, and a task that fails logs `spawned task failed` instead of surfacing as an unretrieved exception at garbage-collection time. + +### Added +- `tests/unit/kernel/test_lifecycle_unload_cleanup.py`: router/middleware reset and replacement, exported-service removal (and respect for a service another plugin took over), cancelled-task cleanup ordering, tracking-list hygiene, unload from inside a spawned task. + +## [2.6.5] - 2026-10-01 + +### Fixed +- **After boot, the scheduler's forced cleanup silently stopped working — and so did tenant isolation for `get_service()`**: `PluginContext.get_service()` consulted the `PluginRegistry` first. During `load_all()` the registry is still empty of core services, so it fell back to the plugin's own `ctx.services` — where the kernel had put the plugin's `_ScopedScheduler` tracker proxy (and the tenant-aware `db`/`cache` wrappers when tenancy is on). But once `supervisor.boot()` finished and ran `register_core_service()`, the registry started answering with the *raw* core objects. Any plugin loaded or reloaded after boot that did `self.get_service("scheduler").add_job(...)` therefore bypassed the tracker: the job stayed in `_JOB_REGISTRY` and APScheduler after unload, kept firing against a dead plugin, and pinned the unloaded instance, its module and its state in memory forever (verified: instance still alive after `gc.collect()`). The same bypass handed out the raw `db`/`cache` instead of `TenantAwareDB`/`TenantAwareCache`, so a plugin reloaded after boot escaped tenant isolation. + `get_service()` now serves **kernel** services from the plugin's own context (new `PluginRegistry.is_core_service()` tells kernel services from plugin exports) and keeps resolving plugin-exported services — with their `public`/`private` scoping — through the registry. +- **Scheduler job ids collided across plugins**: `_JOB_REGISTRY` and APScheduler are global and keyed by the bare job id (`fn.__name__` by default), so two plugins that both register a `cleanup` job overwrote each other, and unloading one removed the other's job. `_ScopedScheduler` now namespaces ids as `:` for `add_job`, `cron` and `interval`; plugins keep using their own unprefixed ids (`remove_job`/`pause_job`/`resume_job` translate). Visible side effect: job ids shown by `scheduler.jobs()` and in the Redis job store are now prefixed with the plugin name. + +### Added +- `PluginRegistry.is_core_service(name)`. +- `tests/unit/kernel/test_plugin_gc_scheduler.py`: job released and instance garbage-collectable after unload *after boot*, no job accumulation across reloads, no collision between plugins, `interval` decorator, tenant wrapping preserved by `get_service()` after boot. + +## [2.6.4] - 2026-10-01 + +### Fixed +- **After boot, the second plugin reload/load of the whole process failed and left the plugin stuck in `FAILED`**: `LifecycleManager.propagate_services(is_reload=True)` ran `self._services.update(instance_services)`, but `self._services` *is* the `ServiceContainer`'s shared dict and `instance_services` is the plugin's `ctx.services` copy — which holds the plugin's own garbage-collection proxy (`_ScopedScheduler`) in place of the real scheduler (and tenant wrappers in place of `db`/`cache` when tenancy is on). The first reload therefore replaced the kernel's real `scheduler` in the shared container with that plugin's proxy; the next reload/load of *any* plugin then received a proxy-of-a-proxy, which the one-level `_real` unwrapping could not match against the kernel-protected service, raising `PermissionError: Impossible d'écraser le service protégé 'scheduler'`. The proxy chain also grew by one level per reload. Reproduced against a real `PluginRegistry` + `ServiceContainer` (the existing tests mocked the registry, so none of this was visible): `reload(A)` OK, then `reload(B)`, `load(C)` and `reload(A)` all failed. + `LifecycleManager` now snapshots the services it injected (`_injected_services`, taken after tenant/GC wrapping, before `on_load`) and `propagate_services()` ignores any entry that is still *exactly* that injected object — it is received, not exported — in the registry loop, in the shared-container update and in the no-registry fallback check. Only services the plugin actually exported are written back; an attempt to replace a core service with a *different* object is still rejected. The proxy unwrapping fallback now strips every proxy level instead of one. +- **A plugin in `FAILED` could never be unloaded or reloaded**: the state machine only allowed `reset` from `FAILED`, and nothing in the kernel ever calls `reset` — so `_do_unload()` never ran for a plugin that failed mid-reload and its jobs, subscriptions, tasks and `sys.modules` entries stayed registered forever. `FAILED` now also accepts `unload` (forced cleanup) and `reload` (retry). +- **A failed `load()`/`reload()` left everything the plugin had already registered in place**: scheduler jobs, event/hook subscriptions, health checks, spawned tasks and `sys.modules` entries of a half-initialized plugin were never released. Both paths now run the forced cleanup (without calling the plugin's own hooks, whose state is inconsistent) before raising `LoadError`. + +### Added +- `tests/unit/kernel/test_lifecycle_reload.py`: regression suite for reload/load *after* boot with a real registry and container (repeated reloads, cross-plugin reload, hot-load after a reload, exported services still propagated, core-service override still rejected, failed-load cleanup, unload/reload from `FAILED`). + +## [2.6.3] - 2026-09-30 + +### Fixed +- **Sandboxed plugin logs never reached the console or `log/app.log`**: `xcore/kernel/sandbox/worker.py` hardcoded the subprocess `LOG_LEVEL` to `WARNING` when the env var wasn't set, and `SandboxProcessManager._spawn()` never set it — so a sandboxed plugin's `self.logger.info(...)` calls were dropped at the source regardless of `integration.yaml`'s `observability.logging.level`. Separately, `_watch_loop()` only ever read subprocess stderr once, in the crash path — so even `WARNING`/`ERROR`-level output from a healthy running plugin sat in the OS pipe buffer and was never drained during normal operation. Since `sandboxed` is now the default execution mode (2.6.2), this affected any plugin that doesn't explicitly declare `execution_mode`. + Fixed by threading the real configured level through a new `KernelContext.log_level` field (set from `observability.logging.level` at boot) → `SandboxedActivator` → the subprocess `env` in `SandboxProcessManager._spawn()`, and by replacing the one-shot crash-time stderr read with a `_stderr_pump()` task that drains stderr continuously for the subprocess's whole lifetime and relays each line through the main process's logger (`xcore/kernel/sandbox/process_manager.py`). + ## [2.6.2] - 2026-09-28 ### Security diff --git a/CLAUDE.md b/CLAUDE.md index b8c3fbd5..3c17b78b 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -6,7 +6,7 @@ This file provides guidance to Claude Code (claude.ai/code) when working with co ## Présentation -**xcore v2.5.3** — framework d'orchestration plugin-first construit sur FastAPI. +**xcore v2.6.8** — framework d'orchestration plugin-first construit sur FastAPI. Charge, isole et gère des plugins modulaires dans un environnement sandboxé. - **Language** : Python 3.12+ @@ -240,3 +240,10 @@ Le cache `.venv` est clé sur `poetry.lock` — un changement de dépendances in - **Branche principale** : `main`. Ne pas confondre avec les branches de feature (`add-ephemeral`, etc.). - **Seuil de coverage** : `fail_under = 80` dans `pyproject.toml` (`branch = true`). Le CI échoue en dessous. Patcher les imports locaux dans `boot()` au niveau du module source (`xcore.services.container.ServiceContainer`) et non au niveau `xcore`. - **`asyncio_mode = auto`** dans `pyproject.toml` — pas besoin de `@pytest.mark.asyncio` sur chaque test async. +- **Tâches de fond d'un plugin** — `ctx.spawn_task()`, jamais `asyncio.create_task()` brut : seules les tâches suivies par le kernel sont annulées *et attendues* au unload/reload. Une tâche brute épingle l'ancienne génération du plugin (visible dans les logs : `plugin instance still referenced after unload`). +- **`self._services` d'un plugin est le dict partagé du `ServiceContainer`** (`LifecycleManager._services`) : n'y écrire que des services *exportés* par le plugin. `propagate_services()` ignore ce qui est identique à l'objet injecté (`_injected_services`) — ne jamais réintroduire un `update()` brut des services injectés (proxy de ramasse-miette, wrappers tenant) dans ce dict : ça casse le reload/load de tous les plugins. +- **`get_service()` des services noyau** — `PluginContext.get_service()` sert les services noyau (`PluginRegistry.is_core_service`) depuis `ctx.services` du plugin, pas depuis le registre (qui contient les objets bruts après le boot : le suivi des jobs et l'isolation tenant seraient contournés). +- **Plugins Ephemeral** — chaque instance poolée est un `LifecycleManager(..., pooled=True)` : espace de noms `sys.modules` propre, pas de désinscription du registre à l'unload. +- **Routes de plugin** — monter/retirer via `Xcore._mount_plugin_router` / `_unmount_plugin_router` (suivi des objets route) ; `app.routes` n'a pas de setter et les `_IncludedRouter` de FastAPI ≥ 0.14x n'ont pas de `.path`. +- **Budget CPU du sandbox** — `RLIMIT_CPU` est cumulatif : limite souple réarmée par requête dans `worker.py` (`_arm_cpu_budget`), limite dure = plafond de vie du worker (`max_cpu_lifetime_seconds`), recyclage propre via `RECYCLE_EXIT_CODE`. Ne pas reposer une limite unique au démarrage. +- **Tests d'intégration du reload** — utiliser un vrai `PluginRegistry` + `ServiceContainer` (+ `register_core_service` pour simuler « après boot »), pas des `MagicMock` : les mocks avaient masqué ces bugs. diff --git a/doc/changelog.md b/doc/changelog.md index 4ff4225a..f8a48122 100644 --- a/doc/changelog.md +++ b/doc/changelog.md @@ -5,6 +5,80 @@ All notable changes to this project will be documented in this file. The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.1.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). +## [2.6.8] - 2026-10-01 + +### Fixed +- **A healthy sandboxed worker was killed after 10 cumulative CPU-seconds, then the plugin went `FAILED`**: `RLIMIT_CPU` counts the process's *total* CPU time since it started, but the worker set it once at startup (soft 10 s / hard 15 s, from a hardcoded `_SANDBOX_MAX_CPU_SEC=10`). The kernel's default `SIGXCPU` action terminates the process, and no handler exists (`signal` is forbidden to plugins) — so any plugin doing real work was killed after a few minutes of ordinary requests, restarted, killed again, and marked `FAILED` after `max_restarts` (3). Since `sandboxed` is the default execution mode (2.6.2), this hit every plugin that doesn't declare `execution_mode`. The limit is now two-level: + - **soft limit = CPU budget per request** (`SandboxConfig.max_cpu_seconds`, default 10): the worker re-arms it to "CPU already consumed + budget" before every call (`_arm_cpu_budget`, `resource` is imported before the import guards go up). A request that burns more than its budget is still killed by `SIGXCPU`. + - **hard limit = lifetime ceiling of a worker generation** (`SandboxConfig.max_cpu_lifetime_seconds`, default 3600, +5 s grace). A hard limit can never be raised without privilege, so it stays a kernel-enforced backstop a plugin cannot lift. Before reaching it the worker **recycles itself** between two requests (exit code `RECYCLE_EXIT_CODE`, 75) instead of being killed mid-request; `SandboxProcessManager` restarts it without counting a crash. + Verified end-to-end with the real worker process: 8 requests of 0.5 s CPU each under a 1 s per-request budget all succeed (4 s cumulative — the old behavior killed the worker after the first couple); with a 4 s lifetime ceiling the worker exits with code 75 after 3 requests, not `-24` (`SIGXCPU`). + **Behavior change to be aware of**: the kernel-enforced CPU backstop moves from 15 CPU-seconds per worker to 3600 per worker generation. Runaway requests are still bounded by the 10 s per-request soft limit and by the manager's wall-clock IPC timeout (`resources.timeout_seconds`, which kills and restarts a stuck worker); both settings are configurable. +- **A sandboxed plugin that crashed rarely still ended up `FAILED` for good**: `SandboxProcessManager._restarts` was only reset in `start()`, so three crashes spread over weeks exhausted `max_restarts`. If the subprocess ran at least `SandboxConfig.restart_reset_after` (60 s) before crashing, the restart sequence now starts over; a crash loop is still capped. + +### Added +- **The event loop being frozen by synchronous plugin code is now visible and attributable.** A Trusted plugin runs on the application's single event-loop thread: CPU work, `time.sleep()` or a blocking call between two `await`s suspends every request, `asyncio.wait_for(timeout=...)` cannot interrupt it (measured: a `handle()` burning 1 s of CPU with `timeout_seconds: 0.2` returned `status: ok` after 1000 ms), and under the GIL threads do not help CPU-bound work. `LifecycleManager.call()` now times each synchronous *step* of `handle()` (`xcore.kernel.observability.blocking.watch_blocking`, transparent to results, exceptions, cancellation and timeouts) and logs `plugin blocked the event loop` with the plugin, the action and the blocked time when a step exceeds `plugins.loop_block_warn_ms` (default `250`, `0` disables; one warning per plugin per 10 s). `status()` gains `max_loop_block_ms`. +- Same detection for scheduler jobs (`scheduler job blocked the event loop` — a synchronous job runs entirely on the loop) and for synchronous hooks that exceed their `timeout` (`sync hook timed out, its worker thread keeps running`: `wait_for` stops waiting, not the thread). +- `SandboxConfig.max_cpu_seconds`, `max_cpu_lifetime_seconds`, `restart_reset_after`; `plugins.loop_block_warn_ms`. + +### Documentation +- `doc/plugins/trusted-plugins.md`: why `timeout_seconds` cannot interrupt synchronous code and what the new warning means; a "Reload, Unload and Memory" section (`ctx.spawn_task` vs bare `asyncio.create_task`, what the kernel releases, `plugin instance still referenced after unload`, namespaced scheduler job ids); and the known limitation that **a reload only affects the server worker that handled the request** — there is no cross-worker reload broadcast yet. +- `CLAUDE.md`: version synced (it still said 2.5.3) and the plugin lifecycle/reload pitfalls fixed in 2.6.4–2.6.8 recorded. + +### Not changed (deliberately) +- Synchronous scheduler jobs are **not** moved to `asyncio.to_thread` here: it would silently change the threading model for existing jobs (no running loop in the thread, non-thread-safe state). They are reported instead; moving them is a decision for a minor release. + +## [2.6.7] - 2026-10-01 + +### Fixed +- **A plugin's HTTP routes were never removed on unload or reload — the old code kept serving**: `Xcore._unmount_plugin_router()` did `app.routes = [...]`, but `routes` is a read-only property in Starlette (`AttributeError: property 'routes' ... has no setter`, swallowed by the `EventBus` as an `event handler error`), and even with a working setter it filtered on `route.path`, an attribute FastAPI ≥ 0.14x's `_IncludedRouter` does not have. A reload therefore kept the previous router mounted (the old closures served requests and pinned the old plugin generation in memory) and `unload`/`disable` left a disabled plugin's endpoints reachable. Mounting now goes through a single `_mount_plugin_router()` that records the route objects `include_router()` added; unmounting removes exactly those (in place, invalidating FastAPI's route cache) plus any route whose `path` is the plugin prefix or below it. The prefix match is now segment-exact: unmounting `/plugins/shop` no longer removes `/plugins/shop2`. Boot and reload now share the same mount logic — the reload path used to always wrap the router in a second `/plugins/` prefix while boot only did so when the router wasn't already prefixed — and the "plugin routes mounted" log no longer reads an undefined `wrapper` for a router that is already prefixed. +- **Unloading one instance of an Ephemeral plugin broke its sibling instances and unregistered the plugin**: every pooled instance of the same manifest shared one `sys.modules` namespace (`xcore_plugin_`), and every instance's unload purged it and called `registry.unregister()`. Unloading or evicting one warm-pool instance made the others' lazy relative imports fail with `ModuleNotFoundError: No module named 'xcore_plugin_'`, and removed the still-active plugin from the registry until the next instance happened to re-register it. Pooled instances (`LifecycleManager(..., pooled=True)`, used by `WarmPool` and `EphemeralHandler`) now get their own module namespace and leave the registry alone; `EphemeralHandler.stop()` unregisters the plugin once, when the plugin itself stops. +- **A plugin that exports a service could not be reloaded after boot**: `PluginSupervisor.boot()` step 5 registered the entire `ServiceContainer` as kernel-protected services — including the services plugins had just propagated into it — so the exporting plugin's next reload failed with `Impossible d'écraser le service protégé '' (propriétaire actuel: kernel)`. Services already owned by a plugin in the registry (`PluginRegistry.service_owner()`) are now left with their owner. + +### Added +- **Forced garbage collection after unload/reload, with a leak report**: a plugin instance lives in reference cycles (class, module, context, tasks), so reference counting never frees it and Python's automatic collector only reaches it after a full collection — measured on 3.14.7: a dead cycle promoted to the old generation was still alive after 11.5 million allocations on a 3-million-object heap (0 full collections ran), and the old generation of a reloaded plugin (module, state, buffers) stayed resident all that time. `LifecycleManager` now schedules one `gc.collect()` shortly after a persistent plugin is unloaded or reloaded (`_GC_DELAY_S`, 1 s; several unloads within the window share a single collection), then checks via a `weakref` that the old instance is gone. If it is not, it logs `plugin instance still referenced after unload` with the types of its referrers — the signature of a raw `asyncio.create_task`, a callback registered outside `ctx`, or a service held elsewhere. Ephemeral pool instances are exempt (short-lived young cycles; a full collection per call would cost more than it frees). + A full collection is stop-the-world: ~15 ms on a 300 000-object heap, ~850 ms on 3 million. It happens once per unload/reload burst, never on the request path. Opt out with `plugins.gc_after_unload: false` in `integration.yaml` (default `true`). +- `PluginRegistry.service_owner(name)`; `LifecycleManager(..., pooled=...)`. +- Regression tests: `tests/unit/test_xcore_plugin_routes.py` (mount/unmount/remount against a real FastAPI app), `tests/unit/kernel/test_ephemeral_isolation.py`, `tests/unit/kernel/test_supervisor_exported_services.py` (real supervisor boot + reload), `tests/unit/kernel/test_plugin_release_watcher.py`. + +## [2.6.6] - 2026-10-01 + +### Fixed +- **Unloading a plugin left its exported services callable in the shared container**: `PluginRegistry.unregister()` only cleans the registry, but `propagate_services()` also writes a plugin's exported services into the `ServiceContainer`'s shared dict — where they stayed after unload, reachable by every other plugin through `ctx.services` and pinning the dead plugin (instance, module, state) in memory. `LifecycleManager` now remembers what *it* wrote and removes exactly those entries at unload — never one that another plugin has since replaced. +- **A plugin's HTTP router and middlewares survived unload and reload**: `plugin_router`/`plugin_middlewares` were never reset in `_do_unload()`, so an unloaded handler kept the old router (and, through its closures, the old module), and a reload whose new code no longer exposed a router kept serving the previous one. `_collect_middlewares()` also *merged* the new `add_state()` result into the old dict (`.update`), so removed middlewares lived on. Both are now cleared at unload and replaced, not merged, on load. +- **Cancelled background tasks were not awaited before the plugin's module was dropped**: `_do_unload()` called `task.cancel()` and moved on, so the tasks' `finally` blocks ran *after* `sys.modules` had been purged. Tasks created with `ctx.spawn_task()` are now awaited after cancellation (bounded by `_TASK_CANCEL_TIMEOUT_S`, 2 s; a task that swallows `CancelledError` is logged and no longer blocks the unload). An unload triggered from inside one of those tasks no longer cancels itself. +- **`ctx.spawn_task()` leaked every finished task**: the tracking list only ever grew for the lifetime of the plugin. Finished tasks are now dropped as they complete, and a task that fails logs `spawned task failed` instead of surfacing as an unretrieved exception at garbage-collection time. + +### Added +- `tests/unit/kernel/test_lifecycle_unload_cleanup.py`: router/middleware reset and replacement, exported-service removal (and respect for a service another plugin took over), cancelled-task cleanup ordering, tracking-list hygiene, unload from inside a spawned task. + +## [2.6.5] - 2026-10-01 + +### Fixed +- **After boot, the scheduler's forced cleanup silently stopped working — and so did tenant isolation for `get_service()`**: `PluginContext.get_service()` consulted the `PluginRegistry` first. During `load_all()` the registry is still empty of core services, so it fell back to the plugin's own `ctx.services` — where the kernel had put the plugin's `_ScopedScheduler` tracker proxy (and the tenant-aware `db`/`cache` wrappers when tenancy is on). But once `supervisor.boot()` finished and ran `register_core_service()`, the registry started answering with the *raw* core objects. Any plugin loaded or reloaded after boot that did `self.get_service("scheduler").add_job(...)` therefore bypassed the tracker: the job stayed in `_JOB_REGISTRY` and APScheduler after unload, kept firing against a dead plugin, and pinned the unloaded instance, its module and its state in memory forever (verified: instance still alive after `gc.collect()`). The same bypass handed out the raw `db`/`cache` instead of `TenantAwareDB`/`TenantAwareCache`, so a plugin reloaded after boot escaped tenant isolation. + `get_service()` now serves **kernel** services from the plugin's own context (new `PluginRegistry.is_core_service()` tells kernel services from plugin exports) and keeps resolving plugin-exported services — with their `public`/`private` scoping — through the registry. +- **Scheduler job ids collided across plugins**: `_JOB_REGISTRY` and APScheduler are global and keyed by the bare job id (`fn.__name__` by default), so two plugins that both register a `cleanup` job overwrote each other, and unloading one removed the other's job. `_ScopedScheduler` now namespaces ids as `:` for `add_job`, `cron` and `interval`; plugins keep using their own unprefixed ids (`remove_job`/`pause_job`/`resume_job` translate). Visible side effect: job ids shown by `scheduler.jobs()` and in the Redis job store are now prefixed with the plugin name. + +### Added +- `PluginRegistry.is_core_service(name)`. +- `tests/unit/kernel/test_plugin_gc_scheduler.py`: job released and instance garbage-collectable after unload *after boot*, no job accumulation across reloads, no collision between plugins, `interval` decorator, tenant wrapping preserved by `get_service()` after boot. + +## [2.6.4] - 2026-10-01 + +### Fixed +- **After boot, the second plugin reload/load of the whole process failed and left the plugin stuck in `FAILED`**: `LifecycleManager.propagate_services(is_reload=True)` ran `self._services.update(instance_services)`, but `self._services` *is* the `ServiceContainer`'s shared dict and `instance_services` is the plugin's `ctx.services` copy — which holds the plugin's own garbage-collection proxy (`_ScopedScheduler`) in place of the real scheduler (and tenant wrappers in place of `db`/`cache` when tenancy is on). The first reload therefore replaced the kernel's real `scheduler` in the shared container with that plugin's proxy; the next reload/load of *any* plugin then received a proxy-of-a-proxy, which the one-level `_real` unwrapping could not match against the kernel-protected service, raising `PermissionError: Impossible d'écraser le service protégé 'scheduler'`. The proxy chain also grew by one level per reload. Reproduced against a real `PluginRegistry` + `ServiceContainer` (the existing tests mocked the registry, so none of this was visible): `reload(A)` OK, then `reload(B)`, `load(C)` and `reload(A)` all failed. + `LifecycleManager` now snapshots the services it injected (`_injected_services`, taken after tenant/GC wrapping, before `on_load`) and `propagate_services()` ignores any entry that is still *exactly* that injected object — it is received, not exported — in the registry loop, in the shared-container update and in the no-registry fallback check. Only services the plugin actually exported are written back; an attempt to replace a core service with a *different* object is still rejected. The proxy unwrapping fallback now strips every proxy level instead of one. +- **A plugin in `FAILED` could never be unloaded or reloaded**: the state machine only allowed `reset` from `FAILED`, and nothing in the kernel ever calls `reset` — so `_do_unload()` never ran for a plugin that failed mid-reload and its jobs, subscriptions, tasks and `sys.modules` entries stayed registered forever. `FAILED` now also accepts `unload` (forced cleanup) and `reload` (retry). +- **A failed `load()`/`reload()` left everything the plugin had already registered in place**: scheduler jobs, event/hook subscriptions, health checks, spawned tasks and `sys.modules` entries of a half-initialized plugin were never released. Both paths now run the forced cleanup (without calling the plugin's own hooks, whose state is inconsistent) before raising `LoadError`. + +### Added +- `tests/unit/kernel/test_lifecycle_reload.py`: regression suite for reload/load *after* boot with a real registry and container (repeated reloads, cross-plugin reload, hot-load after a reload, exported services still propagated, core-service override still rejected, failed-load cleanup, unload/reload from `FAILED`). + +## [2.6.3] - 2026-09-30 + +### Fixed +- **Sandboxed plugin logs never reached the console or `log/app.log`**: `xcore/kernel/sandbox/worker.py` hardcoded the subprocess `LOG_LEVEL` to `WARNING` when the env var wasn't set, and `SandboxProcessManager._spawn()` never set it — so a sandboxed plugin's `self.logger.info(...)` calls were dropped at the source regardless of `integration.yaml`'s `observability.logging.level`. Separately, `_watch_loop()` only ever read subprocess stderr once, in the crash path — so even `WARNING`/`ERROR`-level output from a healthy running plugin sat in the OS pipe buffer and was never drained during normal operation. Since `sandboxed` is now the default execution mode (2.6.2), this affected any plugin that doesn't explicitly declare `execution_mode`. + Fixed by threading the real configured level through a new `KernelContext.log_level` field (set from `observability.logging.level` at boot) → `SandboxedActivator` → the subprocess `env` in `SandboxProcessManager._spawn()`, and by replacing the one-shot crash-time stderr read with a `_stderr_pump()` task that drains stderr continuously for the subprocess's whole lifetime and relays each line through the main process's logger (`xcore/kernel/sandbox/process_manager.py`). + ## [2.6.2] - 2026-09-28 ### Security diff --git a/doc/plugins/trusted-plugins.md b/doc/plugins/trusted-plugins.md index bac412b3..ae89d4a3 100644 --- a/doc/plugins/trusted-plugins.md +++ b/doc/plugins/trusted-plugins.md @@ -134,6 +134,7 @@ class Plugin(TrustedBase): | `get_service(name)` | Returns a service from the container. Supports literal overloads for IDE typing. | | `get_service_as(name, type)` | Returns a service cast to a specific type (e.g., `AsyncSQLAdapter`). | | `call_plugin(name, action, payload)` | IPC helper to call another plugin from within the Trusted environment. | +| `ctx.spawn_task(coro, name=None)` | Creates a background task tracked by the kernel: it is cancelled **and awaited** when the plugin is unloaded or reloaded. Use it instead of a bare `asyncio.create_task()`. | --- @@ -156,8 +157,30 @@ entry_point: "src/main.py" **Fix**: Prefix your service names (e.g., `myplugin_db`) or use the `PluginRegistry` to set them as private. !!! warning "Synchronous Blocking" - Trusted plugins run in the main event loop. If you perform blocking I/O (like `time.sleep()` or synchronous requests) inside a hook or `handle`, you will freeze the entire application. - **Fix**: Always use `async`/`await` or `run_in_executor`. + Trusted plugins run in the main event loop, in a single thread. Anything your code does *between two `await`s* — CPU work, `time.sleep()`, a synchronous HTTP or database call — freezes the **entire application**, and the Python GIL means threads do not change that for CPU-bound work. + **Fix**: use `async`/`await`; for blocking I/O use `asyncio.to_thread()`; for heavy CPU work use `execution_mode: sandboxed` (one process per plugin, outside the main loop and its GIL). + +!!! warning "`timeout_seconds` cannot interrupt synchronous code" + The `resources.timeout_seconds` limit is enforced with `asyncio.wait_for`, which can only act at an `await`. A `handle()` that burns 1 s of CPU without awaiting and has `timeout_seconds: 0.2` still returns normally after 1 s. + Xcore now **reports** it instead: a synchronous step longer than `plugins.loop_block_warn_ms` (default `250`, `0` disables) logs `plugin blocked the event loop` with the plugin and action, rate-limited to one warning per plugin every 10 s, and `status()` exposes `max_loop_block_ms`. The same warning exists for scheduler jobs (`scheduler job blocked the event loop`) and for synchronous hooks that exceed their timeout (their worker thread cannot be interrupted and keeps running). + +--- + +### Reload, Unload and Memory + +When a plugin is unloaded or reloaded, the kernel releases what it can track: scheduler jobs, health checks, event/hook subscriptions, services you exported, your router and middlewares, and tasks created with `ctx.spawn_task()`. A plugin instance lives in reference cycles, so Xcore also schedules a garbage collection shortly afterwards (`plugins.gc_after_unload`, default `true`) and checks that the old instance is really gone. + +If you see `plugin instance still referenced after unload` in the logs, something outside the plugin context still holds it — typically: + +- a task started with a bare `asyncio.create_task()` (use `ctx.spawn_task()`), +- a callback or bound method registered on a global object you imported yourself, +- a service object stored somewhere that outlives the plugin. + +!!! note "Scheduler job ids are namespaced" + Jobs you register are stored as `:` so two plugins can both have a `cleanup` job. Inside your plugin you keep using your own id (`remove_job("cleanup")`). + +!!! warning "Reload only affects one worker process" + With several server workers (`uvicorn --workers N`, `xcli manager start --workers N`) each worker process loads its own copy of every plugin. A `POST /plugins//reload` is handled by **one** worker only; the others keep running the old code until restarted. There is no cross-worker reload broadcast yet: restart the workers (or reload through each of them) to roll out a new plugin version. --- diff --git a/pyproject.toml b/pyproject.toml index 4b0593b3..792d9a0a 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -1,6 +1,6 @@ [project] name = "XCoreRuntime" -version = "2.6.2" +version = "2.6.8" description = "Plugin-first orchestration framework built on FastAPI" authors = [ { name = "Eliezer Traore", email = "68350805+traoreera@users.noreply.github.com" }, diff --git a/tests/unit/kernel/test_blocking_sources.py b/tests/unit/kernel/test_blocking_sources.py new file mode 100644 index 00000000..51112e22 --- /dev/null +++ b/tests/unit/kernel/test_blocking_sources.py @@ -0,0 +1,103 @@ +""" +Les autres sources de code synchrone dans le event loop sont signalées elles +aussi : jobs du scheduler et hooks synchrones qui dépassent leur timeout. +""" + +import asyncio +import logging +import threading +import time + +from xcore.kernel.events.hooks import HookManager +from xcore.services.scheduler import service as scheduler_module + + +def _spin(seconds: float) -> None: + end = time.perf_counter() + seconds + while time.perf_counter() < end: + pass + + +class TestSchedulerJobs: + async def test_sync_job_blocking_the_loop_is_reported(self, caplog): + scheduler_module._JOB_REGISTRY["sync_job"] = lambda: _spin(0.06) + try: + scheduler_module._BLOCK_WARN_MS, old = 30, scheduler_module._BLOCK_WARN_MS + with caplog.at_level(logging.WARNING): + await scheduler_module._dispatch_job("sync_job") + finally: + scheduler_module._BLOCK_WARN_MS = old + scheduler_module._JOB_REGISTRY.pop("sync_job", None) + + assert any( + "scheduler job blocked the event loop" in r.getMessage() + for r in caplog.records + ) + + async def test_blocking_step_inside_an_async_job_is_reported(self, caplog): + async def job(): + await asyncio.sleep(0) + _spin(0.06) + + scheduler_module._JOB_REGISTRY["async_job"] = job + try: + scheduler_module._BLOCK_WARN_MS, old = 30, scheduler_module._BLOCK_WARN_MS + with caplog.at_level(logging.WARNING): + await scheduler_module._dispatch_job("async_job") + finally: + scheduler_module._BLOCK_WARN_MS = old + scheduler_module._JOB_REGISTRY.pop("async_job", None) + + assert any("blocked the event loop" in r.getMessage() for r in caplog.records) + + async def test_cooperative_async_job_is_silent_and_runs(self, caplog): + ran = [] + + async def job(): + await asyncio.sleep(0.001) + ran.append(1) + + scheduler_module._JOB_REGISTRY["quiet_job"] = job + try: + with caplog.at_level(logging.WARNING): + await scheduler_module._dispatch_job("quiet_job") + finally: + scheduler_module._JOB_REGISTRY.pop("quiet_job", None) + + assert ran == [1] + assert not [r for r in caplog.records if "blocked" in r.getMessage()] + + +class TestSyncHookTimeout: + async def test_sync_hook_timeout_warns_that_the_thread_keeps_running(self, caplog): + release = threading.Event() + + def slow_hook(event): + release.wait(2) + + hooks = HookManager() + hooks.register("evt", slow_hook, timeout=0.05) + + try: + with caplog.at_level(logging.WARNING): + results = await hooks.emit("evt") + finally: + release.set() + + assert results and results[0].error is not None + assert any( + "worker thread keeps running" in r.getMessage() for r in caplog.records + ) + + async def test_async_hook_timeout_does_not_emit_the_thread_warning(self, caplog): + async def slow_hook(event): + await asyncio.sleep(1) + + hooks = HookManager() + hooks.register("evt", slow_hook, timeout=0.05) + + with caplog.at_level(logging.WARNING): + results = await hooks.emit("evt") + + assert results[0].error is not None + assert not [r for r in caplog.records if "worker thread" in r.getMessage()] diff --git a/tests/unit/kernel/test_context.py b/tests/unit/kernel/test_context.py index fc9f6af5..ec5019c3 100644 --- a/tests/unit/kernel/test_context.py +++ b/tests/unit/kernel/test_context.py @@ -63,3 +63,24 @@ def test_env_default_empty(self): def test_config_default_empty(self): ctx = PluginContext(name="auth") assert ctx.config == {} + + + def test_get_service_core_service_served_from_plugin_context(self): + """Un service noyau vient du contexte du plugin (proxy/tenant), pas du registre brut.""" + registry = MagicMock() + registry.is_core_service.return_value = True + registry.get_service.return_value = "raw_scheduler" + ctx = PluginContext( + name="auth", services={"scheduler": "scoped_scheduler"}, registry=registry + ) + + assert ctx.get_service("scheduler") == "scoped_scheduler" + registry.get_service.assert_not_called() + + def test_get_service_plugin_export_still_resolved_by_registry(self): + registry = MagicMock() + registry.is_core_service.return_value = False + registry.get_service.return_value = "exported" + ctx = PluginContext(name="auth", services={"cart": "stale"}, registry=registry) + + assert ctx.get_service("cart") == "exported" diff --git a/tests/unit/kernel/test_ephemeral_isolation.py b/tests/unit/kernel/test_ephemeral_isolation.py new file mode 100644 index 00000000..9fa37eef --- /dev/null +++ b/tests/unit/kernel/test_ephemeral_isolation.py @@ -0,0 +1,150 @@ +""" +Régression : plusieurs instances d'un même plugin Ephemeral coexistent (warm +pool, appels concurrents). Avant le correctif elles partageaient le même nom de +module dans `sys.modules` et chaque unload faisait `registry.unregister(plugin)` : +décharger UNE instance cassait les imports paresseux des instances sœurs +(`ModuleNotFoundError: No module named 'xcore_plugin_'`) et retirait du +registre un plugin pourtant toujours actif. +""" + +import sys +from types import SimpleNamespace + +from xcore.configurations.sections import EphemeralConfig, ServicesConfig +from xcore.kernel.context import KernelContext +from xcore.kernel.events.bus import EventBus +from xcore.kernel.events.hooks import HookManager +from xcore.kernel.observability.health import HealthChecker +from xcore.kernel.runtime.ephemeral_handler import EphemeralHandler +from xcore.kernel.runtime.lifecycle import LifecycleManager +from xcore.kernel.runtime.warm_pool import WarmPool +from xcore.registry.index import PluginRegistry +from xcore.services.container import ServiceContainer + +PLUGIN_SRC = """ +from xcore.kernel.api.contract import TrustedBase + +class Plugin(TrustedBase): + async def handle(self, action, payload): + from . import helper # import paresseux relatif + return {"status": "ok", "v": helper.VALUE} +""" + + +def _setup(tmp_path): + plugin_dir = tmp_path / "eph" + (plugin_dir / "src").mkdir(parents=True) + (plugin_dir / "src" / "main.py").write_text(PLUGIN_SRC) + (plugin_dir / "src" / "helper.py").write_text("VALUE = 42\n") + manifest = SimpleNamespace( + name="eph", + plugin_dir=plugin_dir, + entry_point="src/main.py", + resources=SimpleNamespace(timeout_seconds=10), + env={}, + requires=[], + extra={}, + ) + registry = PluginRegistry() + ctx = KernelContext( + config=SimpleNamespace(tenancy=None), + services=ServiceContainer(ServicesConfig()), + registry=registry, + events=EventBus(), + hooks=HookManager(), + health=HealthChecker(), + ) + return manifest, ctx, registry + + +class TestPooledLifecycleManagers: + async def test_unloading_one_instance_does_not_break_its_sibling(self, tmp_path): + manifest, ctx, _ = _setup(tmp_path) + a = LifecycleManager(manifest, ctx, pooled=True) + b = LifecycleManager(manifest, ctx, pooled=True) + await a.load() + await b.load() + + await a.unload() + + assert await b.call("x", {}) == {"status": "ok", "v": 42} + await b.unload() + + async def test_unloading_a_pooled_instance_keeps_the_registry_entry(self, tmp_path): + manifest, ctx, registry = _setup(tmp_path) + registry.register("eph", object()) + lm = LifecycleManager(manifest, ctx, pooled=True) + await lm.load() + + await lm.unload() + + assert registry.has("eph") + + async def test_pooled_instances_get_distinct_module_namespaces(self, tmp_path): + manifest, ctx, _ = _setup(tmp_path) + a = LifecycleManager(manifest, ctx, pooled=True) + b = LifecycleManager(manifest, ctx, pooled=True) + persistent = LifecycleManager(manifest, ctx) + + assert len({a._module_name, b._module_name, persistent._module_name}) == 3 + assert persistent._module_name == "xcore_plugin_eph" + + async def test_unload_only_purges_its_own_modules(self, tmp_path): + manifest, ctx, _ = _setup(tmp_path) + a = LifecycleManager(manifest, ctx, pooled=True) + b = LifecycleManager(manifest, ctx, pooled=True) + await a.load() + await b.load() + + await a.unload() + + assert not [m for m in sys.modules if m.startswith(a._module_name)] + assert f"{b._module_name}.main" in sys.modules + await b.unload() + + async def test_non_pooled_unload_still_unregisters_the_plugin(self, tmp_path): + manifest, ctx, registry = _setup(tmp_path) + registry.register("eph", object()) + lm = LifecycleManager(manifest, ctx) + await lm.load() + + await lm.unload() + + assert not registry.has("eph") + + +class TestWarmPoolInstances: + async def test_discarding_a_pool_instance_keeps_the_other_ones_working( + self, tmp_path + ): + manifest, ctx, _ = _setup(tmp_path) + pool = WarmPool(manifest=manifest, ctx=ctx, pool_size=2) + await pool.start() + try: + first = await pool.acquire() + second = await pool.acquire() + assert first._module_name != second._module_name + + await pool.discard(first) + + assert await second.call("x", {}) == {"status": "ok", "v": 42} + await pool.release(second) + finally: + await pool.shutdown() + + +class TestEphemeralHandlerRegistry: + async def test_stop_unregisters_the_plugin_from_the_registry(self, tmp_path): + manifest, ctx, registry = _setup(tmp_path) + registry.register("eph", object()) + handler = EphemeralHandler( + manifest=manifest, ctx=ctx, config=EphemeralConfig(pool_size=1) + ) + await handler.start() + assert registry.has("eph") # démarrer / servir ne la désinscrit pas + assert (await handler.call("x", {}))["v"] == 42 + assert registry.has("eph") + + await handler.stop() + + assert not registry.has("eph") diff --git a/tests/unit/kernel/test_lifecycle.py b/tests/unit/kernel/test_lifecycle.py index 2e66c301..0ccefa46 100644 --- a/tests/unit/kernel/test_lifecycle.py +++ b/tests/unit/kernel/test_lifecycle.py @@ -420,7 +420,7 @@ async def _inject_context(self, ctx): await manager.load() real_scheduler.add_job.assert_called_once() await manager.unload() - real_scheduler.remove_job.assert_called_once_with("nightly") + real_scheduler.remove_job.assert_called_once_with("test_plugin:nightly") @pytest.mark.asyncio async def test_unload_removes_health_check(self, mock_manifest): diff --git a/tests/unit/kernel/test_lifecycle_reload.py b/tests/unit/kernel/test_lifecycle_reload.py new file mode 100644 index 00000000..2a0cc90e --- /dev/null +++ b/tests/unit/kernel/test_lifecycle_reload.py @@ -0,0 +1,204 @@ +""" +Régression : reload / load de plugins Trusted APRÈS le boot, avec un vrai +PluginRegistry (services noyau protégés) et un vrai ServiceContainer. + +Avant le correctif, le 1er reload d'un plugin écrivait son proxy de +ramasse-miette dans le dict partagé du ServiceContainer à la place du vrai +scheduler ; le reload/load suivant de n'importe quel plugin échouait alors avec +« Impossible d'écraser le service protégé 'scheduler' » et le plugin restait +bloqué en FAILED (unload refusé). +""" + +from types import SimpleNamespace + +import pytest + +from xcore.configurations.sections import SchedulerConfig, ServicesConfig +from xcore.kernel.context import KernelContext +from xcore.kernel.events.bus import EventBus +from xcore.kernel.events.hooks import HookManager +from xcore.kernel.observability.health import HealthChecker +from xcore.kernel.runtime.lifecycle import LifecycleManager, LoadError +from xcore.kernel.runtime.state_machine import PluginState +from xcore.registry.index import PluginRegistry +from xcore.services.container import ServiceContainer +from xcore.services.scheduler import service as scheduler_module +from xcore.services.scheduler.service import SchedulerService + +PLUGIN_SRC = """ +from xcore.kernel.api.contract import TrustedBase + +class Plugin(TrustedBase): + async def handle(self, action, payload): + return {"status": "ok"} +""" + + +def _manifest(tmp_path, name): + plugin_dir = tmp_path / name + (plugin_dir / "src").mkdir(parents=True) + (plugin_dir / "src" / "main.py").write_text(PLUGIN_SRC) + return SimpleNamespace( + name=name, + plugin_dir=plugin_dir, + entry_point="src/main.py", + resources=SimpleNamespace(timeout_seconds=10), + env={}, + requires=[], + extra={}, + ) + + +@pytest.fixture +async def booted_kernel(): + """Noyau « après boot » : scheduler réel + services noyau protégés.""" + scheduler = SchedulerService(SchedulerConfig()) + await scheduler.init() + container = ServiceContainer(ServicesConfig()) + container._raw["scheduler"] = scheduler + registry = PluginRegistry() + ctx = KernelContext( + config=SimpleNamespace(tenancy=SimpleNamespace(enabled=False)), + services=container, + registry=registry, + events=EventBus(), + hooks=HookManager(), + health=HealthChecker(), + ) + yield SimpleNamespace( + ctx=ctx, container=container, registry=registry, scheduler=scheduler + ) + scheduler_module._JOB_REGISTRY.clear() + await scheduler.shutdown() + + +def _finish_boot(kernel): + """Reproduit PluginSupervisor.boot() étape 5 : register_core_service().""" + for name, svc in kernel.container.as_dict().items(): + kernel.registry.register_core_service(name, svc) + + +class TestReloadAfterBoot: + async def test_reload_twice_succeeds(self, booted_kernel, tmp_path): + lm = LifecycleManager(_manifest(tmp_path, "a"), booted_kernel.ctx) + await lm.load() + _finish_boot(booted_kernel) + + for _ in range(3): + await lm.reload() + assert lm.state == PluginState.READY + + async def test_reload_keeps_real_core_services_in_shared_container( + self, booted_kernel, tmp_path + ): + lm = LifecycleManager(_manifest(tmp_path, "a"), booted_kernel.ctx) + await lm.load() + _finish_boot(booted_kernel) + + for _ in range(3): + await lm.reload() + assert ( + booted_kernel.container.as_dict()["scheduler"] + is booted_kernel.scheduler + ) + + async def test_reload_of_one_plugin_does_not_break_the_others( + self, booted_kernel, tmp_path + ): + a = LifecycleManager(_manifest(tmp_path, "a"), booted_kernel.ctx) + b = LifecycleManager(_manifest(tmp_path, "b"), booted_kernel.ctx) + await a.load() + await b.load() + _finish_boot(booted_kernel) + + await a.reload() + await b.reload() + await a.reload() + + # hot-load d'un plugin neuf après des reloads + c = LifecycleManager(_manifest(tmp_path, "c"), booted_kernel.ctx) + await c.load() + + assert [m.state for m in (a, b, c)] == [PluginState.READY] * 3 + + async def test_plugin_exported_service_is_still_propagated( + self, booted_kernel, tmp_path + ): + """Seuls les services injectés sont ignorés : un export du plugin passe.""" + manifest = _manifest(tmp_path, "exporter") + (manifest.plugin_dir / "src" / "main.py").write_text( + PLUGIN_SRC.replace( + " async def handle", + " async def on_load(self):\n" + " self._services['exported_svc'] = 'v1'\n\n" + " async def handle", + ) + ) + lm = LifecycleManager(manifest, booted_kernel.ctx) + await lm.load() + + assert booted_kernel.container.as_dict()["exported_svc"] == "v1" + assert booted_kernel.container.as_dict()["scheduler"] is booted_kernel.scheduler + + async def test_override_of_core_service_is_still_rejected( + self, booted_kernel, tmp_path + ): + """Un plugin qui remplace un service noyau par un AUTRE objet est bloqué.""" + manifest = _manifest(tmp_path, "evil") + (manifest.plugin_dir / "src" / "main.py").write_text( + PLUGIN_SRC.replace( + " async def handle", + " async def on_load(self):\n" + " self._services['scheduler'] = object()\n\n" + " async def handle", + ) + ) + lm = LifecycleManager(manifest, booted_kernel.ctx) + await lm.load() # 1er boot : le registre ne protège pas encore le noyau + _finish_boot(booted_kernel) + + with pytest.raises(LoadError, match="protégé"): + await lm.reload() + + +class TestFailedPluginIsRecoverable: + async def test_failed_reload_releases_what_the_plugin_registered( + self, booted_kernel, tmp_path + ): + manifest = _manifest(tmp_path, "leaky") + (manifest.plugin_dir / "src" / "main.py").write_text( + PLUGIN_SRC.replace( + " async def handle", + " async def on_load(self):\n" + " self.ctx.services['scheduler'].add_job(\n" + " self.handle, 'interval', job_id='leaky_tick', seconds=3600)\n" + " raise RuntimeError('boom')\n\n" + " async def handle", + ) + ) + lm = LifecycleManager(manifest, booted_kernel.ctx) + with pytest.raises(LoadError): + await lm.load() + + assert lm.state == PluginState.FAILED + assert "leaky_tick" not in scheduler_module._JOB_REGISTRY + assert booted_kernel.scheduler._scheduler.get_job("leaky_tick") is None + + async def test_unload_is_allowed_from_failed(self, booted_kernel, tmp_path): + lm = LifecycleManager(_manifest(tmp_path, "a"), booted_kernel.ctx) + await lm.load() + lm._sm.force(PluginState.FAILED) + + await lm.unload() + + assert lm.state == PluginState.UNLOADED + assert lm._instance is None + + async def test_reload_is_allowed_from_failed(self, booted_kernel, tmp_path): + lm = LifecycleManager(_manifest(tmp_path, "a"), booted_kernel.ctx) + await lm.load() + lm._sm.force(PluginState.FAILED) + + await lm.reload() + + assert lm.state == PluginState.READY diff --git a/tests/unit/kernel/test_lifecycle_unload_cleanup.py b/tests/unit/kernel/test_lifecycle_unload_cleanup.py new file mode 100644 index 00000000..65b65c5d --- /dev/null +++ b/tests/unit/kernel/test_lifecycle_unload_cleanup.py @@ -0,0 +1,269 @@ +""" +Régression : ce qu'un plugin laisse derrière lui au unload / reload — router et +middlewares, services exportés dans le container partagé, tâches de fond. +""" + +import asyncio +import gc +import weakref +from types import SimpleNamespace + +from xcore.configurations.sections import ServicesConfig +from xcore.kernel.context import KernelContext +from xcore.kernel.events.bus import EventBus +from xcore.kernel.events.hooks import HookManager +from xcore.kernel.observability.health import HealthChecker +from xcore.kernel.runtime.lifecycle import LifecycleManager +from xcore.registry.index import PluginRegistry +from xcore.services.container import ServiceContainer + +HEADER = """ +import asyncio +from xcore.kernel.api.contract import TrustedBase +""" + + +def _plugin(body: str) -> str: + return ( + HEADER + + "\nclass Plugin(TrustedBase):\n" + + body + + "\n async def handle(self, action, payload):\n" + + ' return {"status": "ok"}\n' + ) + + +def _manifest(tmp_path, name="p"): + plugin_dir = tmp_path / name + (plugin_dir / "src").mkdir(parents=True) + return SimpleNamespace( + name=name, + plugin_dir=plugin_dir, + entry_point="src/main.py", + resources=SimpleNamespace(timeout_seconds=10), + env={}, + requires=[], + extra={}, + ) + + +def _write(manifest, body): + (manifest.plugin_dir / "src" / "main.py").write_text(_plugin(body)) + + +def _manager(manifest): + container = ServiceContainer(ServicesConfig()) + ctx = KernelContext( + config=SimpleNamespace(tenancy=None), + services=container, + registry=PluginRegistry(), + events=EventBus(), + hooks=HookManager(), + health=HealthChecker(), + ) + return LifecycleManager(manifest, ctx), container + + +ROUTER_V1 = """ + def get_router(self): + return object() + + def add_state(self): + return {"mw_v1": 1} +""" + +NO_ROUTER_V2 = """ + def add_state(self): + return {"mw_v2": 2} +""" + + +class TestRouterAndMiddlewares: + async def test_unload_clears_router_and_middlewares(self, tmp_path): + manifest = _manifest(tmp_path) + _write(manifest, ROUTER_V1) + lm, _ = _manager(manifest) + await lm.load() + assert lm.plugin_router is not None + assert lm.plugin_middlewares == {"mw_v1": 1} + + await lm.unload() + + assert lm.plugin_router is None + assert lm.plugin_middlewares == {} + + async def test_reload_drops_router_the_new_code_no_longer_exposes(self, tmp_path): + manifest = _manifest(tmp_path) + _write(manifest, ROUTER_V1) + lm, _ = _manager(manifest) + await lm.load() + + _write(manifest, NO_ROUTER_V2) + await lm.reload() + + assert lm.plugin_router is None + + async def test_reload_replaces_middlewares_instead_of_merging(self, tmp_path): + manifest = _manifest(tmp_path) + _write(manifest, ROUTER_V1) + lm, _ = _manager(manifest) + await lm.load() + + _write(manifest, NO_ROUTER_V2) + await lm.reload() + + assert lm.plugin_middlewares == {"mw_v2": 2} + + +EXPORTS = """ + async def on_load(self): + self.blob = bytearray(100_000) + self._services["probe_svc"] = self +""" + + +class TestExportedServices: + async def test_unload_removes_exported_service_from_shared_container( + self, tmp_path + ): + manifest = _manifest(tmp_path) + _write(manifest, EXPORTS) + lm, container = _manager(manifest) + await lm.load() + assert "probe_svc" in container.as_dict() + ref = weakref.ref(lm._instance) + + await lm.unload() + gc.collect() + + assert "probe_svc" not in container.as_dict() + assert ref() is None, "le plugin déchargé est encore référencé" + + async def test_reload_swaps_in_the_new_instance(self, tmp_path): + manifest = _manifest(tmp_path) + _write(manifest, EXPORTS) + lm, container = _manager(manifest) + await lm.load() + first = container.as_dict()["probe_svc"] + + await lm.reload() + + assert container.as_dict()["probe_svc"] is lm._instance + assert container.as_dict()["probe_svc"] is not first + + async def test_unload_keeps_a_service_another_plugin_took_over(self, tmp_path): + manifest = _manifest(tmp_path) + _write(manifest, EXPORTS) + lm, container = _manager(manifest) + await lm.load() + takeover = object() + container.as_dict()["probe_svc"] = takeover + + await lm.unload() + + assert container.as_dict()["probe_svc"] is takeover + + +SPAWNING = """ + async def on_load(self): + self.cleaned = [] + self.ctx.spawn_task(self._worker(), name="worker") + + async def _worker(self): + try: + await asyncio.sleep(3600) + finally: + await asyncio.sleep(0) # nettoyage asynchrone du plugin + self.cleaned.append("worker") +""" + + +class TestSpawnedTasks: + async def test_unload_waits_for_cancelled_tasks_to_finish_their_cleanup( + self, tmp_path + ): + manifest = _manifest(tmp_path) + _write(manifest, SPAWNING) + lm, _ = _manager(manifest) + await lm.load() + await asyncio.sleep(0) # laisse la tâche démarrer + instance = lm._instance + + await lm.unload() + + # le `finally` de la tâche s'est exécuté AVANT le retour de unload() + assert instance.cleaned == ["worker"] + + async def test_finished_tasks_are_dropped_from_the_tracking_list(self, tmp_path): + manifest = _manifest(tmp_path) + _write( + manifest, + """ + async def on_load(self): + async def short(): + return 1 + for _ in range(5): + self.ctx.spawn_task(short()) +""", + ) + lm, _ = _manager(manifest) + await lm.load() + assert len(lm._spawned_tasks) == 5 + + await asyncio.sleep(0.01) + + assert lm._spawned_tasks == [] + + async def test_task_that_ignores_cancellation_does_not_block_unload(self, tmp_path): + manifest = _manifest(tmp_path) + _write( + manifest, + """ + async def on_load(self): + self.stop = False + self.ctx.spawn_task(self._stubborn(), name="stubborn") + + async def _stubborn(self): + while not self.stop: + try: + await asyncio.sleep(3600) + except asyncio.CancelledError: + pass +""", + ) + lm, _ = _manager(manifest) + lm._TASK_CANCEL_TIMEOUT_S = 0.05 + await lm.load() + await asyncio.sleep(0) + instance = lm._instance + stubborn = next(t for t in asyncio.all_tasks() if t.get_name() == "stubborn") + + try: + await asyncio.wait_for(lm.unload(), timeout=2) + assert lm._instance is None + finally: # laisse la tâche récalcitrante se terminer pour fermer le loop + instance.stop = True + stubborn.cancel() + await asyncio.wait([stubborn], timeout=1) + + async def test_unload_from_inside_a_spawned_task_does_not_cancel_itself( + self, tmp_path + ): + manifest = _manifest(tmp_path) + _write( + manifest, + """ + async def on_load(self): + self.done = asyncio.Event() +""", + ) + lm, _ = _manager(manifest) + await lm.load() + + async def unload_from_task(): + lm._spawned_tasks.append(asyncio.current_task()) + await lm.unload() + + await asyncio.create_task(unload_from_task()) + + assert lm._instance is None diff --git a/tests/unit/kernel/test_loop_block_watch.py b/tests/unit/kernel/test_loop_block_watch.py new file mode 100644 index 00000000..4bd55b23 --- /dev/null +++ b/tests/unit/kernel/test_loop_block_watch.py @@ -0,0 +1,251 @@ +""" +Détection du code synchrone qui gèle le event loop (`watch_blocking`) et son +branchement dans `LifecycleManager.call` pour les plugins Trusted. +""" + +import asyncio +import logging +import time +from types import SimpleNamespace + +import pytest + +from xcore.configurations.sections import ServicesConfig +from xcore.kernel.context import KernelContext +from xcore.kernel.events.bus import EventBus +from xcore.kernel.events.hooks import HookManager +from xcore.kernel.observability.blocking import watch_blocking +from xcore.kernel.observability.health import HealthChecker +from xcore.kernel.runtime.lifecycle import LifecycleManager +from xcore.registry.index import PluginRegistry +from xcore.services.container import ServiceContainer + + +def _spin(seconds: float) -> None: + end = time.perf_counter() + seconds + while time.perf_counter() < end: + pass + + +class TestWatchBlocking: + async def test_reports_a_synchronous_step(self): + seen = [] + + async def work(): + _spin(0.06) # 60 ms sans await + await asyncio.sleep(0) + return "done" + + result = await watch_blocking(work(), 30, seen.append) + + assert result == "done" + assert len(seen) == 1 and seen[0] >= 0.05 + + async def test_cooperative_code_is_not_reported(self): + seen = [] + + async def work(): + for _ in range(20): + await asyncio.sleep(0.001) + return 1 + + assert await watch_blocking(work(), 30, seen.append) == 1 + assert seen == [] + + async def test_each_blocking_step_is_reported_separately(self): + seen = [] + + async def work(): + _spin(0.04) + await asyncio.sleep(0) + _spin(0.04) + + await watch_blocking(work(), 30, seen.append) + + assert len(seen) == 2 + + async def test_exceptions_propagate_unchanged(self): + async def work(): + await asyncio.sleep(0) + raise ValueError("boom") + + with pytest.raises(ValueError, match="boom"): + await watch_blocking(work(), 30, lambda s: None) + + async def test_blocking_step_before_an_exception_is_still_reported(self): + seen = [] + + async def work(): + _spin(0.05) + raise ValueError("boom") + + with pytest.raises(ValueError): + await watch_blocking(work(), 30, seen.append) + + assert len(seen) == 1 + + async def test_cancellation_reaches_the_inner_coroutine(self): + cleaned = [] + + async def work(): + try: + await asyncio.sleep(3600) + finally: + cleaned.append(1) + + task = asyncio.create_task(_run(watch_blocking(work(), 30, lambda s: None))) + await asyncio.sleep(0.01) + task.cancel() + + with pytest.raises(asyncio.CancelledError): + await task + assert cleaned == [1] + + async def test_wait_for_timeout_still_works_through_the_wrapper(self): + async def work(): + await asyncio.sleep(10) + + with pytest.raises(asyncio.TimeoutError): + await asyncio.wait_for(watch_blocking(work(), 30, lambda s: None), 0.05) + + async def test_closing_the_iterator_closes_the_inner_coroutine(self): + cleaned = [] + + async def work(): + try: + await asyncio.sleep(10) + finally: + cleaned.append(1) + + it = watch_blocking(work(), 30, lambda s: None).__await__() + next(it) # avance jusqu'au premier await + it.close() + + assert cleaned == [1] + + async def test_a_failing_report_callback_never_breaks_the_call(self): + async def work(): + _spin(0.05) + return "ok" + + def broken(_): + raise RuntimeError("reporter bug") + + assert await watch_blocking(work(), 30, broken) == "ok" + + async def test_disabled_or_non_awaitable_is_returned_untouched(self): + async def work(): + return 1 + + coro = work() + assert watch_blocking(coro, 0, lambda s: None) is coro + assert watch_blocking(42, 30, lambda s: None) == 42 + await coro + + +async def _run(aw): + return await aw + + +PLUGIN_SRC = """ +import asyncio, time +from xcore.kernel.api.contract import TrustedBase + +class Plugin(TrustedBase): + async def handle(self, action, payload): + if action == "spin": + end = time.perf_counter() + 0.12 + while time.perf_counter() < end: + pass + elif action == "sleep": + await asyncio.sleep(1.0) + return {"status": "ok"} +""" + + +def _manager(tmp_path, timeout=10, **config): + plugin_dir = tmp_path / "p" + (plugin_dir / "src").mkdir(parents=True) + (plugin_dir / "src" / "main.py").write_text(PLUGIN_SRC) + manifest = SimpleNamespace( + name="p", + plugin_dir=plugin_dir, + entry_point="src/main.py", + resources=SimpleNamespace(timeout_seconds=timeout), + env={}, + requires=[], + extra={}, + ) + ctx = KernelContext( + config=SimpleNamespace(tenancy=None, **config), + services=ServiceContainer(ServicesConfig()), + registry=PluginRegistry(), + events=EventBus(), + hooks=HookManager(), + health=HealthChecker(), + ) + return LifecycleManager(manifest, ctx) + + +def _block_warnings(caplog): + return [r for r in caplog.records if "blocked the event loop" in r.getMessage()] + + +class TestPluginCallReportsLoopBlocking: + async def test_synchronous_handler_is_reported_with_plugin_and_action( + self, tmp_path, caplog + ): + lm = _manager(tmp_path, loop_block_warn_ms=50) + await lm.load() + + with caplog.at_level(logging.WARNING): + assert (await lm.call("spin", {}))["status"] == "ok" + + assert len(_block_warnings(caplog)) == 1 + assert lm.status()["max_loop_block_ms"] >= 100 + + async def test_cooperative_handler_is_not_reported(self, tmp_path, caplog): + lm = _manager(tmp_path, loop_block_warn_ms=50) + await lm.load() + + with caplog.at_level(logging.WARNING): + await lm.call("fast", {}) + + assert _block_warnings(caplog) == [] + assert lm.status()["max_loop_block_ms"] == 0 + + async def test_warnings_are_rate_limited_per_plugin(self, tmp_path, caplog): + lm = _manager(tmp_path, loop_block_warn_ms=50) + await lm.load() + + with caplog.at_level(logging.WARNING): + await lm.call("spin", {}) + await lm.call("spin", {}) + + assert len(_block_warnings(caplog)) == 1 + + async def test_can_be_disabled(self, tmp_path, caplog): + lm = _manager(tmp_path, loop_block_warn_ms=0) + await lm.load() + + with caplog.at_level(logging.WARNING): + await lm.call("spin", {}) + + assert _block_warnings(caplog) == [] + + async def test_default_threshold_applies_without_config(self, tmp_path, caplog): + lm = _manager(tmp_path) # pas de loop_block_warn_ms → 250 ms : 120 ms passe + await lm.load() + + with caplog.at_level(logging.WARNING): + await lm.call("spin", {}) + + assert _block_warnings(caplog) == [] + + async def test_timeout_still_enforced_for_cooperative_code(self, tmp_path): + lm = _manager(tmp_path, timeout=0.2, loop_block_warn_ms=50) + await lm.load() + + result = await lm.call("sleep", {}) + + assert result["code"] == "timeout" diff --git a/tests/unit/kernel/test_plugin_gc_scheduler.py b/tests/unit/kernel/test_plugin_gc_scheduler.py new file mode 100644 index 00000000..74ec7ecd --- /dev/null +++ b/tests/unit/kernel/test_plugin_gc_scheduler.py @@ -0,0 +1,215 @@ +""" +Régression : le ramasse-miette forcé du scheduler doit fonctionner aussi APRÈS +le boot, quand le registre contient les services noyau bruts, et deux plugins +ne doivent pas se marcher dessus dans le registre de jobs global. +""" + +import gc +import weakref +from types import SimpleNamespace + +import pytest + +from xcore.configurations.sections import SchedulerConfig, ServicesConfig +from xcore.kernel.context import KernelContext +from xcore.kernel.events.bus import EventBus +from xcore.kernel.events.hooks import HookManager +from xcore.kernel.observability.health import HealthChecker +from xcore.kernel.runtime.lifecycle import LifecycleManager +from xcore.kernel.tenancy.services import TenantAwareDB +from xcore.registry.index import PluginRegistry +from xcore.services.container import ServiceContainer +from xcore.services.scheduler import service as scheduler_module +from xcore.services.scheduler.service import SchedulerService + +PLUGIN_TEMPLATE = """ +from xcore.kernel.api.contract import TrustedBase + +class Plugin(TrustedBase): + async def on_load(self): + self.blob = bytearray(100_000) +{body} + + async def tick(self): + return len(self.blob) + + async def handle(self, action, payload): + return {{"status": "ok"}} +""" + +VIA_GET_SERVICE = """ + self.get_service("scheduler").add_job( + self.tick, "interval", job_id="cleanup", seconds=3600 + ) +""" + + +def _manifest(tmp_path, name, body=VIA_GET_SERVICE): + plugin_dir = tmp_path / name + (plugin_dir / "src").mkdir(parents=True) + (plugin_dir / "src" / "main.py").write_text(PLUGIN_TEMPLATE.format(body=body)) + return SimpleNamespace( + name=name, + plugin_dir=plugin_dir, + entry_point="src/main.py", + resources=SimpleNamespace(timeout_seconds=10), + env={}, + requires=[], + extra={}, + ) + + +def _kernel(scheduler, tenancy=None, extra_services=None): + container = ServiceContainer(ServicesConfig()) + container._raw["scheduler"] = scheduler + container._raw.update(extra_services or {}) + registry = PluginRegistry() + ctx = KernelContext( + config=SimpleNamespace(tenancy=tenancy), + services=container, + registry=registry, + events=EventBus(), + hooks=HookManager(), + health=HealthChecker(), + ) + return ctx, container, registry + + +def _finish_boot(container, registry): + for name, svc in container.as_dict().items(): + registry.register_core_service(name, svc) + + +@pytest.fixture +async def scheduler(): + svc = SchedulerService(SchedulerConfig()) + await svc.init() + yield svc + scheduler_module._JOB_REGISTRY.clear() + await svc.shutdown() + + +class TestSchedulerReleasedAfterBoot: + async def test_job_registered_via_get_service_is_released_on_unload( + self, scheduler, tmp_path + ): + ctx, container, registry = _kernel(scheduler) + lm = LifecycleManager(_manifest(tmp_path, "p"), ctx) + _finish_boot(container, registry) # plugin (re)chargé APRÈS le boot + + await lm.load() + job_id = "p:cleanup" + assert job_id in scheduler_module._JOB_REGISTRY + assert scheduler._scheduler.get_job(job_id) is not None + ref = weakref.ref(lm._instance) + + await lm.unload() + gc.collect() + + assert job_id not in scheduler_module._JOB_REGISTRY + assert scheduler._scheduler.get_job(job_id) is None + assert ref() is None, "l'instance déchargée est encore référencée" + + async def test_reload_after_boot_does_not_accumulate_jobs( + self, scheduler, tmp_path + ): + ctx, container, registry = _kernel(scheduler) + lm = LifecycleManager(_manifest(tmp_path, "p"), ctx) + await lm.load() + _finish_boot(container, registry) + + for _ in range(3): + await lm.reload() + + assert [j for j in scheduler_module._JOB_REGISTRY if j.startswith("p:")] == [ + "p:cleanup" + ] + refs = scheduler_module._JOB_REGISTRY["p:cleanup"].__self__ + assert refs is lm._instance + + +class TestJobIdsAreNamespacedPerPlugin: + async def test_two_plugins_with_same_job_name_do_not_collide( + self, scheduler, tmp_path + ): + ctx, container, registry = _kernel(scheduler) + a = LifecycleManager(_manifest(tmp_path, "a"), ctx) + b = LifecycleManager(_manifest(tmp_path, "b"), ctx) + await a.load() + await b.load() + + assert {"a:cleanup", "b:cleanup"} <= set(scheduler_module._JOB_REGISTRY) + assert scheduler_module._JOB_REGISTRY["a:cleanup"].__self__ is a._instance + assert scheduler_module._JOB_REGISTRY["b:cleanup"].__self__ is b._instance + + async def test_unloading_one_plugin_keeps_the_other_plugins_job( + self, scheduler, tmp_path + ): + ctx, container, registry = _kernel(scheduler) + a = LifecycleManager(_manifest(tmp_path, "a"), ctx) + b = LifecycleManager(_manifest(tmp_path, "b"), ctx) + await a.load() + await b.load() + + await a.unload() + + assert "a:cleanup" not in scheduler_module._JOB_REGISTRY + assert "b:cleanup" in scheduler_module._JOB_REGISTRY + assert scheduler._scheduler.get_job("b:cleanup") is not None + + async def test_plugin_keeps_using_its_own_unprefixed_ids(self, scheduler, tmp_path): + body = """ + sch = self.get_service("scheduler") + sch.add_job(self.tick, "interval", job_id="cleanup", seconds=3600) + sch.add_job(self.tick, "interval", job_id="other", seconds=3600) + sch.remove_job("cleanup") +""" + ctx, _, _ = _kernel(scheduler) + lm = LifecycleManager(_manifest(tmp_path, "p", body), ctx) + await lm.load() + + assert "p:cleanup" not in scheduler_module._JOB_REGISTRY + assert "p:other" in scheduler_module._JOB_REGISTRY + + async def test_interval_decorator_is_namespaced_and_released( + self, scheduler, tmp_path + ): + body = """ + @self.get_service("scheduler").interval(seconds=3600) + async def heartbeat(): + return 1 +""" + ctx, _, _ = _kernel(scheduler) + lm = LifecycleManager(_manifest(tmp_path, "p", body), ctx) + await lm.load() + assert "p:heartbeat" in scheduler_module._JOB_REGISTRY + + await lm.unload() + assert "p:heartbeat" not in scheduler_module._JOB_REGISTRY + + +class TestCoreServicesKeepTheirPerPluginWrapping: + async def test_get_service_after_boot_is_still_tenant_aware( + self, scheduler, tmp_path + ): + """Après le boot, get_service('db') rendait le db brut (registre).""" + body = """ + self.db = self.get_service("db") +""" + tenancy = SimpleNamespace( + enabled=True, + isolate_db=True, + isolate_cache=False, + isolate_scheduler=False, + ) + raw_db = object() + ctx, container, registry = _kernel( + scheduler, tenancy=tenancy, extra_services={"db": raw_db} + ) + lm = LifecycleManager(_manifest(tmp_path, "p", body), ctx) + _finish_boot(container, registry) + + await lm.load() + + assert isinstance(lm._instance.db, TenantAwareDB) + assert lm._instance.db is not raw_db diff --git a/tests/unit/kernel/test_plugin_release_watcher.py b/tests/unit/kernel/test_plugin_release_watcher.py new file mode 100644 index 00000000..4d9b472f --- /dev/null +++ b/tests/unit/kernel/test_plugin_release_watcher.py @@ -0,0 +1,173 @@ +""" +Après un unload/reload, une collecte du GC est forcée (différée, regroupée) et +les instances qui survivent sont signalées. Sans ça, un plugin déchargé — qui vit +dans des cycles de références — restait en mémoire jusqu'à la prochaine collecte +complète de Python, qui peut ne jamais venir sur un gros tas. +""" + +import asyncio +import gc +import logging +import weakref +from types import SimpleNamespace + +import pytest + +from xcore.configurations.sections import ServicesConfig +from xcore.kernel.context import KernelContext +from xcore.kernel.events.bus import EventBus +from xcore.kernel.events.hooks import HookManager +from xcore.kernel.observability.health import HealthChecker +from xcore.kernel.runtime import lifecycle as lifecycle_module +from xcore.kernel.runtime.lifecycle import LifecycleManager +from xcore.registry.index import PluginRegistry +from xcore.services.container import ServiceContainer + +PLUGIN_SRC = """ +from xcore.kernel.api.contract import TrustedBase + +class Plugin(TrustedBase): + async def on_load(self): + self.me = self # cycle : le comptage de références seul ne libère pas + self.blob = bytearray(100_000) + + async def handle(self, action, payload): + return {"status": "ok"} +""" + + +@pytest.fixture(autouse=True) +def fast_delay(monkeypatch): + monkeypatch.setattr(lifecycle_module, "_GC_DELAY_S", 0.02) + watcher = lifecycle_module._release_watcher + watcher._pending, watcher._handle, watcher._loop = [], None, None + yield + watcher._pending, watcher._handle, watcher._loop = [], None, None + + +def _manager(tmp_path, name="p", gc_after_unload=True, pooled=False): + plugin_dir = tmp_path / name + (plugin_dir / "src").mkdir(parents=True) + (plugin_dir / "src" / "main.py").write_text(PLUGIN_SRC) + manifest = SimpleNamespace( + name=name, + plugin_dir=plugin_dir, + entry_point="src/main.py", + resources=SimpleNamespace(timeout_seconds=10), + env={}, + requires=[], + extra={}, + ) + ctx = KernelContext( + config=SimpleNamespace(tenancy=None, gc_after_unload=gc_after_unload), + services=ServiceContainer(ServicesConfig()), + registry=PluginRegistry(), + events=EventBus(), + hooks=HookManager(), + health=HealthChecker(), + ) + return LifecycleManager(manifest, ctx, pooled=pooled) + + +async def test_dead_plugin_generation_is_collected_without_manual_gc(tmp_path): + gc.disable() # le GC automatique ne doit pas être ce qui libère l'instance + try: + lm = _manager(tmp_path) + await lm.load() + ref = weakref.ref(lm._instance) + + await lm.unload() + assert ref() is not None # le cycle la retient jusqu'à la collecte différée + + await asyncio.sleep(0.1) + assert ref() is None + finally: + gc.enable() + + +async def test_reload_collects_the_previous_generation(tmp_path): + gc.disable() + try: + lm = _manager(tmp_path) + await lm.load() + old = weakref.ref(lm._instance) + + await lm.reload() + await asyncio.sleep(0.1) + + assert old() is None + assert lm._instance is not None + finally: + gc.enable() + + +async def test_instance_still_referenced_after_unload_is_reported(tmp_path, caplog): + lm = _manager(tmp_path) + await lm.load() + leak = lm._instance # quelque chose la retient encore (tâche brute, callback…) + + with caplog.at_level(logging.WARNING): + await lm.unload() + await asyncio.sleep(0.1) + + messages = [r.getMessage() for r in caplog.records] + assert any("still referenced after unload" in m for m in messages), messages + assert leak is not None + + +async def test_clean_unload_does_not_warn(tmp_path, caplog): + lm = _manager(tmp_path) + await lm.load() + + with caplog.at_level(logging.WARNING): + await lm.unload() + await asyncio.sleep(0.1) + + assert not [r for r in caplog.records if "still referenced" in r.getMessage()] + + +async def test_unloads_within_the_window_share_one_collection(tmp_path, monkeypatch): + calls = [] + real_collect = gc.collect + monkeypatch.setattr( + lifecycle_module.gc, "collect", lambda *a: calls.append(1) or real_collect(*a) + ) + managers = [_manager(tmp_path, f"p{i}") for i in range(3)] + for lm in managers: + await lm.load() + + for lm in managers: + await lm.unload() + await asyncio.sleep(0.1) + + assert len(calls) == 1 + + +async def test_disabled_by_config(tmp_path): + lm = _manager(tmp_path, gc_after_unload=False) + await lm.load() + + await lm.unload() + + assert lifecycle_module._release_watcher._pending == [] + assert lifecycle_module._release_watcher._handle is None + + +async def test_pooled_ephemeral_instances_are_not_watched(tmp_path): + lm = _manager(tmp_path, pooled=True) + await lm.load() + + await lm.unload() + + assert lifecycle_module._release_watcher._pending == [] + + +def test_gc_after_unload_defaults_to_enabled(): + from xcore.configurations.loader import ConfigLoader + from xcore.configurations.sections import PluginConfig + + assert PluginConfig().gc_after_unload is True + assert ConfigLoader._parse_plugins({}).gc_after_unload is True + assert ( + ConfigLoader._parse_plugins({"gc_after_unload": False}).gc_after_unload is False + ) diff --git a/tests/unit/kernel/test_process_manager.py b/tests/unit/kernel/test_process_manager.py index 66ed14c1..e5d0e6fe 100644 --- a/tests/unit/kernel/test_process_manager.py +++ b/tests/unit/kernel/test_process_manager.py @@ -3,11 +3,37 @@ """ import asyncio +from unittest.mock import AsyncMock, MagicMock, patch + import pytest -from unittest.mock import MagicMock, AsyncMock, patch -from pathlib import Path -from xcore.kernel.sandbox.process_manager import SandboxProcessManager, SandboxConfig, ProcessState -from xcore.kernel.sandbox.ipc import IPCResponse, IPCProcessDead, IPCTimeoutError + +from xcore.kernel.sandbox.ipc import IPCProcessDead, IPCResponse, IPCTimeoutError +from xcore.kernel.sandbox.process_manager import ( + _STDERR_LEVEL_RE, + ProcessState, + SandboxConfig, + SandboxProcessManager, +) + + +class _FakeStderr: + """ + Simule asyncio.StreamReader.readline() pour tester _stderr_pump() sans + subprocess réel : items est une liste de bytes (une "ligne" chacun, + la dernière b"" simule l'EOF) ou d'exceptions à lever à cette itération. + """ + + def __init__(self, items): + self._items = list(items) + + async def readline(self): + if not self._items: + return b"" + item = self._items.pop(0) + if isinstance(item, Exception): + raise item + return item + @pytest.fixture def mock_manifest(tmp_path): @@ -23,21 +49,20 @@ def mock_manifest(tmp_path): manifest.runtime.health_check.timeout_seconds = 0.1 return manifest + @pytest.fixture def mock_loader(): loader = MagicMock() loader._events.emit_sync = MagicMock() return loader + @pytest.fixture def manager(mock_manifest, mock_loader): - config = SandboxConfig( - startup_timeout=0.1, - restart_delay=0.01, - max_restarts=2 - ) + config = SandboxConfig(startup_timeout=0.1, restart_delay=0.01, max_restarts=2) return SandboxProcessManager(mock_manifest, mock_loader, config=config) + @pytest.mark.asyncio async def test_manager_init(manager, mock_manifest): assert manager.state == ProcessState.STOPPED @@ -45,6 +70,7 @@ async def test_manager_init(manager, mock_manifest): assert manager.uptime is None assert manager.status()["name"] == "test_plugin" + @pytest.mark.asyncio async def test_manager_start_success(manager, mock_manifest, mock_loader): with patch("asyncio.create_subprocess_exec", new_callable=AsyncMock) as mock_spawn: @@ -53,11 +79,13 @@ async def test_manager_start_success(manager, mock_manifest, mock_loader): mock_proc.returncode = None mock_proc.stdin = MagicMock() mock_proc.stdout = MagicMock() - mock_proc.stderr = MagicMock() + mock_proc.stderr = _FakeStderr([b""]) # EOF immédiat, pump se termine seule mock_proc.wait = AsyncMock(return_value=0) mock_spawn.return_value = mock_proc - with patch("xcore.kernel.sandbox.ipc.IPCChannel.call", new_callable=AsyncMock) as mock_call: + with patch( + "xcore.kernel.sandbox.ipc.IPCChannel.call", new_callable=AsyncMock + ) as mock_call: mock_call.return_value = IPCResponse(success=True, data={"status": "ok"}) await manager.start() @@ -68,6 +96,7 @@ async def test_manager_start_success(manager, mock_manifest, mock_loader): mock_spawn.assert_called_once() mock_loader._events.emit_sync.assert_called() + @pytest.mark.asyncio async def test_manager_start_timeout(manager, mock_manifest): with patch("asyncio.create_subprocess_exec", new_callable=AsyncMock) as mock_spawn: @@ -77,7 +106,9 @@ async def test_manager_start_timeout(manager, mock_manifest): mock_proc.wait = AsyncMock(return_value=1) mock_spawn.return_value = mock_proc - with patch("xcore.kernel.sandbox.ipc.IPCChannel.call", new_callable=AsyncMock) as mock_call: + with patch( + "xcore.kernel.sandbox.ipc.IPCChannel.call", new_callable=AsyncMock + ) as mock_call: mock_call.side_effect = asyncio.TimeoutError() with pytest.raises(RuntimeError, match="Pas de réponse au ping"): @@ -86,12 +117,15 @@ async def test_manager_start_timeout(manager, mock_manifest): assert manager.state == ProcessState.STARTING mock_proc.terminate.assert_called() + @pytest.mark.asyncio async def test_manager_call_success(manager): # Setup running state manager._state = ProcessState.RUNNING manager._channel = MagicMock() - manager._channel.call = AsyncMock(return_value=IPCResponse(success=True, data={"status": "ok", "result": "hi"})) + manager._channel.call = AsyncMock( + return_value=IPCResponse(success=True, data={"status": "ok", "result": "hi"}) + ) # Execute res = await manager.call("hello", {"name": "world"}) @@ -100,6 +134,7 @@ async def test_manager_call_success(manager): assert res == {"status": "ok", "result": "hi"} manager._channel.call.assert_called_with("hello", {"name": "world"}) + @pytest.mark.asyncio async def test_manager_call_not_available(manager): with pytest.raises(RuntimeError, match="non disponible"): @@ -135,6 +170,7 @@ async def test_manager_call_ipc_timeout_triggers_recycle(manager): await manager.call("ping", {}) mock_crash.assert_called_once() + @pytest.mark.asyncio async def test_manager_stop(manager): manager._state = ProcessState.RUNNING @@ -150,6 +186,7 @@ async def test_manager_stop(manager): manager._channel.close.assert_called_once() manager._process.terminate.assert_called() + @pytest.mark.asyncio async def test_manager_handle_crash_restart_success(manager, mock_manifest): manager._state = ProcessState.RUNNING @@ -166,11 +203,12 @@ async def test_manager_handle_crash_restart_success(manager, mock_manifest): assert manager._restarts == 1 mock_spawn.assert_called_once() + @pytest.mark.asyncio async def test_manager_handle_crash_max_restarts(manager, mock_manifest): manager._state = ProcessState.RUNNING manager.config.max_restarts = 1 - manager._restarts = 0 # Start from 0 to allow one loop + manager._restarts = 0 # Start from 0 to allow one loop with patch.object(manager, "_spawn", new_callable=AsyncMock) as mock_spawn: mock_spawn.side_effect = Exception("Spawn failed") @@ -179,3 +217,112 @@ async def test_manager_handle_crash_max_restarts(manager, mock_manifest): assert manager.state == ProcessState.FAILED assert manager._restarts == 1 + + +@pytest.mark.asyncio +async def test_stderr_pump_dispatches_by_level_and_survives_bad_line(manager): + """ + _stderr_pump() doit : router chaque ligne vers le niveau logger indiqué + par son bracket [LEVEL] (format worker.py), retomber en error() pour une + ligne non structurée (traceback brut), et continuer à lire après une + ValueError (ligne trop longue) au lieu de s'arrêter définitivement. + """ + manager._process = MagicMock() + manager._process.stderr = _FakeStderr( + [ + b"2026-09-30 12:00:00,000 [INFO] worker: plugin loaded\n", + b"2026-09-30 12:00:00,001 [ERROR] worker: boom\n", + b"raw traceback line without brackets\n", + ValueError("Separator is not found, and chunk exceed the limit"), + b"2026-09-30 12:00:00,002 [DEBUG] worker: still alive after bad line\n", + b"", + ] + ) + + with patch("xcore.kernel.sandbox.process_manager.logger") as mock_logger: + await manager._stderr_pump() + + mock_logger.info.assert_any_call( + "subprocess stderr", + plugin="test_plugin", + line="2026-09-30 12:00:00,000 [INFO] worker: plugin loaded", + ) + mock_logger.error.assert_any_call( + "subprocess stderr", + plugin="test_plugin", + line="2026-09-30 12:00:00,001 [ERROR] worker: boom", + ) + # Ligne non structurée -> error par défaut (pas warning), comme + # l'ancien lecteur crash-time. + mock_logger.error.assert_any_call( + "subprocess stderr", + plugin="test_plugin", + line="raw traceback line without brackets", + ) + # La ValueError est catchée et loggée à part, sans arrêter la pompe. + assert mock_logger.warning.called + # La ligne suivant la ValueError est bien lue -> pas de mort silencieuse. + mock_logger.debug.assert_any_call( + "subprocess stderr", + plugin="test_plugin", + line="2026-09-30 12:00:00,002 [DEBUG] worker: still alive after bad line", + ) + + +def test_worker_stderr_format_stays_compatible_with_level_regex(): + """ + _STDERR_LEVEL_RE parse la sortie du _TextFormatter utilisé par worker.py + (xcore/kernel/observability/logging.py, même formateur que le process + principal) pour router chaque ligne stderr vers le bon niveau. Rend un + vrai LogRecord à travers le vrai formateur plutôt que de comparer des + chaînes, pour attraper toute dérive future de leur formatage respectif. + """ + import logging + + from xcore.kernel.observability.logging import _TextFormatter + + formatter = _TextFormatter() + for level_name, level_no in ( + ("DEBUG", logging.DEBUG), + ("WARNING", logging.WARNING), + ("ERROR", logging.ERROR), + ): + record = logging.LogRecord( + name="xcore.worker", + level=level_no, + pathname=__file__, + lineno=1, + msg="test message", + args=(), + exc_info=None, + ) + rendered = formatter.format(record) + match = _STDERR_LEVEL_RE.search(rendered) + assert match, f"level regex didn't match rendered line: {rendered!r}" + assert match.group(1) == level_name + + +def test_worker_formatter_renders_structured_fields(): + """ + worker.py doit utiliser _TextFormatter (pas un format="..." brut) pour + que les champs structurés (logger.info(msg, plugin=..., error=...)) + apparaissent dans stderr — sinon ils sont attachés via extra={"xcore_ctx"} + et un Formatter texte simple les ignore silencieusement. + """ + from xcore.kernel.sandbox import worker + + assert isinstance(worker._worker_handler.formatter, type(worker._TextFormatter())) + + record = worker.logging.LogRecord( + name="xcore.worker", + level=worker.logging.ERROR, + pathname=__file__, + lineno=1, + msg="sandbox filesystem violation", + args=(), + exc_info=None, + ) + record.xcore_ctx = {"plugin": "test_plugin", "error": "boom"} + rendered = worker._worker_handler.formatter.format(record) + assert "plugin=test_plugin" in rendered + assert "error=boom" in rendered diff --git a/tests/unit/kernel/test_sandbox_cpu_budget.py b/tests/unit/kernel/test_sandbox_cpu_budget.py new file mode 100644 index 00000000..2d68f4a9 --- /dev/null +++ b/tests/unit/kernel/test_sandbox_cpu_budget.py @@ -0,0 +1,182 @@ +""" +Le budget CPU du worker sandboxed est PAR REQUÊTE, pas cumulatif. + +RLIMIT_CPU compte le temps CPU total du processus : posé une fois à 10 s, il tuait +un worker parfaitement sain (SIGXCPU) après 10 s de CPU cumulées sur toute sa vie, +puis le plugin passait FAILED après `max_restarts` plantages. Ces tests tournent +dans un sous-processus : abaisser RLIMIT_CPU du process pytest le tuerait. +""" + +import os +import signal +import subprocess +import sys +import textwrap +import time + +import pytest + +from xcore.kernel.sandbox.process_manager import ( + ProcessState, + SandboxConfig, + SandboxProcessManager, +) + +pytestmark = pytest.mark.skipif( + sys.platform == "win32", reason="RLIMIT_CPU n'existe pas sous Windows" +) + +SCRIPT = textwrap.dedent(""" + import os, sys, time + os.environ["_SANDBOX_MAX_CPU_SEC"] = "1" + os.environ["_SANDBOX_MAX_CPU_LIFETIME_SEC"] = sys.argv[3] + from xcore.kernel.sandbox import worker + + worker._apply_resource_limits() + + def burn(seconds): + end = time.process_time() + seconds + while time.process_time() < end: + pass + + for _ in range(int(sys.argv[1])): + worker._arm_cpu_budget() # = avant chaque requête + burn(float(sys.argv[2])) + print("survived", worker._needs_recycle()) + """) + + +def _run( + requests: int, burn_s: float, lifetime_s: int = 0 +) -> subprocess.CompletedProcess: + return subprocess.run( + [sys.executable, "-c", SCRIPT, str(requests), str(burn_s), str(lifetime_s)], + capture_output=True, + text=True, + timeout=60, + env={**os.environ, "LOG_LEVEL": "ERROR"}, + ) + + +def test_cpu_cumulated_over_many_requests_does_not_kill_the_worker(): + # 5 requêtes de 0,6 s = 3 s de CPU au total, bien au-delà du budget de 1 s + result = _run(requests=5, burn_s=0.6) + + assert result.returncode == 0, result.stderr + assert "survived False" in result.stdout # pas de plafond de vie configuré + + +def test_a_single_request_over_budget_is_still_killed(): + started = time.monotonic() + result = _run(requests=1, burn_s=30) + + assert result.returncode == -signal.SIGXCPU + assert time.monotonic() - started < 15 + + +def test_worker_asks_to_be_recycled_before_the_lifetime_ceiling_is_hit( + monkeypatch, +): + """ + Plafond de vie 4 s, budget 1 s : dès que ≥ 2 s de CPU sont consommées la + requête suivante ne pourrait plus avoir son budget complet (2 + 1 + 1 >= 4) — + le worker doit demander son recyclage plutôt que d'être tué en pleine requête. + Déterministe : la consommation CPU est simulée (aucune limite posée sur pytest). + """ + from xcore.kernel.sandbox import worker + + monkeypatch.setattr(worker, "_cpu_budget_s", 1) + monkeypatch.setattr(worker, "_cpu_lifetime_s", 4) + + for consumed, expected in ((0.2, False), (1.9, False), (2.0, True), (3.5, True)): + monkeypatch.setattr(worker, "_cpu_consumed", lambda c=consumed: c) + assert worker._needs_recycle() is expected, consumed + + monkeypatch.setattr(worker, "_cpu_lifetime_s", 0) # aucun plafond configuré + assert worker._needs_recycle() is False + + +def test_worker_does_not_recycle_while_far_from_the_ceiling(): + result = _run(requests=1, burn_s=0.2, lifetime_s=60) + + assert result.returncode == 0, result.stderr + assert "survived False" in result.stdout + + +def test_recycle_exit_code_is_shared_between_worker_and_parent(): + from xcore.kernel.sandbox import process_manager, worker + + assert worker.RECYCLE_EXIT_CODE == process_manager.RECYCLE_EXIT_CODE == 75 + + +class TestRestartCounterReset: + @pytest.fixture + def manager(self, tmp_path): + from unittest.mock import AsyncMock, MagicMock + + manifest = MagicMock() + manifest.name = "p" + manifest.plugin_dir = tmp_path + manifest.resources.max_disk_mb = 10 + manifest.resources.max_memory_mb = 128 + manifest.resources.timeout_seconds = 5 + manifest.env = {} + manifest.runtime.health_check.enabled = False + config = SandboxConfig( + restart_delay=0.01, max_restarts=2, restart_reset_after=60.0 + ) + mgr = SandboxProcessManager(manifest, MagicMock(), config=config) + mgr._process = MagicMock(returncode=None, wait=AsyncMock(return_value=1)) + mgr._state = ProcessState.RUNNING + mgr._spawn = AsyncMock() + return mgr + + async def test_crash_after_a_long_stable_run_starts_a_fresh_sequence(self, manager): + manager._restarts = 2 # == max_restarts : serait FAILED sans le reset + manager._started_at = time.monotonic() - 3600 + + await manager._handle_crash() + + assert manager.state == ProcessState.RUNNING + assert manager._restarts == 1 + + async def test_crash_loop_is_still_capped(self, manager): + manager._restarts = 2 + manager._started_at = time.monotonic() - 1 # vient de redémarrer + + await manager._handle_crash() + + assert manager.state == ProcessState.FAILED + + def test_cpu_limits_are_configurable(self): + config = SandboxConfig() + assert config.max_cpu_seconds == 10 + assert config.max_cpu_lifetime_seconds == 3600 + assert SandboxConfig(max_cpu_seconds=3).max_cpu_seconds == 3 + + async def test_recycled_worker_is_restarted_without_counting_as_a_crash( + self, manager + ): + from unittest.mock import AsyncMock + + from xcore.kernel.sandbox.isolation import RECYCLE_EXIT_CODE + + manager._process.wait = AsyncMock(return_value=RECYCLE_EXIT_CODE) + manager._restarts = 2 # == max_restarts : un vrai plantage serait fatal + manager._started_at = time.monotonic() - 1 + + await manager._watch_loop() + + assert manager.state == ProcessState.RUNNING + assert manager._restarts == 1 # le redémarrage lui-même, pas l'historique + + async def test_real_crash_exit_code_still_counts(self, manager): + from unittest.mock import AsyncMock + + manager._process.wait = AsyncMock(return_value=-24) # SIGXCPU + manager._restarts = 2 + manager._started_at = time.monotonic() - 1 + + await manager._watch_loop() + + assert manager.state == ProcessState.FAILED diff --git a/tests/unit/kernel/test_state_machine.py b/tests/unit/kernel/test_state_machine.py index a64e9542..067eaadb 100644 --- a/tests/unit/kernel/test_state_machine.py +++ b/tests/unit/kernel/test_state_machine.py @@ -124,13 +124,31 @@ def test_transition_from_failed(self, sm): sm.transition("error") assert sm.state == PluginState.FAILED - # From FAILED, only reset is valid + # From FAILED : "load" reste invalide, mais unload/reload/reset sont possibles with pytest.raises(InvalidTransition): sm.transition("load") sm.transition("reset") assert sm.state == PluginState.UNLOADED + def test_failed_can_be_unloaded(self, sm): + """Un plugin FAILED doit pouvoir être déchargé (donc nettoyé).""" + sm.transition("load") + sm.transition("error") + sm.transition("unload") + assert sm.state == PluginState.UNLOADING + sm.transition("ok") + assert sm.state == PluginState.UNLOADED + + def test_failed_can_be_reloaded(self, sm): + """Un plugin FAILED doit pouvoir être rechargé (nouvel essai).""" + sm.transition("load") + sm.transition("error") + sm.transition("reload") + assert sm.state == PluginState.RELOADING + sm.transition("ok") + assert sm.state == PluginState.READY + def test_callback_on_change(self): """Test on_change callback.""" callbacks = [] diff --git a/tests/unit/kernel/test_supervisor_exported_services.py b/tests/unit/kernel/test_supervisor_exported_services.py new file mode 100644 index 00000000..f08d6351 --- /dev/null +++ b/tests/unit/kernel/test_supervisor_exported_services.py @@ -0,0 +1,89 @@ +""" +Régression : un plugin qui EXPORTE un service (dans `self._services`) doit rester +rechargeable après le boot. + +`PluginSupervisor.boot()` enregistrait, à son étape 5, tout le contenu du +ServiceContainer comme service noyau protégé — y compris les services que les +plugins venaient d'y propager. Le propriétaire devenait « kernel » et le reload +du plugin qui l'exportait échouait avec « Impossible d'écraser le service +protégé ». +""" + +from types import SimpleNamespace + +import pytest + +from xcore.configurations.sections import ServicesConfig +from xcore.kernel.context import KernelContext +from xcore.kernel.events.bus import EventBus +from xcore.kernel.events.hooks import HookManager +from xcore.kernel.observability.health import HealthChecker +from xcore.kernel.runtime.supervisor import PluginSupervisor +from xcore.registry.index import PluginRegistry +from xcore.services.container import ServiceContainer + +MANIFEST = """ +name: exporter +version: 1.0.0 +execution_mode: trusted +entry_point: src/main.py +""" + +SRC = """ +from xcore.kernel.api.contract import TrustedBase + +class Plugin(TrustedBase): + async def on_load(self): + self._services["exported_svc"] = self + + async def handle(self, action, payload): + return {"status": "ok"} +""" + + +@pytest.fixture +async def booted(tmp_path): + plugins = tmp_path / "plugins" + (plugins / "exporter" / "src").mkdir(parents=True) + (plugins / "exporter" / "plugin.yaml").write_text(MANIFEST) + (plugins / "exporter" / "src" / "main.py").write_text(SRC) + + container = ServiceContainer(ServicesConfig()) + container._raw["cache"] = object() # un service noyau + registry = PluginRegistry() + ctx = KernelContext( + config=SimpleNamespace( + directory=str(plugins), + tenancy=None, + strict_trusted=False, + secret_key=b"test", + ), + services=container, + registry=registry, + events=EventBus(), + hooks=HookManager(), + health=HealthChecker(), + ) + supervisor = PluginSupervisor(ctx) + await supervisor.boot() + yield SimpleNamespace(supervisor=supervisor, container=container, registry=registry) + await supervisor.shutdown() + + +async def test_plugin_is_loaded_and_its_export_stays_owned_by_the_plugin(booted): + assert "exporter" in booted.supervisor.list_plugins() + exported = [ + s for s in booted.registry.list_services() if s["name"] == "exported_svc" + ] + assert exported and exported[0]["plugin"] == "exporter" + assert booted.registry.is_core_service("cache") is True + assert booted.registry.is_core_service("exported_svc") is False + + +async def test_plugin_exporting_a_service_can_be_reloaded_after_boot(booted): + await booted.supervisor.reload("exporter") + await booted.supervisor.reload("exporter") # le 2e reload cassait aussi + + handler = booted.supervisor._loader.get("exporter") + assert handler.state.value == "ready" + assert booted.container.as_dict()["exported_svc"] is handler._instance diff --git a/tests/unit/test_registry_index.py b/tests/unit/test_registry_index.py index 7efdc81b..b0e30268 100644 --- a/tests/unit/test_registry_index.py +++ b/tests/unit/test_registry_index.py @@ -7,6 +7,7 @@ class TestPluginRegistry: def _make(self): from xcore.registry.index import PluginRegistry + return PluginRegistry() def test_register_and_has(self): @@ -71,7 +72,9 @@ def test_register_service_protected_overwrite_raises(self): def test_get_service_private_denied(self): reg = self._make() - reg.register_service("owner_plugin", "private_svc", MagicMock(), scope="private") + reg.register_service( + "owner_plugin", "private_svc", MagicMock(), scope="private" + ) with pytest.raises(PermissionError): reg.get_service("private_svc", requester="other_plugin") @@ -135,7 +138,11 @@ def test_search(self): reg = self._make() handler = MagicMock() handler.manifest = None - reg.register("auth_plugin", handler, metadata={"description": "auth service", "author": "me"}) + reg.register( + "auth_plugin", + handler, + metadata={"description": "auth service", "author": "me"}, + ) result = reg.search("auth") assert len(result) >= 1 @@ -156,3 +163,27 @@ def test_unregister_cleans_services(self): assert not reg.has("plugin_x") with pytest.raises(KeyError): reg.get_service("x_svc") + + +def test_is_core_service_distinguishes_kernel_from_plugin_exports(): + from xcore.registry.index import PluginRegistry + + reg = PluginRegistry() + reg.register_core_service("scheduler", object()) + reg.register_service("shop", "cart", object()) + + assert reg.is_core_service("scheduler") is True + assert reg.is_core_service("cart") is False + assert reg.is_core_service("missing") is False + + +def test_service_owner_reports_kernel_plugin_or_none(): + from xcore.registry.index import PluginRegistry + + reg = PluginRegistry() + reg.register_core_service("scheduler", object()) + reg.register_service("shop", "cart", object()) + + assert reg.service_owner("scheduler") == "kernel" + assert reg.service_owner("cart") == "shop" + assert reg.service_owner("missing") is None diff --git a/tests/unit/test_xcore_plugin_routes.py b/tests/unit/test_xcore_plugin_routes.py new file mode 100644 index 00000000..21c7ebaf --- /dev/null +++ b/tests/unit/test_xcore_plugin_routes.py @@ -0,0 +1,139 @@ +""" +Régression : montage / retrait des routes FastAPI d'un plugin au unload et au +reload (`Xcore._mount_plugin_router`, `_unmount_plugin_router`, +`_remount_plugin_router`). + +Avant le correctif, `_unmount_plugin_router` faisait `app.routes = [...]` — +propriété sans setter chez Starlette (AttributeError, avalée par l'EventBus) — et +filtrait sur `route.path`, attribut que les `_IncludedRouter` de FastAPI ≥ 0.14x +n'ont pas : après un unload ou un reload les anciennes routes restaient montées +et continuaient de servir l'ancien code du plugin. +""" + +from types import SimpleNamespace + +import pytest +from fastapi import APIRouter, FastAPI +from fastapi.testclient import TestClient + +from xcore import Xcore + + +def _router(answer: int) -> APIRouter: + router = APIRouter() + + @router.get("/ping") + async def ping(): + return {"answer": answer} + + return router + + +@pytest.fixture +def xcore_app(): + app = FastAPI() + x = object.__new__(Xcore) + x._app = app + x._config = SimpleNamespace( + app=SimpleNamespace(plugin_prefix="/plugins", plugin_tags=[]) + ) + x._logger = SimpleNamespace(info=lambda *a, **k: None) + x._plugin_routes = {} + x.plugins = SimpleNamespace(_loader=SimpleNamespace(get=lambda name: None)) + return x, app, TestClient(app) + + +def _mount(x, app, name, answer): + x._mount_plugin_router(app, name, _router(answer), "/plugins", []) + + +class TestUnmount: + def test_unmount_removes_the_plugin_routes(self, xcore_app): + x, app, client = xcore_app + _mount(x, app, "shop", 1) + assert client.get("/plugins/shop/ping").json() == {"answer": 1} + + x._unmount_plugin_router("shop") + + assert client.get("/plugins/shop/ping").status_code == 404 + + def test_unmount_does_not_touch_a_plugin_with_a_longer_name(self, xcore_app): + """`/plugins/shop` est un préfixe textuel de `/plugins/shop2`.""" + x, app, client = xcore_app + _mount(x, app, "shop", 1) + _mount(x, app, "shop2", 2) + + x._unmount_plugin_router("shop") + + assert client.get("/plugins/shop/ping").status_code == 404 + assert client.get("/plugins/shop2/ping").json() == {"answer": 2} + + def test_unmount_without_app_is_a_noop(self, xcore_app): + x, _, _ = xcore_app + x._app = None + x._unmount_plugin_router("shop") # ne lève pas + + def test_unmount_invalidates_the_openapi_schema(self, xcore_app): + x, app, client = xcore_app + _mount(x, app, "shop", 1) + assert "/plugins/shop/ping" in client.get("/openapi.json").json()["paths"] + + x._unmount_plugin_router("shop") + + assert "/plugins/shop/ping" not in client.get("/openapi.json").json()["paths"] + + +class TestRemountAfterReload: + def test_remount_serves_the_new_router_not_the_old_one(self, xcore_app): + x, app, client = xcore_app + _mount(x, app, "shop", 1) + new_handler = SimpleNamespace(plugin_router=_router(2)) + x.plugins = SimpleNamespace(_loader=SimpleNamespace(get=lambda n: new_handler)) + + x._remount_plugin_router("shop") + + assert client.get("/plugins/shop/ping").json() == {"answer": 2} + paths = [p for p in client.get("/openapi.json").json()["paths"] if "shop" in p] + assert paths == ["/plugins/shop/ping"] # pas de doublon + + def test_remount_drops_routes_when_the_new_code_has_no_router(self, xcore_app): + x, app, client = xcore_app + _mount(x, app, "shop", 1) + x.plugins = SimpleNamespace( + _loader=SimpleNamespace(get=lambda n: SimpleNamespace(plugin_router=None)) + ) + + x._remount_plugin_router("shop") + + assert client.get("/plugins/shop/ping").status_code == 404 + + def test_remount_after_unload_of_the_handler_leaves_no_route(self, xcore_app): + x, app, client = xcore_app + _mount(x, app, "shop", 1) + + def _raise(name): + raise KeyError(name) + + x.plugins = SimpleNamespace(_loader=SimpleNamespace(get=_raise)) + + x._remount_plugin_router("shop") + + assert client.get("/plugins/shop/ping").status_code == 404 + + +class TestMount: + def test_router_already_prefixed_with_plugins_is_not_double_prefixed( + self, xcore_app + ): + x, app, client = xcore_app + router = APIRouter(prefix="/plugins/custom") + + @router.get("/ping") + async def ping(): + return {"answer": 3} + + x._mount_plugin_router(app, "custom", router, "/plugins", []) + + assert client.get("/plugins/custom/ping").json() == {"answer": 3} + x._unmount_plugin_router("custom") + assert client.get("/plugins/custom/ping").status_code == 404 diff --git a/xcore/__init__.py b/xcore/__init__.py index 5d1589cc..15398beb 100644 --- a/xcore/__init__.py +++ b/xcore/__init__.py @@ -20,7 +20,7 @@ from __future__ import annotations import contextlib -from typing import TYPE_CHECKING +from typing import TYPE_CHECKING, Any if TYPE_CHECKING: from fastapi import FastAPI @@ -133,6 +133,10 @@ def __init__(self, config_path: str | None = None): self._app: "FastAPI | None" = ( None # référence conservée pour remount après reload ) + # Objets route réellement ajoutés à l'app par plugin — la seule façon + # fiable de les retirer, quelle que soit la façon dont la version de + # FastAPI installée stocke un router inclus (voir _mount_plugin_router). + self._plugin_routes: dict[str, list[Any]] = {} self._logger = get_logger("xcore") @@ -233,6 +237,7 @@ async def _check(_s=_svc): metrics=self.metrics, tracer=self.tracer, health=self.health, + log_level=self._config.observability.logging.level.upper(), ) self.plugins = PluginSupervisor(ctx) @@ -280,13 +285,44 @@ async def shutdown(self) -> None: self._booted = False self._logger.info("xcore stopped") + def _mount_plugin_router( + self, app, plugin_name: str, plugin_router, prefix: str, tags: list[str] + ) -> str: + """ + Monte le router d'un plugin sous `/` et mémorise les + objets route que `include_router()` a ajoutés à l'app. + + Les retrouver par leur `path` ne marche plus : depuis FastAPI 0.14x, + `include_router()` stocke un `_IncludedRouter` sans attribut `path`. On + compare donc les routes de l'app avant/après l'inclusion. + """ + from fastapi import APIRouter + + plugin_prefix = f"{prefix}/{plugin_name}" + mounted: Any = plugin_router + if not getattr(plugin_router, "prefix", "").startswith("/plugins/"): + # Préfixe automatique si le plugin n'a pas déjà /plugins/... + mounted = APIRouter(prefix=plugin_prefix, tags=tags) + mounted.include_router(plugin_router) + + before = {id(r) for r in app.router.routes} + app.include_router(mounted) + self._plugin_routes[plugin_name] = [ + r for r in app.router.routes if id(r) not in before + ] + app.openapi_schema = None # force regen du schéma OpenAPI + return getattr(mounted, "prefix", plugin_prefix) + def _unmount_plugin_router(self, plugin_name: str) -> None: """ Retire de l'app FastAPI toutes les routes montées pour ce plugin. - FastAPI n'offre pas de désinscription native d'un routeur — on filtre - donc `app.routes`, seule approche possible. Utilisé au unload/disable - et en première étape du remount lors d'un reload. + FastAPI n'offre pas de désinscription native d'un routeur. On retire les + objets route mémorisés au montage (`_mount_plugin_router`), plus — pour + les versions où les routes exposent un `path` — celles dont le chemin est + exactement le préfixe du plugin ou en dessous (`/plugins/shop` ne doit + pas emporter `/plugins/shop2`). Utilisé au unload/disable et en première + étape du remount lors d'un reload. """ app = self._app if app is None: @@ -294,12 +330,22 @@ def _unmount_plugin_router(self, plugin_name: str) -> None: prefix = self._config.app.plugin_prefix or "/plugins" plugin_prefix = f"{prefix}/{plugin_name}" + tracked = {id(r) for r in self._plugin_routes.pop(plugin_name, [])} + + def belongs(route) -> bool: + if id(route) in tracked: + return True + path = getattr(route, "path", None) + return isinstance(path, str) and ( + path == plugin_prefix or path.startswith(plugin_prefix + "/") + ) - app.routes = [ - r - for r in app.routes - if not getattr(r, "path", "").startswith(plugin_prefix) - ] + # `app.routes` est une propriété sans setter (Starlette) : on modifie la + # liste du router en place. + app.router.routes[:] = [r for r in app.router.routes if not belongs(r)] + mark_changed = getattr(app.router, "_mark_routes_changed", None) + if callable(mark_changed): # invalide le cache de routes de FastAPI ≥ 0.14x + mark_changed() app.openapi_schema = None # force regen du schéma OpenAPI def _remount_plugin_router(self, plugin_name: str) -> None: @@ -311,7 +357,6 @@ def _remount_plugin_router(self, plugin_name: str) -> None: self._unmount_plugin_router(plugin_name) prefix = self._config.app.plugin_prefix or "/plugins" - plugin_prefix = f"{prefix}/{plugin_name}" # Récupère le nouveau router depuis le handler rechargé try: @@ -323,22 +368,20 @@ def _remount_plugin_router(self, plugin_name: str) -> None: if plugin_router is None: return - from fastapi import APIRouter - - wrapper = APIRouter( - prefix=plugin_prefix, - tags=(self._config.app.plugin_tags or []), + mounted_prefix = self._mount_plugin_router( + app, + plugin_name, + plugin_router, + prefix, + self._config.app.plugin_tags or [], ) - wrapper.include_router(plugin_router) - app.include_router(wrapper) - app.openapi_schema = None # force regen du schéma OpenAPI n_routes = len(getattr(plugin_router, "routes", [])) self._logger.info( "plugin routes remounted after reload", plugin=plugin_name, routes=n_routes, - prefix=plugin_prefix, + prefix=mounted_prefix, ) def _attach_router( @@ -365,24 +408,19 @@ def _attach_router( plugin_routers = self.plugins.collect_plugin_routers() for plugin_name, plugin_router in plugin_routers: # Monte sous /plugins// + le prefix du router du plugin - prefixed_router = plugin_router - if not getattr(plugin_router, "prefix", "").startswith("/plugins/"): - # Préfixe automatique si le plugin n'a pas déjà /plugins/... - from fastapi import APIRouter - - wrapper = APIRouter( - prefix=f"{prefix}/{plugin_name}", - tags=(self._config.app.plugin_tags or []) + (tags or []), - ) - wrapper.include_router(plugin_router) - prefixed_router = wrapper - app.include_router(prefixed_router) + mounted_prefix = self._mount_plugin_router( + app, + plugin_name, + plugin_router, + prefix or self._config.app.plugin_prefix or "/plugins", + (self._config.app.plugin_tags or []) + (tags or []), + ) n_routes = len(getattr(plugin_router, "routes", [])) self._logger.info( "plugin routes mounted", plugin=plugin_name, routes=n_routes, - prefix=wrapper.prefix, + prefix=mounted_prefix, ) for middleware in self.plugins.collect_app_state(): diff --git a/xcore/__version__.py b/xcore/__version__.py index 94d7bcf8..ae25f6b4 100644 --- a/xcore/__version__.py +++ b/xcore/__version__.py @@ -1,4 +1,4 @@ -__version__ = "2.6.2" -__version_info__ = (2, 6, 2) +__version__ = "2.6.8" +__version_info__ = (2, 6, 8) __author__ = "xcore contributors" __license__ = "MIT" diff --git a/xcore/configurations/loader.py b/xcore/configurations/loader.py index 893af1f5..b2a40d4e 100644 --- a/xcore/configurations/loader.py +++ b/xcore/configurations/loader.py @@ -197,6 +197,8 @@ def _parse_plugins(d: dict) -> PluginConfig: strict_trusted=d.get("strict_trusted", True), interval=d.get("interval", 2), entry_point=d.get("entry_point", "src/main.py"), + gc_after_unload=d.get("gc_after_unload", True), + loop_block_warn_ms=d.get("loop_block_warn_ms", 250), snapshot=d.get( "snapshot", { diff --git a/xcore/configurations/sections.py b/xcore/configurations/sections.py index 7de7420c..161a2bf7 100644 --- a/xcore/configurations/sections.py +++ b/xcore/configurations/sections.py @@ -273,6 +273,12 @@ class PluginConfig: strict_trusted: bool = False interval: int = 2 # watcher interval (secondes) entry_point: str = "src/main.py" + # Force une collecte du GC (différée, regroupée) après un unload/reload de + # plugin et signale les instances qui survivent — voir _ReleaseWatcher. + gc_after_unload: bool = True + # Un plugin Trusted dont un pas synchrone (entre deux `await`) dépasse ce + # seuil en ms est signalé comme gelant le event loop (0 = désactivé). + loop_block_warn_ms: int = 250 snapshot: dict[str, Any] = field( default_factory=lambda: { "extensions": [".log", ".pyc", ".html"], diff --git a/xcore/kernel/api/context.py b/xcore/kernel/api/context.py index eaf74d2a..c9799fc3 100644 --- a/xcore/kernel/api/context.py +++ b/xcore/kernel/api/context.py @@ -9,9 +9,14 @@ from __future__ import annotations import asyncio +import contextlib from dataclasses import dataclass, field from typing import TYPE_CHECKING, Any, Awaitable, Callable, Coroutine +from ..observability import get_logger + +logger = get_logger("xcore.api.context") + if TYPE_CHECKING: from ...registry import PluginRegistry from ..observability import HealthChecker, MetricsRegistry, Tracer @@ -62,8 +67,26 @@ def spawn_task(self, coro: Coroutine, name: str | None = None) -> asyncio.Task: qu'on_unload/on_stop l'ait fait ou non. """ task = asyncio.create_task(coro, name=name) - if self._task_sink is not None: - self._task_sink.append(task) + sink = self._task_sink + if sink is not None: + sink.append(task) + plugin = self.name + + def _on_done(t: asyncio.Task) -> None: + # Une tâche terminée n'a plus rien à annuler : sans ça la liste + # grossissait pendant toute la vie du plugin, et chaque tâche + # finie restait référencée (avec son résultat / son exception). + with contextlib.suppress(ValueError): + sink.remove(t) + if not t.cancelled() and t.exception() is not None: + logger.error( + "spawned task failed", + plugin=plugin, + task=t.get_name(), + error=str(t.exception()), + ) + + task.add_done_callback(_on_done) return task def get_service(self, name: str) -> Any: @@ -71,8 +94,18 @@ def get_service(self, name: str) -> Any: Accès sécurisé à un service avec vérification de scoping via le registry si disponible, sinon via le container partagé. """ - # Priorité au registry pour le respect des scopes (public/private/protected) if self.registry: + # Service noyau (db, cache, scheduler…) : on sert la version injectée + # dans CE contexte — proxy de ramasse-miette du plugin, wrappers + # tenant-aware — et non l'objet brut du registre. Après le boot, le + # registre contient les services noyau bruts : passer par lui + # contournait le suivi des jobs au unload et l'isolation tenant. + if self.registry.is_core_service(name) is True: + svc = self.services.get(name) + if svc is not None: + return svc + + # Priorité au registry pour le respect des scopes (public/private/protected) try: return self.registry.get_service(name, requester=self.name) except (KeyError, PermissionError) as e: diff --git a/xcore/kernel/context.py b/xcore/kernel/context.py index 7a9cfa9c..ffde7be5 100644 --- a/xcore/kernel/context.py +++ b/xcore/kernel/context.py @@ -33,6 +33,7 @@ class KernelContext: metrics: MetricsRegistry | None = None tracer: Tracer | None = None health: HealthChecker | None = None + log_level: str = "WARNING" def as_plugin_context_params( self, plugin_name: str, caller: Any = None diff --git a/xcore/kernel/events/hooks.py b/xcore/kernel/events/hooks.py index 44cfae2c..f4496422 100644 --- a/xcore/kernel/events/hooks.py +++ b/xcore/kernel/events/hooks.py @@ -170,6 +170,24 @@ async def _execute_single_hook( result=result, execution_time_ms=(time.time() - start) * 1000, ) + except asyncio.TimeoutError as e: + if not hook_info.is_async: + # wait_for() annule l'attente, pas le thread : un hook synchrone + # qui dépasse son timeout continue de tourner (en tenant le GIL + # par tranches) et occupe un worker du pool par défaut. + logger.warning( + "sync hook timed out, its worker thread keeps running", + hook=hook_name, + event=event.name, + timeout_s=hook_info.timeout, + hint="make the hook async, or have it honour its own deadline", + ) + return HookResult( + hook_name=hook_name, + event_name=event.name, + error=e, + execution_time_ms=(time.time() - start) * 1000, + ) except Exception as e: return HookResult( hook_name=hook_name, diff --git a/xcore/kernel/observability/blocking.py b/xcore/kernel/observability/blocking.py new file mode 100644 index 00000000..c3f22f78 --- /dev/null +++ b/xcore/kernel/observability/blocking.py @@ -0,0 +1,85 @@ +""" +blocking.py — Détection du code synchrone qui gèle le event loop. + +Un plugin Trusted (ou un job du scheduler) s'exécute dans le thread du event loop. +Tout ce qu'il fait *entre deux `await`* — calcul CPU, I/O bloquant, `time.sleep` — +suspend l'application entière, et `asyncio.wait_for(timeout=...)` ne peut rien y +faire : le timer ne passe qu'au prochain `await`. Mesuré : un handler qui consomme +1 s de CPU sans `await` avec `timeout_seconds=0.2` rend `status: ok` au bout de +1000 ms, pas une erreur de timeout au bout de 200 ms. + +`watch_blocking()` ne peut pas l'empêcher (c'est la limite du GIL + d'un loop +unique), mais le rend visible et attribuable : elle mesure chaque *pas* synchrone +de l'awaitable — le temps passé entre deux suspensions — et prévient quand il +dépasse le seuil. Pour du CPU lourd : `asyncio.to_thread`, ou le mode `sandboxed` +(un processus par plugin, donc hors du GIL et du loop principal). +""" + +from __future__ import annotations + +import contextlib +import inspect +import time +from typing import Any, Awaitable, Callable + + +class _StepWatch: + """Awaitable transparent qui chronomètre chaque pas synchrone de l'inner.""" + + __slots__ = ("_aw", "_threshold_s", "_on_block") + + def __init__( + self, + aw: Awaitable[Any], + threshold_s: float, + on_block: Callable[[float], None], + ) -> None: + self._aw = aw + self._threshold_s = threshold_s + self._on_block = on_block + + def _observe(self, start: float) -> None: + elapsed = time.perf_counter() - start + if elapsed >= self._threshold_s: + # Une erreur de rapport ne doit jamais casser l'appel du plugin. + with contextlib.suppress(Exception): + self._on_block(elapsed) + + def __await__(self): + it = self._aw.__await__() + value: Any = None + exc: BaseException | None = None + while True: + start = time.perf_counter() + try: + yielded = it.throw(exc) if exc is not None else it.send(value) + except StopIteration as stop: + self._observe(start) + return stop.value + except BaseException: + self._observe(start) + raise + self._observe(start) + exc, value = None, None + try: + value = yield yielded + except GeneratorExit: + it.close() + raise + except BaseException as e: # CancelledError (timeout/cancel) inclus + exc = e + + +def watch_blocking( + aw: Awaitable[Any], + threshold_ms: float, + on_block: Callable[[float], None], +) -> Awaitable[Any]: + """ + Enveloppe `aw` pour signaler (via `on_block(seconds)`) chaque pas synchrone + d'au moins `threshold_ms`. Sans effet si le seuil est ≤ 0 ou si `aw` n'est + pas un awaitable. + """ + if threshold_ms <= 0 or not inspect.isawaitable(aw): + return aw + return _StepWatch(aw, threshold_ms / 1000.0, on_block) diff --git a/xcore/kernel/runtime/activator.py b/xcore/kernel/runtime/activator.py index 160df1db..7d48a0a9 100644 --- a/xcore/kernel/runtime/activator.py +++ b/xcore/kernel/runtime/activator.py @@ -91,7 +91,8 @@ async def activate(self, manifest: Any, loader: "PluginLoader") -> "PluginHandle if not scan.passed: raise ValueError("scan failed") - mgr = SandboxProcessManager(manifest=manifest, ctx=loader) + log_level = getattr(loader._ctx, "log_level", "WARNING") + mgr = SandboxProcessManager(manifest=manifest, ctx=loader, log_level=log_level) await mgr.start() return mgr diff --git a/xcore/kernel/runtime/ephemeral_handler.py b/xcore/kernel/runtime/ephemeral_handler.py index a9f1fabf..ebe5f3b8 100644 --- a/xcore/kernel/runtime/ephemeral_handler.py +++ b/xcore/kernel/runtime/ephemeral_handler.py @@ -109,6 +109,7 @@ async def start(self) -> None: manifest=self._manifest, ctx=self._ctx, caller=self._caller, + pooled=True, ) try: await lm.load() @@ -125,6 +126,11 @@ async def start(self) -> None: async def stop(self) -> None: """Arrête le warm pool et décharge toutes les instances.""" await self._pool.shutdown() + # Les instances poolées ne touchent pas au registre : c'est ce handler + # (le plugin, pas une instance) qui s'en désinscrit à l'arrêt. + registry = getattr(self._ctx, "registry", None) + if registry is not None: + registry.unregister(self._manifest.name) logger.info("ephemeral plugin stopped", plugin=self._manifest.name) # ── Appel ───────────────────────────────────────────────────────────────── diff --git a/xcore/kernel/runtime/lifecycle.py b/xcore/kernel/runtime/lifecycle.py index 9d6c3a3a..0bdaa280 100644 --- a/xcore/kernel/runtime/lifecycle.py +++ b/xcore/kernel/runtime/lifecycle.py @@ -10,11 +10,14 @@ from __future__ import annotations import asyncio +import gc import importlib.util import inspect +import itertools import sys import time import types +import weakref from pathlib import Path from typing import TYPE_CHECKING, Any @@ -24,11 +27,95 @@ from ..api.context import PluginContext from ..api.contract import BasePlugin from ..observability import get_logger -from .plugin_gc import PluginResourceTracker +from ..observability.blocking import watch_blocking +from .plugin_gc import PluginResourceTracker, _ScopedScheduler from .state_machine import PluginState, StateMachine logger = get_logger("xcore.runtime.lifecycle") +# Seuil (ms) au-delà duquel un pas synchrone d'un plugin Trusted — du code qui +# tourne entre deux `await` — est signalé comme gelant le event loop (0 = off). +_DEFAULT_LOOP_BLOCK_WARN_MS = 250 +# Au plus un avertissement de gel par plugin sur cette fenêtre (secondes). +_LOOP_BLOCK_LOG_INTERVAL_S = 10.0 + +# Délai avant la collecte qui suit un unload/reload : laisse les tâches annulées, +# les callbacks et les réponses en vol se terminer, et regroupe plusieurs unloads +# rapprochés en UNE seule collecte. +_GC_DELAY_S = 1.0 + + +class _ReleaseWatcher: + """ + Contrôle de libération des plugins déchargés. + + Une instance de plugin déchargée vit dans des cycles de références (classe, + module, contexte, tâches) : le comptage de références ne la libère jamais, et + le GC automatique de Python ne passe en génération ancienne qu'après + beaucoup d'allocations — mesuré : un cycle mort promu en vieille génération + n'était pas libéré après 11,5 M d'allocations sur un tas de 3 M d'objets. + Après un unload/reload, on force donc UNE collecte (différée et regroupée), + puis on vérifie via un weakref que l'instance a bien disparu — sinon quelque + chose la référence encore (tâche brute, callback enregistré en dehors du + ctx…) et on le signale, avec le type de ses référents. + """ + + def __init__(self) -> None: + self._pending: list[tuple[weakref.ref, str]] = [] + self._handle: asyncio.TimerHandle | None = None + self._loop: asyncio.AbstractEventLoop | None = None + + def watch(self, instance: Any, plugin: str, delay: float) -> None: + try: + ref = weakref.ref(instance) + except TypeError: # classe avec __slots__ sans __weakref__ + return + self._pending.append((ref, plugin)) + loop = asyncio.get_running_loop() + if self._handle is not None and self._loop is loop: + return # une collecte est déjà programmée : on s'y greffe + self._loop = loop + self._handle = loop.call_later(delay, self._collect) + + def _collect(self) -> None: + self._handle = None + pending, self._pending = self._pending, [] + started = time.perf_counter() + collected = gc.collect() + duration_ms = round((time.perf_counter() - started) * 1000, 1) + leaked = [(ref, plugin) for ref, plugin in pending if ref() is not None] + logger.debug( + "plugin garbage collected", + plugins=sorted({plugin for _, plugin in pending}), + unreachable_objects=collected, + duration_ms=duration_ms, + ) + for ref, plugin in leaked: + instance = ref() + if instance is None: + continue + referrers = sorted( + { + type(r).__name__ + for r in gc.get_referrers(instance) + if not isinstance(r, types.FrameType) + } + )[:8] + logger.warning( + "plugin instance still referenced after unload", + plugin=plugin, + referrers=referrers, + hint="a task, callback or service registered outside ctx still holds it", + ) + del instance + + +_release_watcher = _ReleaseWatcher() + +# Identifiants d'instances « poolées » (plugins Ephemeral) : chacune reçoit son +# propre espace de noms de modules. +_POOLED_INSTANCE_IDS = itertools.count(1) + class LoadError(Exception): """Erreur fatale lors du chargement d'un plugin Trusted.""" @@ -41,14 +128,32 @@ class LifecycleManager: PROTECTED_SERVICES = {"db", "cache", "scheduler", "events", "hooks", "database"} + # Délai accordé aux tâches annulées au unload pour exécuter leurs `finally` + # avant que le module du plugin soit retiré de sys.modules. + _TASK_CANCEL_TIMEOUT_S = 2.0 + def __init__( self, manifest, # PluginManifest ctx: "KernelContext", caller=None, + *, + pooled: bool = False, ) -> None: + """ + `pooled=True` : instance jetable d'un plugin Ephemeral (plusieurs + instances du même manifest coexistent). Elle reçoit son propre espace de + noms `sys.modules` et ne désinscrit pas le plugin du registre à son + unload — sinon décharger UNE instance cassait les imports paresseux des + instances sœurs encore actives et retirait du registre un plugin pourtant + toujours actif. + """ self._ctx = ctx self.manifest = manifest + self._module_name = f"xcore_plugin_{manifest.name}" + if pooled: + self._module_name += f"__i{next(_POOLED_INSTANCE_IDS)}" + self._manages_registry = not pooled self._services = ctx.services.as_dict() if ctx.services else {} self._events = ctx.events self._hooks = ctx.hooks @@ -72,6 +177,20 @@ def __init__( self._resource_tracker: PluginResourceTracker | None = None self._spawned_tasks: list[asyncio.Task] = [] + # Services injectés par le noyau dans ctx.services (après wrapping + # tenant/ramasse-miette), au moment du load : nom → objet exact reçu. + # Sert à distinguer, dans propagate_services(), ce que le plugin a + # *exporté* de ce qu'il a simplement reçu en injection — ces derniers + # ne doivent jamais être réécrits dans le container partagé. + self._injected_services: dict[str, Any] = {} + # Services que CE plugin a écrits dans le container partagé (nom → objet), + # retirés au unload pour ne pas laisser un plugin mort appelable. + self._exported_to_container: dict[str, Any] = {} + + # Gel du event loop par du code synchrone du plugin (voir watch_blocking) + self._max_block_ms: float = 0.0 + self._last_block_log: float = float("-inf") + self._sm = StateMachine( manifest.name, on_change=self._on_state_change, @@ -133,6 +252,7 @@ async def load(self) -> None: logger.exception( "plugin load failed", plugin=self.manifest.name, error=str(e) ) + await self._cleanup_after_failure() raise LoadError(f"[{self.manifest.name}] Loading failed: {e}") from e async def _do_load(self) -> None: @@ -140,7 +260,7 @@ async def _do_load(self) -> None: if not entry.exists(): raise LoadError(f"Not found entry point: {entry}") - module_name = f"xcore_plugin_{self.manifest.name}" + module_name = self._module_name package_name = module_name # Crée un package namespace virtuel pour isoler le plugin @@ -206,6 +326,7 @@ async def _do_load(self) -> None: ) self._resource_tracker = tracker ctx._task_sink = self._spawned_tasks + self._injected_services = dict(ctx.services) if hasattr(self._instance, "_inject_context"): await self._instance._inject_context(ctx) @@ -273,6 +394,28 @@ def _import_module(name: str, path: Path) -> Any: # ── Appel ───────────────────────────────────────────────── + def _loop_block_warn_ms(self) -> float: + value = getattr(self._ctx.config, "loop_block_warn_ms", None) + if isinstance(value, bool) or not isinstance(value, (int, float)): + return _DEFAULT_LOOP_BLOCK_WARN_MS + return value + + def _on_loop_block(self, action: str, seconds: float) -> None: + """Un pas synchrone du plugin vient de geler le event loop `seconds`.""" + self._max_block_ms = max(self._max_block_ms, seconds * 1000) + now = time.monotonic() + if now - self._last_block_log < _LOOP_BLOCK_LOG_INTERVAL_S: + return + self._last_block_log = now + logger.warning( + "plugin blocked the event loop", + plugin=self.manifest.name, + action=action, + blocked_ms=round(seconds * 1000), + hint="synchronous CPU/IO between two awaits; use await, " + "asyncio.to_thread, or execution_mode: sandboxed", + ) + async def call(self, action: str, payload: dict) -> dict: if self._instance is None: raise RuntimeError(f"[{self.manifest.name}] not loaded") @@ -285,7 +428,11 @@ async def call(self, action: str, payload: dict) -> dict: timeout = self.manifest.resources.timeout_seconds try: result = await asyncio.wait_for( - self._instance.handle(action, payload), + watch_blocking( + self._instance.handle(action, payload), + self._loop_block_warn_ms(), + lambda seconds: self._on_loop_block(action, seconds), + ), timeout=timeout if timeout > 0 else None, ) except asyncio.TimeoutError: @@ -316,6 +463,10 @@ async def reload(self) -> None: logger.info("plugin reloaded", plugin=self.manifest.name) except Exception as e: self._sm.transition("error") + logger.error( + "plugin reload failed", plugin=self.manifest.name, error=str(e) + ) + await self._cleanup_after_failure() raise LoadError(f"[{self.manifest.name}] failed reload : {e}") from e # ── Unload ──────────────────────────────────────────────── @@ -330,8 +481,49 @@ async def unload(self) -> None: self._sm.transition("error") raise - async def _do_unload(self) -> None: - if self._instance: + async def _cleanup_after_failure(self) -> None: + """ + Ramasse-miette forcé après un load()/reload() raté, sans rappeler les + hooks du plugin (son état interne est incohérent). Sans ça, ce qu'il a + déjà enregistré (jobs, abonnements, tâches, module dans sys.modules) + restait en place alors que le plugin passe en FAILED. + """ + try: + await self._do_unload(run_hooks=False) + except Exception as e: # pragma: no cover — best-effort + logger.error( + "forced cleanup after failure failed", + plugin=self.manifest.name, + error=str(e), + ) + + async def _cancel_spawned_tasks(self) -> None: + """ + Annule les tâches créées via ctx.spawn_task() et ATTEND qu'elles se + terminent (délai borné) : un simple cancel() ne fait que programmer + l'annulation, leurs `finally` s'exécutaient donc après que le module du + plugin ait été retiré de sys.modules. + """ + current = asyncio.current_task() # un unload peut venir d'une de ces tâches + pending = [t for t in self._spawned_tasks if t is not current and not t.done()] + self._spawned_tasks = [] + for task in pending: + task.cancel() + if not pending: + return + _, still_running = await asyncio.wait( + pending, timeout=self._TASK_CANCEL_TIMEOUT_S + ) + if still_running: + logger.warning( + "spawned tasks ignored cancellation", + plugin=self.manifest.name, + tasks=sorted(t.get_name() for t in still_running), + timeout_s=self._TASK_CANCEL_TIMEOUT_S, + ) + + async def _do_unload(self, *, run_hooks: bool = True) -> None: + if self._instance and run_hooks: # Best-effort : on essaie les hooks du plugin, mais une erreur ici # ne doit pas empêcher le ramasse-miette forcé ci-dessous — c'est # justement le filet de sécurité pour un on_unload/on_stop bâclé. @@ -350,15 +542,28 @@ async def _do_unload(self) -> None: self._resource_tracker.cleanup() self._resource_tracker = None - for task in self._spawned_tasks: - if not task.done(): - task.cancel() - self._spawned_tasks = [] + await self._cancel_spawned_tasks() - if self._registry is not None: + if self._registry is not None and self._manages_registry: self._registry.unregister(self.manifest.name) - module_name = f"xcore_plugin_{self.manifest.name}" + # `unregister()` ne nettoie que le registre : les services que le plugin + # a exportés restaient aussi dans le dict partagé du ServiceContainer, + # donc appelables par les autres plugins (et le plugin déchargé épinglé + # en mémoire). On ne retire que ce que CE plugin y a mis, tel quel. + for name, obj in self._exported_to_container.items(): + if self._services.get(name) is obj: + self._services.pop(name, None) + self._exported_to_container = {} + self._injected_services = {} + + # Router HTTP / middlewares du plugin : sans ça, un handler déchargé + # gardait l'ancien router (et via ses closures l'ancien module), et un + # reload dont le nouveau code n'en expose plus gardait l'ancien actif. + self.plugin_router = None + self.plugin_middlewares = {} + + module_name = self._module_name # Nettoie le module principal et le package namespace sys.modules.pop(f"{module_name}.main", None) sys.modules.pop(module_name, None) @@ -366,8 +571,19 @@ async def _do_unload(self) -> None: for mod_name in list(sys.modules.keys()): if mod_name.startswith(f"{module_name}."): sys.modules.pop(mod_name, None) - self._instance = None + instance, self._instance = self._instance, None self._module = None + if instance is not None and self._should_watch_release(): + _release_watcher.watch(instance, self.manifest.name, _GC_DELAY_S) + del instance + + def _should_watch_release(self) -> bool: + # Les instances poolées (Ephemeral) sont jetées à chaque appel : le GC + # automatique les gère (jeunes cycles) et une collecte complète par appel + # coûterait bien plus qu'elle ne rapporte. + if not self._manages_registry: + return False + return getattr(self._ctx.config, "gc_after_unload", True) is not False # ── Router HTTP custom ──────────────────────────────────── @@ -409,7 +625,7 @@ def _collect_middlewares(self) -> None: try: middlewares = add_middlewares() if middlewares is not None: - self.plugin_middlewares.update(middlewares) + self.plugin_middlewares = dict(middlewares) logger.info( "middlewares collected", plugin=self.manifest.name, @@ -422,6 +638,17 @@ def _collect_middlewares(self) -> None: # ── Propagation des services (fix #3 v1) ────────────────── + def _is_injected(self, name: str, obj: Any) -> bool: + """Vrai si `obj` est exactement l'objet injecté par le noyau sous `name`.""" + return name in self._injected_services and self._injected_services[name] is obj + + @staticmethod + def _unwrap_proxy(obj: Any) -> Any: + """Retire tous les niveaux de proxy de ramasse-miette autour d'un service.""" + while isinstance(obj, _ScopedScheduler): + obj = obj._real + return obj + def propagate_services(self, *, is_reload: bool = False) -> dict: """ Propage les services enregistrés par le plugin vers le container partagé. @@ -453,6 +680,11 @@ def propagate_services(self, *, is_reload: bool = False) -> dict: # la source de vérité et assure la protection des services noyau. if self._registry: for name, obj in instance_services.items(): + # Service reçu en injection (db, cache, scheduler…), pas exporté + # par ce plugin : ni à enregistrer ni à réécrire dans le + # container partagé. + if self._is_injected(name, obj): + continue svc_meta = manifest_services_config.get(name, {}) scope = svc_meta.get("scope", "public") @@ -482,10 +714,10 @@ def propagate_services(self, *, is_reload: bool = False) -> dict: # différent, c'est une vraie tentative malveillante : on # relève l'erreur telle quelle. `obj` peut être un proxy de # ramasse-miette (_ScopedScheduler, etc.) posé par ce même - # LifecycleManager autour du service réel — on déballe un - # niveau (`_real`) avant de comparer, sinon l'identité ne - # matcherait jamais pour un service ainsi enveloppé. - underlying = getattr(obj, "_real", obj) + # LifecycleManager autour du service réel — on déballe tous + # les niveaux de proxy avant de comparer, sinon l'identité + # ne matcherait jamais pour un service ainsi enveloppé. + underlying = self._unwrap_proxy(obj) if self._registry.is_registered_as( name, obj ) or self._registry.is_registered_as(name, underlying): @@ -500,7 +732,11 @@ def propagate_services(self, *, is_reload: bool = False) -> dict: # Fallback de sécurité si le registre est absent (pour les tests ou configs minimales) # On définit une liste minimale de services à protéger protected = {"db", "cache", "scheduler", "events", "hooks", "database"} - if collisions := set(instance_services.keys()) & protected: + if collisions := { + k + for k, v in instance_services.items() + if k in protected and not self._is_injected(k, v) + }: raise PermissionError( f"[{self.manifest.name}] Tentative d'écrasement de services " f"noyau sans registre : {collisions}" @@ -517,18 +753,28 @@ def propagate_services(self, *, is_reload: bool = False) -> dict: }, ) - # Mise à jour du container local (rétro-compatibilité et accès rapide) + # Mise à jour du container local (rétro-compatibilité et accès rapide). + # `self._services` EST le dict partagé du ServiceContainer : on n'y + # écrit que ce que le plugin a exporté, jamais les services du noyau + # reçus en injection — sinon un reload y laissait le proxy de + # ramasse-miette du plugin à la place du vrai service (et chaque reload + # empilait un proxy de plus, cassant le reload/load suivant de + # n'importe quel plugin). + exported = { + k: v for k, v in instance_services.items() if not self._is_injected(k, v) + } + self._exported_to_container.update(exported) if is_reload: - self._services.update(instance_services) + self._services.update(exported) logger.info( "services updated on reload", plugin=self.manifest.name, - services=sorted(instance_services.keys()), + services=sorted(exported.keys()), ) else: - new_keys = set(instance_services.keys()) - set(self._services.keys()) + new_keys = set(exported.keys()) - set(self._services.keys()) for k in new_keys: - self._services[k] = instance_services[k] + self._services[k] = exported[k] if new_keys: logger.info( "services registered", @@ -547,4 +793,5 @@ def status(self) -> dict: "state": self._sm.state.value, "loaded": self._instance is not None, "uptime": round(self.uptime, 1) if self.uptime else None, + "max_loop_block_ms": round(self._max_block_ms), } diff --git a/xcore/kernel/runtime/plugin_gc.py b/xcore/kernel/runtime/plugin_gc.py index 7df83234..726bd3b3 100644 --- a/xcore/kernel/runtime/plugin_gc.py +++ b/xcore/kernel/runtime/plugin_gc.py @@ -33,12 +33,26 @@ class _ScopedScheduler: - """Proxy autour de SchedulerService : mémorise les job_id créés par CE plugin.""" + """ + Proxy autour de SchedulerService : mémorise les job_id créés par CE plugin. - def __init__(self, real: Any) -> None: + Les job_id sont préfixés par le nom du plugin (`:`) : le + registre de jobs du scheduler est global, donc deux plugins avec un job + `cleanup` s'écrasaient mutuellement — et le unload de l'un supprimait le + job de l'autre. Le plugin continue de manipuler ses ids non préfixés + (remove_job/pause_job/resume_job traduisent). + """ + + def __init__(self, real: Any, plugin_name: str | None = None) -> None: self._real = real + self._prefix = f"{plugin_name}:" if plugin_name else "" self._job_ids: set[str] = set() + def _scoped_id(self, job_id: str) -> str: + if not self._prefix or job_id.startswith(self._prefix): + return job_id + return f"{self._prefix}{job_id}" + def add_job( self, func: Callable, @@ -46,24 +60,36 @@ def add_job( job_id: str | None = None, **kwargs: Any, ) -> Any: - effective_id = job_id or getattr(func, "__name__", repr(func)) + effective_id = self._scoped_id(job_id or getattr(func, "__name__", repr(func))) self._job_ids.add(effective_id) - return self._real.add_job(func, trigger=trigger, job_id=job_id, **kwargs) + return self._real.add_job(func, trigger=trigger, job_id=effective_id, **kwargs) def cron(self, expression: str, job_id: str | None = None) -> Callable: def decorator(fn: Callable) -> Callable: - self._job_ids.add(job_id or fn.__name__) - return self._real.cron(expression, job_id=job_id)(fn) + effective_id = self._scoped_id(job_id or fn.__name__) + self._job_ids.add(effective_id) + return self._real.cron(expression, job_id=effective_id)(fn) return decorator def interval(self, **kwargs: Any) -> Callable: def decorator(fn: Callable) -> Callable: - self._job_ids.add(fn.__name__) - return self._real.interval(**kwargs)(fn) + self.add_job(fn, "interval", **kwargs) + return fn return decorator + def remove_job(self, job_id: str) -> None: + scoped = self._scoped_id(job_id) + self._job_ids.discard(scoped) + self._real.remove_job(scoped) + + def pause_job(self, job_id: str) -> None: + self._real.pause_job(self._scoped_id(job_id)) + + def resume_job(self, job_id: str) -> None: + self._real.resume_job(self._scoped_id(job_id)) + def cleanup(self, plugin_name: str) -> None: for job_id in self._job_ids: with contextlib.suppress(Exception): @@ -223,7 +249,7 @@ def __init__(self, plugin_name: str) -> None: def wrap_scheduler(self, real: Any) -> Any: if real is None: return real - proxy = _ScopedScheduler(real) + proxy = _ScopedScheduler(real, self._plugin_name) self._scoped.append(proxy) return proxy diff --git a/xcore/kernel/runtime/state_machine.py b/xcore/kernel/runtime/state_machine.py index f0a39d59..e6719788 100644 --- a/xcore/kernel/runtime/state_machine.py +++ b/xcore/kernel/runtime/state_machine.py @@ -8,6 +8,8 @@ READY ──reload► RELOADING──► READY * ──error──► FAILED FAILED ──reset──► UNLOADED + FAILED ──unload► UNLOADING──► UNLOADED (nettoyage forcé d'un plugin planté) + FAILED ──reload► RELOADING──► READY (nouvel essai) """ from __future__ import annotations @@ -36,7 +38,14 @@ class PluginState(str, Enum): }, PluginState.UNLOADING: {"ok": PluginState.UNLOADED, "error": PluginState.FAILED}, PluginState.RELOADING: {"ok": PluginState.READY, "error": PluginState.FAILED}, - PluginState.FAILED: {"reset": PluginState.UNLOADED}, + # FAILED doit rester récupérable : sans "unload", un plugin planté en plein + # reload ne pouvait plus jamais être déchargé (donc nettoyé) ni rechargé — + # "reset" n'est appelé par aucun code du noyau. + PluginState.FAILED: { + "reset": PluginState.UNLOADED, + "unload": PluginState.UNLOADING, + "reload": PluginState.RELOADING, + }, } diff --git a/xcore/kernel/runtime/supervisor.py b/xcore/kernel/runtime/supervisor.py index c76051af..29794005 100644 --- a/xcore/kernel/runtime/supervisor.py +++ b/xcore/kernel/runtime/supervisor.py @@ -148,6 +148,13 @@ async def boot(self) -> None: # ── 5. Enregistrement services noyau (inchangé) ───────── if self._registry: for name, svc in self._services.as_dict().items(): + # Les plugins viennent de propager leurs services exportés dans + # ce même dict : ils restent la propriété du plugin. Les marquer + # « kernel » (protégés) empêchait ensuite le reload du plugin qui + # les exporte (« Impossible d'écraser le service protégé »). + owner = self._registry.service_owner(name) + if owner not in (None, "kernel"): + continue try: self._registry.register_core_service(name, svc) except Exception as e: diff --git a/xcore/kernel/runtime/warm_pool.py b/xcore/kernel/runtime/warm_pool.py index 7af1cdd8..aac98521 100644 --- a/xcore/kernel/runtime/warm_pool.py +++ b/xcore/kernel/runtime/warm_pool.py @@ -259,6 +259,7 @@ async def _cold_boot(self) -> "LifecycleManager": manifest=self._manifest, ctx=self._ctx, caller=self._caller, + pooled=True, ) try: await asyncio.wait_for(lm.load(), timeout=self._boot_timeout) diff --git a/xcore/kernel/sandbox/isolation.py b/xcore/kernel/sandbox/isolation.py index d6ab968f..a9a519e6 100644 --- a/xcore/kernel/sandbox/isolation.py +++ b/xcore/kernel/sandbox/isolation.py @@ -10,6 +10,11 @@ logger = get_logger("xcore.sandbox.isolation") +# Code de sortie d'un worker qui se recycle de lui-même parce que son plafond de +# CPU cumulé est presque atteint (EX_TEMPFAIL) — ce n'est pas un plantage : le +# SandboxProcessManager le relance sans le compter dans `max_restarts`. +RECYCLE_EXIT_CODE = 75 + class DiskQuotaExceeded(Exception): pass diff --git a/xcore/kernel/sandbox/process_manager.py b/xcore/kernel/sandbox/process_manager.py index a06ba9c4..2b0c53b0 100644 --- a/xcore/kernel/sandbox/process_manager.py +++ b/xcore/kernel/sandbox/process_manager.py @@ -7,6 +7,7 @@ import asyncio import contextlib +import re import sys import time from dataclasses import dataclass @@ -20,10 +21,24 @@ from ..runtime.loader import PluginLoader from .ipc import IPCChannel, IPCProcessDead, IPCTimeoutError -from .isolation import DiskQuotaExceeded, DiskWatcher +from .isolation import RECYCLE_EXIT_CODE, DiskQuotaExceeded, DiskWatcher logger = get_logger("xcore.sandbox.process_manager") +# Le worker sandbox formate ses lignes stderr via _TextFormatter (même +# formateur que le process principal, xcore/kernel/observability/logging.py), +# qui aligne le levelname sur 8 caractères -> espaces possibles avant le "]" +# (ex: "[INFO ]"). On s'en sert pour relayer chaque ligne au bon niveau +# plutôt que de tout logger en warning. +_STDERR_LEVEL_RE = re.compile(r"\[(DEBUG|INFO|WARNING|ERROR|CRITICAL)\s*\]") +_STDERR_LEVEL_METHODS = { + "DEBUG": "debug", + "INFO": "info", + "WARNING": "warning", + "ERROR": "error", + "CRITICAL": "critical", +} + class ProcessState(Enum): STOPPED = "stopped" @@ -39,6 +54,16 @@ class SandboxConfig: max_restarts: int = 3 restart_delay: float = 1.0 startup_timeout: float = 5.0 + # Budget CPU du worker PAR REQUÊTE (secondes) — 0 = illimité. + max_cpu_seconds: int = 10 + # Plafond de CPU cumulé de la vie d'un worker (secondes), filet noyau + # infranchissable pour le plugin. Avant de l'atteindre le worker se recycle + # tout seul (RECYCLE_EXIT_CODE) — relance qui ne compte pas comme un plantage. + max_cpu_lifetime_seconds: int = 3600 + # Si le subprocess a tourné au moins aussi longtemps avant de planter, la + # séquence de redémarrages repart de zéro : sans ça, un plugin qui plante une + # fois par semaine finissait FAILED au 3e plantage en 3 semaines. + restart_reset_after: float = 60.0 class SandboxProcessManager: @@ -54,6 +79,7 @@ def __init__( manifest, ctx: "PluginLoader", config: SandboxConfig | None = None, + log_level: str = "WARNING", ) -> None: self.manifest = manifest self.config = config or SandboxConfig() @@ -64,6 +90,8 @@ def __init__( self._started_at: float | None = None self._watch_task: asyncio.Task | None = None self._health_task: asyncio.Task | None = None + self._stderr_task: asyncio.Task | None = None + self._log_level = log_level data_dir = manifest.plugin_dir / "data" self._ctx = ctx @@ -95,6 +123,9 @@ async def start(self) -> None: self._watch_task = asyncio.create_task( self._watch_loop(), name=f"watch-{self.manifest.name}" ) + self._stderr_task = asyncio.create_task( + self._stderr_pump(), name=f"stderr-{self.manifest.name}" + ) hc = self.manifest.runtime.health_check if hc.enabled: self._health_task = asyncio.create_task( @@ -134,7 +165,9 @@ async def _spawn(self) -> None: "PYTHONDONTWRITEBYTECODE": "1", "PYTHONUNBUFFERED": "1", "_SANDBOX_MAX_MEM_MB": str(self.manifest.resources.max_memory_mb), - "_SANDBOX_MAX_CPU_SEC": "10", + "_SANDBOX_MAX_CPU_SEC": str(self.config.max_cpu_seconds), + "_SANDBOX_MAX_CPU_LIFETIME_SEC": str(self.config.max_cpu_lifetime_seconds), + "LOG_LEVEL": self._log_level, } env |= self.manifest.env @@ -193,20 +226,70 @@ async def _watch_loop(self) -> None: code = await self._process.wait() if self._state == ProcessState.STOPPED: return - logger.warning("subprocess exited", plugin=self.manifest.name, exit_code=code) - if self._process.stderr: - with contextlib.suppress(Exception): - err = await asyncio.wait_for( - self._process.stderr.read(2048), timeout=1.0 - ) - if err: - logger.error( - "subprocess stderr output", - plugin=self.manifest.name, - stderr=err.decode("utf-8", "replace").strip(), - ) + if code == RECYCLE_EXIT_CODE: + # Le worker a atteint son plafond de CPU cumulé et s'est arrêté de + # lui-même entre deux requêtes : relance normale, pas un plantage. + logger.info("subprocess recycled", plugin=self.manifest.name) + self._restarts = 0 + else: + logger.warning( + "subprocess exited", plugin=self.manifest.name, exit_code=code + ) await self._handle_crash() + async def _stderr_pump(self) -> None: + """ + Draine stderr du subprocess en continu pendant toute sa durée de vie. + Sans ça, les logs WARNING+ du plugin (niveau lu depuis le pipe) restaient + bloqués dans le buffer OS et ne remontaient qu'au crash, en tronqué. + """ + if not self._process or not self._process.stderr: + return + stream = self._process.stderr + while True: + try: + line = await stream.readline() + except ValueError as e: + # Ligne plus longue que la limite du StreamReader (défaut 64 KiB) : + # readline() nettoie déjà le buffer interne avant de relever cette + # ValueError — sans ce catch dédié, le blanket suppress() d'avant + # tuait la tâche entière pour le reste de la vie du process. + logger.warning( + "subprocess stderr line too long, skipped", + plugin=self.manifest.name, + error=str(e), + ) + continue + except Exception as e: + logger.error( + "subprocess stderr pump stopped unexpectedly", + plugin=self.manifest.name, + error=str(e), + ) + return + if not line: + return + try: + text = line.decode("utf-8", "replace").rstrip() + if not text: + continue + # Ligne sans bracket [LEVEL] reconnu (traceback brut, print, ou + # "FATAL: ..." émis directement sur stderr par worker.py) : par + # défaut en error, comme le faisait l'ancien lecteur au crash — + # une ligne non structurée est plus probablement un problème + # qu'un warning bénin. + match = _STDERR_LEVEL_RE.search(text) + method_name = _STDERR_LEVEL_METHODS.get( + match.group(1) if match else "", "error" + ) + getattr(logger, method_name)( + "subprocess stderr", plugin=self.manifest.name, line=text + ) + except Exception: + # Un échec du côté décodage/log (jamais vu en pratique) ne doit + # pas arrêter le drainage des lignes suivantes. + continue + async def _health_loop(self, interval: float, timeout: float) -> None: await asyncio.sleep(interval) while self._state == ProcessState.RUNNING: @@ -237,6 +320,11 @@ async def _handle_crash(self) -> None: ): return # anti-réentrance + if ( + self._started_at is not None + and time.monotonic() - self._started_at >= self.config.restart_reset_after + ): + self._restarts = 0 self._state = ProcessState.RESTARTING while self._restarts < self.config.max_restarts: @@ -251,12 +339,12 @@ async def _handle_crash(self) -> None: ) await asyncio.sleep(delay) - for task in (self._watch_task, self._health_task): + for task in (self._watch_task, self._health_task, self._stderr_task): if task and not task.done(): task.cancel() with contextlib.suppress(asyncio.CancelledError): await task - self._watch_task = self._health_task = None + self._watch_task = self._health_task = self._stderr_task = None await self._kill() try: @@ -271,6 +359,9 @@ async def _handle_crash(self) -> None: self._watch_task = asyncio.create_task( self._watch_loop(), name=f"watch-{self.manifest.name}" ) + self._stderr_task = asyncio.create_task( + self._stderr_pump(), name=f"stderr-{self.manifest.name}" + ) hc = self.manifest.runtime.health_check if hc.enabled: self._health_task = asyncio.create_task( @@ -293,7 +384,7 @@ async def _handle_crash(self) -> None: async def stop(self) -> None: self._state = ProcessState.STOPPED - for task in (self._watch_task, self._health_task): + for task in (self._watch_task, self._health_task, self._stderr_task): if task and not task.done(): task.cancel() if self._channel: diff --git a/xcore/kernel/sandbox/worker.py b/xcore/kernel/sandbox/worker.py index 81c70c3c..23e443b2 100644 --- a/xcore/kernel/sandbox/worker.py +++ b/xcore/kernel/sandbox/worker.py @@ -23,15 +23,24 @@ from pathlib import Path from xcore.kernel.observability import get_logger +from xcore.kernel.observability.logging import _TextFormatter +from xcore.kernel.sandbox.isolation import RECYCLE_EXIT_CODE # ContextVar par tâche asyncio — évite les race conditions entre coroutines # qui partageraient le même FilesystemGuard (requis pour la sécurité sandbox). _sandbox_in_guard: ContextVar[bool] = ContextVar("sandbox_in_guard", default=False) +# _TextFormatter (le même que le process principal, xcore/kernel/observability/ +# logging.py) et non un simple format="..." : un basicConfig(format=...) plein +# texte ignore les champs structurés passés en kwargs (logger.info(msg, plugin=...)) +# — ils sont attachés via extra={"xcore_ctx": ...} et seuls _TextFormatter/ +# _JsonFormatter savent les rendre. Sans ça, ces champs étaient silencieusement +# perdus même une fois le niveau et le drainage stderr corrigés côté kernel. +_worker_handler = logging.StreamHandler(sys.stderr) +_worker_handler.setFormatter(_TextFormatter()) logging.basicConfig( level=os.environ.get("LOG_LEVEL", "WARNING"), - format="%(asctime)s [%(levelname)s] worker: %(message)s", - stream=sys.stderr, + handlers=[_worker_handler], ) logger = get_logger("xcore.worker") @@ -56,19 +65,89 @@ def _apply_resource_limits() -> None: logger.debug("memory limit applied", max_mb=max_mb, resource="DATA+RSS") # ── CPU ─────────────────────────────────────────────────────────── + # RLIMIT_CPU compte le temps CPU CUMULÉ du processus depuis son + # démarrage : posée une fois à 10 s, elle tuait (SIGXCPU — action par + # défaut : terminer) tout worker sain après 10 s de CPU au total sur sa + # vie, soit quelques minutes de requêtes ordinaires, puis le plugin + # finissait FAILED après `max_restarts`. Deux niveaux à la place : + # - limite SOUPLE = budget PAR REQUÊTE, réarmée avant chaque appel à + # « CPU déjà consommé + budget » (_arm_cpu_budget) ; + # - limite DURE = plafond de CPU cumulé de la vie du worker (+ grace). + # Une limite dure ne peut jamais être relevée sans privilège, donc + # elle reste un filet côté noyau qu'un plugin ne peut pas contourner. + # Avant de l'atteindre le worker se recycle proprement + # (_needs_recycle → RECYCLE_EXIT_CODE) au lieu d'être tué. + global _cpu_budget_s, _cpu_lifetime_s max_cpu_s = int(os.environ.get("_SANDBOX_MAX_CPU_SEC", "0")) if max_cpu_s > 0: - # soft = envoi SIGXCPU quand la limite est atteinte (attrapable) - # hard = SIGKILL irrécupérable, fixé légèrement au-dessus - soft = max_cpu_s - hard = max_cpu_s + 5 # 5s de grâce pour un éventuel cleanup - resource.setrlimit(resource.RLIMIT_CPU, (soft, hard)) - logger.debug("cpu limit applied", soft_s=soft, hard_s=hard) + _cpu_budget_s = max_cpu_s + _cpu_lifetime_s = int(os.environ.get("_SANDBOX_MAX_CPU_LIFETIME_SEC", "0")) + hard = _cpu_lifetime_s + 5 if _cpu_lifetime_s > 0 else None + _arm_cpu_budget(hard) + logger.debug( + "cpu limits applied", + per_request_s=_cpu_budget_s, + lifetime_s=_cpu_lifetime_s, + ) except Exception as e: logger.warning("failed to apply resource limits", error=str(e)) +# Budget CPU par requête et plafond cumulé du worker (secondes), 0 = illimité — +# voir _apply_resource_limits. +_cpu_budget_s: int = 0 +_cpu_lifetime_s: int = 0 + +# Importé ici, AVANT l'installation des gardes d'import : `resource` est interdit +# au code du plugin, mais le worker en a besoin à chaque requête. +try: + import resource as _resource +except ImportError: # Windows + _resource = None + + +def _cpu_consumed() -> float: + usage = _resource.getrusage(_resource.RUSAGE_SELF) + return usage.ru_utime + usage.ru_stime + + +def _arm_cpu_budget(hard: int | None = None) -> None: + """ + Réarme la limite SOUPLE de RLIMIT_CPU à « CPU déjà consommé + budget ». + + `hard` n'est passé qu'au premier appel (il fixe la limite dure, irréversible) ; + ensuite on garde celle déjà en place. Au dépassement de la limite souple le + noyau envoie SIGXCPU ; sans handler (`signal` est interdit au plugin) c'est la + fin du processus, que SandboxProcessManager détecte et relance. + """ + if not _cpu_budget_s or _resource is None: + return + try: + soft = int(_cpu_consumed()) + _cpu_budget_s + 1 # +1 : granularité 1 s + if hard is None: + _, hard = _resource.getrlimit(_resource.RLIMIT_CPU) + if hard != _resource.RLIM_INFINITY: + soft = min(soft, hard) + _resource.setrlimit(_resource.RLIMIT_CPU, (soft, hard)) + except Exception as e: + logger.debug("cannot re-arm cpu budget", error=str(e)) + + +def _needs_recycle() -> bool: + """ + Vrai quand la prochaine requête ne pourrait plus avoir son budget complet + sous le plafond cumulé : mieux vaut se recycler (proprement, entre deux + requêtes) que d'être tué en plein milieu de la suivante. + """ + if not _cpu_lifetime_s or not _cpu_budget_s or _resource is None: + return False + try: + return _cpu_consumed() + _cpu_budget_s + 1 >= _cpu_lifetime_s + except Exception: + return False + + builtins_open = _builtins_module.open @@ -292,10 +371,15 @@ def wrapper(*args, **kwargs): if sig is not None: try: - bound = sig.bind_partial(*args, **kwargs).arguments + bound = sig.bind_partial(*args, **kwargs) + # apply_defaults() : sans ça, un appel qui compte sur + # une valeur par défaut (ex: os.listdir() -> cwd) a un + # bound.arguments vide et passait le guard sans aucune + # vérification. + bound.apply_defaults() paths = [ v - for k, v in bound.items() + for k, v in bound.arguments.items() if k in pnames and isinstance(v, (str, os.PathLike)) ] except Exception: @@ -345,6 +429,8 @@ def __init__(self, file, *args, **kwargs): "stat", "lstat", "chmod", + "symlink", + "link", ]: if hasattr(os, op): setattr(os, op, _guarded_op(getattr(os, op), f"os.{op}")) @@ -363,6 +449,8 @@ def __init__(self, file, *args, **kwargs): "exists", "is_file", "is_dir", + "symlink_to", + "hardlink_to", ]: if hasattr(_Path, op): setattr(_Path, op, _guarded_op(getattr(_Path, op), f"Path.{op}")) @@ -703,7 +791,7 @@ def _load_manifest(plugin_dir: Path) -> _PluginManifest: if not manifest_path.exists(): continue try: - return _extracted_from__load_manifest_20(fname, manifest_path, manifest) + return _parse_manifest_file(fname, manifest_path, manifest) except Exception as e: logger.warning("cannot read manifest file", file=fname, error=str(e)) @@ -711,7 +799,7 @@ def _load_manifest(plugin_dir: Path) -> _PluginManifest: return manifest -def _extracted_from__load_manifest_20(fname, manifest_path, manifest: _PluginManifest): +def _parse_manifest_file(fname, manifest_path, manifest: _PluginManifest): if fname.endswith(".yaml"): import yaml @@ -775,7 +863,9 @@ def _trace_id_from_carrier(carrier: dict | None) -> str | None: # ───────────────────────────────────────────────────────────────────────────── -async def _run(plugin_dir: Path) -> None: +async def _run(plugin_dir: Path) -> bool: + """Boucle du worker. Retourne True si le worker demande à être recyclé.""" + recycle = False # 1. Lecture du manifeste manifest = _load_manifest(plugin_dir) @@ -821,6 +911,14 @@ def connection_lost(self, exc): line = await reader.readline() except (asyncio.IncompleteReadError, EOFError): break + except ValueError as e: + # Ligne IPC plus longue que la limite du StreamReader (défaut + # 64 KiB) : readline() nettoie déjà son buffer interne avant de + # relever cette ValueError. Sans ce catch, une seule requête trop + # grosse tuait tout le worker (et donc toutes les requêtes en + # cours/à venir pour ce plugin), pas seulement celle-là. + logger.warning("ipc line too long, skipped", error=str(e)) + continue if not line: break @@ -845,6 +943,7 @@ def connection_lost(self, exc): _send(transport, response) break else: + _arm_cpu_budget() result = await plugin.handle(action, payload) response = ( result @@ -871,6 +970,15 @@ def connection_lost(self, exc): _send(transport, response) + if _needs_recycle(): + logger.info( + "cpu ceiling nearly reached, recycling worker", + consumed_s=round(_cpu_consumed(), 1), + lifetime_s=_cpu_lifetime_s, + ) + recycle = True + break + if hasattr(plugin, "on_unload"): try: await plugin.on_unload() @@ -881,6 +989,7 @@ def connection_lost(self, exc): plugin._import_hook.uninstall() logger.info("sandbox worker stopped") + return recycle # ───────────────────────────────────────────────────────────────────────────── @@ -898,7 +1007,8 @@ def connection_lost(self, exc): sys.exit(1) try: - asyncio.run(_run(plugin_dir)) + if asyncio.run(_run(plugin_dir)): + sys.exit(RECYCLE_EXIT_CODE) except KeyboardInterrupt: pass except Exception as e: diff --git a/xcore/registry/index.py b/xcore/registry/index.py index d9ad112f..448b16bf 100644 --- a/xcore/registry/index.py +++ b/xcore/registry/index.py @@ -135,6 +135,17 @@ def list_services(self) -> list[dict]: for name, meta in self._exported_services.items() ] + def service_owner(self, service_name: str) -> str | None: + """Nom du propriétaire d'un service exporté ("kernel" ou un plugin), ou None.""" + existing = self._exported_services.get(service_name) + return None if existing is None else existing.get("plugin") + + def is_core_service(self, service_name: str) -> bool: + """Vrai si `service_name` est un service noyau (enregistré par le kernel + via register_core_service) et non un service exporté par un plugin.""" + existing = self._exported_services.get(service_name) + return existing is not None and existing.get("plugin") == "kernel" + def is_registered_as(self, service_name: str, obj: Any) -> bool: """Vrai si `service_name` est déjà exporté et pointe vers CE MÊME objet (identité, pas égalité) — utile pour distinguer une simple ré-injection diff --git a/xcore/services/scheduler/service.py b/xcore/services/scheduler/service.py index 94285f18..b05158ad 100644 --- a/xcore/services/scheduler/service.py +++ b/xcore/services/scheduler/service.py @@ -47,12 +47,14 @@ async def morning_sync(): from __future__ import annotations import inspect +import time from typing import TYPE_CHECKING, Any, Callable if TYPE_CHECKING: from ...configurations.sections import SchedulerConfig from ...kernel.observability import get_logger +from ...kernel.observability.blocking import watch_blocking from ..base import BaseService, ServiceStatus logger = get_logger("xcore.services.scheduler") @@ -71,6 +73,32 @@ async def morning_sync(): _LOCK_TTL = 300 +# Seuil (ms) au-delà duquel un job qui tourne entre deux `await` est signalé +# comme gelant le event loop — les jobs s'exécutent dans le loop de l'application. +_BLOCK_WARN_MS = 250 + + +def _warn_blocking(job_id: str, seconds: float) -> None: + logger.warning( + "scheduler job blocked the event loop", + job_id=job_id, + blocked_ms=round(seconds * 1000), + hint="a sync job runs on the event loop; make it async or use asyncio.to_thread", + ) + + +async def _run_job(fn: Callable, job_id: str) -> None: + started = time.perf_counter() + result = fn() # un job synchrone s'exécute ENTIÈREMENT ici, sur le loop + elapsed = time.perf_counter() - started + if elapsed * 1000 >= _BLOCK_WARN_MS: + _warn_blocking(job_id, elapsed) + if inspect.isawaitable(result): + await watch_blocking( + result, _BLOCK_WARN_MS, lambda seconds: _warn_blocking(job_id, seconds) + ) + + async def _dispatch_job(job_id: str) -> None: fn = _JOB_REGISTRY.get(job_id) if fn is None: @@ -90,15 +118,11 @@ async def _dispatch_job(job_id: str) -> None: ) return try: - result = fn() - if inspect.isawaitable(result): - await result + await _run_job(fn, job_id) finally: await _REDIS_LOCK_CLIENT.delete(lock_key) else: - result = fn() - if inspect.isawaitable(result): - await result + await _run_job(fn, job_id) class SchedulerService(BaseService):