Worker: an idle worker writes two log lines and a heartbeat file every two seconds, and its log pushes real errors out of the kept log in about a day #1117

New issue

Closed

opened 2026-10-31 03:04:08 +00:00 by tiagoagueda · 0 comments

tiagoagueda commented

2026-10-31 03:04:08 +00:00

Owner

What exists today

src/postulo/core/management/commands/work.py:60-86 builds a new upstream Worker in batch mode on every pass, runs it, writes the worker heartbeat (scheduler.worker_beat, core/scheduler.py:111, a mkstemp plus os.replace on the shared volume) and sleeps --every (default 2 s, line 39).

The installed django_tasks_db 0.13.0 (.venv/Lib/site-packages/django_tasks_db/management/commands/db_worker.py) logs at INFO on logger django_tasks_db: "Starting worker worker_id=… queues=…" at the top of run() (line 96) and "No more tasks to run for worker_id=… - exiting gracefully." when a batch finds the queue empty (line 139). So an idle worker emits two INFO lines per pass, one pass every 2 s plus the pass time: about 43,200 passes and 86,400 lines a day.

Upstream's own db_worker command sets that logger's level in configure_logging (line 307); work constructs Worker directly and never calls it, so the logger inherits the root level. LOGGING in src/postulo/config/settings/base.py:1004-1015 quietens fontTools, weasyprint, httpx and httpcore, not django_tasks_db; root is INFO with both the console and the shared JSON file handler (lines 1017-1019).

Measured: postulo.core.logs.JSONFormatter renders the two lines at 159 and 175 bytes (one call each under the test settings). That is about 337 bytes a pass, about 14.5 MB a day into data/logs/postulo.log. The file rotates at POSTULO_LOG_MAX_BYTES 5 MB with 3 backups (lines 945-946), 20 MB in all, and every process (web, scheduler, worker) shares it. An idle worker alone therefore rotates the kept log, including the web's errors shown on the staff log page, in about 1.4 days. The same lines go to docker logs for the worker container, unbounded (see D6).

Each pass also opens a fresh database connection (close_old_connections() with the default CONN_MAX_AGE 0, which closes after every loop, so each pass reconnects and reruns the init_command PRAGMAs of config/sqlite.py:53) and takes an EXCLUSIVE transaction on SQLite for the claim (django_tasks_db/utils.py exclusive_transaction). Both are short; they are part of the cost of the 2 s poll, not a separate finding.

Rebuilding the Worker object per pass costs nothing worth naming; the scout's "rebuilds upstream Worker every 2 s" is true but not where the cost is.

The worker healthcheck accepts a heartbeat up to 5 minutes old (docker/compose.yml:111, docker/compose.postgres.yml:112), and the staff overview shows its age (core/server_views.py:260).

What would change

Add "django_tasks_db": {"level": "WARNING"} to LOGGING["loggers"] beside httpx. Shutdown warnings (lines 66, 72) and "Task id=… failed unexpectedly" (logger.exception, line 197) still appear. Optionally log one INFO line of Postulo's own when the work command starts, so docker logs still shows that the worker came up.
In work.py, write the heartbeat only when the last one is more than 60 s old (keep a monotonic timestamp in the loop). The 5-minute healthcheck and the overview's "last pass" stay correct to within a minute.
Optional, separate decision: keep the 2 s poll while work was found recently and back off to, say, 10 s after a minute idle. That cuts the connection, PRAGMA and EXCLUSIVE-lock churn by five but delays the first errand after a quiet spell by up to 10 s, which the errand page (polling every 2 s) would show. Not recommended without the user.

No library needed; this is configuration and a few lines in the command.

What it saves or protects

large: about 86,400 log lines (about 14.5 MB of JSON) a day from an idle worker gone, so the 20 MB kept log holds weeks instead of about 1.4 days; 43,200 heartbeat file writes a day cut to about 1,440

Accessibility

none

Decided by the maintainer (2026-10-31)

quieten django_tasks_db to WARNING and write the heartbeat at most once a minute

Decisions

Quieten django_tasks_db to WARNING? Recommended: yes. The two lines say nothing an operator acts on; failures and stops are still logged.
Heartbeat at most once a minute? Recommended: yes; the healthcheck allows five.
Idle back-off of the poll? Recommended: no for now; the two changes above remove the log cost, and the poll's database cost is milliseconds.

Found by the efficiency and reliability audit of 2026-10-30 (finding B1; index postulo/postulo#1108). Checked against main at daee30b15 (2026-10-30).

## What exists today `src/postulo/core/management/commands/work.py:60-86` builds a new upstream `Worker` in batch mode on every pass, runs it, writes the worker heartbeat (`scheduler.worker_beat`, `core/scheduler.py:111`, a `mkstemp` plus `os.replace` on the shared volume) and sleeps `--every` (default 2 s, line 39). The installed `django_tasks_db` 0.13.0 (`.venv/Lib/site-packages/django_tasks_db/management/commands/db_worker.py`) logs at INFO on logger `django_tasks_db`: "Starting worker worker_id=… queues=…" at the top of `run()` (line 96) and "No more tasks to run for worker_id=… - exiting gracefully." when a batch finds the queue empty (line 139). So an idle worker emits two INFO lines per pass, one pass every 2 s plus the pass time: about 43,200 passes and 86,400 lines a day. Upstream's own `db_worker` command sets that logger's level in `configure_logging` (line 307); `work` constructs `Worker` directly and never calls it, so the logger inherits the root level. `LOGGING` in `src/postulo/config/settings/base.py:1004-1015` quietens `fontTools`, `weasyprint`, `httpx` and `httpcore`, not `django_tasks_db`; root is INFO with both the console and the shared JSON file handler (lines 1017-1019). Measured: `postulo.core.logs.JSONFormatter` renders the two lines at 159 and 175 bytes (one call each under the test settings). That is about 337 bytes a pass, about 14.5 MB a day into `data/logs/postulo.log`. The file rotates at `POSTULO_LOG_MAX_BYTES` 5 MB with 3 backups (lines 945-946), 20 MB in all, and every process (web, scheduler, worker) shares it. An idle worker alone therefore rotates the kept log, including the web's errors shown on the staff log page, in about 1.4 days. The same lines go to `docker logs` for the worker container, unbounded (see D6). Each pass also opens a fresh database connection (`close_old_connections()` with the default `CONN_MAX_AGE` 0, which closes after every loop, so each pass reconnects and reruns the `init_command` PRAGMAs of `config/sqlite.py:53`) and takes an `EXCLUSIVE` transaction on SQLite for the claim (`django_tasks_db/utils.py` `exclusive_transaction`). Both are short; they are part of the cost of the 2 s poll, not a separate finding. Rebuilding the `Worker` object per pass costs nothing worth naming; the scout's "rebuilds upstream `Worker` every 2 s" is true but not where the cost is. The worker healthcheck accepts a heartbeat up to 5 minutes old (`docker/compose.yml:111`, `docker/compose.postgres.yml:112`), and the staff overview shows its age (`core/server_views.py:260`). ## What would change 1. Add `"django_tasks_db": {"level": "WARNING"}` to `LOGGING["loggers"]` beside `httpx`. Shutdown warnings (lines 66, 72) and "Task id=… failed unexpectedly" (`logger.exception`, line 197) still appear. Optionally log one INFO line of Postulo's own when the `work` command starts, so `docker logs` still shows that the worker came up. 2. In `work.py`, write the heartbeat only when the last one is more than 60 s old (keep a monotonic timestamp in the loop). The 5-minute healthcheck and the overview's "last pass" stay correct to within a minute. 3. Optional, separate decision: keep the 2 s poll while work was found recently and back off to, say, 10 s after a minute idle. That cuts the connection, PRAGMA and EXCLUSIVE-lock churn by five but delays the first errand after a quiet spell by up to 10 s, which the errand page (polling every 2 s) would show. Not recommended without the user. No library needed; this is configuration and a few lines in the command. ## What it saves or protects large: about 86,400 log lines (about 14.5 MB of JSON) a day from an idle worker gone, so the 20 MB kept log holds weeks instead of about 1.4 days; 43,200 heartbeat file writes a day cut to about 1,440 ## Accessibility none ## Decided by the maintainer (2026-10-31) quieten django_tasks_db to WARNING and write the heartbeat at most once a minute ## Decisions - **Quieten `django_tasks_db` to WARNING?** Recommended: yes. The two lines say nothing an operator acts on; failures and stops are still logged. - **Heartbeat at most once a minute?** Recommended: yes; the healthcheck allows five. - **Idle back-off of the poll?** Recommended: no for now; the two changes above remove the log cost, and the poll's database cost is milliseconds. --- Found by the efficiency and reliability audit of 2026-10-30 (finding B1; index postulo/postulo#1108). Checked against `main` at `daee30b15` (2026-10-30).

tiagoagueda added this to the 0.6.0 milestone

2026-10-31 03:04:08 +00:00

tiagoagueda added the

performance

enhancement

labels

2026-10-31 03:04:08 +00:00

tiagoagueda referenced this issue

2026-10-31 03:04:40 +00:00

Efficiency and reliability audit of 2026-10-30: index #1108

tiagoagueda referenced this issue from a pull request that will close it,

2026-11-11 10:38:54 +00:00