diff --git a/CHANGELOG.md b/CHANGELOG.md index 82ffa2b..0c40da8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,28 +9,130 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed -- Recover claims that committed but whose reply was lost on MySQL, - PostgreSQL and SQLite. Previously, such a task stayed `RUNNING` until - the reaper requeued it with an attempt spent, or marked it `LOST` on - its final attempt even though its body never ran. Upgraded workers - now find their own unconfirmed claims and return them to `READY` - with the attempt refunded, within `LOCK_TIMEOUT` and before the - row's lease expires. `Worker.run_once()` and `testing.run_tasks()` - still raise the claim's original error; after a successful release, - the next call can claim and run the task normally. Recovery does not - cover claims made by workers that have not been upgraded, workers - that die before recovery, or database outages that outlast - `LOCK_TIMEOUT`. If the claim's commit becomes visible only after the - recovery look, it may escape recovery and be reaped normally, +- Recover claims that committed but whose reply was lost, only in + `Worker.run()` (the loop used by `ox_worker`), on PostgreSQL with + psycopg 3, pooled or not, MySQL and SQLite. In 1.6.0, such a task stayed + `RUNNING` until the reaper requeued it with an attempt spent, or marked + it `LOST` on its final attempt even though its body never ran. Upgraded + workers running this loop look for their own unconfirmed claims on + later poll passes, or once at stop, and return eligible rows to `READY` + with the attempt refunded, within `LOCK_TIMEOUT` and before the row's + lease expires. + + A pending recovery look runs at the head of a poll pass unless another + claim of the same Worker is in flight. In that case it makes no read; + if a claim begins before the look compares the claim generation, it + releases nothing. If a claim begins after that comparison, the look + still releases the orphans it read, but not that claim's row. Either way, + recovery stays pending, that pass claims as usual, and the next pass + looks again. Claims on a shared Worker remain concurrent, as in 1.6.0; + recovery bookkeeping uses a short lock never held across a database + call. A claim made through `run()`, `run_once()` or the base `claim_one()` + counts as in flight until its returned row is + registered, including subclass work after the base claim returns. + `ox_worker` is unaffected by shared-Worker deferrals: its Worker is not + shared, and its loop claims and checks recovery on one thread. + + A failed recovery read ends that pass with `worker_poll_failed` and + `claim_recovery` set to `"pending"`; no new claim is made and no error + is raised to a caller. Recovery is retried on later passes until it + succeeds or the window expires. Continuous claims on a shared Worker + can keep recovery pending beyond `LOCK_TIMEOUT`; the next look that + passes the in-flight check expires the window and releases nothing. + The rows remain subject to the reaper throughout. + + PostgreSQL with psycopg2 retains 1.6.0's behaviour, with no recovery. + `Worker.run_once()` and `testing.run_tasks()` also retain 1.6.0's + behaviour: they raise the claim's original error at once, with no + immediate or pending recovery attempt. A claim that landed stays + `RUNNING` for the reaper, and the next call does not find it while it + remains `RUNNING`. It is requeued with the attempt spent or marked + `LOST` on the final attempt. + + Recovery does not cover claims made by workers that have not been + upgraded, workers that die before recovery, or database outages that + outlast `LOCK_TIMEOUT`. If the claim's commit becomes visible only + after the recovery look, it may escape recovery and be reaped normally, consuming the attempt and becoming `LOST` on the final attempt. + The loop makes at most one recovery attempt when stopping, without + scheduling a recovery retry. Only this stop-time look has + recovery-specific waiting limits. It waits up to five seconds for + claims in flight on the same Worker. If that budget runs out, or a + claim begins during the look, it gives up with + `worker_claim_recovery_failed`. A look given up because a claim began + after its claim-generation comparison may already have released rows, + each logged as `worker_claim_released`, before logging + `worker_claim_recovery_failed`. + + On PostgreSQL with psycopg 3, pooled or not, the stop-time look uses a + private connection and a five-second budget covering that claim wait, + connection establishment and every reply. Host name resolution is + outside that bound and can exceed it. The private connection does not + inherit a session-level `lock_timeout` from the worker's existing + connection and can use its whole budget waiting on a locked table. + With Django's PostgreSQL pool, this connection is outside `max_size`; + budget up to `max_size + 3` server connections during the stop-time + look, including the private renewal and timeout-watchdog connections. + + On MySQL, the stop-time look uses a private connection with five-second + connect, read and write timeouts; a shorter configured timeout is + raised to five seconds. These are per-operation limits, not one + deadline for the whole attempt. Host name resolution is outside these + timeout bounds, and mysqlclient may extend a read to 15 seconds. + On SQLite, database waiting during the stop-time look is bounded by + the busy timeout, not by an overall recovery deadline. The five-second + claim wait applies on MySQL and SQLite too. psycopg2 makes no stop-time + recovery attempt. + + A recovery error does not prevent shutdown. These limits do not bound + shutdown as a whole. The pool health checks that the `run()` loop makes + after a failed pass and MySQL's pre-existing wait for Django's + reconnection during the claim's atomic-block exit can delay shutdown + before the stop-time recovery look is reached. + +### Changed + +- Give a Worker used in a process forked after its creation a new worker + id in the child, retaining any `-` suffix, so that + `Worker.run()`'s recovery looks in one process cannot release the + other's running task. An at-fork hook re-identifies the child. For + forks that run no at-fork hook, such as uWSGI's default, a pid check + re-identifies it at its first `claim_one()`, claim, recovery look or + `run()`. Until that check, the child's copy can still report the + parent's id. + + The child starts with empty claim bookkeeping and fresh locks; the + parent keeps its id. As in 1.6.0, the child keeps touching the inherited + heartbeat path. It does so under its new id, and its heartbeat warning + names that id. A shared heartbeat path proves that one writer is alive, + not that every child is alive. + + This identity handling applies, for example, to a module-level Worker + used for `run_once()` under gunicorn `--preload` or uWSGI without + `lazy-apps`, or to a launcher that forks before the Worker claims + anything. Handing an already-claimed row to a child for execution is + unsupported: the row retains the parent's id, so the child with its + new id cannot renew the lease, and the reaper can requeue it while the + child runs it. + + This identity handling does not make arbitrary native forks safe or + establish that inherited database connections, threads or other + resources are safe to use. `ox_worker --processes` starts fresh + children rather than forking them. + Version 1.6.0 shared the id after a fork without a recovery-release + risk, because it had no recovery look. + ### Added - Stable structured-log events `worker_claim_released`, `worker_claim_recovery_failed`, `worker_claim_recovery_expired` and `worker_claim_release_refused`, with their documented extra keys. `worker_poll_failed` now includes `claim_recovery`, set to `"pending"` - while a recovery read is owed, or `null` otherwise. + while a recovery read is owed, or `null` otherwise; with psycopg2 it + is always `null`. `worker_claim_recovery_failed` is emitted only for + a failed stop-time recovery look in `Worker.run()`, with + `claim_recovery` always set to `"expired"`. ## [1.6.0] - 2026-09-27 diff --git a/docs/agents.md b/docs/agents.md index 98a8cef..d8a8c41 100644 --- a/docs/agents.md +++ b/docs/agents.md @@ -166,9 +166,14 @@ TASKS = { - With Django's PostgreSQL pool, provide at least `concurrency + 1` pooled connections per worker process; add a spare pooled connection if fallback must work under full load. Budget up to `max_size + 2` server connections - per process, including any added spare: one private renewal connection + per process and database alias in normal operation, including any added spare: + one private renewal connection and one possible watchdog connection. A worker whose tasks never use - timeouts needs only the first. An absent timeout in `OPTIONS` does not + timeouts needs only the first, for `max_size + 1` in normal operation. + A worker stopping with recovery pending opens one more private connection + for its stop-time recovery look: budget up to `max_size + 3` during that + look, or `max_size + 2` if its tasks never use timeouts. + An absent timeout in `OPTIONS` does not establish that, because tasks can declare their own. Account for all processes, aliases, other clients and reserved slots. - The worker polls; `--interval` (default 1.0 s) is the idle sleep, so a task diff --git a/docs/llms-full.txt b/docs/llms-full.txt index 555cd87..0a1fdba 100644 --- a/docs/llms-full.txt +++ b/docs/llms-full.txt @@ -3609,13 +3609,19 @@ of date, open an issue with the link that shows it. Run `manage.py ox_worker` as a foreground process under your process supervisor. A worker started while the database refuses connections stays up and polls until it returns. Failed passes are logged as -`worker_poll_failed`, and the connection is reopened. After a claim raises -a database error, the next pass first reads the worker's own unconfirmed -claims. It does not replay the failed claim or assume that it rolled back. +`worker_poll_failed`, and the connection is reopened. + +Claim recovery runs only in `Worker.run()`, the loop used by `ox_worker`, +on PostgreSQL with psycopg 3, pooled or not, MySQL and SQLite. After a +claim raises a database error, the loop checks the worker's own +unconfirmed claims before claiming on a later pass, subject to the +shared-Worker rules below. It does not replay the failed claim or assume +that it rolled back. PostgreSQL with psycopg2 makes no recovery attempt; +a claim that committed without returning is left to the reaper. A claim can commit on the database even though the worker receives an error instead of its reply. On a connection the worker owns, in -autocommit, the worker checks for its own `RUNNING` rows that no claim +autocommit, recovery checks for its own `RUNNING` rows that no claim returned. It excludes every epoch of a row that is in flight, has been handed off, or has an unsettled outcome. It never recovers another worker's rows. @@ -3636,54 +3642,99 @@ row's lease. Recovery also checks each row against the reaper's own lease-expiry predicate and clock. A row the reaper could already take is left to it, even within the recovery window. -`Worker.run()` checks before claiming on the next poll pass. If the -database is still unreachable, recovery stays pending and is retried on -later passes until it succeeds or the window expires. A failed recovery -read ends that pass with `worker_poll_failed`; no new claim is made. +`Worker.run()` checks before claiming on the next poll pass unless +another claim of the same Worker is in flight. In that case it makes no +recovery read; if a claim begins before the look compares the claim +generation, it releases nothing. If a claim begins after that comparison, +the look still releases the orphans it read, but not that claim's row. +Either way, recovery stays pending, that pass claims as usual, and the +next pass looks again. Continuous claims on a shared Worker can keep +recovery pending beyond `LOCK_TIMEOUT`; the next look that passes the +in-flight check expires the window and releases nothing. The rows remain +subject to the reaper throughout. + +If the database is still unreachable, recovery stays pending and is +retried on later passes until it succeeds or the window expires. A failed +recovery read ends that pass with `worker_poll_failed` and +`claim_recovery` set to `"pending"`; no new claim is made and no error is +raised to a caller. The worker makes at most one recovery attempt when stopping, without -scheduling a recovery retry. On PostgreSQL with psycopg 3, pooled or not, -this attempt waits at most five seconds, including connection -establishment and every reply, then gives up. - -On MySQL, the attempt uses a private connection with five-second connect, -read and write timeouts. A shorter configured timeout is raised to five -seconds. These are per-operation limits, not one deadline for the whole -attempt. mysqlclient may retry a read, extending its effective read limit -to 15 seconds. Other configurations, including PostgreSQL with psycopg2 -and SQLite, have no recovery-specific deadline. - -A recovery error does not prevent shutdown. These limits apply only to the -stop-time recovery attempt, not to shutdown as a whole. Existing waits -elsewhere, including MySQL claim-path reconnection and pooled PostgreSQL -health checks, can delay shutdown before this attempt is reached. - -`Worker.run_once()` and `testing.run_tasks()` instead attempt recovery -once immediately after a claim raises, then re-raise the original claim -error. A recovery error at that point is logged without replacing the -claim error. After a successful release, the next call can claim and run -the task normally. If recovery is still pending from an earlier call, -the next call attempts it before claiming anything. A database error -from that pending recovery read is raised to the caller. - -This recovery does not run inside a caller's transaction, including -`atomic()` and Django `TestCase`, or when the caller has disabled -autocommit. There, the claim belongs to the caller's transaction and -rolls back with it. - -`--batch` does not finish while recovery is pending. `--max-tasks` counts -only claims that returned; a claim that raised uses no slot. Oxpull Pro -also counts admission only for a claim that returned, so a released row -is counted when it is claimed again. +scheduling a recovery retry. It waits up to five seconds for claims in +flight on the same Worker. If that budget runs out, or a claim begins +during the look, it gives up with `worker_claim_recovery_failed`. +A look given up because a claim began after its claim-generation +comparison may already have released rows, each logged as +`worker_claim_released`, before logging `worker_claim_recovery_failed`. + +On PostgreSQL with psycopg 3, pooled or not, the stop-time attempt uses a +private connection and a five-second budget covering that claim wait, +connection establishment and every reply. Host name resolution is outside +that bound and can exceed it. The private connection does not inherit a +session-level `lock_timeout` from the worker's existing connection and +can use its whole budget waiting on a locked table. + +On MySQL, the stop-time attempt uses a private connection with five-second +connect, read and write timeouts. A shorter configured timeout is raised +to five seconds. These are per-operation limits, not one deadline for the +whole attempt. Host name resolution is outside these timeout bounds. +mysqlclient may retry a read, extending its effective read limit to 15 +seconds. On SQLite, database waiting during the stop-time look is bounded +by the busy timeout, not by an overall recovery deadline. The five-second +claim wait applies on MySQL and SQLite too. PostgreSQL with psycopg2 makes +no stop-time recovery attempt. + +A recovery error does not prevent shutdown. These recovery limits apply +only to the stop-time attempt. They do not bound shutdown as a whole. +Existing waits elsewhere can delay shutdown before the stop-time attempt +is reached, including MySQL claim-path reconnection and the pooled +PostgreSQL health checks that `Worker.run()` makes after a failed pass. + +`Worker.run_once()` and `testing.run_tasks()` raise the claim's original +error at once, without an immediate recovery attempt or a pending recovery +read on the next call. A claim that committed stays `RUNNING` and is left +to the reaper, which requeues it with the attempt spent or marks it `LOST` +on the final attempt. The next call does not find that landed claim while +it remains `RUNNING`. + +Threads sharing a Worker can claim concurrently. No lock is held across +a claim, including a subclass's statements after the base `claim_one()` +returns, so a database wait in one claim does not block another claim +through a Worker lock. A claim made through `run()`, `run_once()` or the +base `claim_one()` counts as in flight until its returned row is +registered. A short per-Worker lock protects this bookkeeping and is +never held across a database call. `ox_worker` does not share its Worker: +its loop claims and checks recovery on one thread. + +Neither `run_once()` nor `run_tasks()` closes the failed claim's +connection for recovery or tests idle connections in Django's PostgreSQL +pool. The caller's connection and session, including advisory locks, +temporary tables and `SET` values, are left as the claim left them. +The `run()` loop tests the pool after a failed pass. + +`run_once()` and `run_tasks()` perform no recovery either inside or +outside a caller's transaction. Inside `atomic()` or Django `TestCase`, +or when the caller has disabled autocommit, the claim belongs to the +caller's transaction and rolls back with it. + +`ox_worker --batch` does not finish while recovery is pending. On a shared +Worker, recovery deferred by another thread's claim does not hold the +batch open; the stop-time look waits up to five seconds for that claim. +If the claim is still in flight then, the look gives up with +`worker_claim_recovery_failed` and a row that landed is left to the reaper. +`--max-tasks` counts only claims +that returned; a claim that raised uses no slot. Oxpull Pro also counts +admission only for a claim that returned, so a released row is counted +when it is claimed again. No database statement is added to the ordinary task path. A recovery look uses one SELECT over `RUNNING` rows filtered to this worker. It may make follow-up SELECTs, by primary key, for rows belonging to excluded entries that the first read did not return, with one SELECT per chunk of up to 500 primary keys. Recovery then uses one conditional UPDATE per eligible row. -Failed recovery reads may be retried. If a release commits but its own -reply is lost, there is no `worker_claim_released` event for that release; -the next read finds the row already `READY`. +Failed recovery reads may be retried on later passes. If a release commits +but its own reply is lost, there is no `worker_claim_released` event for +that release; the next read finds the row already `READY`. With settings schedules, the worker opens its first connection during polling. With `DatabaseScheduleSource`, a refused startup read logs @@ -4116,12 +4167,17 @@ With Django's PostgreSQL pool, lease renewal uses a connection outside the pool, in addition to `max_size`. The timeout watchdog can use a second private connection whenever an attempt has a timeout. That timeout can come from the task declaration, not just `TASK_TIMEOUT` or `TASK_TIMEOUTS`. - -Budget up to `max_size + 2` server connections per worker process. This is -a worst-case budget, not a count of open connections. A worker whose tasks -never use a timeout needs only the baseline private connection, for -`max_size + 1`. An absent timeout in `OPTIONS` alone does not establish that. -Check PostgreSQL `max_connections` and role connection limits before upgrading. +With psycopg 3, a worker stopping with recovery pending opens one more +private connection outside the pool for its stop-time recovery look. + +Budget up to `max_size + 2` server connections per worker process during +normal operation, and `max_size + 3` during a stop-time recovery look. +These are worst-case budgets, not counts of open connections. A worker +whose tasks never use a timeout needs only the baseline private connection +during normal operation, for `max_size + 1`, and up to `max_size + 2` +during a stop-time recovery look. An absent timeout in `OPTIONS` alone +does not establish that tasks never use a timeout. Check PostgreSQL +`max_connections` and role connection limits before upgrading. Lease renewal normally uses a private connection outside the pool. The stock worker opens it on the first renewal tick with work in flight. It reuses the @@ -4143,8 +4199,10 @@ PostgreSQL's reserved slots and role connection limits. Reserved slots that the worker's role cannot use are not worker capacity. For example, two worker processes with `max_size=5` need a worst-case budget -of 14 worker connections. If no task either worker runs has a timeout, -12 suffice for the workers. These totals exclude all other clients and +of 14 worker connections in normal operation and 16 while both make a +stop-time recovery look. If no task either worker runs has a timeout, +12 suffice for the workers in normal operation, and 14 during that look. +These totals exclude all other clients and unusable reserved slots. A separate database alias needs its own budget, even when it connects to the same PostgreSQL server. @@ -4806,19 +4864,22 @@ in 1.4.0 and later, private connects that keep failing for about `LOCK_TIMEOUT`, with no pooled spare, can still do so. See [PostgreSQL pooling](#database-connections-and-postgresql-pooling). -Before 1.7.0, a claim that committed while its reply was lost could also -leave a row to lapse on its final attempt without the task body ever -running. It became `LOST` with a `TaskAbandoned` record saying that the -worker "stopped renewing its lease", although the worker had never -started the task. From 1.7.0, upgraded workers recover their own -unconfirmed claims within `LOCK_TIMEOUT`, before the row's lease -expires, and return them to `READY` with the attempt refunded. The old -outcome remains possible if the worker dies before it can check, the -database remains unreachable past `LOCK_TIMEOUT`, or the claim was made -by a worker that has not been upgraded. In a mixed fleet, an upgraded -worker does not recover another worker's claims. Rows left to the reaper -are still requeued with the attempt spent, or marked `LOST` on the final -attempt with the same `TaskAbandoned` text. +A claim that commits while its reply is lost can leave a row to lapse on +its final attempt without the task body ever running. It becomes `LOST` +with a `TaskAbandoned` record saying that the worker "stopped renewing its +lease", although the worker never started the task. `Worker.run()`, the +loop used by `ox_worker`, recovers its own unconfirmed claims on PostgreSQL +with psycopg 3, pooled or not, MySQL and SQLite. Within `LOCK_TIMEOUT` and +before the row's lease expires, it returns eligible rows to `READY` with +the attempt refunded. + +A claim can still be left to the reaper if the worker dies before it can +check, the database remains unreachable past `LOCK_TIMEOUT`, or the claim +was made by `Worker.run_once()`, `testing.run_tasks()`, a worker using +psycopg2, or a worker without recovery support. In a mixed fleet, a worker +with recovery support does not recover another worker's claims. Rows left +to the reaper are requeued with the attempt spent, or marked `LOST` on the +final attempt with the same `TaskAbandoned` text. Raising `LOCK_TIMEOUT` gives delayed renewals more time, but does not fix connection starvation and delays recovery from dead workers. See @@ -4841,15 +4902,17 @@ worker between the claim and the call has used an attempt without running, and a task that exhausts its stored budget this way reaches a terminal state having never executed. The window is small: a worker claims only when it has a free thread and hands the task straight to it. It is not zero. -A claim the worker could not confirm is different: if the worker finds -that it landed and can safely release it before its lease expires and -within the recovery window, the attempt is refunded. For that claim, -the attempt count then reflects claims that reached a worker, not the -unconfirmed claim. This does not guarantee that every counted claim ran -the task body. After a refund, `last_attempted_at` keeps the instant of -the lost claim. A `READY` row can therefore have `attempts` equal to 0 -and `last_attempted_at` set. `started_at` is cleared only when the refund -reduces `attempts` to 0. +A claim the worker could not confirm can be different: in `Worker.run()` +on PostgreSQL with psycopg 3, pooled or not, MySQL or SQLite, if the worker +finds that it landed and can safely release it before its lease expires +and within the recovery window, the attempt is refunded. This recovery +does not run with psycopg2 or in `Worker.run_once()` or +`testing.run_tasks()`. For a refunded claim, the attempt count reflects +claims that reached a worker, not the unconfirmed claim. This does not +guarantee that every counted claim ran the task body. After a refund, +`last_attempted_at` keeps the instant of the lost claim. A `READY` row can +therefore have `attempts` equal to 0 and `last_attempted_at` set. +`started_at` is cleared only when the refund reduces `attempts` to 0. At enqueue, a task's declared `max_attempts` takes precedence over the backend's `MAX_ATTEMPTS`, which defaults to 3. That value is stored on the @@ -5752,7 +5815,7 @@ The message text is not part of the contract. The keys are. | `schedule_boundary_heal_failed` | WARNING | That move failed and will be retried. | | `worker_error` | ERROR | The execution wrapper itself raised (an internal worker error, not a task failure). A connection-level outcome-write failure whose recovery on a new connection also failed is reported as `task_outcome_unrecorded` instead. | | `worker_claim_released` | WARNING | A claim raised an error even though it had committed. This worker returned the row to `READY` and refunded 1 attempt. Includes `task_id`, `task_path`, `queue`, `attempt` after the refund, `worker_id`, `old_epoch`, `new_epoch`, `refunded_attempts` and `reason` set to `claim_outcome_unknown`. | -| `worker_claim_recovery_failed` | WARNING | A recovery read could not run or finish after a claim error in `run_once()` or `run_tasks()`, or while stopping. Includes a traceback. `claim_recovery` is `pending` if recovery remains due, or `expired` when stopping without another retry or when `run_tasks()` will not retry recovery in that call. Any unrecovered row is then left to the reaper. | +| `worker_claim_recovery_failed` | WARNING | A recovery read could not run or finish while `Worker.run()` was stopping, including when another claim of the same Worker remained in flight past the five-second claim-wait budget or began during the look. Includes a traceback; the exception text identifies claim interference. `claim_recovery` is always `expired`: the worker is stopping without another recovery retry. Rows the look released before giving up are `READY`, each logged as `worker_claim_released`. Any unrecovered row is then left to the reaper. | | `worker_claim_recovery_expired` | WARNING | The recovery window passed before recovery completed, or a recovery read found a row whose lease the reaper could already take. `claim_recovery` is `expired`. Window expiry has no task id; a row-specific event includes `task_id`, `task_path` and `queue`. The reaper handles the row with the attempt still charged. | | `worker_claim_release_refused` | ERROR | A row's history is inconsistent: `attempts` does not equal the number of `worker_ids`, or the last entry is not this worker. The row was not released and is left to the reaper. Includes `task_id`, `task_path`, `queue`, `attempts` and `worker_ids`. Report this as a defect. | | `worker_poll_failed` | WARNING | A database error ended one pass of the poll loop. The pass is abandoned and retried on the next one; the worker keeps running. `claim_recovery` is `pending` while a recovery read is owed, or `null` otherwise. A failed recovery read prevents new claims for that pass. A steady stream of this event means database operations are failing, not merely slow. | @@ -5796,7 +5859,7 @@ A failed connect while recording a stuck attempt logs | Key | Present on | Meaning | | --- | --- | --- | | `event` | all events | The event name from the table above. | -| `worker_id` | Worker events except `heartbeat_write_failed`, `schedule_source_unavailable`, `schedule_boundary_healed`, `schedule_boundary_heal_failed`, `schedule_row_skipped` and `schedule_lock_unavailable` for a stored schedule; also `run_tasks_callback_failed`; includes `worker_claim_released` | Unique id of the worker emitting the record. With `--processes`, the slot number is the last part of the id. Settings-declared `schedule_lock_unavailable` events carry this key. Records from `run_tasks()` use the drain worker's hostname-pid-random id, created for each call. `task_policy_inert` and `run_tasks_timeout_inert` omit this key. On `worker_claim_released`, identifies the worker that made the unconfirmed claim and released it. | +| `worker_id` | Worker events except `heartbeat_write_failed`, `schedule_source_unavailable`, `schedule_boundary_healed`, `schedule_boundary_heal_failed`, `schedule_row_skipped` and `schedule_lock_unavailable` for a stored schedule; also `run_tasks_callback_failed`; includes `worker_claim_released` | Unique id of the worker emitting the record. With `--processes`, the slot number is the last part of the id. A Worker used in a process forked after its creation takes a new id in the child, retaining any `-` suffix; the parent keeps its id. An at-fork hook re-identifies the child. If the fork runs no at-fork hook, as with uWSGI's default, a pid check re-identifies it at its first `claim_one()`, claim, recovery look or `run()`; until then, the child's copy can still report the parent's id. Fork before claiming: handing an already-claimed row to a child for execution is unsupported, because the child's new id cannot renew the parent's lease and the reaper can requeue the row while the child runs it. This identity handling does not make arbitrary native forks safe. `ox_worker --processes` starts fresh children rather than forking them. Settings-declared `schedule_lock_unavailable` events carry this key. Records from `run_tasks()` use the drain worker's hostname-pid-random id, created for each call. `task_policy_inert` and `run_tasks_timeout_inert` omit this key. On `worker_claim_released`, identifies the worker that made the unconfirmed claim and released it. | | `worker_class` | `claim_filter_sql_missing` | The Worker subclass's class name. | | `claimed` | `worker_batch_empty`, `worker_max_tasks_reached` | Task attempts this worker claimed in its run, failed attempts and retries included. | | `task_id` | Worker task events, including `worker_claim_released`, row-specific `worker_claim_recovery_expired` and `worker_claim_release_refused`; also `run_tasks_callback_failed`; absent from `run_tasks_timeout_inert` | The task's UUID primary key, as a string. Absent from `task_policy_inert`. Absent from `worker_claim_recovery_expired` when only the recovery window expired. | @@ -5822,7 +5885,7 @@ A failed connect while recording a stuck attempt logs | `dropped_status` | `task_lease_lost`, `task_outcome_unrecorded` | The status the dropped write would have set: `SUCCESSFUL`, `FAILED` or `READY`. | | `outcome` | `task_outcome_reconnected` | Confirmed outcome status: `SUCCESSFUL`, `READY` or `FAILED`. `READY` means the failed attempt was recorded for retry with its backoff. | | `already_written` | `task_outcome_reconnected` | Boolean. `true` when the new connection found the first write already committed; `false` when recovery wrote the outcome on the new connection. | -| `claim_recovery` | `worker_poll_failed`, `worker_claim_recovery_failed`, `worker_claim_recovery_expired` | Recovery state. On `worker_poll_failed`, `pending` means a recovery read is owed; otherwise `null`. On `worker_claim_recovery_failed`, `pending` means recovery remains due, and `expired` means the worker is stopping without another retry or `run_tasks()` will not retry recovery in that call. On `worker_claim_recovery_expired`, always `expired`. | +| `claim_recovery` | `worker_poll_failed`, `worker_claim_recovery_failed`, `worker_claim_recovery_expired` | Recovery state. On `worker_poll_failed`, `pending` means a recovery read is owed; otherwise `null`. With psycopg2, it is always `null` on `worker_poll_failed`. On `worker_claim_recovery_failed`, always `expired`: `Worker.run()` is stopping without another recovery retry. On `worker_claim_recovery_expired`, always `expired`. | | `old_epoch` | `worker_claim_released` | The row's lease epoch before release. | | `new_epoch` | `worker_claim_released` | The row's lease epoch after release: `old_epoch + 1`. | | `refunded_attempts` | `worker_claim_released` | Number of attempts refunded by this release. Always 1. | @@ -5837,7 +5900,7 @@ A failed connect while recording a stuck attempt logs | `database` | `connection_pool_too_small`, `schedule_dispatch_error`, `schedule_dispatch_failed`, `schedule_dispatch_recovered` | The worker's database alias: `--database`, or the alias used to write `OxTask`. | | `max_size` | `connection_pool_too_small` | The effective pool maximum. `pool=True` means 4. For a non-empty mapping, use `max_size`; if absent or `None`, use `min_size`, defaulting to 4. The sizing check skips values that are not an `int` of at least 1. It excludes booleans and floats such as `10.0`. | | `recommended_max_size` | `connection_pool_too_small` | `concurrency + 1`: one pooled connection per task thread and one for the poll loop. This does not reserve fallback capacity or validate the server budget. | -| `unpooled_connections` | `connection_pool_too_small` | Worst-case additional private-connection budget per worker process, not a count of open connections. Always 2: one for lease renewal and one possible timeout-watchdog connection. A worker whose tasks never use timeouts needs only the first. An absent timeout in `OPTIONS` alone does not establish that, because a task can declare its own. | +| `unpooled_connections` | `connection_pool_too_small` | Worst-case additional private-connection budget per worker process in normal operation, not a count of open connections. Always 2: one for lease renewal and one possible timeout-watchdog connection. This does not count the additional private connection used for a stop-time recovery look. A worker whose tasks never use timeouts needs only the first. An absent timeout in `OPTIONS` alone does not establish that, because a task can declare its own. | | `pending` | `worker_draining` | In-flight tasks at shutdown. | | `processes` | `supervisor_started` | Worker processes the supervisor runs. | | `worker_index`, `exit_code` | `worker_process_restarted`, `worker_process_recycled`, `supervisor_restart_cap` | Which slot exited and how. A negative code is the signal that killed it. | @@ -6210,13 +6273,17 @@ export names this page does not list; those names are not public. or recycled, 1 when a slot hit the restart cap, and otherwise with the first other non-zero worker code. A worker killed by a signal reports `128 + the signal number`, following the shell convention. -- **The heartbeat-file protocol**: one process writes `PATH`; above one - process, the supervisor writes `PATH.supervisor` and slot i writes - `PATH.i`. The modification time is the signal; file contents are not - read or written. Every expected file must be regular and have an age - between zero and the configured maximum, inclusive. A passing check - means the expected controlling loops have advanced recently, not that - tasks are progressing. The documented +- **The heartbeat-file protocol**: with `ox_worker`, one process writes + `PATH`; above one process, the supervisor writes `PATH.supervisor` and + slot i writes `PATH.i`. The modification time is the signal; file + contents are not read or written. Every expected file must be regular + and have an age between zero and the configured maximum, inclusive. + A passing check means the expected controlling loops have advanced + recently, not that tasks are progressing. A launcher that constructs + one Worker with `heartbeat_file` and then forks it leaves the children + touching the same inherited path under their own worker ids. A fresh + shared path proves that one writer is alive, not that every child is + alive. The documented [file-mode JSON fields](monitoring.md#file-mode-json) are public too. - **The system check IDs**, including the `django_ox.E0xx` and `django_ox.W0xx` identifiers, which you may list in @@ -6279,11 +6346,12 @@ export names this page does not list; those names are not public. It also includes `worker_claim_released`, `worker_claim_recovery_failed`, `worker_claim_recovery_expired` and `worker_claim_release_refused`, and their documented keys. These are - stable, not provisional. The new keys include `claim_recovery`, + stable, not provisional. The recovery keys include `claim_recovery`, `old_epoch`, `new_epoch`, `refunded_attempts`, `attempts` and `worker_ids`. On `worker_poll_failed`, `claim_recovery` is `"pending"` - while a recovery read is owed, or `null` otherwise. The recovery - events also use `"expired"` as documented. + while a recovery read is owed, or `null` otherwise; with psycopg2 it + is always `null`. On `worker_claim_recovery_failed` and + `worker_claim_recovery_expired`, it is always `"expired"`. - **The testing helpers** `django_ox.testing.ImmediateBackend`, `django_ox.testing.DummyBackend` and `django_ox.testing.run_tasks`. The backends accept policy declarations but do not enforce retries, @@ -6341,24 +6409,107 @@ are not public. ### Worker implementation details `Worker` internals remain **Not public**. This includes `_handed_off`, -`_unsettled`, `_claimer`, `_claim`, `_claim_inline`, `_recover_claims` -and `_release_claim`. +`_unsettled`, `_fence`, `_claims_in_flight`, `_claim_generation`, +`_claiming`, `_claim`, `_claim_inline`, `_recover_claims` and +`_release_claim`. -`Worker._run_attempt` is also private. It now returns a `bool` indicating +`Worker._run_attempt` is also private. It returns a `bool` indicating whether the outcome was recorded. A subclass override that returns `None` is treated as "outcome not recorded". This keeps its row excluded from claim recovery; it does not itself change the row's outcome. -Subclass authors may notice two behaviour changes. The base -`claim_one()` now holds a per-worker reentrant lock while claiming. -Two threads claiming on the same `Worker` instance are serialised: -the second waits rather than being refused. Recovery reads use the -same lock. - -`Worker.run_once()` and `testing.run_tasks()` may raise a database error -from a pending recovery read before making any new claim. After a new -claim raises, an immediate recovery attempt does not replace the -original claim error, which is still raised to the caller. +Threads sharing a Worker can claim concurrently. No lock is held across +`claim_one()` or an override of it, including subclass statements after +the base claim returns. A database wait in one claim does not block +another claim through a Worker lock. A claim made through `run()`, +`run_once()` or the base `claim_one()` counts as in flight until its +returned row is registered. A short per-Worker lock protects this +bookkeeping and is never held across a database call. + +`Worker.run_once()` and `testing.run_tasks()` raise a claim's original +error at once. They make no immediate recovery attempt and no pending +recovery read before a later claim, whether inside or outside a caller's +transaction. A claim that committed stays `RUNNING` and is left to the +reaper, which requeues it with the attempt spent or marks it `LOST` on +the final attempt. The next call does not find that landed claim while +it remains `RUNNING`. + +Neither `run_once()` nor `run_tasks()` closes the failed claim's connection +for recovery or tests idle connections in Django's PostgreSQL pool. +The caller's connection and session, including advisory locks, temporary +tables and `SET` values, are left as the claim left them. The `run()` loop +tests the pool after a failed pass. + +Recovery runs only in `Worker.run()`, the loop used by `ox_worker`, on +PostgreSQL with psycopg 3, pooled or not, MySQL and SQLite. Pending recovery +is checked at the head of a poll pass unless another claim of the same +Worker is in flight. In that case it makes no recovery read; if a claim +begins before the look compares the claim generation, it releases nothing. +If a claim begins after that comparison, the look still releases the +orphans it read, but not that claim's row. Either way, recovery stays +pending, that pass claims as usual, and the next pass looks again. +Continuous claims on a shared Worker can keep recovery pending beyond +`LOCK_TIMEOUT`; the next look that passes the in-flight check expires +the window and releases nothing. The rows remain subject to the reaper. + +A failed recovery read ends that pass with `worker_poll_failed` and +`claim_recovery` set to `"pending"`; no new claim is made and no error is +raised to a caller. PostgreSQL with psycopg2 makes no recovery attempt. +`ox_worker` does not share its Worker: its loop claims and checks recovery +on one thread. + +The loop makes at most one recovery attempt when stopping. Only this +stop-time look has recovery-specific waiting limits. It waits up to five +seconds for claims in flight on the same Worker. If that budget runs out, +or a claim begins during the look, it gives up with +`worker_claim_recovery_failed`. A look given up because a claim began +after its claim-generation comparison may already have released rows, +each logged as `worker_claim_released`, before logging +`worker_claim_recovery_failed`. + +On PostgreSQL with psycopg 3, pooled or not, the stop-time look uses a +private connection and a five-second budget covering that claim wait, +connection establishment and every reply. Host name resolution is outside +that bound and can exceed it. The private connection does not inherit a +session-level `lock_timeout` from the worker's existing connection and +can use its whole budget waiting on a locked table. + +On MySQL, the stop-time look uses a private connection with five-second +connect, read and write timeouts, raising any shorter configured timeout +to five seconds. These limits are per operation, not an overall deadline, +and host name resolution is outside them. mysqlclient may extend a read +to 15 seconds. On SQLite, database waiting during the stop-time look is +bounded by the busy timeout, not by an overall recovery deadline. The +five-second claim wait applies on MySQL and SQLite too. A recovery error +does not prevent shutdown, and these limits do not bound shutdown as a +whole. + +A Worker used in a process forked after the Worker was created takes a +new worker id in the child, retaining any `-` suffix. An at-fork +hook re-identifies the child. For forks that run no at-fork hook, such as +uWSGI's default, a pid check does so at the child's first `claim_one()`, +claim, recovery look or `run()`. Until that check, the child's copy can +still report the parent's id. The parent keeps its id. + +The child starts with empty claim bookkeeping and fresh locks. It keeps +the inherited heartbeat path and continues touching it under its new id; +a heartbeat warning names the child's id. If several children share that +path, a fresh heartbeat proves that one writer is alive, not that every +child is alive. + +This identity handling applies, for example, to a module-level Worker used +for `run_once()` under gunicorn `--preload` or uWSGI without `lazy-apps`, +or to a launcher that forks before the Worker claims anything. Handing an +already-claimed row to a child for execution is unsupported: the row +retains the parent's id, so the child with its new id cannot renew the +lease, and the reaper can requeue it while the child runs it. + +This identity handling does not make arbitrary native forks safe or +establish that inherited database connections, threads or other resources +are safe to use. Separate worker identities prevent `Worker.run()`'s +recovery looks in one process from releasing the other's running task and +causing its body to run twice. `ox_worker --processes` starts fresh +children rather than forking them. ## Versioning @@ -6780,9 +6931,14 @@ TASKS = { - With Django's PostgreSQL pool, provide at least `concurrency + 1` pooled connections per worker process; add a spare pooled connection if fallback must work under full load. Budget up to `max_size + 2` server connections - per process, including any added spare: one private renewal connection + per process and database alias in normal operation, including any added spare: + one private renewal connection and one possible watchdog connection. A worker whose tasks never use - timeouts needs only the first. An absent timeout in `OPTIONS` does not + timeouts needs only the first, for `max_size + 1` in normal operation. + A worker stopping with recovery pending opens one more private connection + for its stop-time recovery look: budget up to `max_size + 3` during that + look, or `max_size + 2` if its tasks never use timeouts. + An absent timeout in `OPTIONS` does not establish that, because tasks can declare their own. Account for all processes, aliases, other clients and reserved slots. - The worker polls; `--interval` (default 1.0 s) is the idle sleep, so a task @@ -6959,28 +7115,130 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed -- Recover claims that committed but whose reply was lost on MySQL, - PostgreSQL and SQLite. Previously, such a task stayed `RUNNING` until - the reaper requeued it with an attempt spent, or marked it `LOST` on - its final attempt even though its body never ran. Upgraded workers - now find their own unconfirmed claims and return them to `READY` - with the attempt refunded, within `LOCK_TIMEOUT` and before the - row's lease expires. `Worker.run_once()` and `testing.run_tasks()` - still raise the claim's original error; after a successful release, - the next call can claim and run the task normally. Recovery does not - cover claims made by workers that have not been upgraded, workers - that die before recovery, or database outages that outlast - `LOCK_TIMEOUT`. If the claim's commit becomes visible only after the - recovery look, it may escape recovery and be reaped normally, +- Recover claims that committed but whose reply was lost, only in + `Worker.run()` (the loop used by `ox_worker`), on PostgreSQL with + psycopg 3, pooled or not, MySQL and SQLite. In 1.6.0, such a task stayed + `RUNNING` until the reaper requeued it with an attempt spent, or marked + it `LOST` on its final attempt even though its body never ran. Upgraded + workers running this loop look for their own unconfirmed claims on + later poll passes, or once at stop, and return eligible rows to `READY` + with the attempt refunded, within `LOCK_TIMEOUT` and before the row's + lease expires. + + A pending recovery look runs at the head of a poll pass unless another + claim of the same Worker is in flight. In that case it makes no read; + if a claim begins before the look compares the claim generation, it + releases nothing. If a claim begins after that comparison, the look + still releases the orphans it read, but not that claim's row. Either way, + recovery stays pending, that pass claims as usual, and the next pass + looks again. Claims on a shared Worker remain concurrent, as in 1.6.0; + recovery bookkeeping uses a short lock never held across a database + call. A claim made through `run()`, `run_once()` or the base `claim_one()` + counts as in flight until its returned row is + registered, including subclass work after the base claim returns. + `ox_worker` is unaffected by shared-Worker deferrals: its Worker is not + shared, and its loop claims and checks recovery on one thread. + + A failed recovery read ends that pass with `worker_poll_failed` and + `claim_recovery` set to `"pending"`; no new claim is made and no error + is raised to a caller. Recovery is retried on later passes until it + succeeds or the window expires. Continuous claims on a shared Worker + can keep recovery pending beyond `LOCK_TIMEOUT`; the next look that + passes the in-flight check expires the window and releases nothing. + The rows remain subject to the reaper throughout. + + PostgreSQL with psycopg2 retains 1.6.0's behaviour, with no recovery. + `Worker.run_once()` and `testing.run_tasks()` also retain 1.6.0's + behaviour: they raise the claim's original error at once, with no + immediate or pending recovery attempt. A claim that landed stays + `RUNNING` for the reaper, and the next call does not find it while it + remains `RUNNING`. It is requeued with the attempt spent or marked + `LOST` on the final attempt. + + Recovery does not cover claims made by workers that have not been + upgraded, workers that die before recovery, or database outages that + outlast `LOCK_TIMEOUT`. If the claim's commit becomes visible only + after the recovery look, it may escape recovery and be reaped normally, consuming the attempt and becoming `LOST` on the final attempt. + The loop makes at most one recovery attempt when stopping, without + scheduling a recovery retry. Only this stop-time look has + recovery-specific waiting limits. It waits up to five seconds for + claims in flight on the same Worker. If that budget runs out, or a + claim begins during the look, it gives up with + `worker_claim_recovery_failed`. A look given up because a claim began + after its claim-generation comparison may already have released rows, + each logged as `worker_claim_released`, before logging + `worker_claim_recovery_failed`. + + On PostgreSQL with psycopg 3, pooled or not, the stop-time look uses a + private connection and a five-second budget covering that claim wait, + connection establishment and every reply. Host name resolution is + outside that bound and can exceed it. The private connection does not + inherit a session-level `lock_timeout` from the worker's existing + connection and can use its whole budget waiting on a locked table. + With Django's PostgreSQL pool, this connection is outside `max_size`; + budget up to `max_size + 3` server connections during the stop-time + look, including the private renewal and timeout-watchdog connections. + + On MySQL, the stop-time look uses a private connection with five-second + connect, read and write timeouts; a shorter configured timeout is + raised to five seconds. These are per-operation limits, not one + deadline for the whole attempt. Host name resolution is outside these + timeout bounds, and mysqlclient may extend a read to 15 seconds. + On SQLite, database waiting during the stop-time look is bounded by + the busy timeout, not by an overall recovery deadline. The five-second + claim wait applies on MySQL and SQLite too. psycopg2 makes no stop-time + recovery attempt. + + A recovery error does not prevent shutdown. These limits do not bound + shutdown as a whole. The pool health checks that the `run()` loop makes + after a failed pass and MySQL's pre-existing wait for Django's + reconnection during the claim's atomic-block exit can delay shutdown + before the stop-time recovery look is reached. + +### Changed + +- Give a Worker used in a process forked after its creation a new worker + id in the child, retaining any `-` suffix, so that + `Worker.run()`'s recovery looks in one process cannot release the + other's running task. An at-fork hook re-identifies the child. For + forks that run no at-fork hook, such as uWSGI's default, a pid check + re-identifies it at its first `claim_one()`, claim, recovery look or + `run()`. Until that check, the child's copy can still report the + parent's id. + + The child starts with empty claim bookkeeping and fresh locks; the + parent keeps its id. As in 1.6.0, the child keeps touching the inherited + heartbeat path. It does so under its new id, and its heartbeat warning + names that id. A shared heartbeat path proves that one writer is alive, + not that every child is alive. + + This identity handling applies, for example, to a module-level Worker + used for `run_once()` under gunicorn `--preload` or uWSGI without + `lazy-apps`, or to a launcher that forks before the Worker claims + anything. Handing an already-claimed row to a child for execution is + unsupported: the row retains the parent's id, so the child with its + new id cannot renew the lease, and the reaper can requeue it while the + child runs it. + + This identity handling does not make arbitrary native forks safe or + establish that inherited database connections, threads or other + resources are safe to use. `ox_worker --processes` starts fresh + children rather than forking them. + Version 1.6.0 shared the id after a fork without a recovery-release + risk, because it had no recovery look. + ### Added - Stable structured-log events `worker_claim_released`, `worker_claim_recovery_failed`, `worker_claim_recovery_expired` and `worker_claim_release_refused`, with their documented extra keys. `worker_poll_failed` now includes `claim_recovery`, set to `"pending"` - while a recovery read is owed, or `null` otherwise. + while a recovery read is owed, or `null` otherwise; with psycopg2 it + is always `null`. `worker_claim_recovery_failed` is emitted only for + a failed stop-time recovery look in `Worker.run()`, with + `claim_recovery` always set to `"expired"`. ## [1.6.0] - 2026-09-27 diff --git a/docs/llms.txt b/docs/llms.txt index cd76f38..192425c 100644 --- a/docs/llms.txt +++ b/docs/llms.txt @@ -90,12 +90,18 @@ Operational facts to get right: so a live worker that cannot get one can still lose the lease. - With Django's PostgreSQL pool, use at least `concurrency + 1` pooled connections per worker process. Budget two additional server connections - outside the pool per worker as a worst case: one for lease renewal and + outside the pool per worker and database alias as a worst case in normal + operation: one for lease renewal and one possible timeout-watchdog connection. This gives `max_size + 2` - per worker for capacity planning, not a count of open connections or a + per worker and database alias in normal operation for capacity planning, + not a count of open connections or a startup requirement. A worker whose tasks never use timeouts needs only - the baseline extra connection; absent OPTIONS timeouts do not prove + the baseline extra connection, for `max_size + 1` in normal operation; + absent OPTIONS timeouts do not prove that, because a task can declare its own timeout. + A worker stopping with recovery pending opens one more private connection + for its stop-time recovery look: budget up to `max_size + 3` during that + look, or `max_size + 2` if its tasks never use timeouts. Include all processes, aliases, other clients, and reserved slots. Pool fallback needs a spare pooled connection; add and budget one if fallback must work under full load. diff --git a/docs/monitoring.md b/docs/monitoring.md index 69dc1d5..04af887 100644 --- a/docs/monitoring.md +++ b/docs/monitoring.md @@ -691,7 +691,7 @@ The message text is not part of the contract. The keys are. | `schedule_boundary_heal_failed` | WARNING | That move failed and will be retried. | | `worker_error` | ERROR | The execution wrapper itself raised (an internal worker error, not a task failure). A connection-level outcome-write failure whose recovery on a new connection also failed is reported as `task_outcome_unrecorded` instead. | | `worker_claim_released` | WARNING | A claim raised an error even though it had committed. This worker returned the row to `READY` and refunded 1 attempt. Includes `task_id`, `task_path`, `queue`, `attempt` after the refund, `worker_id`, `old_epoch`, `new_epoch`, `refunded_attempts` and `reason` set to `claim_outcome_unknown`. | -| `worker_claim_recovery_failed` | WARNING | A recovery read could not run or finish after a claim error in `run_once()` or `run_tasks()`, or while stopping. Includes a traceback. `claim_recovery` is `pending` if recovery remains due, or `expired` when stopping without another retry or when `run_tasks()` will not retry recovery in that call. Any unrecovered row is then left to the reaper. | +| `worker_claim_recovery_failed` | WARNING | A recovery read could not run or finish while `Worker.run()` was stopping, including when another claim of the same Worker remained in flight past the five-second claim-wait budget or began during the look. Includes a traceback; the exception text identifies claim interference. `claim_recovery` is always `expired`: the worker is stopping without another recovery retry. Rows the look released before giving up are `READY`, each logged as `worker_claim_released`. Any unrecovered row is then left to the reaper. | | `worker_claim_recovery_expired` | WARNING | The recovery window passed before recovery completed, or a recovery read found a row whose lease the reaper could already take. `claim_recovery` is `expired`. Window expiry has no task id; a row-specific event includes `task_id`, `task_path` and `queue`. The reaper handles the row with the attempt still charged. | | `worker_claim_release_refused` | ERROR | A row's history is inconsistent: `attempts` does not equal the number of `worker_ids`, or the last entry is not this worker. The row was not released and is left to the reaper. Includes `task_id`, `task_path`, `queue`, `attempts` and `worker_ids`. Report this as a defect. | | `worker_poll_failed` | WARNING | A database error ended one pass of the poll loop. The pass is abandoned and retried on the next one; the worker keeps running. `claim_recovery` is `pending` while a recovery read is owed, or `null` otherwise. A failed recovery read prevents new claims for that pass. A steady stream of this event means database operations are failing, not merely slow. | @@ -735,7 +735,7 @@ A failed connect while recording a stuck attempt logs | Key | Present on | Meaning | | --- | --- | --- | | `event` | all events | The event name from the table above. | -| `worker_id` | Worker events except `heartbeat_write_failed`, `schedule_source_unavailable`, `schedule_boundary_healed`, `schedule_boundary_heal_failed`, `schedule_row_skipped` and `schedule_lock_unavailable` for a stored schedule; also `run_tasks_callback_failed`; includes `worker_claim_released` | Unique id of the worker emitting the record. With `--processes`, the slot number is the last part of the id. Settings-declared `schedule_lock_unavailable` events carry this key. Records from `run_tasks()` use the drain worker's hostname-pid-random id, created for each call. `task_policy_inert` and `run_tasks_timeout_inert` omit this key. On `worker_claim_released`, identifies the worker that made the unconfirmed claim and released it. | +| `worker_id` | Worker events except `heartbeat_write_failed`, `schedule_source_unavailable`, `schedule_boundary_healed`, `schedule_boundary_heal_failed`, `schedule_row_skipped` and `schedule_lock_unavailable` for a stored schedule; also `run_tasks_callback_failed`; includes `worker_claim_released` | Unique id of the worker emitting the record. With `--processes`, the slot number is the last part of the id. A Worker used in a process forked after its creation takes a new id in the child, retaining any `-` suffix; the parent keeps its id. An at-fork hook re-identifies the child. If the fork runs no at-fork hook, as with uWSGI's default, a pid check re-identifies it at its first `claim_one()`, claim, recovery look or `run()`; until then, the child's copy can still report the parent's id. Fork before claiming: handing an already-claimed row to a child for execution is unsupported, because the child's new id cannot renew the parent's lease and the reaper can requeue the row while the child runs it. This identity handling does not make arbitrary native forks safe. `ox_worker --processes` starts fresh children rather than forking them. Settings-declared `schedule_lock_unavailable` events carry this key. Records from `run_tasks()` use the drain worker's hostname-pid-random id, created for each call. `task_policy_inert` and `run_tasks_timeout_inert` omit this key. On `worker_claim_released`, identifies the worker that made the unconfirmed claim and released it. | | `worker_class` | `claim_filter_sql_missing` | The Worker subclass's class name. | | `claimed` | `worker_batch_empty`, `worker_max_tasks_reached` | Task attempts this worker claimed in its run, failed attempts and retries included. | | `task_id` | Worker task events, including `worker_claim_released`, row-specific `worker_claim_recovery_expired` and `worker_claim_release_refused`; also `run_tasks_callback_failed`; absent from `run_tasks_timeout_inert` | The task's UUID primary key, as a string. Absent from `task_policy_inert`. Absent from `worker_claim_recovery_expired` when only the recovery window expired. | @@ -761,7 +761,7 @@ A failed connect while recording a stuck attempt logs | `dropped_status` | `task_lease_lost`, `task_outcome_unrecorded` | The status the dropped write would have set: `SUCCESSFUL`, `FAILED` or `READY`. | | `outcome` | `task_outcome_reconnected` | Confirmed outcome status: `SUCCESSFUL`, `READY` or `FAILED`. `READY` means the failed attempt was recorded for retry with its backoff. | | `already_written` | `task_outcome_reconnected` | Boolean. `true` when the new connection found the first write already committed; `false` when recovery wrote the outcome on the new connection. | -| `claim_recovery` | `worker_poll_failed`, `worker_claim_recovery_failed`, `worker_claim_recovery_expired` | Recovery state. On `worker_poll_failed`, `pending` means a recovery read is owed; otherwise `null`. On `worker_claim_recovery_failed`, `pending` means recovery remains due, and `expired` means the worker is stopping without another retry or `run_tasks()` will not retry recovery in that call. On `worker_claim_recovery_expired`, always `expired`. | +| `claim_recovery` | `worker_poll_failed`, `worker_claim_recovery_failed`, `worker_claim_recovery_expired` | Recovery state. On `worker_poll_failed`, `pending` means a recovery read is owed; otherwise `null`. With psycopg2, it is always `null` on `worker_poll_failed`. On `worker_claim_recovery_failed`, always `expired`: `Worker.run()` is stopping without another recovery retry. On `worker_claim_recovery_expired`, always `expired`. | | `old_epoch` | `worker_claim_released` | The row's lease epoch before release. | | `new_epoch` | `worker_claim_released` | The row's lease epoch after release: `old_epoch + 1`. | | `refunded_attempts` | `worker_claim_released` | Number of attempts refunded by this release. Always 1. | @@ -776,7 +776,7 @@ A failed connect while recording a stuck attempt logs | `database` | `connection_pool_too_small`, `schedule_dispatch_error`, `schedule_dispatch_failed`, `schedule_dispatch_recovered` | The worker's database alias: `--database`, or the alias used to write `OxTask`. | | `max_size` | `connection_pool_too_small` | The effective pool maximum. `pool=True` means 4. For a non-empty mapping, use `max_size`; if absent or `None`, use `min_size`, defaulting to 4. The sizing check skips values that are not an `int` of at least 1. It excludes booleans and floats such as `10.0`. | | `recommended_max_size` | `connection_pool_too_small` | `concurrency + 1`: one pooled connection per task thread and one for the poll loop. This does not reserve fallback capacity or validate the server budget. | -| `unpooled_connections` | `connection_pool_too_small` | Worst-case additional private-connection budget per worker process, not a count of open connections. Always 2: one for lease renewal and one possible timeout-watchdog connection. A worker whose tasks never use timeouts needs only the first. An absent timeout in `OPTIONS` alone does not establish that, because a task can declare its own. | +| `unpooled_connections` | `connection_pool_too_small` | Worst-case additional private-connection budget per worker process in normal operation, not a count of open connections. Always 2: one for lease renewal and one possible timeout-watchdog connection. This does not count the additional private connection used for a stop-time recovery look. A worker whose tasks never use timeouts needs only the first. An absent timeout in `OPTIONS` alone does not establish that, because a task can declare its own. | | `pending` | `worker_draining` | In-flight tasks at shutdown. | | `processes` | `supervisor_started` | Worker processes the supervisor runs. | | `worker_index`, `exit_code` | `worker_process_restarted`, `worker_process_recycled`, `supervisor_restart_cap` | Which slot exited and how. A negative code is the signal that killed it. | diff --git a/docs/production.md b/docs/production.md index 604dfe7..0558a28 100644 --- a/docs/production.md +++ b/docs/production.md @@ -3,13 +3,19 @@ Run `manage.py ox_worker` as a foreground process under your process supervisor. A worker started while the database refuses connections stays up and polls until it returns. Failed passes are logged as -`worker_poll_failed`, and the connection is reopened. After a claim raises -a database error, the next pass first reads the worker's own unconfirmed -claims. It does not replay the failed claim or assume that it rolled back. +`worker_poll_failed`, and the connection is reopened. + +Claim recovery runs only in `Worker.run()`, the loop used by `ox_worker`, +on PostgreSQL with psycopg 3, pooled or not, MySQL and SQLite. After a +claim raises a database error, the loop checks the worker's own +unconfirmed claims before claiming on a later pass, subject to the +shared-Worker rules below. It does not replay the failed claim or assume +that it rolled back. PostgreSQL with psycopg2 makes no recovery attempt; +a claim that committed without returning is left to the reaper. A claim can commit on the database even though the worker receives an error instead of its reply. On a connection the worker owns, in -autocommit, the worker checks for its own `RUNNING` rows that no claim +autocommit, recovery checks for its own `RUNNING` rows that no claim returned. It excludes every epoch of a row that is in flight, has been handed off, or has an unsettled outcome. It never recovers another worker's rows. @@ -30,54 +36,99 @@ row's lease. Recovery also checks each row against the reaper's own lease-expiry predicate and clock. A row the reaper could already take is left to it, even within the recovery window. -`Worker.run()` checks before claiming on the next poll pass. If the -database is still unreachable, recovery stays pending and is retried on -later passes until it succeeds or the window expires. A failed recovery -read ends that pass with `worker_poll_failed`; no new claim is made. +`Worker.run()` checks before claiming on the next poll pass unless +another claim of the same Worker is in flight. In that case it makes no +recovery read; if a claim begins before the look compares the claim +generation, it releases nothing. If a claim begins after that comparison, +the look still releases the orphans it read, but not that claim's row. +Either way, recovery stays pending, that pass claims as usual, and the +next pass looks again. Continuous claims on a shared Worker can keep +recovery pending beyond `LOCK_TIMEOUT`; the next look that passes the +in-flight check expires the window and releases nothing. The rows remain +subject to the reaper throughout. + +If the database is still unreachable, recovery stays pending and is +retried on later passes until it succeeds or the window expires. A failed +recovery read ends that pass with `worker_poll_failed` and +`claim_recovery` set to `"pending"`; no new claim is made and no error is +raised to a caller. The worker makes at most one recovery attempt when stopping, without -scheduling a recovery retry. On PostgreSQL with psycopg 3, pooled or not, -this attempt waits at most five seconds, including connection -establishment and every reply, then gives up. - -On MySQL, the attempt uses a private connection with five-second connect, -read and write timeouts. A shorter configured timeout is raised to five -seconds. These are per-operation limits, not one deadline for the whole -attempt. mysqlclient may retry a read, extending its effective read limit -to 15 seconds. Other configurations, including PostgreSQL with psycopg2 -and SQLite, have no recovery-specific deadline. - -A recovery error does not prevent shutdown. These limits apply only to the -stop-time recovery attempt, not to shutdown as a whole. Existing waits -elsewhere, including MySQL claim-path reconnection and pooled PostgreSQL -health checks, can delay shutdown before this attempt is reached. - -`Worker.run_once()` and `testing.run_tasks()` instead attempt recovery -once immediately after a claim raises, then re-raise the original claim -error. A recovery error at that point is logged without replacing the -claim error. After a successful release, the next call can claim and run -the task normally. If recovery is still pending from an earlier call, -the next call attempts it before claiming anything. A database error -from that pending recovery read is raised to the caller. - -This recovery does not run inside a caller's transaction, including -`atomic()` and Django `TestCase`, or when the caller has disabled -autocommit. There, the claim belongs to the caller's transaction and -rolls back with it. - -`--batch` does not finish while recovery is pending. `--max-tasks` counts -only claims that returned; a claim that raised uses no slot. Oxpull Pro -also counts admission only for a claim that returned, so a released row -is counted when it is claimed again. +scheduling a recovery retry. It waits up to five seconds for claims in +flight on the same Worker. If that budget runs out, or a claim begins +during the look, it gives up with `worker_claim_recovery_failed`. +A look given up because a claim began after its claim-generation +comparison may already have released rows, each logged as +`worker_claim_released`, before logging `worker_claim_recovery_failed`. + +On PostgreSQL with psycopg 3, pooled or not, the stop-time attempt uses a +private connection and a five-second budget covering that claim wait, +connection establishment and every reply. Host name resolution is outside +that bound and can exceed it. The private connection does not inherit a +session-level `lock_timeout` from the worker's existing connection and +can use its whole budget waiting on a locked table. + +On MySQL, the stop-time attempt uses a private connection with five-second +connect, read and write timeouts. A shorter configured timeout is raised +to five seconds. These are per-operation limits, not one deadline for the +whole attempt. Host name resolution is outside these timeout bounds. +mysqlclient may retry a read, extending its effective read limit to 15 +seconds. On SQLite, database waiting during the stop-time look is bounded +by the busy timeout, not by an overall recovery deadline. The five-second +claim wait applies on MySQL and SQLite too. PostgreSQL with psycopg2 makes +no stop-time recovery attempt. + +A recovery error does not prevent shutdown. These recovery limits apply +only to the stop-time attempt. They do not bound shutdown as a whole. +Existing waits elsewhere can delay shutdown before the stop-time attempt +is reached, including MySQL claim-path reconnection and the pooled +PostgreSQL health checks that `Worker.run()` makes after a failed pass. + +`Worker.run_once()` and `testing.run_tasks()` raise the claim's original +error at once, without an immediate recovery attempt or a pending recovery +read on the next call. A claim that committed stays `RUNNING` and is left +to the reaper, which requeues it with the attempt spent or marks it `LOST` +on the final attempt. The next call does not find that landed claim while +it remains `RUNNING`. + +Threads sharing a Worker can claim concurrently. No lock is held across +a claim, including a subclass's statements after the base `claim_one()` +returns, so a database wait in one claim does not block another claim +through a Worker lock. A claim made through `run()`, `run_once()` or the +base `claim_one()` counts as in flight until its returned row is +registered. A short per-Worker lock protects this bookkeeping and is +never held across a database call. `ox_worker` does not share its Worker: +its loop claims and checks recovery on one thread. + +Neither `run_once()` nor `run_tasks()` closes the failed claim's +connection for recovery or tests idle connections in Django's PostgreSQL +pool. The caller's connection and session, including advisory locks, +temporary tables and `SET` values, are left as the claim left them. +The `run()` loop tests the pool after a failed pass. + +`run_once()` and `run_tasks()` perform no recovery either inside or +outside a caller's transaction. Inside `atomic()` or Django `TestCase`, +or when the caller has disabled autocommit, the claim belongs to the +caller's transaction and rolls back with it. + +`ox_worker --batch` does not finish while recovery is pending. On a shared +Worker, recovery deferred by another thread's claim does not hold the +batch open; the stop-time look waits up to five seconds for that claim. +If the claim is still in flight then, the look gives up with +`worker_claim_recovery_failed` and a row that landed is left to the reaper. +`--max-tasks` counts only claims +that returned; a claim that raised uses no slot. Oxpull Pro also counts +admission only for a claim that returned, so a released row is counted +when it is claimed again. No database statement is added to the ordinary task path. A recovery look uses one SELECT over `RUNNING` rows filtered to this worker. It may make follow-up SELECTs, by primary key, for rows belonging to excluded entries that the first read did not return, with one SELECT per chunk of up to 500 primary keys. Recovery then uses one conditional UPDATE per eligible row. -Failed recovery reads may be retried. If a release commits but its own -reply is lost, there is no `worker_claim_released` event for that release; -the next read finds the row already `READY`. +Failed recovery reads may be retried on later passes. If a release commits +but its own reply is lost, there is no `worker_claim_released` event for +that release; the next read finds the row already `READY`. With settings schedules, the worker opens its first connection during polling. With `DatabaseScheduleSource`, a refused startup read logs @@ -510,12 +561,17 @@ With Django's PostgreSQL pool, lease renewal uses a connection outside the pool, in addition to `max_size`. The timeout watchdog can use a second private connection whenever an attempt has a timeout. That timeout can come from the task declaration, not just `TASK_TIMEOUT` or `TASK_TIMEOUTS`. - -Budget up to `max_size + 2` server connections per worker process. This is -a worst-case budget, not a count of open connections. A worker whose tasks -never use a timeout needs only the baseline private connection, for -`max_size + 1`. An absent timeout in `OPTIONS` alone does not establish that. -Check PostgreSQL `max_connections` and role connection limits before upgrading. +With psycopg 3, a worker stopping with recovery pending opens one more +private connection outside the pool for its stop-time recovery look. + +Budget up to `max_size + 2` server connections per worker process during +normal operation, and `max_size + 3` during a stop-time recovery look. +These are worst-case budgets, not counts of open connections. A worker +whose tasks never use a timeout needs only the baseline private connection +during normal operation, for `max_size + 1`, and up to `max_size + 2` +during a stop-time recovery look. An absent timeout in `OPTIONS` alone +does not establish that tasks never use a timeout. Check PostgreSQL +`max_connections` and role connection limits before upgrading. Lease renewal normally uses a private connection outside the pool. The stock worker opens it on the first renewal tick with work in flight. It reuses the @@ -537,8 +593,10 @@ PostgreSQL's reserved slots and role connection limits. Reserved slots that the worker's role cannot use are not worker capacity. For example, two worker processes with `max_size=5` need a worst-case budget -of 14 worker connections. If no task either worker runs has a timeout, -12 suffice for the workers. These totals exclude all other clients and +of 14 worker connections in normal operation and 16 while both make a +stop-time recovery look. If no task either worker runs has a timeout, +12 suffice for the workers in normal operation, and 14 during that look. +These totals exclude all other clients and unusable reserved slots. A separate database alias needs its own budget, even when it connects to the same PostgreSQL server. @@ -1200,19 +1258,22 @@ in 1.4.0 and later, private connects that keep failing for about `LOCK_TIMEOUT`, with no pooled spare, can still do so. See [PostgreSQL pooling](#database-connections-and-postgresql-pooling). -Before 1.7.0, a claim that committed while its reply was lost could also -leave a row to lapse on its final attempt without the task body ever -running. It became `LOST` with a `TaskAbandoned` record saying that the -worker "stopped renewing its lease", although the worker had never -started the task. From 1.7.0, upgraded workers recover their own -unconfirmed claims within `LOCK_TIMEOUT`, before the row's lease -expires, and return them to `READY` with the attempt refunded. The old -outcome remains possible if the worker dies before it can check, the -database remains unreachable past `LOCK_TIMEOUT`, or the claim was made -by a worker that has not been upgraded. In a mixed fleet, an upgraded -worker does not recover another worker's claims. Rows left to the reaper -are still requeued with the attempt spent, or marked `LOST` on the final -attempt with the same `TaskAbandoned` text. +A claim that commits while its reply is lost can leave a row to lapse on +its final attempt without the task body ever running. It becomes `LOST` +with a `TaskAbandoned` record saying that the worker "stopped renewing its +lease", although the worker never started the task. `Worker.run()`, the +loop used by `ox_worker`, recovers its own unconfirmed claims on PostgreSQL +with psycopg 3, pooled or not, MySQL and SQLite. Within `LOCK_TIMEOUT` and +before the row's lease expires, it returns eligible rows to `READY` with +the attempt refunded. + +A claim can still be left to the reaper if the worker dies before it can +check, the database remains unreachable past `LOCK_TIMEOUT`, or the claim +was made by `Worker.run_once()`, `testing.run_tasks()`, a worker using +psycopg2, or a worker without recovery support. In a mixed fleet, a worker +with recovery support does not recover another worker's claims. Rows left +to the reaper are requeued with the attempt spent, or marked `LOST` on the +final attempt with the same `TaskAbandoned` text. Raising `LOCK_TIMEOUT` gives delayed renewals more time, but does not fix connection starvation and delays recovery from dead workers. See @@ -1235,15 +1296,17 @@ worker between the claim and the call has used an attempt without running, and a task that exhausts its stored budget this way reaches a terminal state having never executed. The window is small: a worker claims only when it has a free thread and hands the task straight to it. It is not zero. -A claim the worker could not confirm is different: if the worker finds -that it landed and can safely release it before its lease expires and -within the recovery window, the attempt is refunded. For that claim, -the attempt count then reflects claims that reached a worker, not the -unconfirmed claim. This does not guarantee that every counted claim ran -the task body. After a refund, `last_attempted_at` keeps the instant of -the lost claim. A `READY` row can therefore have `attempts` equal to 0 -and `last_attempted_at` set. `started_at` is cleared only when the refund -reduces `attempts` to 0. +A claim the worker could not confirm can be different: in `Worker.run()` +on PostgreSQL with psycopg 3, pooled or not, MySQL or SQLite, if the worker +finds that it landed and can safely release it before its lease expires +and within the recovery window, the attempt is refunded. This recovery +does not run with psycopg2 or in `Worker.run_once()` or +`testing.run_tasks()`. For a refunded claim, the attempt count reflects +claims that reached a worker, not the unconfirmed claim. This does not +guarantee that every counted claim ran the task body. After a refund, +`last_attempted_at` keeps the instant of the lost claim. A `READY` row can +therefore have `attempts` equal to 0 and `last_attempted_at` set. +`started_at` is cleared only when the refund reduces `attempts` to 0. At enqueue, a task's declared `max_attempts` takes precedence over the backend's `MAX_ATTEMPTS`, which defaults to 3. That value is stored on the diff --git a/docs/stability.md b/docs/stability.md index 21c9949..abd6542 100644 --- a/docs/stability.md +++ b/docs/stability.md @@ -33,13 +33,17 @@ export names this page does not list; those names are not public. or recycled, 1 when a slot hit the restart cap, and otherwise with the first other non-zero worker code. A worker killed by a signal reports `128 + the signal number`, following the shell convention. -- **The heartbeat-file protocol**: one process writes `PATH`; above one - process, the supervisor writes `PATH.supervisor` and slot i writes - `PATH.i`. The modification time is the signal; file contents are not - read or written. Every expected file must be regular and have an age - between zero and the configured maximum, inclusive. A passing check - means the expected controlling loops have advanced recently, not that - tasks are progressing. The documented +- **The heartbeat-file protocol**: with `ox_worker`, one process writes + `PATH`; above one process, the supervisor writes `PATH.supervisor` and + slot i writes `PATH.i`. The modification time is the signal; file + contents are not read or written. Every expected file must be regular + and have an age between zero and the configured maximum, inclusive. + A passing check means the expected controlling loops have advanced + recently, not that tasks are progressing. A launcher that constructs + one Worker with `heartbeat_file` and then forks it leaves the children + touching the same inherited path under their own worker ids. A fresh + shared path proves that one writer is alive, not that every child is + alive. The documented [file-mode JSON fields](monitoring.md#file-mode-json) are public too. - **The system check IDs**, including the `django_ox.E0xx` and `django_ox.W0xx` identifiers, which you may list in @@ -102,11 +106,12 @@ export names this page does not list; those names are not public. It also includes `worker_claim_released`, `worker_claim_recovery_failed`, `worker_claim_recovery_expired` and `worker_claim_release_refused`, and their documented keys. These are - stable, not provisional. The new keys include `claim_recovery`, + stable, not provisional. The recovery keys include `claim_recovery`, `old_epoch`, `new_epoch`, `refunded_attempts`, `attempts` and `worker_ids`. On `worker_poll_failed`, `claim_recovery` is `"pending"` - while a recovery read is owed, or `null` otherwise. The recovery - events also use `"expired"` as documented. + while a recovery read is owed, or `null` otherwise; with psycopg2 it + is always `null`. On `worker_claim_recovery_failed` and + `worker_claim_recovery_expired`, it is always `"expired"`. - **The testing helpers** `django_ox.testing.ImmediateBackend`, `django_ox.testing.DummyBackend` and `django_ox.testing.run_tasks`. The backends accept policy declarations but do not enforce retries, @@ -164,24 +169,107 @@ are not public. ### Worker implementation details `Worker` internals remain **Not public**. This includes `_handed_off`, -`_unsettled`, `_claimer`, `_claim`, `_claim_inline`, `_recover_claims` -and `_release_claim`. +`_unsettled`, `_fence`, `_claims_in_flight`, `_claim_generation`, +`_claiming`, `_claim`, `_claim_inline`, `_recover_claims` and +`_release_claim`. -`Worker._run_attempt` is also private. It now returns a `bool` indicating +`Worker._run_attempt` is also private. It returns a `bool` indicating whether the outcome was recorded. A subclass override that returns `None` is treated as "outcome not recorded". This keeps its row excluded from claim recovery; it does not itself change the row's outcome. -Subclass authors may notice two behaviour changes. The base -`claim_one()` now holds a per-worker reentrant lock while claiming. -Two threads claiming on the same `Worker` instance are serialised: -the second waits rather than being refused. Recovery reads use the -same lock. - -`Worker.run_once()` and `testing.run_tasks()` may raise a database error -from a pending recovery read before making any new claim. After a new -claim raises, an immediate recovery attempt does not replace the -original claim error, which is still raised to the caller. +Threads sharing a Worker can claim concurrently. No lock is held across +`claim_one()` or an override of it, including subclass statements after +the base claim returns. A database wait in one claim does not block +another claim through a Worker lock. A claim made through `run()`, +`run_once()` or the base `claim_one()` counts as in flight until its +returned row is registered. A short per-Worker lock protects this +bookkeeping and is never held across a database call. + +`Worker.run_once()` and `testing.run_tasks()` raise a claim's original +error at once. They make no immediate recovery attempt and no pending +recovery read before a later claim, whether inside or outside a caller's +transaction. A claim that committed stays `RUNNING` and is left to the +reaper, which requeues it with the attempt spent or marks it `LOST` on +the final attempt. The next call does not find that landed claim while +it remains `RUNNING`. + +Neither `run_once()` nor `run_tasks()` closes the failed claim's connection +for recovery or tests idle connections in Django's PostgreSQL pool. +The caller's connection and session, including advisory locks, temporary +tables and `SET` values, are left as the claim left them. The `run()` loop +tests the pool after a failed pass. + +Recovery runs only in `Worker.run()`, the loop used by `ox_worker`, on +PostgreSQL with psycopg 3, pooled or not, MySQL and SQLite. Pending recovery +is checked at the head of a poll pass unless another claim of the same +Worker is in flight. In that case it makes no recovery read; if a claim +begins before the look compares the claim generation, it releases nothing. +If a claim begins after that comparison, the look still releases the +orphans it read, but not that claim's row. Either way, recovery stays +pending, that pass claims as usual, and the next pass looks again. +Continuous claims on a shared Worker can keep recovery pending beyond +`LOCK_TIMEOUT`; the next look that passes the in-flight check expires +the window and releases nothing. The rows remain subject to the reaper. + +A failed recovery read ends that pass with `worker_poll_failed` and +`claim_recovery` set to `"pending"`; no new claim is made and no error is +raised to a caller. PostgreSQL with psycopg2 makes no recovery attempt. +`ox_worker` does not share its Worker: its loop claims and checks recovery +on one thread. + +The loop makes at most one recovery attempt when stopping. Only this +stop-time look has recovery-specific waiting limits. It waits up to five +seconds for claims in flight on the same Worker. If that budget runs out, +or a claim begins during the look, it gives up with +`worker_claim_recovery_failed`. A look given up because a claim began +after its claim-generation comparison may already have released rows, +each logged as `worker_claim_released`, before logging +`worker_claim_recovery_failed`. + +On PostgreSQL with psycopg 3, pooled or not, the stop-time look uses a +private connection and a five-second budget covering that claim wait, +connection establishment and every reply. Host name resolution is outside +that bound and can exceed it. The private connection does not inherit a +session-level `lock_timeout` from the worker's existing connection and +can use its whole budget waiting on a locked table. + +On MySQL, the stop-time look uses a private connection with five-second +connect, read and write timeouts, raising any shorter configured timeout +to five seconds. These limits are per operation, not an overall deadline, +and host name resolution is outside them. mysqlclient may extend a read +to 15 seconds. On SQLite, database waiting during the stop-time look is +bounded by the busy timeout, not by an overall recovery deadline. The +five-second claim wait applies on MySQL and SQLite too. A recovery error +does not prevent shutdown, and these limits do not bound shutdown as a +whole. + +A Worker used in a process forked after the Worker was created takes a +new worker id in the child, retaining any `-` suffix. An at-fork +hook re-identifies the child. For forks that run no at-fork hook, such as +uWSGI's default, a pid check does so at the child's first `claim_one()`, +claim, recovery look or `run()`. Until that check, the child's copy can +still report the parent's id. The parent keeps its id. + +The child starts with empty claim bookkeeping and fresh locks. It keeps +the inherited heartbeat path and continues touching it under its new id; +a heartbeat warning names the child's id. If several children share that +path, a fresh heartbeat proves that one writer is alive, not that every +child is alive. + +This identity handling applies, for example, to a module-level Worker used +for `run_once()` under gunicorn `--preload` or uWSGI without `lazy-apps`, +or to a launcher that forks before the Worker claims anything. Handing an +already-claimed row to a child for execution is unsupported: the row +retains the parent's id, so the child with its new id cannot renew the +lease, and the reaper can requeue it while the child runs it. + +This identity handling does not make arbitrary native forks safe or +establish that inherited database connections, threads or other resources +are safe to use. Separate worker identities prevent `Worker.run()`'s +recovery looks in one process from releasing the other's running task and +causing its body to run twice. `ox_worker --processes` starts fresh +children rather than forking them. ## Versioning diff --git a/src/django_ox/_run_tasks.py b/src/django_ox/_run_tasks.py index 2ce400e..fda6b64 100644 --- a/src/django_ox/_run_tasks.py +++ b/src/django_ox/_run_tasks.py @@ -585,12 +585,7 @@ def drain( try: while len(results) < limit: _refuse_broken_transactions() - # claim_one(), through the path run_once() takes: on a connection - # the worker owns, a claim that raised is looked for before the - # error is raised. Inside a TestCase there is no such connection - # and it is claim_one() alone. This worker lasts one call, so no - # later look is promised. - db_task = worker._claim_inline(retained=False) + db_task = worker.claim_one() if db_task is None: return results results.append(_run_one(worker, db_task, raise_failures=raise_failures)) diff --git a/src/django_ox/worker.py b/src/django_ox/worker.py index 20fb286..3d40305 100644 --- a/src/django_ox/worker.py +++ b/src/django_ox/worker.py @@ -13,6 +13,7 @@ import threading import time import uuid +import weakref from collections.abc import Callable, Coroutine, Generator, Iterator, Mapping from concurrent.futures import FIRST_COMPLETED, Future, ThreadPoolExecutor, wait from contextlib import ( @@ -27,7 +28,7 @@ from dataclasses import dataclass from datetime import UTC, datetime, timedelta from inspect import iscoroutinefunction -from threading import Barrier, BrokenBarrierError, Condition, Event, Lock, RLock, Thread +from threading import Barrier, BrokenBarrierError, Condition, Event, Lock, Thread from traceback import format_exception from typing import Any, cast @@ -150,20 +151,6 @@ # before 3.32 refuses a statement with more than 999 parameters. RECOVERY_READ_CHUNK = 500 -# What a worker_claim_recovery_failed record says will happen next, after a -# claim error in run_once(), whose Worker the caller keeps, and in -# run_tasks(), whose Worker lasts one call. -CLAIM_RECOVERY_RETAINED = ( - "Claim outcome is unknown. This Worker will look again before its next " - "claim while the LOCK_TIMEOUT recovery window remains open. Recovery is not " - "guaranteed; an unrecovered claim may be reaped with its attempt spent." -) -CLAIM_RECOVERY_NOT_RETAINED = ( - "Claim outcome is unknown. Recovery looks are limited to this run_tasks() " - "call; pending recovery state is not retained for later calls. Recovery is " - "not guaranteed; an unrecovered claim may be reaped with its attempt spent." -) - # The task path of the attempt Worker.execute() is running in this context, or # None outside one. django_ox.testing.run_tasks() reads it to refuse a drain # started from inside a task. A context variable rather than a thread-local or @@ -172,6 +159,40 @@ # that builds a worker of its own. _executing: ContextVar[str | None] = ContextVar("django_ox_executing", default=None) +# Every Worker alive in this process, for _reinitialize_forked_workers. Weak, +# so the registry never keeps a Worker alive: run_tasks() builds one per call. +_live_workers: "weakref.WeakSet[Worker]" = weakref.WeakSet() + +# The lock Worker._in_own_process takes, one per process, keyed by pid. A +# lock a child inherits may be held by a thread of the parent's that the +# child does not have, so a process only ever takes the one under its own. +_reidentifying: dict[int, Lock] = {} + + +def _reinitialize_forked_workers() -> None: + """ + In the child of an os.fork(), give every Worker the fork copied a new + identity and state of its own: Worker._after_fork_in_child. + + A Worker built before a fork is in both processes afterwards, as with a + module-level Worker in a web server that forks after importing the + application, or a launcher that forks a Worker it has built. Both copies + would claim under one worker id with bookkeeping of their own, and a + look for a claim that raised in one would take the other's executing + row for its own and release it. Registered once, at import, for every + Worker in the process, rather than per instance. + + A fork that runs no at-fork hook, as uWSGI's does by default, is caught + later, by Worker._in_own_process, before the child's copy claims, looks + or runs its loop. + """ + for worker in list(_live_workers): + worker._after_fork_in_child() + + +if hasattr(os, "register_at_fork"): + os.register_at_fork(after_in_child=_reinitialize_forked_workers) + def _load_async_exc_injector() -> Callable[[int], None] | None: """ @@ -954,6 +975,21 @@ def _close_lost_connection(conn: Any) -> None: _sweep_pool(conn) +def _looks_for_claims(conn: Any) -> bool: + """ + Whether run() looks for a claim of its own that raised on `conn`'s + database: everywhere but PostgreSQL with psycopg2, whose look could not + be bounded, _answering_by, and whose claim that raised is left to the + reaper, as before there was a look. Read from the wrapper alone, so it + never connects. + """ + if conn.vendor != "postgresql": + return True + from django.db.backends.postgresql.psycopg_any import is_psycopg3 + + return bool(is_psycopg3) + + def _worker_may_use(conn: Any) -> bool: """ Whether a look for a claim that raised may run on `conn`, and close it @@ -1511,6 +1547,11 @@ def missed(self, why: str, pool_why: str) -> None: self.unreported = 0 +def _new_worker_id(suffix: str) -> str: + """A worker id for this process: host, pid, a random part, then `suffix`.""" + return f"{socket.gethostname()[:40]}-{os.getpid()}-{get_random_string(8)}{suffix}" + + class Worker: """ Claims READY tasks and executes them, at least once. @@ -1709,10 +1750,12 @@ def __init__( # log line or a worker_ids entry names the slot as well as the pid. # It rides on the id rather than replacing the random part; a # restarted slot is a new worker and must not inherit the old lease. - suffix = "" if worker_index is None else f"-{worker_index}" - self.worker_id = ( - f"{socket.gethostname()[:40]}-{os.getpid()}-{get_random_string(8)}{suffix}" - ) + # A child of os.fork() gets a new id with the same suffix; + # _after_fork_in_child. + self._worker_id_suffix = "" if worker_index is None else f"-{worker_index}" + self.worker_id = _new_worker_id(self._worker_id_suffix) + # The process this Worker's id and locks belong to; _in_own_process. + self._pid = os.getpid() # Updated at the head of every poll and drain pass and before each # claim, and nowhere else; django_ox.heartbeat says what a fresh file # does and does not prove. @@ -1761,13 +1804,30 @@ def __init__( # whose row no look can see stays, however long. self._handed_off: set[tuple[Any, int]] = set() self._unsettled: set[tuple[Any, int]] = set() - # One claimer per worker at a time: every claim, and every look for - # a claim that raised, holds it. A look that ran while another claim - # was on its way back would find that claim's row RUNNING under this - # worker's id and in none of the sets above. Reentrant, because - # claim_one() takes it too and the entry points call claim_one() - # holding it. - self._claimer = RLock() + # The claim fence. A look that ran while a claim was on its way back + # would find that claim's row RUNNING under this worker's id and in + # none of the sets above. So every claim, run()'s, run_once()'s and + # the base claim_one()'s, counts itself in flight and moves the + # generation on before it claims, and counts itself out only once + # the row it returned is in _handed_off; a look makes no read while + # a claim is in flight, and releases nothing if the generation moved + # while it read. The lock guards those two numbers and nothing else, + # and is never held across a database call: a claim that waits on + # the database, an override's own statements after the base claim + # included, holds up no other claim of this worker's. Claims made + # inside claims count twice, which is what an override that calls + # the base claim_one() does. _claiming, _recover_claims. + # + # A claim can run on a task's thread, under a timeout, so claims and + # looks take the raw lock the way _disarm takes the injection lock + # below, never through the Condition: its with statement is Python, + # and an exception delivered inside it leaves the lock held. The + # Condition is for the stop-time look's wait alone, + # _recover_claims_by. + self._fence_lock = Lock() + self._fence = Condition(self._fence_lock) + self._claims_in_flight = 0 + self._claim_generation = 0 # time.monotonic() of the most recent claim_one() that raised a # database error on a connection the worker owned, while no look # since has settled it; None otherwise. See _recover_claims. @@ -1815,6 +1875,93 @@ def __init__( # only timeouts are tasks' own finds out. if self.timeouts.enabled and _inject_async_exc is None: self._note_injection_unavailable() + # Last, so a fork never finds a Worker whose __init__ has not run. + _live_workers.add(self) + + def _in_own_process(self) -> None: + """ + Make this Worker the current process's own, _after_fork_in_child, + when the process is not the one it was built in or last made its + own in: a copy made by a fork that ran no at-fork hook, as uWSGI's + does unless told to. Called first by claim_one(), _claim(), the + looks and run(), before any of the Worker's locks is touched, since + an inherited one may be held forever. Costs one getpid() otherwise. + """ + pid = os.getpid() + if self._pid == pid: + return + # Taken as _claiming takes the fence: a claim's thread runs this. + lock = _reidentifying.setdefault(pid, Lock()) + held: list[bool] = [] + try: + held.extend(map(lock.acquire, (True,))) + if self._pid != pid: + self._after_fork_in_child() + finally: + if held: + lock.release() + + def _after_fork_in_child(self) -> None: + """ + Called in the child of a fork for a Worker the fork copied, by the + at-fork hook or else by _in_own_process: make the child's copy a + worker of its own, and leave the parent's alone. The parent keeps + its id, its rows and its bookkeeping. + + - A new worker id, with the same slot suffix. Every row the child + claims carries it, so neither process's look for a claim that + raised can take the other's row for its own; _recover_claims. + - Bookkeeping empty: _in_flight, _handed_off and _unsettled name + the parent's executions, and so do the timeout watches and the + maps of the parent's pool threads, none of which exist here. No + look pending, no claim in flight, and no count of claims: the + parent made those. + - Every lock new, and every Condition and Event built on one. A + lock another thread held when the process forked stays held in + the child forever, with no thread left to release it. The stop + flag keeps its state. + - The same heartbeat file, which the child goes on updating, as a + launcher that builds the Worker and forks it expects; what it + reports names the child's id. + - The dispatch report and the notices said once per worker start + over, under the new id. + + The process is recorded last, so _in_own_process in another thread + finds it only once everything above is in place. + """ + self.worker_id = _new_worker_id(self._worker_id_suffix) + self._heartbeat = ( + HeartbeatFile(self.heartbeat_file, owner=f"Worker {self.worker_id}") + if self.heartbeat_file + else None + ) + stop = Event() + if self._stop.is_set(): + stop.set() + self._stop = stop + self._claimed = 0 + self._claim_contended = False + self._dispatch_report = _DispatchReport(self.worker_id, self._db_alias) + self._in_flight = set() + self._in_flight_lock = Lock() + self._handed_off = set() + self._unsettled = set() + self._fence_lock = Lock() + self._fence = Condition(self._fence_lock) + self._claims_in_flight = 0 + self._claim_generation = 0 + self._claim_unconfirmed_at = None + self._watches = {} + self._watch_lock = Lock() + self._watch_cv = Condition(self._watch_lock) + self._watchdog = None + self._stuck = {} + self._running_on = {} + self._recycling = False + self._backstop_only_notice = False + self._claim_filter_notice = False + self._backstop_only_lock = Lock() + self._pid = os.getpid() # -- logging ----------------------------------------------------------- @@ -1985,13 +2132,12 @@ def _claim_one_postgresql(self, run_after_cutoff: datetime) -> OxTask | None: def claim_one(self) -> OxTask | None: """Atomically claim the next runnable task, or return None.""" - # Under the claimer lock, and registered before it is released, so a - # caller that claims here directly and executes the row later is - # never taken for a claim that raised; see _recover_claims. - with self._claimer: - db_task = self._claim_one() - if db_task is not None: - self._hand_off(db_task) + self._in_own_process() + # Inside the claim fence, and registered before the claim counts + # itself out, so a caller that claims here directly and executes the + # row later is never taken for a claim that raised; see + # _recover_claims. + db_task = self._claiming(self._claim_one) if db_task is not None: logger.debug( "Claimed task id=%s path=%s (attempt %d/%d)", @@ -2097,48 +2243,122 @@ def _reload_claimed(self, pk: uuid.UUID, granted_epoch: int) -> OxTask | None: def _hand_off(self, db_task: OxTask) -> None: """ Register a claim that returned, until execute() moves it into - _in_flight. + _in_flight. The lock is taken as _claiming takes the fence's. """ - with self._in_flight_lock: - self._handed_off.add((db_task.pk, db_task.lease_epoch)) + entry = (db_task.pk, db_task.lease_epoch) + lock = self._in_flight_lock + held: list[bool] = [] + try: + held.extend(map(lock.acquire, (True,))) + self._handed_off.add(entry) + finally: + if held: + lock.release() - def _claim(self, *, owned: bool | None = None) -> OxTask | None: + def _claiming(self, claim: Callable[[], OxTask | None]) -> OxTask | None: + """ + The claim fence around one claim: counted in flight, and the claim + generation moved on, before `claim` runs; the row it returns + registered, _hand_off; then counted out, however it ended, so a + claim that raised never holds a look off. Nothing is held while + `claim` runs. + + A task's thread can run this under a timeout, and an exception + delivered to it, the watchdog's TaskTimeout or a KeyboardInterrupt, + lands at the next instruction that checks for one. Each acquire is + _disarm's: recorded in `held` by the same instruction, inside the + try whose finally releases it, so no delivery leaves the lock held. + The count-out is set up before the count-in, and counts the claim + out in the finally that follows its own acquire, so a delivery + anywhere after the count-in still counts it out. The count goes up + before `counted` records it: a delivery between the two could only + leave the count too high, which makes looks defer as they do to a + claim in flight, never too low. """ - claim_one() as run(), run_once() and run_tasks() call it. + lock = self._fence_lock + counted: list[bool] = [] + # The count-out's acquire, built before the count-in, so that the + # count-out's first instruction that can take a delivery is the one + # after its acquire. + count_out = map(lock.acquire, (True,)) + try: + held: list[bool] = [] + try: + held.extend(map(lock.acquire, (True,))) + self._claims_in_flight += 1 + self._claim_generation += 1 + counted.append(True) + finally: + if held: + lock.release() + db_task = claim() + if db_task is not None: + self._hand_off(db_task) + return db_task + finally: + # Counted out on the fence it was counted on. A fork that made + # the Worker another process's own in between gave it a new + # fence, which never counted this claim, and the old one's lock + # may be held by a thread the child does not have. + if counted and self._fence_lock is lock: + held = [] + try: + held.extend(count_out) + finally: + if held: + try: + self._claims_in_flight -= 1 + if not self._claims_in_flight: + self._fence.notify_all() + finally: + lock.release() + + def _claim(self, *, recover: bool = True) -> OxTask | None: + """ + claim_one() as run() and run_once() call it. A claim can commit and still raise: the connection goes after the server has applied it and before its reply arrives. The row is then RUNNING under this worker's id with an attempt charged, nothing runs it and nothing renews it, and it waits out its lease until a reaper takes it back with the attempt spent, or marks it LOST on its last. - Nothing here replays the claim or takes the error for a rollback. The - failure is noted, and _recover_claims later reads what the database - holds. - - Noted only for a connection the worker owned when the claim began, - _owns_connection. `owned` is that decision when the caller has made it - already, as _claim_inline does; otherwise it is made here, before the - claim. Every database error out of claim_one() is noted, whichever - statement raised it: an override may make reads of its own first, and - a look that finds nothing costs one read on a path that has already - failed. - - The row a claim returns is registered before the claimer lock is - released, here as well as in the base claim_one(), so an override that - claims without calling it is covered too. + Nothing here replays the claim or takes the error for a rollback. For + run()'s claims the failure is noted, and _recover_claims later reads + what the database holds. + + Noted only when `recover` is set, as run() leaves it; only for a + connection the worker owned when the claim began, _owns_connection, + decided here, before the claim; and only where the look can be + bounded, _looks_for_claims. Every database error out of claim_one() + is noted, whichever statement raised it: an override may make reads + of its own first, and a look that finds nothing costs one read on a + path that has already failed. + + The whole of claim_one(), an override's included, runs inside the + claim fence, _claiming, with no lock held across it: an override's + own statements after the base claim can wait on the database without + holding up another claim of this worker's. The row it returns is + registered before the claim counts itself out, here as well as in + the base claim_one(), so an override that claims without calling it + is covered too; so is the note of a claim that raised, which a look + already under way therefore never clears. """ - if owned is None: - owned = self._owns_connection() - with self._claimer: + self._in_own_process() + noted = ( + recover + and self._owns_connection() + and _looks_for_claims(connections[self._db_alias]) + ) + + def claim() -> OxTask | None: try: - db_task = self.claim_one() + return self.claim_one() except Error: - if owned: + if noted: self._claim_unconfirmed_at = time.monotonic() raise - if db_task is not None: - self._hand_off(db_task) - return db_task + + return self._claiming(claim) def _owns_connection(self) -> bool: """ @@ -2152,90 +2372,54 @@ def _owns_connection(self) -> bool: conn = connections[self._db_alias] return not conn.in_atomic_block and conn.get_autocommit() - def _claim_inline(self, *, retained: bool = True) -> OxTask | None: + def _claim_inline(self) -> OxTask | None: """ - _claim() for run_once() and run_tasks(), on the caller's thread. - - A look still pending from an earlier call comes first, as run() makes - it before a claim pass, and a database error from it is raised: no - claim is made until it has been answered or its window has passed. - - Whether the claim is the worker's own is decided before it starts, - and the error path acts on that decision. When the claim raises on a - connection the worker owned, one look is made there and then, and the - claim's own error is raised whatever the look did. When it did not, - no look is made: the connection, and any transaction open on it, are - the caller's, and a look already pending stays pending. A look that - fails is logged and stays pending; it never takes the place of the - error the caller has to see. A row it releases is claimed by a later - call, here or anywhere else. - - `retained` is False for run_tasks(), whose worker lasts one call, and - selects what that log says about a later look. + _claim() for run_once(), on the caller's thread; run_tasks() calls + claim_one() itself, which is the same but for the registration an + override of claim_one() may skip, and its Worker lasts one call. + + A claim that raises is raised at once, and nothing else is done: + it is not noted, no look is made for it or for one noted earlier, + and the caller's connection is left as the claim left it, with + whatever the caller holds on its session. A claim that committed + before its reply was lost is the reaper's once its lease expires, + as it always was for these calls. Only run() looks for such a + claim, on its own thread. """ - self._recover_claims() - owned = self._owns_connection() - try: - return self._claim(owned=owned) - except Error: - if owned: - self._recover_claims_once(stopping=False, retained=retained) - raise + return self._claim(recover=False) def _claim_recovery(self) -> str | None: """For log records: "pending" while a look is owed, else None.""" return None if self._claim_unconfirmed_at is None else "pending" - def _recover_claims_once(self, *, stopping: bool, retained: bool = True) -> None: + def _recover_claims_once(self) -> None: """ - _recover_claims(), with anything it raises logged rather than raised: - after a claim error that must reach the caller unchanged, and as the - worker stops. Stopping, the look is the bounded one, - _recover_claims_by; otherwise it follows a claim the worker owned - that raised, _claim_inline. `retained` is False when this worker - will not be asked to claim again, and so will not look again: - run_tasks(). + The bounded look, _recover_claims_by, as the worker stops, with + anything it raises logged rather than raised: whatever is left is + the reaper's. """ + self._in_own_process() if self._claim_unconfirmed_at is None: return try: - if stopping: - self._recover_claims_by(time.monotonic() + OWN_CONNECTION_DEADLINE) - else: - self._recover_claims(after_own_claim=True) + self._recover_claims_by(time.monotonic() + OWN_CONNECTION_DEADLINE) except Exception as exc: - conn = connections[self._db_alias] - if not stopping and _worker_may_use(conn): - # The next statement on this thread reconnects rather than - # failing on the same dead connection. A connection out of - # autocommit or inside an atomic block may hold a caller's - # transaction, and is left exactly as it is. Stopping, there - # is no next statement, and a pool sweep could wait on the - # very server the deadline gave up on. - _close_lost_connection(conn) - if stopping: - then = ( - "It is stopping, so a row that did land is the reaper's once " - "its lease expires, with the attempt charged" - ) - elif retained: - then = CLAIM_RECOVERY_RETAINED - else: - then = CLAIM_RECOVERY_NOT_RETAINED - # run_tasks() makes no later look, so none is pending. - state = "pending" if retained and not stopping else "expired" + # The thread's connection is left as it is: there is no next + # statement, and a pool sweep could wait on the very server the + # deadline gave up on. logger.warning( "Worker %s could not look for a claim of its own that raised " - "and may have committed (%s: %s). %s", + "and may have committed (%s: %s). It is stopping, so a row that " + "did land is the reaper's once its lease expires, with the " + "attempt charged", self.worker_id, type(exc).__qualname__, _reason(exc), - then, exc_info=True, extra={ "event": "worker_claim_recovery_failed", "worker_id": self.worker_id, - "claim_recovery": state, + "claim_recovery": "expired", }, ) @@ -2243,61 +2427,85 @@ def _recover_claims_by(self, deadline: float) -> None: """ _recover_claims() as a stopping worker makes it: done by `deadline`, on time.monotonic(), or given up, on PostgreSQL with psycopg 3; with - each wait on the server bounded, on MySQL. - - The wait for the claimer lock ends at the deadline, and the look runs - on a connection of the thread's own, _answering_by. On PostgreSQL it - opens by the deadline, or by a shorter positive connect_timeout, and - every reply is held to the deadline, so a database that is gone, or + each wait on the server bounded, on MySQL. Returns at once when no + look is pending. + + A claim of this worker's in flight on another thread is waited for, + and the wait ends at the deadline. A claim that begins while the + look is under way leaves it pending, _recover_claims, and the look + is given up then too: the worker is stopping and makes no other. + The look runs on a connection of the thread's own, _answering_by. On + PostgreSQL it opens by the deadline, or by a shorter positive + connect_timeout, and every reply is held to the deadline, so a + database that is gone, or that stops answering once connected, costs the stop no more than - that. On MySQL its connect, read and write timeouts bound each - operation instead, not the look as a whole. A look given up is a - look that failed: nothing is inferred from it and nothing is - refunded, and a row that did land is the reaper's. It is not made - while the thread's connection may hold a caller's transaction, as - _recover_claims says. - - On any other database, and with psycopg2, the look runs on the - thread's connection, as _recover_claims does, bounded only by the - driver's own timeouts. + that. It is never one of Django's pool's. On MySQL its connect, read + and write timeouts bound each operation instead, not the look as a + whole. A look given up is a look that failed: nothing is inferred + from it and nothing is refunded, and a row that did land is the + reaper's. It is not made while the thread's connection may hold a + caller's transaction, as _recover_claims says. + + On any other database the look runs on the thread's connection, as + _recover_claims does, bounded only by the driver's own timeouts. """ + self._in_own_process() + if self._claim_unconfirmed_at is None: + return if not _worker_may_use(connections[self._db_alias]): return - if not self._claimer.acquire(timeout=max(deadline - time.monotonic(), 0.0)): - raise TimeoutError("another claim of this worker's held the claimer lock") + # The fence this call waits on is the one it releases, whatever + # self._fence names by then. It is never held across a statement, + # so the acquire is short, and bounded all the same. It is taken as + # _claiming takes it, so that no delivery between the acquire and + # the try leaves it held; the Condition is used for the wait alone. + fence, lock = self._fence, self._fence_lock + taken: list[bool] = [] try: - with _answering_by(self._db_alias, deadline): - self._recover_claims() + taken.extend( + map(lock.acquire, (True,), (max(deadline - time.monotonic(), 0.0),)) + ) + clear = taken[0] and fence.wait_for( + lambda: not self._claims_in_flight, + timeout=max(deadline - time.monotonic(), 0.0), + ) finally: - self._claimer.release() + if taken and taken[0]: + lock.release() + if not clear: + raise TimeoutError("another claim of this worker's was on its way back") + with _answering_by(self._db_alias, deadline): + if not self._recover_claims(): + raise RuntimeError( + "another claim of this worker's began while it looked" + ) - def _recovery_connection(self, conn: Any, *, after_own_claim: bool) -> None: + def _recovery_connection(self, conn: Any) -> None: """ - Leave `conn`, which is outside any atomic block, with no connection - open, or with one that answers and is in autocommit, so the look runs - on a connection that answers rather than the one a claim just failed - on. One that is not is closed and, with Django's PostgreSQL pool, the - pool's idle connections are swept, _close_lost_connection: after a - restart they are as dead as this one. With none open, the look's read - opens one. + Leave `conn`, which is outside any atomic block and in autocommit or + not yet open, with no connection open, or with one that answers, so + the look runs on a connection that answers rather than one a claim + just failed on. One that does not is closed, and the look's read + opens another. It holds no transaction, being in autocommit. Only on the recovery path, where the probe's round trip is paid once - per look. A connection out of autocommit reaches this only with - `after_own_claim`, as _recover_claims says: whatever it still holds is - the claim's. Any other that is closed here is in autocommit and holds - no transaction. + per look. A look _recover_claims_by makes on a connection of its own + finds it not yet open and pays nothing. Django's pool is not swept + here: run()'s failed pass sweeps it, and nothing on a caller's + thread does. """ if conn.connection is None: return - if conn.autocommit and conn.is_usable(): - return - if conn.autocommit or after_own_claim: - _close_lost_connection(conn) + if not conn.is_usable(): + with suppress(Error): + conn.close() - def _recover_claims(self, *, after_own_claim: bool = False) -> None: + def _recover_claims(self) -> bool: """ Look for a claim of this worker's that raised and may have committed, and put each one found back on the queue with its attempt refunded. + Returns False when a claim of this worker's leaves the look pending, + as below, and True otherwise. Only while one is pending, as _claim noted it; only within LOCK_TIMEOUT of the latest claim that raised, after which it stops @@ -2305,27 +2513,34 @@ def _recover_claims(self, *, after_own_claim: bool = False) -> None: and only on a connection _worker_may_use passes, checked again here whoever asks: never inside an atomic block or on a connection out of autocommit, which may hold a caller's transaction. Returns at once - when nothing is pending, so the ordinary path pays nothing. - - One exception, `after_own_claim`: the look _claim_inline makes at - once when a claim raised that began on a connection the worker owned, - autocommit on and no atomic block open, decided before the claim. If - that connection is now out of autocommit outside any atomic block, - the claim's own block failed to put autocommit back, as when the - reply lost was the one to SET autocommit=1 after the COMMIT, and - nothing else has run on it since, so whatever it holds is the - claim's. It is closed and the look runs on a new connection. + when nothing is pending, so the ordinary path pays nothing. A claim + of the worker's own that left its connection out of autocommit has + had that connection closed first, by run()'s failed pass: Django's + close_old_connections() closes a connection whose autocommit is not + the configured one. The look is one read on a usable connection: every row RUNNING under this worker's id, less those in _in_flight, _handed_off and _unsettled, taken as one snapshot under their lock before the read. - The claimer lock is held throughout, so no claim is on its way back - while it runs, and every claim that returned is in one of those sets - until its outcome is recorded. The worker id belongs to this Worker - instance alone, so no other worker's row can match. What is left is a - claim that raised. Absence from _in_flight alone is never taken as - that: a claim still being handed to a pool thread, and an execution - whose outcome could not be recorded, are absent from it too. + A claim on its way back, committed and not yet registered, would be + in none of them, so the claim fence decides whether the look may + use what it read, _claiming. It makes no read while a claim of this + worker's is in flight; it takes the snapshot after that check; and + if a claim has begun since the check, whose row the read may have + seen before the claim registered it, it releases nothing and the + look stays pending. A claim that begins after that comparison + commits after the read, so its row is not among those released, but + it may yet raise, and the look stays pending for it too. Neither + check waits, and no statement runs under the fence's lock: a look + that meets a claim is made again on the next pass. Every claim that + returned is in one of the sets until its outcome is recorded. The + worker id belongs to this Worker instance alone, so no other + worker's row can match: a copy of the + Worker that a fork made gets a new id in the child before it claims + or looks, _after_fork_in_child. What is left is a claim that raised. + Absence from _in_flight alone is never taken as that: a claim still + being handed to a pool thread, and an execution whose outcome could + not be recorded, are absent from it too. A row whose lease the reaper would already take is left to the reaper: the read carries the reaper's own test of the lease, on the @@ -2364,134 +2579,173 @@ def _recover_claims(self, *, after_own_claim: bool = False) -> None: READY and has nothing to do. That look is never a claim: a released row is claimed afresh, by this worker or another, and charged then. """ - with self._claimer: + self._in_own_process() + # The fence's lock is taken as _claiming takes it, here too: from + # Python 3.14 a with statement acquires one instruction before its + # cleanup covers the lock. + lock = self._fence_lock + held: list[bool] = [] + try: + held.extend(map(lock.acquire, (True,))) + if self._claims_in_flight: + return False since = self._claim_unconfirmed_at if since is None: - return - if time.monotonic() - since > self.lock_timeout: + return True + generation = self._claim_generation + expired = time.monotonic() - since > self.lock_timeout + if expired: self._claim_unconfirmed_at = None + finally: + if held: + lock.release() + if expired: + logger.warning( + "Worker %s stopped looking for a claim of its own that " + "raised and may have committed: %gs have passed since it " + "raised. A row that did land is the reaper's once its " + "lease expires, with the attempt charged", + self.worker_id, + self.lock_timeout, + extra={ + "event": "worker_claim_recovery_expired", + "worker_id": self.worker_id, + "claim_recovery": "expired", + }, + ) + return True + conn = connections[self._db_alias] + if not _worker_may_use(conn): + return True + self._recovery_connection(conn) + with self._in_flight_lock: + known = self._in_flight | self._handed_off | self._unsettled + examined = self._handed_off | self._unsettled + cutoff = _lease_now() - timedelta(seconds=self.lock_timeout) + rows = list( + OxTask.objects.using(self._db_alias) + .filter(status=OxTask.Status.RUNNING, locked_by=self.worker_id) + .annotate( + ox_lease_abandoned=ExpressionWrapper( + self._abandoned_lease_q(cutoff), output_field=BooleanField() + ) + ) + .values_list( + "pk", + "lease_epoch", + "attempts", + "worker_ids", + "task_path", + "queue_name", + "ox_lease_abandoned", + ) + ) + # Positive evidence only, as the docstring says: absence from the + # read above is not evidence, since an uncommitted claim is absent + # from it too. A claim made since the check cannot undo it: every + # claim moves the epoch, and only entries in the snapshot are judged. + state: dict[Any, tuple[int, str, str | None]] = { + pk: (epoch, OxTask.Status.RUNNING, self.worker_id) for pk, epoch, *_ in rows + } + unseen = list({pk for pk, _ in examined} - state.keys()) + for start in range(0, len(unseen), RECOVERY_READ_CHUNK): + for pk, epoch, status, owner in ( + OxTask.objects.using(self._db_alias) + .filter(pk__in=unseen[start : start + RECOVERY_READ_CHUNK]) + .values_list("pk", "lease_epoch", "status", "locked_by") + ): + state[pk] = (epoch, status, owner) + over: set[tuple[Any, int]] = set() + for pk, epoch in examined: + if pk not in state: + continue + row_epoch, status, owner = state[pk] + if row_epoch > epoch or ( + row_epoch == epoch + and (status != OxTask.Status.RUNNING or owner != self.worker_id) + ): + over.add((pk, epoch)) + with self._in_flight_lock: + self._handed_off -= over + self._unsettled -= over + # A claim that began after the check may have committed before the + # read and registered after the snapshot: its row would be in `rows` + # and not in `known`. One that begins after this comparison committed + # after the read, so its row is not in `rows`. + held = [] + try: + held.extend(map(lock.acquire, (True,))) + moved = self._fence_lock is not lock or self._claim_generation != generation + finally: + if held: + lock.release() + if moved: + return False + known_pks = {pk for pk, _ in known} + for pk, epoch, attempts, history, task_path, queue, abandoned in rows: + if pk in known_pks: + continue + if abandoned: logger.warning( - "Worker %s stopped looking for a claim of its own that " - "raised and may have committed: %gs have passed since it " - "raised. A row that did land is the reaper's once its " - "lease expires, with the attempt charged", + "Worker %s found task id=%s path=%s RUNNING under its " + "own id though no claim of it returned. Its lease has " + "expired, so it is the reaper's, with the attempt " + "charged", self.worker_id, - self.lock_timeout, + pk, + task_path, extra={ "event": "worker_claim_recovery_expired", + "task_id": str(pk), + "task_path": task_path, + "queue": queue, "worker_id": self.worker_id, "claim_recovery": "expired", }, ) - return - conn = connections[self._db_alias] - if conn.in_atomic_block or not (after_own_claim or _worker_may_use(conn)): - return - self._recovery_connection(conn, after_own_claim=after_own_claim) - with self._in_flight_lock: - known = self._in_flight | self._handed_off | self._unsettled - examined = self._handed_off | self._unsettled - cutoff = _lease_now() - timedelta(seconds=self.lock_timeout) - rows = list( - OxTask.objects.using(self._db_alias) - .filter(status=OxTask.Status.RUNNING, locked_by=self.worker_id) - .annotate( - ox_lease_abandoned=ExpressionWrapper( - self._abandoned_lease_q(cutoff), output_field=BooleanField() - ) - ) - .values_list( - "pk", - "lease_epoch", - "attempts", - "worker_ids", - "task_path", - "queue_name", - "ox_lease_abandoned", + continue + if not ( + isinstance(history, list) + and attempts >= 1 + and len(history) == attempts + and history[-1] == self.worker_id + ): + logger.error( + "Worker %s found task id=%s path=%s RUNNING under its " + "own id though no claim of it returned, and did not " + "release it: its history does not hold one entry per " + "attempt ending with this worker (attempts %s, " + "worker_ids %r). The reaper takes it back once its " + "lease expires", + self.worker_id, + pk, + task_path, + attempts, + history, + extra={ + "event": "worker_claim_release_refused", + "task_id": str(pk), + "task_path": task_path, + "queue": queue, + "worker_id": self.worker_id, + "attempts": attempts, + "worker_ids": history, + }, ) - ) - # Positive evidence only, as the docstring says: absence from - # the read above is not evidence, since an uncommitted claim is - # absent from it too. - state: dict[Any, tuple[int, str, str | None]] = { - pk: (epoch, OxTask.Status.RUNNING, self.worker_id) - for pk, epoch, *_ in rows - } - unseen = list({pk for pk, _ in examined} - state.keys()) - for start in range(0, len(unseen), RECOVERY_READ_CHUNK): - for pk, epoch, status, owner in ( - OxTask.objects.using(self._db_alias) - .filter(pk__in=unseen[start : start + RECOVERY_READ_CHUNK]) - .values_list("pk", "lease_epoch", "status", "locked_by") - ): - state[pk] = (epoch, status, owner) - over: set[tuple[Any, int]] = set() - for pk, epoch in examined: - if pk not in state: - continue - row_epoch, status, owner = state[pk] - if row_epoch > epoch or ( - row_epoch == epoch - and (status != OxTask.Status.RUNNING or owner != self.worker_id) - ): - over.add((pk, epoch)) - with self._in_flight_lock: - self._handed_off -= over - self._unsettled -= over - known_pks = {pk for pk, _ in known} - for pk, epoch, attempts, history, task_path, queue, abandoned in rows: - if pk in known_pks: - continue - if abandoned: - logger.warning( - "Worker %s found task id=%s path=%s RUNNING under its " - "own id though no claim of it returned. Its lease has " - "expired, so it is the reaper's, with the attempt " - "charged", - self.worker_id, - pk, - task_path, - extra={ - "event": "worker_claim_recovery_expired", - "task_id": str(pk), - "task_path": task_path, - "queue": queue, - "worker_id": self.worker_id, - "claim_recovery": "expired", - }, - ) - continue - if not ( - isinstance(history, list) - and attempts >= 1 - and len(history) == attempts - and history[-1] == self.worker_id - ): - logger.error( - "Worker %s found task id=%s path=%s RUNNING under its " - "own id though no claim of it returned, and did not " - "release it: its history does not hold one entry per " - "attempt ending with this worker (attempts %s, " - "worker_ids %r). The reaper takes it back once its " - "lease expires", - self.worker_id, - pk, - task_path, - attempts, - history, - extra={ - "event": "worker_claim_release_refused", - "task_id": str(pk), - "task_path": task_path, - "queue": queue, - "worker_id": self.worker_id, - "attempts": attempts, - "worker_ids": history, - }, - ) - continue - self._release_claim(pk, epoch, attempts, history, task_path, queue) + continue + self._release_claim(pk, epoch, attempts, history, task_path, queue) + # Cleared only if no claim began since the check: one that raised + # meanwhile noted a look this one has not made. + held = [] + try: + held.extend(map(lock.acquire, (True,))) + if self._fence_lock is not lock or self._claim_generation != generation: + return False self._claim_unconfirmed_at = None + finally: + if held: + lock.release() + return True def _release_claim( self, @@ -5259,14 +5513,6 @@ def run_once(self) -> bool: A connection taken out of autocommit without an atomic block still gets renewal. The task can commit and make its lease visible while it runs. An atomic block on a different database does not disable renewal. - - A claim that raises is raised, but on a connection the worker owns - (autocommit, no atomic block of the caller's) it may have committed - all the same. One look for such a row is made before the error is - raised, and a row it finds goes back to READY with its attempt - refunded, for a later call to run; the claim's own error is what the - caller gets either way. - See _claim_inline. """ in_callers_transaction = connections[self._db_alias].in_atomic_block db_task = self._claim_inline() @@ -5379,6 +5625,7 @@ def _execute_in_thread(self, db_task: OxTask) -> None: def run(self) -> None: """Poll for tasks until request_stop(), then drain in-flight tasks.""" + self._in_own_process() logger.info( "Worker %s starting: queues=%s concurrency=%d poll=%.1fs schedules=%d", self.worker_id, @@ -5489,7 +5736,9 @@ def run(self) -> None: # id that nothing will run. A look that fails raises into # the handler below like any failed pass, still pending, # and this pass claims nothing. _recover_claims says when - # it looks and what it releases. + # it looks and what it releases. One that meets a claim + # of this Worker's made on another thread stays pending, + # and this pass claims as usual. self._recover_claims() in_flight = {f for f in in_flight if not f.done()} # Read before claiming, not after: a task still running @@ -5616,7 +5865,7 @@ def run(self) -> None: # on PostgreSQL given up after OWN_CONNECTION_DEADLINE and on # MySQL with each wait bounded, _recover_claims_by: whatever is # left is the reaper's. - self._recover_claims_once(stopping=True) + self._recover_claims_once() pending = sum(1 for f in in_flight if not f.done()) if pending: logger.info( diff --git a/tests/lost_reply.py b/tests/lost_reply.py index d785c1b..4f4cc42 100644 --- a/tests/lost_reply.py +++ b/tests/lost_reply.py @@ -29,7 +29,7 @@ from weakref import WeakSet import pytest -from django.db import connection +from django.db import connection, connections from django.db.backends.signals import connection_created from django_ox.models import OxTask @@ -291,3 +291,33 @@ def remove_all(self): for seam in self.installed: connection_created.disconnect(seam.install) seam.uninstall() + + +class LookReads: + """ + Every read a look for a claim that raised makes, on the test thread's + connection and on every connection opened while installed, a look's + own included. A test module's fixture yields reads and calls remove(). + """ + + def __init__(self): + self.reads = [] + self._installed = WeakSet() + connection_created.connect(self._install, weak=False) + self._install(sender=None, connection=connections["default"]) + + def _count(self, execute, sql, params, many, context): + if "ox_lease_abandoned" in sql: + self.reads.append(sql) + return execute(sql, params, many, context) + + def _install(self, sender, connection, **kwargs): + if connection not in self._installed: + self._installed.add(connection) + connection.execute_wrappers.append(self._count) + + def remove(self): + connection_created.disconnect(self._install) + for conn in list(self._installed): + if self._count in conn.execute_wrappers: + conn.execute_wrappers.remove(self._count) diff --git a/tests/tasks.py b/tests/tasks.py index b0a8513..0ff7e3d 100644 --- a/tests/tasks.py +++ b/tests/tasks.py @@ -1,6 +1,7 @@ """Module-level task functions; django.tasks requires module-level definitions.""" import asyncio +import os import sys import time from pathlib import Path @@ -62,6 +63,30 @@ def record(label): return label +@task +def append_line(path, label, seconds=0): + """ + Append `label` and the pid to the file at `path`, then sleep `seconds`: + a record of every execution that another process can read. + """ + with Path(path).open("a") as runs: + runs.write(f"{label} {os.getpid()}\n") + time.sleep(seconds) + return label + + +@task +def claim_on_a_shared_worker(label): + """ + run_once() on the Worker in STATE["shared_worker"], which a test shares + between tasks as a module-level Worker is shared. + """ + STATE.setdefault("shared_began", []).append(label) + STATE["shared_worker"].run_once() + STATE.setdefault("shared_done", []).append(label) + return label + + @task def labelled(label, **kwargs): """Returns its label. A schedule names itself with it, so a task row says diff --git a/tests/test_claim_fence.py b/tests/test_claim_fence.py new file mode 100644 index 0000000..39679b8 --- /dev/null +++ b/tests/test_claim_fence.py @@ -0,0 +1,940 @@ +""" +One Worker shared by threads: claims, and looks for a claim that raised. + +A claim counts itself in flight while it runs and registers what it returned +before it counts itself out; a look makes no read while a claim is in flight, +and releases nothing if a claim began while it read. Nothing is held across a +claim, so a claim that waits on the database, an override's statements after +the base claim included, holds up no other claim of the Worker's, which is +what a module-level Worker in a threaded web process needs when a view claims +inside its own transaction. Worker._claiming says how. +""" + +import collections +import ctypes +import logging +import random +import sys +import threading +import time +import traceback + +import pytest +from django.db import ( + DatabaseError, + OperationalError, + close_old_connections, + connection, + connections, + transaction, +) +from django.db.backends.signals import connection_created +from django.db.models import F + +from django_ox import worker as worker_module +from django_ox.exceptions import TaskTimeout +from django_ox.models import OxTask +from django_ox.worker import Worker + +from . import tasks +from .conftest import start_worker_thread, wait_for +from .dead_connection_tasks import end_session, from_another_connection +from .lost_reply import is_the_release, session_of +from .test_timeouts import interruptible_attempts # noqa: F401 (a fixture) + +pytestmark = pytest.mark.django_db(transaction=True) + +#: No test here waits on a lease unless it says so. +LOCK_TIMEOUT = 300.0 +LIMIT = 60.0 + +#: How long a call that is waiting on nothing may take here, far above what +#: any of them takes and far below a wait that never ends. +PROMPT = 5.0 + +#: A deadlock is called one once both threads have waited this long. +DEADLOCK = 20.0 + + +def _budget(settings, attempts): + settings.TASKS = { + "default": { + "BACKEND": "django_ox.backend.OxBackend", + "QUEUES": ["default"], + "OPTIONS": {"MAX_ATTEMPTS": attempts}, + } + } + + +def _events(caplog, name, worker=None): + return [ + r + for r in caplog.records + if getattr(r, "event", None) == name + and (worker is None or getattr(r, "worker_id", None) == worker.worker_id) + ] + + +def _released_ids(caplog, worker): + return sorted(r.task_id for r in _events(caplog, "worker_claim_released", worker)) + + +def _runs(label): + return tasks.STATE.get("order", []).count(label) + + +def _row(result): + return OxTask.objects.get(id=result.id) + + +def _state(result): + row = _row(result) + return (row.status, row.attempts, row.lease_epoch) + + +def _orphan(worker, label="orphan"): + """ + A row RUNNING under `worker`'s id that no claim of its returned, and a + look pending: what a claim that raised after committing leaves. + """ + result = tasks.record.enqueue(label) + # The base claim, whatever the class under test overrides. + db_task = Worker.claim_one(worker) + assert db_task is not None and str(db_task.id) == str(result.id) + with worker._in_flight_lock: + worker._handed_off.clear() + worker._claim_unconfirmed_at = time.monotonic() + return result + + +def _on_a_thread(target, name): + """target() on a thread of its own, and so a connection of its own.""" + out = {} + + def run(): + try: + out["returned"] = target() + except BaseException as exc: + out["raised"] = exc + finally: + connections.close_all() + + thread = threading.Thread(target=run, name=name, daemon=True) + thread.start() + return thread, out + + +# -- a claim that waits on the database holds up no other claim -------------------- + + +class CountsAfterClaiming(Worker): + """ + Counts every claim it makes on a row of its own after the base claim has + returned, as Oxpull Pro counts a rate-limited admission: an UPDATE whose + row lock a caller's transaction holds until it commits. + """ + + counter = None + + def claim_one(self): + db_task = super().claim_one() + if db_task is not None: + OxTask.objects.using(self._db_alias).filter(pk=self.counter).update( + priority=F("priority") + 1 + ) + return db_task + + +def _waiting_on_a_row_lock(other): + with other.cursor() as cursor: + if other.vendor == "postgresql": + cursor.execute( + "SELECT count(*) FROM pg_stat_activity WHERE datname = " + "current_database() AND wait_event_type = 'Lock'" + ) + else: + cursor.execute( + "SELECT count(*) FROM information_schema.innodb_trx " + "WHERE trx_state = 'LOCK WAIT'" + ) + return cursor.fetchone()[0] > 0 + + +def _two_callers(worker, *, wait_for_a, pause=1.0): + """ + B calls run_once() twice inside one atomic() block; A calls run_once() on + the same Worker after B's first call, while B's transaction is open. B + makes its second call once wait_for_a() says A is waiting on B, or after + `pause` when it is None. A deadlock is broken after DEADLOCK seconds by + ending B's session, and reported as blocked. + """ + out = {} + b_first = threading.Event() + a_started = threading.Event() + + def b(): + try: + connection.ensure_connection() + if connection.vendor != "sqlite": + out["b_session"] = session_of(connection) + with transaction.atomic(): + out["b1"] = worker.run_once() + b_first.set() + a_started.wait(LIMIT) + if wait_for_a is None: + time.sleep(pause) + else: + out["a_waited"] = wait_for(wait_for_a, timeout=10.0, interval=0.1) + began = time.monotonic() + out["b2"] = worker.run_once() + out["b2_took"] = time.monotonic() - began + out["b"] = "committed" + except BaseException as exc: + out["b"] = f"raised {exc!r}" + finally: + connections.close_all() + + def a(): + try: + b_first.wait(LIMIT) + a_started.set() + began = time.monotonic() + try: + out["a"] = worker.run_once() + except DatabaseError as exc: + out["a"] = f"raised {exc!r}" + out["a_took"] = time.monotonic() - began + finally: + connections.close_all() + + tb = threading.Thread(target=b, name="caller-b", daemon=True) + ta = threading.Thread(target=a, name="caller-a", daemon=True) + started = time.monotonic() + tb.start() + ta.start() + tb.join(DEADLOCK) + ta.join(max(DEADLOCK - (time.monotonic() - started), 0.1)) + blocked = {"a": ta.is_alive(), "b": tb.is_alive()} + if any(blocked.values()) and "b_session" in out: + from_another_connection(lambda other: end_session(other, out["b_session"])) + tb.join(LIMIT) + ta.join(LIMIT) + assert not (tb.is_alive() or ta.is_alive()), "a caller never returned" + return out, blocked + + +@pytest.mark.skipif( + connection.vendor == "sqlite", + reason="PostgreSQL and MySQL: a row lock the override's UPDATE waits on; " + "on SQLite the claim itself waits, test_a_claim_waiting_on_sqlites_write_lock", +) +def test_an_override_waiting_on_a_callers_transaction_holds_up_no_claim(settings): + """ + X3-1 without Oxpull Pro. One Worker shared by two threads, whose + claim_one() override updates a row after the base claim. B's transaction + holds that row's lock after B's first run_once(); A's run_once() claims + and then waits for it; B's second run_once() must not wait for A, or + neither ever finishes: the database cannot see a lock held in Python. + """ + _budget(settings, 3) + counter = tasks.record.enqueue("counter") + OxTask.objects.filter(id=counter.id).update(status=OxTask.Status.SUCCESSFUL) + worker = CountsAfterClaiming(lock_timeout=LOCK_TIMEOUT, backoff_initial=0) + worker.counter = _row(counter).pk + results = [tasks.record.enqueue(f"t{i}") for i in range(4)] + + def a_is_waiting(): + seen = [] + from_another_connection( + lambda other: seen.append(_waiting_on_a_row_lock(other)) + ) + return seen[0] + + out, blocked = _two_callers(worker, wait_for_a=a_is_waiting) + + # The instrument: A was waiting on B's row lock when B claimed again. + assert out.get("a_waited") is True, out + assert blocked == {"a": False, "b": False}, f"deadlock: {out}" + assert out["b"] == "committed", out + assert (out["b1"], out["b2"], out["a"]) == (True, True, True), out + assert out["b2_took"] < PROMPT, out + assert _row(counter).priority == 3 + ran = [r for r in results if _row(r).status == OxTask.Status.SUCCESSFUL] + assert len(ran) == 3 + assert sorted(_runs(f"t{i}") for i in range(4)) == [0, 1, 1, 1] + + +def test_a_claim_waiting_on_sqlites_write_lock_holds_up_no_claim(settings, monkeypatch): + """ + X3-2. On SQLite, B's transaction holds the write lock after its first + run_once(); A's claim waits for it in the busy handler; B's second + run_once() must go ahead, so that B can commit and A's claim can land, + rather than wait for A until A's busy timeout gives up. PostgreSQL and + MySQL claims skip locked rows, so A never waits there, and the same + calls must finish there too. + """ + _budget(settings, 3) + if connection.vendor == "sqlite": + # A's claim gives up after this, where the suite's twenty seconds + # would only make the failure slower. + monkeypatch.setitem(connection.settings_dict["OPTIONS"], "timeout", 5) + connections.close_all() + worker = Worker(lock_timeout=LOCK_TIMEOUT, backoff_initial=0) + for i in range(4): + tasks.record.enqueue(f"t{i}") + + out, blocked = _two_callers(worker, wait_for_a=None) + connections.close_all() + + assert blocked == {"a": False, "b": False}, out + assert out["b"] == "committed", out + assert (out["b1"], out["b2"], out["a"]) == (True, True, True), out + assert out["b2_took"] < PROMPT, out + if connection.vendor == "sqlite": + # The instrument: A's claim did wait, for B's commit. + assert out["a_took"] >= 0.8, out + assert sorted(_runs(f"t{i}") for i in range(4)) == [0, 1, 1, 1] + + +# -- a claim and a look on the same Worker --------------------------------------- + + +class ClaimsWithoutTheBase(Worker): + """An override that claims a row itself and never calls the base.""" + + def claim_one(self): + return self._claim_one() + + +#: How the claim is made: the base claim_one() called directly, as +#: run_tasks() and a launcher do; run()'s and run_once()'s _claim() over the +#: base; and _claim() over an override that never calls the base. +CLAIMS = { + "claim_one": (Worker, lambda worker: worker.claim_one()), + "_claim": (Worker, lambda worker: worker._claim()), + "no_super": (ClaimsWithoutTheBase, lambda worker: worker._claim()), +} + + +def _paused_claims(monkeypatch, worker, *, committed, go_on): + """The worker's next claim commits, says so, and waits for go_on.""" + real = worker._claim_one + + def claim_then_pause(): + db_task = real() + committed.set() + go_on.wait(LIMIT) + return db_task + + monkeypatch.setattr(worker, "_claim_one", claim_then_pause) + + +class LookReadGate: + """ + On every connection opened while installed, the test thread's included: + counts the look's read, and before the first one runs calls before(). + """ + + def __init__(self, before=None): + self.reads = 0 + self.before = before + self._lock = threading.Lock() + self._installed = [] + connection_created.connect(self._install, weak=False) + self._install(sender=None, connection=connections["default"]) + + def _wrap(self, execute, sql, params, many, context): + if "ox_lease_abandoned" in sql: + with self._lock: + self.reads += 1 + first = self.reads == 1 + if first and self.before is not None: + self.before() + return execute(sql, params, many, context) + + def _install(self, sender, connection, **kwargs): + if self._wrap not in connection.execute_wrappers: + connection.execute_wrappers.append(self._wrap) + self._installed.append(connection) + + def remove(self): + connection_created.disconnect(self._install) + for conn in self._installed: + if self._wrap in conn.execute_wrappers: + conn.execute_wrappers.remove(self._wrap) + + +@pytest.fixture +def gates(): + installed = [] + + def install(before=None): + gate = LookReadGate(before) + installed.append(gate) + return gate + + yield install + for gate in installed: + gate.remove() + + +@pytest.mark.parametrize("how", list(CLAIMS)) +def test_a_look_that_starts_during_a_claim_makes_no_read( + how, monkeypatch, caplog, gates +): + """ + A claim has committed on one thread and is on its way back, not yet + registered; a look starts on another. It must neither read nor wait: + it stays pending and returns. Once the claim has returned, the next + look releases the row whose claim raised and leaves the other alone. + """ + caplog.set_level(logging.WARNING, logger="django_ox") + cls, claim = CLAIMS[how] + worker = cls(lock_timeout=LOCK_TIMEOUT) + orphan = _orphan(worker) + in_transit = tasks.record.enqueue("in-transit") + committed, go_on = threading.Event(), threading.Event() + _paused_claims(monkeypatch, worker, committed=committed, go_on=go_on) + gate = gates() + claimer, claimed = _on_a_thread(lambda: claim(worker), "claimer") + try: + assert committed.wait(LIMIT) + looker, looked = _on_a_thread(worker._recover_claims, "looker") + looker.join(PROMPT) + assert not looker.is_alive(), "the look waited for the claim" + assert looked == {"returned": False}, looked + assert gate.reads == 0, "the look read while a claim was on its way back" + assert worker._claim_unconfirmed_at is not None + finally: + go_on.set() + claimer.join(LIMIT) + assert str(claimed["returned"].id) == str(in_transit.id) + assert worker._claims_in_flight == 0 + + assert worker._recover_claims() is True + + assert gate.reads == 1 + assert _released_ids(caplog, worker) == [str(orphan.id)] + assert _state(orphan) == (OxTask.Status.READY, 0, 2) + assert _state(in_transit) == (OxTask.Status.RUNNING, 1, 1) + assert worker._claim_unconfirmed_at is None + worker.execute(claimed["returned"]) + assert _state(in_transit) == (OxTask.Status.SUCCESSFUL, 1, 1) + assert _runs("in-transit") == 1 + + +@pytest.mark.parametrize("look", ["pass", "stop"]) +@pytest.mark.parametrize("how", list(CLAIMS)) +def test_a_claim_that_starts_during_a_look_makes_it_release_nothing( + how, look, monkeypatch, caplog, gates +): + """ + A look has checked that no claim is in flight and taken its snapshot; + before its read, a claim on another thread commits a row that it has + not yet registered. The read sees that row RUNNING under this worker's + id and in none of the sets, exactly like the orphan. The look must + release neither and stay pending: a look at the head of a pass returns, + and a stopping look gives up and says so. The claim's row is never + released, and runs once. + """ + caplog.set_level(logging.WARNING, logger="django_ox") + cls, claim = CLAIMS[how] + worker = cls(lock_timeout=LOCK_TIMEOUT) + orphan = _orphan(worker) + in_transit = tasks.record.enqueue("in-transit") + committed, go_on = threading.Event(), threading.Event() + _paused_claims(monkeypatch, worker, committed=committed, go_on=go_on) + started = [] + in_time = [] + + def claim_before_the_read(): + # Not raised here: a look that fails is what a stopping look reports. + claimer, claimed = _on_a_thread(lambda: claim(worker), "claimer") + started.append((claimer, claimed)) + in_time.append(committed.wait(10.0)) + + gate = gates(before=claim_before_the_read) + if look == "pass": + looker, looked = _on_a_thread(worker._recover_claims, "looker") + else: + looker, looked = _on_a_thread(worker._recover_claims_once, "looker") + try: + looker.join(LIMIT) + assert not looker.is_alive() + finally: + go_on.set() + for claimer, _ in started: + claimer.join(LIMIT) + + assert gate.reads == 1 + assert in_time == [True], "the claim did not commit while the look read" + (claimer, claimed) = started[0] + assert "raised" not in looked, looked["raised"] + assert str(claimed["returned"].id) == str(in_transit.id) + assert _released_ids(caplog, worker) == [] + assert _state(orphan) == (OxTask.Status.RUNNING, 1, 1) + assert _state(in_transit) == (OxTask.Status.RUNNING, 1, 1) + if look == "pass": + assert looked == {"returned": False} + assert worker._claim_unconfirmed_at is not None + # The next look has the claim's row registered, and releases only + # the orphan. + assert worker._recover_claims() is True + assert _released_ids(caplog, worker) == [str(orphan.id)] + assert _state(orphan) == (OxTask.Status.READY, 0, 2) + assert worker._claim_unconfirmed_at is None + else: + (failed,) = _events(caplog, "worker_claim_recovery_failed", worker) + assert failed.claim_recovery == "expired" + assert _state(in_transit) == (OxTask.Status.RUNNING, 1, 1) + worker.execute(claimed["returned"]) + assert _state(in_transit) == (OxTask.Status.SUCCESSFUL, 1, 1) + assert _runs("in-transit") == 1 + + +def test_a_claim_that_raises_while_a_look_releases_keeps_it_pending( + monkeypatch, caplog +): + """ + A claim that begins while a look is making its releases committed after + the look's read, so its row is not among them; but it may raise, and + then it notes a look of its own. The look must not clear that note. + """ + caplog.set_level(logging.WARNING, logger="django_ox") + worker = Worker(lock_timeout=LOCK_TIMEOUT) + orphan = _orphan(worker) + raised_at = [] + + def claim_raises(): + raise OperationalError("the reply to this claim was lost") + + def raising_claim(): + monkeypatch.setattr(worker, "_claim_one", claim_raises) + try: + worker._claim() + except OperationalError: + raised_at.append(worker._claim_unconfirmed_at) + + fired = [] + + def before_the_release(execute, sql, params, many, context): + if is_the_release(sql, params) and not fired: + fired.append(True) + thread, _ = _on_a_thread(raising_claim, "claimer") + thread.join(10.0) + return execute(sql, params, many, context) + + connection.ensure_connection() + connection.execute_wrappers.append(before_the_release) + try: + returned = worker._recover_claims() + finally: + connection.execute_wrappers.remove(before_the_release) + + assert fired and raised_at, "the claim did not raise during the release" + assert _released_ids(caplog, worker) == [str(orphan.id)] + assert returned is False + assert worker._claim_unconfirmed_at == raised_at[0] is not None + + +class RaisesAfterTheBase(Worker): + """An override whose own work after the base claim raises.""" + + def claim_one(self): + db_task = super().claim_one() + raise RuntimeError(f"the override failed after claiming {db_task}") + + +#: A claim that raises: the base claim's database error, through claim_one() +#: and through _claim(); and an override's own error after the base claim. +RAISING = { + "claim_one": (Worker, lambda worker: worker.claim_one(), DatabaseError), + "_claim": (Worker, lambda worker: worker._claim(), DatabaseError), + "override": (RaisesAfterTheBase, lambda worker: worker._claim(), RuntimeError), +} + + +@pytest.mark.parametrize("how", list(RAISING)) +def test_a_claim_that_raised_counts_itself_out(how, monkeypatch, caplog): + """ + However a claim ends, it stops counting as in flight: after a claim that + raised, a look is made, and releases the orphan at once, and a stopping + look does not wait out its deadline. + """ + caplog.set_level(logging.WARNING, logger="django_ox") + cls, claim, error = RAISING[how] + worker = cls(lock_timeout=LOCK_TIMEOUT) + orphan = _orphan(worker) + tasks.record.enqueue("next") + if error is DatabaseError: + + def claim_raises(): + raise DatabaseError("the claim failed") + + monkeypatch.setattr(worker, "_claim_one", claim_raises) + for _ in range(3): + with pytest.raises(error): + claim(worker) + + began = time.monotonic() + worker._recover_claims_once() + took = time.monotonic() - began + + assert took < PROMPT + assert _events(caplog, "worker_claim_recovery_failed", worker) == [] + assert _released_ids(caplog, worker) == [str(orphan.id)] + assert _state(orphan) == (OxTask.Status.READY, 0, 2) + assert worker._claim_unconfirmed_at is None + + +# -- the loop and run_once() threads on one Worker, replies lost ----------------- + + +class LosesSomeReplies(Worker): + """ + Every `every`-th claim commits and then raises, as a claim whose reply + was lost does: RUNNING under this worker's id, and never returned. A + pause after the others widens the moment a claim is on its way back. + tests/test_lost_commit_reply.py loses real replies, one at a time. + """ + + def __init__(self, *args, every, **kwargs): + super().__init__(*args, **kwargs) + self.every = every + self._count_lock = threading.Lock() + self.claims = 0 + self.lost = collections.Counter() + self.looks = collections.Counter() + + def _claim_one(self): + db_task = super()._claim_one() + if db_task is None: + return None + with self._count_lock: + self.claims += 1 + lose = self.claims % self.every == 0 + caller = ( + "run_once" if threading.current_thread().name.startswith("once") else "run" + ) + if lose: + self.lost[caller] += 1 + raise OperationalError("the reply to a claim that committed was lost") + time.sleep(random.uniform(0, 0.01)) + return db_task + + def _recover_claims(self): + made = super()._recover_claims() + self.looks[made] += 1 + return made + + +def test_the_loop_and_run_once_threads_on_one_worker_run_every_body_once( + settings, caplog +): + """ + run() and two threads calling run_once() share one Worker while one claim + in five loses its reply. The loop looks for its own; its look meets the + other threads' claims on their way back. A row whose claim raised under + run_once() is the reaper's, or a later look's. Every body runs, and none + twice. + """ + caplog.set_level(logging.WARNING, logger="django_ox") + _budget(settings, 10) + n = 60 + labels = [f"s{i}" for i in range(n)] + results = [tasks.record.enqueue(label) for label in labels] + worker = LosesSomeReplies( + every=5, + concurrency=2, + lock_timeout=2.0, + poll_interval=0.02, + reap_interval=0.25, + backoff_initial=0, + ) + done = threading.Event() + + def call_run_once(): + while not done.is_set(): + try: + ran = worker.run_once() + except DatabaseError: + ran = True + finally: + close_old_connections() + connections.close_all() + if not ran: + time.sleep(0.02) + + threads = [ + threading.Thread(target=call_run_once, name=f"once-{i}", daemon=True) + for i in range(2) + ] + loop = start_worker_thread(worker) + for thread in threads: + thread.start() + + def all_ran(): + return OxTask.objects.filter(status=OxTask.Status.SUCCESSFUL).count() == n + + try: + finished = wait_for(all_ran, timeout=90.0, interval=0.1) + finally: + done.set() + for thread in threads: + thread.join(LIMIT) + worker.request_stop() + loop.join(LIMIT) + + statuses = collections.Counter(OxTask.objects.values_list("status", flat=True)) + twice = {label: _runs(label) for label in labels if _runs(label) > 1} + never = [label for label in labels if _runs(label) == 0] + summary = ( + f"claims={worker.claims} lost={dict(worker.lost)} looks={dict(worker.looks)} " + f"released={len(_released_ids(caplog, worker))} statuses={dict(statuses)}" + ) + logging.getLogger(__name__).warning("shared worker: %s", summary) + assert finished, f"not every task ran: {summary}" + assert twice == {}, f"{twice} {summary}" + assert never == [], f"{never} {summary}" + # The instrument: replies were lost under both callers. + assert worker.lost["run"] >= 1 and worker.lost["run_once"] >= 1, summary + for result in results: + assert _row(result).status == OxTask.Status.SUCCESSFUL + + +# -- an exception delivered inside a claim leaves the fence free ----------------- + +needs_delivery = pytest.mark.skipif( + worker_module._inject_async_exc is None, + reason="delivering an exception to another thread needs PyThreadState_SetAsyncExc", +) + + +def _deliver(thread, exc): + """ + Raise `exc` in `thread` at its next instruction that checks for one, as + the watchdog raises TaskTimeout and a signal handler KeyboardInterrupt. + """ + set_async_exc = ctypes.pythonapi.PyThreadState_SetAsyncExc + assert set_async_exc(ctypes.c_ulong(thread.ident), ctypes.py_object(exc)) == 1 + + +def _free(lock, wait=0.0): + """ + Whether `lock` is free, or comes free within `wait` seconds. A + Condition's acquire and release are its lock's. + """ + if lock.acquire(timeout=wait) if wait else lock.acquire(blocking=False): + lock.release() + return True + return False + + +def _stack(thread): + frame = sys._current_frames().get(thread.ident) + return [] if frame is None else [f.name for f in traceback.extract_stack(frame)] + + +#: Where a thread waits for one of the fence's locks, whichever tree. +WAITS = {"_claiming", "_hand_off", "_recover_claims", "_recover_claims_by", "__enter__"} + + +def _waiting_on_a_lock(thread): + stack = _stack(thread) + return bool(stack) and stack[-1] in WAITS + + +def _let_go(worker, thread): + """ + Release a fence lock nothing holds any more, which is what a delivery + that leaked it leaves, until `thread` is done with the Worker. + """ + for _ in range(50): + thread.join(0.2) + if not thread.is_alive(): + return + # Held across the join, which no claim's own hold ever is. + if not _free(worker._fence) and not _free(worker._fence, wait=0.2): + worker._fence.release() + + +@needs_delivery +@pytest.mark.usefixtures("interruptible_attempts") +def test_a_timeout_delivered_inside_a_claim_leaves_a_shared_workers_fence_free( + settings, caplog +): + """ + A task under a timeout calls run_once() on a Worker shared between tasks, + as a module-level Worker is, and its claim waits for the fence's lock + past the task's deadline. The watchdog's TaskTimeout is pending when the + wait ends, and lands as the acquire returns. That attempt fails; the + next task's same call returns, and the shared Worker's fence is free and + counts no claim. + """ + caplog.set_level(logging.INFO, logger="django_ox") + settings.TASKS = { + "default": { + "BACKEND": "django_ox.backend.OxBackend", + "QUEUES": ["default", "other"], + "OPTIONS": {"MAX_ATTEMPTS": 1}, + } + } + shared = Worker(queues=["other"], lock_timeout=LOCK_TIMEOUT) + tasks.STATE["shared_worker"] = shared + worker = Worker( + queues=["default"], + concurrency=1, + task_timeout=2, + # Past every wait here, so no attempt is given up as stuck. + task_timeout_grace=LIMIT, + poll_interval=0.05, + lock_timeout=LOCK_TIMEOUT, + ) + first = tasks.claim_on_a_shared_worker.enqueue("first") + shared._fence.acquire() + holding = True + loop = start_worker_thread(worker) + try: + assert wait_for(lambda: tasks.STATE.get("shared_began"), timeout=LIMIT) + # The deadline has passed and the watchdog has fired: its TaskTimeout + # waits in the claim's acquire until the lock is free. + assert wait_for( + lambda: any(watch.fired for watch in list(worker._watches.values())), + timeout=LIMIT, + ) + shared._fence.release() + holding = False + assert wait_for(lambda: _row(first).status == OxTask.Status.FAILED, PROMPT) + assert [r.task_id for r in _events(caplog, "task_timed_out")] == [str(first.id)] + + second = tasks.claim_on_a_shared_worker.enqueue("second") + done = wait_for(lambda: _row(second).status == OxTask.Status.SUCCESSFUL, LIMIT) + assert done, f"the next call waited on the fence: {_row(second).status}" + assert tasks.STATE.get("shared_done") == ["second"] + assert _free(shared._fence) + assert shared._claims_in_flight == 0 + finally: + if holding: + shared._fence.release() + worker.request_stop() + _let_go(shared, loop) + + +class PausesInsideTheFence(Worker): + """ + Pauses the claim of the thread named "victim" at `pause_at`: in its + claim_one() override before the base claim ("before_base") or after it + ("after_base"), or inside the base's fence before the claim itself + ("inside_base"), so a test can take the lock the claim needs next. + """ + + pause_at = None + + def __init__(self, *args, **kwargs): + super().__init__(*args, **kwargs) + self.arrived = threading.Event() + self.go_on = threading.Event() + + def _pause(self, where): + if where == self.pause_at and threading.current_thread().name == "victim": + self.arrived.set() + self.go_on.wait(LIMIT) + + def claim_one(self): + self._pause("before_base") + db_task = super().claim_one() + self._pause("after_base") + return db_task + + def _claim_one(self): + self._pause("inside_base") + return super()._claim_one() + + +def _base_claim(worker): + return worker.claim_one() + + +def _run_once_call(worker): + return worker.run_once() + + +def _stopping_look(worker): + worker._claim_unconfirmed_at = time.monotonic() + return worker._recover_claims_by(time.monotonic() + LIMIT) + + +def _look(worker): + worker._claim_unconfirmed_at = time.monotonic() + return worker._recover_claims() + + +#: Each acquire of the fence's lock, or of the lock a claim registers under, +#: on the way through a claim or a look: the call, the lock, where the call +#: pauses first so the test can take that lock (None: the test takes it +#: before the call), and whether a row is due so the claim returns one. +BOUNDARIES = { + "claim_one count in": (_base_claim, "fence", None, False), + "claim_one register": (_base_claim, "in_flight", "inside_base", True), + "claim_one count out": (_base_claim, "fence", "inside_base", False), + "run_once count in": (_run_once_call, "fence", None, False), + "run_once base count in": (_run_once_call, "fence", "before_base", False), + "run_once base register": (_run_once_call, "in_flight", "inside_base", True), + "run_once base count out": (_run_once_call, "fence", "inside_base", False), + "run_once register": (_run_once_call, "in_flight", "after_base", True), + "run_once count out": (_run_once_call, "fence", "after_base", False), + "look": (_look, "fence", None, False), + "stopping look": (_stopping_look, "fence", None, False), +} + + +@needs_delivery +@pytest.mark.parametrize("exc", [TaskTimeout, KeyboardInterrupt]) +@pytest.mark.parametrize("boundary", list(BOUNDARIES)) +def test_an_exception_delivered_as_a_fence_lock_is_taken_leaves_it_free(boundary, exc): + """ + The call waits for a lock the test holds; the test delivers an exception + to it and lets the lock go, so the exception lands as the acquire + returns, at the first instruction there that checks for one. The call + raises it. Both locks are free, no claim counts as in flight, and the + Worker claims again at once. + """ + call, which, pause_at, row_due = BOUNDARIES[boundary] + if row_due: + tasks.record.enqueue("due") + worker = PausesInsideTheFence(lock_timeout=LOCK_TIMEOUT) + worker.pause_at = pause_at + lock = worker._fence if which == "fence" else worker._in_flight_lock + holding = False + if pause_at is None: + lock.acquire() + holding = True + thread, out = _on_a_thread(lambda: call(worker), "victim") + try: + if pause_at is not None: + assert worker.arrived.wait(LIMIT) + lock.acquire() + holding = True + worker.go_on.set() + assert wait_for(lambda: _waiting_on_a_lock(thread), PROMPT), _stack(thread) + # Into the acquire itself, a C call that checks for nothing. + time.sleep(0.2) + _deliver(thread, exc) + lock.release() + holding = False + thread.join(PROMPT) + + assert not thread.is_alive(), f"it did not return: {_stack(thread)}" + assert isinstance(out.get("raised"), exc), out + assert _free(worker._fence) + assert _free(worker._in_flight_lock) + assert worker._claims_in_flight == 0 + worker.pause_at = None + again, again_out = _on_a_thread(worker.claim_one, "again") + again.join(PROMPT) + assert not again.is_alive() and "raised" not in again_out, again_out + finally: + worker.go_on.set() + if holding: + lock.release() + _let_go(worker, thread) diff --git a/tests/test_claim_recovery.py b/tests/test_claim_recovery.py index 4772d9d..8fd7bed 100644 --- a/tests/test_claim_recovery.py +++ b/tests/test_claim_recovery.py @@ -9,6 +9,7 @@ import copy import logging +import sqlite3 import threading import time import traceback @@ -45,7 +46,7 @@ from . import tasks from .conftest import start_worker_thread, wait_for from .dead_connection_tasks import from_another_connection, restart_every_other_session -from .lost_reply import COMMITTED_CLAIM_WINDOWS, Seams, is_the_release +from .lost_reply import COMMITTED_CLAIM_WINDOWS, LookReads, Seams, is_the_release from .unanswering import Unanswering pytestmark = pytest.mark.django_db(transaction=True) @@ -164,6 +165,20 @@ def _orphan(worker, label="orphan"): return result +def _a_failed_pass_then_its_look(worker): + """ + What run() does, on the test's thread: a claim that raises, the failed + pass's handling of the connection, and the look at the head of the next + pass. The claim's error is returned. + """ + with pytest.raises(DatabaseError) as raised: + worker._claim() + close_old_connections() + _sweep_pool(connections[worker._db_alias]) + worker._recover_claims() + return raised.value + + # -- which rows a look may release ---------------------------------------------- @@ -533,61 +548,6 @@ def test_a_claim_returned_by_claim_one_directly_is_never_released(): ) -def test_a_look_waits_for_a_claim_on_its_way_back(monkeypatch): - """ - One claimer per worker. A claim has committed on one thread and is on - its way back, not yet registered; a look started on another thread must - wait for it, and then leaves its row alone. - """ - worker = Worker(lock_timeout=LOCK_TIMEOUT) - result = tasks.record.enqueue("in-transit") - committed = threading.Event() - go_on = threading.Event() - real = worker._claim_one - - def claim_then_pause(): - db_task = real() - committed.set() - go_on.wait(timeout=LIMIT) - return db_task - - monkeypatch.setattr(worker, "_claim_one", claim_then_pause) - reads = [] - - def count(execute, sql, params, many, context): - if "ox_lease_abandoned" in sql: - reads.append(sql) - return execute(sql, params, many, context) - - def install(sender, connection, **kwargs): - connection.execute_wrappers.append(count) - - claimed = [] - claimer = threading.Thread( - target=lambda: (claimed.append(worker._claim()), connections.close_all()) - ) - connection_created.connect(install, weak=False) - try: - claimer.start() - assert committed.wait(timeout=LIMIT) - worker._claim_unconfirmed_at = time.monotonic() - looker = threading.Thread( - target=lambda: (worker._recover_claims(), connections.close_all()) - ) - looker.start() - looker.join(timeout=3) - assert reads == [], "the look read while a claim was on its way back" - go_on.set() - claimer.join(timeout=LIMIT) - looker.join(timeout=LIMIT) - finally: - go_on.set() - connection_created.disconnect(install) - assert len(reads) == 1 - assert str(claimed[0].id) == str(result.id) - assert _row(result).status == OxTask.Status.RUNNING - - def test_a_look_drops_entries_whose_rows_are_no_longer_this_workers(): """ An entry excludes a row only while that row is RUNNING under this worker @@ -616,10 +576,9 @@ def test_a_look_drops_entries_whose_rows_are_no_longer_this_workers(): # -- the release ---------------------------------------------------------------- -@pytest.mark.parametrize("entry", ["loop", "run_once"]) @pytest.mark.parametrize("release_window", ["before", "statement"]) def test_a_release_whose_reply_is_lost_refunds_once( - release_window, entry, settings, caplog, lose_the_reply + release_window, settings, caplog, lose_the_reply ): """ The look's own write loses its reply. Whether it landed or not, the next @@ -633,32 +592,12 @@ def test_a_release_whose_reply_is_lost_refunds_once( claim_window = {"mysql": "commit", "postgresql": "statement"}.get( connection.vendor, "statement" ) - on = connections["default"] if entry == "run_once" else None - claim = lose_the_reply(claim_window, on=on) - release = lose_the_reply(release_window, statement="release", on=on) + claim = lose_the_reply(claim_window) + release = lose_the_reply(release_window, statement="release") worker = Worker(lock_timeout=LOCK_TIMEOUT, poll_interval=0.05) result = tasks.record.enqueue("once") - if entry == "loop": - _run_until(worker, lambda: _row(result).status == OxTask.Status.SUCCESSFUL) - else: - with pytest.raises(DatabaseError) as raised: - worker.run_once() - # As any caller does after a database error: drop a connection that - # died. - close_old_connections() - # The claim's own error, never the look's. - frames = traceback.format_exception(raised.value) - assert "_release_claim" not in "".join(frames) - assert "claim_one" in "".join(frames) - assert _row(result).status == ( - OxTask.Status.READY if release.landed else OxTask.Status.RUNNING - ) - failed = _events(caplog, "worker_claim_recovery_failed", worker) - assert failed - # Recovery stays due: the next call looks again before claiming. - assert {event.claim_recovery for event in failed} == {"pending"} - assert worker.run_once() is True + _run_until(worker, lambda: _row(result).status == OxTask.Status.SUCCESSFUL) assert claim.fired and release.fired if release.landed: @@ -714,13 +653,20 @@ def reap_first(other): Worker(lock_timeout=LOCK_TIMEOUT).reap() race = RaceTheRelease(reap_first) - connections["default"].execute_wrappers.append(race) + + def install(sender, connection, **kwargs): + # The look reconnects the thread's wrapper after the failed pass. + if race not in connection.execute_wrappers: + connection.execute_wrappers.append(race) + + install(None, connections["default"]) + connection_created.connect(install, weak=False) try: - with pytest.raises(DatabaseError): - worker.run_once() + _a_failed_pass_then_its_look(worker) finally: - connections["default"].execute_wrappers.remove(race) - close_old_connections() + connection_created.disconnect(install) + if race in connections["default"].execute_wrappers: + connections["default"].execute_wrappers.remove(race) assert seam.fired and race.fired assert _events(caplog, "worker_claim_released", worker) == [] @@ -773,9 +719,7 @@ def test_a_refund_leaves_an_earlier_attempts_record_as_it_was( assert before.started_at is not None seam = lose_the_reply(window, on=connections["default"]) - with pytest.raises(DatabaseError): - worker.run_once() - close_old_connections() + _a_failed_pass_then_its_look(worker) assert seam.fired row = _row(result) @@ -1109,9 +1053,8 @@ def _read_after_the_restart(read): @pooled_postgresql -@pytest.mark.parametrize("entry", ["loop", "run_once"]) def test_after_every_pooled_connection_died_the_look_still_lands( - entry, settings, caplog, lose_the_reply + settings, caplog, lose_the_reply ): """ The claim's reply is lost as the server restarts: every session ends, @@ -1123,31 +1066,23 @@ def test_after_every_pooled_connection_died_the_look_still_lands( _budget(settings, 1) result = tasks.record.enqueue("pooled") _fill_the_pool() - on = connections["default"] if entry == "run_once" else None - seam = lose_the_reply("statement", on=on, also=restart_every_other_session) + seam = lose_the_reply("statement", also=restart_every_other_session) worker = Worker(lock_timeout=LOCK_TIMEOUT, poll_interval=0.05) - if entry == "loop": - thread = start_worker_thread(worker) - try: - wait_for( - lambda: _released_ids(caplog, worker) == [str(result.id)], - timeout=LIMIT, - ) - _read_after_the_restart(lambda: None) - wait_for( - lambda: _row(result).status == OxTask.Status.SUCCESSFUL, - timeout=LIMIT, - ) - finally: - worker.request_stop() - thread.join(timeout=60) - else: - with pytest.raises(DatabaseError): - worker.run_once() - row = _read_after_the_restart(lambda: _row(result)) - assert (row.status, row.attempts) == (OxTask.Status.READY, 0) - assert worker.run_once() is True + thread = start_worker_thread(worker) + try: + wait_for( + lambda: _released_ids(caplog, worker) == [str(result.id)], + timeout=LIMIT, + ) + _read_after_the_restart(lambda: None) + wait_for( + lambda: _row(result).status == OxTask.Status.SUCCESSFUL, + timeout=LIMIT, + ) + finally: + worker.request_stop() + thread.join(timeout=60) assert seam.fired assert _released_ids(caplog, worker) == [str(result.id)], ( @@ -1220,10 +1155,9 @@ def test_a_claim_in_a_callers_manual_transaction_starts_no_look(): assert _row(orphan).status == OxTask.Status.READY -@pytest.mark.parametrize("stopping", [False, True]) @pytest.mark.parametrize("block", ["manual", "atomic"]) def test_a_look_that_fails_leaves_a_callers_transaction_alone( - block, stopping, monkeypatch, caplog + block, monkeypatch, caplog ): """ Whatever makes a look fail, the connection it would close is left as it @@ -1241,7 +1175,7 @@ def look_fails(**kwargs): def the_callers(write): driver = connection.connection - worker._recover_claims_once(stopping=stopping) + worker._recover_claims_once() assert connection.connection is driver assert OxTask.objects.filter(id=write.id).exists() @@ -1736,72 +1670,84 @@ def gave_up(deadline): monkeypatch.setattr(worker, "_recover_claims_by", gave_up) driver = connection.connection assert driver is not None - worker._recover_claims_once(stopping=True) + worker._recover_claims_once() assert connection.connection is driver _given_up(caplog, worker, result) -def test_a_stopping_look_does_not_wait_past_its_deadline_for_the_claimer(caplog): +def test_a_stopping_look_does_not_wait_past_its_deadline_for_a_claim_in_flight( + monkeypatch, caplog +): """ - Another thread sharing the Worker holds the claimer lock, as a claim on - its way back does. The stopping look waits for it no longer than its - deadline, and gives up. + Another thread sharing the Worker has a claim in flight, on its way + back. The stopping look waits for it no longer than its deadline, and + gives up. """ caplog.set_level(logging.WARNING, logger="django_ox") worker = Worker(lock_timeout=LOCK_TIMEOUT) result = _orphan(worker) - holding = threading.Event() + in_flight = threading.Event() release = threading.Event() - def hold(): - with worker._claimer: - holding.set() - release.wait(LIMIT) + def claim_in_flight(): + in_flight.set() + release.wait(LIMIT) - holder = threading.Thread(target=hold) - holder.start() + monkeypatch.setattr(worker, "_claim_one", claim_in_flight) + claimer = threading.Thread( + target=lambda: (worker.claim_one(), connections.close_all()) + ) + claimer.start() try: - assert holding.wait(LIMIT) + assert in_flight.wait(LIMIT) took = _stop(worker) finally: release.set() - holder.join(LIMIT) + claimer.join(LIMIT) assert 4.5 <= took < 8.0 _given_up(caplog, worker, result) -# -- what a failed look says next -------------------------------------------------- +# -- run_once() and run_tasks() make no look ----------------------------------------- -LOOKS_AGAIN = ( - "Claim outcome is unknown. This Worker will look again before its next claim " - "while the LOCK_TIMEOUT recovery window remains open. Recovery is not " - "guaranteed; an unrecovered claim may be reaped with its attempt spent." -) -NO_LATER_LOOK = ( - "Claim outcome is unknown. Recovery looks are limited to this run_tasks() " - "call; pending recovery state is not retained for later calls. Recovery is " - "not guaranteed; an unrecovered claim may be reaped with its attempt spent." +@pytest.fixture +def look_reads(): + looks = LookReads() + yield looks.reads + looks.remove() + + +def _call(call, worker): + return worker.run_once() if call == "run_once" else run_tasks() + + +RECOVERY_EVENTS = ( + "worker_claim_released", + "worker_claim_recovery_failed", + "worker_claim_recovery_expired", ) -@pytest.mark.parametrize("caller", ["run_once", "run_tasks"]) -def test_a_failed_look_says_what_happens_next_for_its_caller( - caller, monkeypatch, caplog -): +def _recovery_events(caplog): + return [r for name in RECOVERY_EVENTS for r in _events(caplog, name)] + + +@pytest.mark.parametrize("call", ["run_once", "run_tasks"]) +def test_an_inline_claim_error_makes_no_look(call, monkeypatch, caplog, look_reads): """ - run_once()'s Worker is the caller's and looks again before its next - claim, so recovery is still pending; run_tasks() builds one per call, - and nothing looks later, so it has expired. + A claim of run_once()'s or run_tasks()'s raises on a connection the + worker owns. The error is raised at once and nothing looks for the + claim, then or later: a look would have raised here. """ caplog.set_level(logging.WARNING, logger="django_ox") tasks.record.enqueue("never claimed") + looks = [] real_look = Worker._recover_claims def look(self, **kwargs): - if self._claim_unconfirmed_at is not None: - raise OperationalError("the database is still gone") + looks.append(self.worker_id) return real_look(self, **kwargs) def claim(self): @@ -1809,20 +1755,446 @@ def claim(self): monkeypatch.setattr(Worker, "_recover_claims", look) monkeypatch.setattr(Worker, "claim_one", claim) + worker = Worker(lock_timeout=LOCK_TIMEOUT) with pytest.raises(OperationalError, match="reply to the claim was lost"): - if caller == "run_once": - Worker(lock_timeout=LOCK_TIMEOUT).run_once() + _call(call, worker) + + assert looks == [] + assert look_reads == [] + assert _recovery_events(caplog) == [] + assert worker._claim_unconfirmed_at is None + + +def test_run_once_makes_no_look_that_run_noted(caplog, look_reads): + """ + A look run() noted is pending on the Worker when run_once() is called + on it. run_once() neither makes it nor clears it: the orphan's row stays + RUNNING and the next task is claimed and run. run()'s next pass is where + the look is made. + """ + caplog.set_level(logging.WARNING, logger="django_ox") + worker = Worker(lock_timeout=LOCK_TIMEOUT) + orphan = _orphan(worker) + pending = worker._claim_unconfirmed_at + after = tasks.record.using(priority=-1).enqueue("after") + + assert worker.run_once() is True + + assert look_reads == [] + assert worker._claim_unconfirmed_at == pending + assert _row(orphan).status == OxTask.Status.RUNNING + assert _row(after).status == OxTask.Status.SUCCESSFUL + worker._recover_claims() + assert _row(orphan).status == OxTask.Status.READY + assert _released_ids(caplog, worker) == [str(orphan.id)] + + +#: What each database's session keeps, and how a claim is made to fail on a +#: connection that still answers: another session holds the task table, and +#: the caller's session waits for it no longer than a moment. +_SESSION = { + "postgresql": { + "setup": [ + "SELECT pg_try_advisory_lock(4242)", + "CREATE TEMPORARY TABLE ox_callers_scratch (x integer)", + "SET lock_timeout = '300ms'", + ], + "checks": { + "session": "SELECT pg_backend_pid()", + "advisory lock": ( + "SELECT count(*) FROM pg_locks WHERE locktype = 'advisory' " + "AND objid = 4242 AND pid = pg_backend_pid() AND granted" + ), + "temporary table": "SELECT count(*) FROM ox_callers_scratch", + "setting": "SHOW lock_timeout", + }, + "teardown": [ + "SELECT pg_advisory_unlock(4242)", + "DROP TABLE ox_callers_scratch", + "RESET lock_timeout", + ], + }, + "mysql": { + "setup": [ + "SELECT GET_LOCK('ox_callers_lock', 0)", + "CREATE TEMPORARY TABLE ox_callers_scratch (x integer)", + "SET SESSION lock_wait_timeout = 1", + ], + "checks": { + "session": "SELECT CONNECTION_ID()", + "advisory lock": "SELECT IS_USED_LOCK('ox_callers_lock') = CONNECTION_ID()", + "temporary table": "SELECT count(*) FROM ox_callers_scratch", + "setting": "SELECT @@SESSION.lock_wait_timeout", + }, + "teardown": [ + "SELECT RELEASE_LOCK('ox_callers_lock')", + "DROP TEMPORARY TABLE ox_callers_scratch", + "SET SESSION lock_wait_timeout = DEFAULT", + ], + }, + "sqlite": { + "setup": [ + "CREATE TEMPORARY TABLE ox_callers_scratch (x integer)", + "PRAGMA busy_timeout = 300", + ], + "checks": { + "temporary table": "SELECT count(*) FROM ox_callers_scratch", + "setting": "PRAGMA busy_timeout", + }, + "teardown": ["DROP TABLE ox_callers_scratch"], + }, +} + + +def _session_state(): + state = {} + with connection.cursor() as cursor: + for name, sql in _SESSION[connection.vendor]["checks"].items(): + cursor.execute(sql) + state[name] = cursor.fetchone()[0] + return state + + +class _TableHeld: + """Another session holds the task table, as a migration that alters it does.""" + + def __init__(self): + table = OxTask._meta.db_table + if connection.vendor == "sqlite": + self._other = sqlite3.connect( + connection.settings_dict["NAME"], isolation_level=None + ) + self._other.execute("BEGIN EXCLUSIVE") + return + self._other = connections.create_connection("default") + if connection.vendor == "postgresql": + self._other.set_autocommit(False) + with self._other.cursor() as cursor: + cursor.execute(f"LOCK TABLE {table} IN ACCESS EXCLUSIVE MODE") else: - run_tasks() - - (failed,) = _events(caplog, "worker_claim_recovery_failed") - message = failed.getMessage() - said, not_said = ( - (LOOKS_AGAIN, NO_LATER_LOOK) - if caller == "run_once" - else (NO_LATER_LOOK, LOOKS_AGAIN) + with self._other.cursor() as cursor: + cursor.execute(f"LOCK TABLES {table} WRITE") + + def release(self): + if connection.vendor == "sqlite": + self._other.execute("ROLLBACK") + self._other.close() + return + if connection.vendor == "postgresql": + self._other.rollback() + self._other.set_autocommit(True) + else: + with self._other.cursor() as cursor: + cursor.execute("UNLOCK TABLES") + self._other.close() + + +@pytest.mark.parametrize("call", ["run_once", "run_tasks"]) +def test_an_inline_claim_error_keeps_the_callers_session( + call, settings, monkeypatch, caplog, look_reads +): + """ + The caller's session holds what a session can: an advisory lock, a + temporary table, a setting. A claim of run_once()'s or run_tasks()'s + then fails on that connection while it still answers: another session + holds the task table, and the caller waits for it no longer than its + own setting allows. The claim's error is raised at once, and the + caller's connection is the one it had, with all of that still on it. + """ + caplog.set_level(logging.WARNING, logger="django_ox") + _budget(settings, 1) + claim_errors = _claim_errors(monkeypatch) + result = tasks.record.enqueue("held") + worker = Worker(lock_timeout=LOCK_TIMEOUT) + session = _SESSION[connection.vendor] + with connection.cursor() as cursor: + for sql in session["setup"]: + cursor.execute(sql) + if "LOCK(" in sql.upper(): + assert cursor.fetchone()[0], "another session holds the lock" + driver = connection.connection + before = _session_state() + try: + held = _TableHeld() + try: + with pytest.raises(DatabaseError) as raised: + _call(call, worker) + finally: + held.release() + assert raised.value is claim_errors[0] + assert connection.connection is driver, "the caller's connection was closed" + assert _session_state() == before + finally: + if connection.connection is driver: + with connection.cursor() as cursor: + for sql in session["teardown"]: + cursor.execute(sql) + connection.close() + if connection.vendor == "postgresql" and _pool_options("default"): + # A connection closed with the session on it went back to the + # pool, its advisory lock and temporary table with it. + connection.close_pool() + + assert look_reads == [] + assert _recovery_events(caplog) == [] + assert _row(result).status == OxTask.Status.READY + + +@pytest.mark.skipif( + connection.vendor != "postgresql", reason="psycopg2 is PostgreSQL's driver" +) +def test_with_psycopg2_the_loop_leaves_a_claim_that_raised_to_the_reaper( + settings, monkeypatch, caplog, lose_the_reply, look_reads +): + """ + psycopg2, emulated: psycopg_any.is_psycopg3 reads False when the worker + asks, as with psycopg2 installed, while Django's backend, which read it + at import, goes on with psycopg 3. The loop's claim commits and loses + its reply. It is not noted: no pass looks for it and nor does the stop, + and the row is RUNNING under the worker, the attempt charged, for the + reaper. The loop goes on claiming. + """ + from django.db.backends.postgresql import psycopg_any + + monkeypatch.setattr(psycopg_any, "is_psycopg3", False) + caplog.set_level(logging.WARNING, logger="django_ox") + _budget(settings, 1) + seam = lose_the_reply("statement") + lost, after = _enqueue("lost", "after") + worker = Worker(lock_timeout=LOCK_TIMEOUT, poll_interval=0.05) + + _run_until(worker, lambda: _row(after).status == OxTask.Status.SUCCESSFUL) + + assert seam.fired + assert look_reads == [] + assert _recovery_events(caplog) == [] + assert worker._claim_unconfirmed_at is None + (poll,) = _events(caplog, "worker_poll_failed", worker) + assert poll.claim_recovery is None + row = _row(lost) + assert (row.status, row.locked_by, row.attempts) == ( + OxTask.Status.RUNNING, + worker.worker_id, + 1, + ) + assert (_runs("lost"), _runs("after")) == (0, 1) + + +# -- a database that stops answering ----------------------------------------------- + + +postgresql_relay = pytest.mark.skipif( + connection.vendor != "postgresql", + reason="a relay in front of PostgreSQL; on MySQL the claim itself can wait on " + "a server that stopped answering, in its transaction's exit, as it always " + "could", +) + +#: Before, the look after a claim error waited at least 40 s on a server that +#: had stopped answering; an inline call makes no look now. +BOUNDED_WELL_UNDER = 20.0 + + +@pytest.fixture +def relay(monkeypatch): + """ + Every connection to the test database opened from here on, Django's + pool's included, goes through a relay that can stop answering + (tests/unanswering.py). go_dark() stops it, and detach() puts + everything back, for reading the outcome afterwards. + """ + conn = connections["default"] + pooled = conn.vendor == "postgresql" and _pool_options("default") is not None + relay = Unanswering( + conn.settings_dict["HOST"] or "127.0.0.1", conn.settings_dict["PORT"] or 5432 ) - assert message.endswith(". " + said) - assert not_said not in message - assert "the database is still gone" in message - assert failed.claim_recovery == ("pending" if caller == "run_once" else "expired") + conn.close() + if pooled: + conn.close_pool() + monkeypatch.setitem(conn.settings_dict, "HOST", "127.0.0.1") + monkeypatch.setitem(conn.settings_dict, "PORT", str(relay.port)) + receivers = [] + detached = [] + + def go_dark(dark): + """ + "gone": the connections open now, the pool's idle ones among them, + never answer again, and a new one is accepted and never answered. + "hung": the same for the connections open now, and a new one is + set up and stops answering as soon as Django has it. + """ + if dark == "gone": + relay.stall() + relay.black_hole() + return + relay.stall_open() + + def stall_it(sender, connection, **kwargs): + relay.stall_open() + + connection_created.connect(stall_it, weak=False) + receivers.append(stall_it) + + def detach(): + if detached: + return + detached.append(True) + for receiver in receivers: + connection_created.disconnect(receiver) + relay.close() + conn.close() + if pooled: + conn.close_pool() + monkeypatch.undo() + conn.close() + + relay.pooled = pooled + relay.go_dark = go_dark + relay.detach = detach + yield relay + detach() + + +class Caller: + """ + A caller of run_once() or run_tasks() on a thread of its own, as a + request handler would be. `setup` runs there first, so the connection + the call starts with is that thread's and already open; the call waits + for start(). + """ + + def __init__(self, setup, call): + self.ready = threading.Event() + self._go = threading.Event() + self.outcome = {} + self.thread = threading.Thread(target=self._run, args=(setup, call)) + self.thread.daemon = True + self.thread.start() + assert self.ready.wait(LIMIT), "the caller's setup did not finish" + assert "setup_error" not in self.outcome, self.outcome["setup_error"] + + def _run(self, setup, call): + try: + try: + setup() + except BaseException as exc: + self.outcome["setup_error"] = exc + return + finally: + self.ready.set() + self._go.wait(LIMIT) + started = time.monotonic() + try: + self.outcome["value"] = call() + except BaseException as exc: + self.outcome["error"] = exc + finally: + self.outcome["took"] = time.monotonic() - started + finally: + connections.close_all() + + def start(self): + self._go.set() + + def returned_within(self, seconds): + self.thread.join(seconds) + return not self.thread.is_alive() + + +def _claim_errors(monkeypatch): + """Every exception a claim raises, as raised.""" + raised = [] + real = Worker.claim_one + + def claim_one(self): + try: + return real(self) + except BaseException as exc: + raised.append(exc) + raise + + monkeypatch.setattr(Worker, "claim_one", claim_one) + return raised + + +def _open_a_connection(): + OxTask.objects.exists() + + +@postgresql_relay +@pytest.mark.parametrize("dark", ["gone", "hung"]) +@pytest.mark.parametrize("call", ["run_once", "run_tasks"]) +def test_an_inline_claim_error_on_a_stalled_database_raises_at_once( + call, dark, relay, settings, monkeypatch, caplog, lose_the_reply +): + """ + The database stops answering right after a claim's reply is lost: every + connection already open, the pool's idle ones included, never answers + again, and a new one is either never answered or set up and then never + answered. The call raises the claim's own error without waiting on the + server: no look, so no connection opened for one and no test of the + pool's idle connections. The row is RUNNING, the attempt charged, for + the reaper. Before, the call made a look first and waited on it. + """ + caplog.set_level(logging.WARNING, logger="django_ox") + _budget(settings, 1) + claim_errors = _claim_errors(monkeypatch) + if relay.pooled: + _fill_the_pool() + untouched = tasks.record.using(priority=-1).enqueue("never claimed") + result = tasks.record.enqueue("dark") + worker = Worker(lock_timeout=LOCK_TIMEOUT) + seam = lose_the_reply("statement", also=lambda other: relay.go_dark(dark)) + caller = Caller(_open_a_connection, lambda: _call(call, worker)) + caller.start() + returned = caller.returned_within(BOUNDED_WELL_UNDER) + relay.detach() + caller.thread.join(LIMIT) + + assert returned, f"the call was still waiting after {BOUNDED_WELL_UNDER:g}s" + assert seam.fired + assert caller.outcome.get("error") is claim_errors[0], caller.outcome + assert _recovery_events(caplog) == [] + assert worker._claim_unconfirmed_at is None + row = _row(result) + assert (row.status, row.attempts) == (OxTask.Status.RUNNING, 1) + row = _row(untouched) + assert (row.status, row.attempts) == (OxTask.Status.READY, 0) + + +@pooled_postgresql +@pytest.mark.parametrize("call", ["run_once", "run_tasks"]) +def test_an_inline_claim_error_never_checks_the_pool( + call, settings, monkeypatch, caplog, lose_the_reply +): + """ + Nothing on the caller's thread tests the connections Django's pool + holds idle after a claim error: pool.check() waits on each of them, and + on a server that stopped answering, for as long as the kernel does. The + loop's failed pass still sweeps the pool. + """ + caplog.set_level(logging.WARNING, logger="django_ox") + _budget(settings, 1) + tasks.record.enqueue("checked") + pool = connections["default"].pool + checks = [] + real_check = pool.check + + def check(*args, **kwargs): + checks.append(threading.current_thread().name) + return real_check(*args, **kwargs) + + monkeypatch.setattr(pool, "check", check) + # The instrument sees a sweep. + _sweep_pool(connections["default"]) + assert checks == [threading.current_thread().name] + checks.clear() + seam = lose_the_reply("statement", on=connections["default"]) + worker = Worker(lock_timeout=LOCK_TIMEOUT) + + with pytest.raises(DatabaseError): + _call(call, worker) + + assert seam.fired + assert checks == [] + assert _recovery_events(caplog) == [] diff --git a/tests/test_forked_worker.py b/tests/test_forked_worker.py new file mode 100644 index 0000000..b21b583 --- /dev/null +++ b/tests/test_forked_worker.py @@ -0,0 +1,557 @@ +""" +A Worker built before a fork and used in both processes afterwards. + +A web server that imports the application and then forks its workers, with +a module-level Worker that views call run_once() on, has one; so does a +launcher that builds a Worker and forks it into several processes. Each +copy used to claim under the same worker id, with bookkeeping of its own, +and a look for a claim that raised in one process took the row the other +was executing for its own: it released it, another claim ran the body a +second time, and the first execution's outcome was fenced out. + +Two forks. os.fork() runs the at-fork hooks, as gunicorn's fork does. libc's +fork() called through ctypes, with the interpreter lock held, runs none, as +uWSGI forks its workers unless told to call them. tests/lost_reply.py loses +the reply to the parent's claim. +""" + +import collections +import ctypes +import gc +import json +import os +import signal +import threading +import time +import traceback +import uuid +import weakref +from contextlib import suppress + +import pytest +from django.db import ( + DatabaseError, + close_old_connections, + connection, + connections, +) + +from django_ox import worker as worker_module +from django_ox.models import OxTask +from django_ox.testing import run_tasks +from django_ox.worker import Worker, _pool_options + +from . import tasks +from .conftest import start_worker_thread, wait_for +from .lost_reply import Seams + +pytestmark = [ + pytest.mark.skipif(not hasattr(os, "fork"), reason="os.fork() is POSIX only"), + # Python 3.12 warns when a process that has threads forks. The tests + # that hold locks at the fork have one on purpose, and a thread an + # earlier test left behind would make any of them warn. + pytest.mark.filterwarnings("ignore::DeprecationWarning"), +] + +LIMIT = 60.0 + +#: The body the child is inside while the parent claims. +LONG_BODY = 4.0 + +#: A call in the child on an empty queue takes a moment; one waiting on a +#: lock copied held never returns. +CHILD_CALL_LIMIT = 20.0 + +#: A reply each database can lose after the claim has committed. +WINDOW = {"postgresql": "statement", "mysql": "commit", "sqlite": "statement"} + +#: os.fork() runs the at-fork hooks; libc's fork() runs none, as uWSGI forks +#: by default. A child forked by libc must not start a thread: CPython keeps +#: the other threads' states in it, and a new thread there is undefined +#: behaviour of the interpreter itself (a child running run() crashed on +#: Python 3.14 in CI). Where the child starts threads, "unhooked" forks with +#: os.fork() and every Worker out of the registry, so the interpreter's own +#: hooks run and django-ox's finds nothing: only the pid check can make the +#: Worker the child's own, as after libc's fork. +FORKS = ["os.fork", "libc"] +THREADED_FORKS = ["os.fork", "unhooked"] + + +@pytest.fixture(autouse=True) +def no_dead_connection_outlives_the_test(): + yield + for conn in connections.all(initialized_only=True): + if ( + conn.connection is not None + and not conn.in_atomic_block + and not conn.is_usable() + ): + conn.close() + + +@pytest.fixture +def lose_the_reply(): + seams = Seams() + yield seams.arm + seams.remove_all() + + +def _budget(settings, attempts): + settings.TASKS = { + "default": { + "BACKEND": "django_ox.backend.OxBackend", + "QUEUES": ["default"], + "OPTIONS": {"MAX_ATTEMPTS": attempts}, + } + } + + +def _ready_to_fork(): + """ + Nothing of the parent's connections for the child to share: each + process opens its own. Django's pool is per process too; the parent + builds a new one on its next statement. + """ + connections.close_all() + if _pool_options("default") is not None and connection.vendor == "postgresql": + connection.close_pool() + + +class Child: + """ + target(*args) in a child forked `how`; the child exits 0 when it + returns and 1 when it raises, without running anything of the parent's + on the way out. + """ + + def __init__(self, how, target, *args): + _ready_to_fork() + if how == "libc": + fork = ctypes.PyDLL(None).fork + fork.restype = ctypes.c_int + fork.argtypes = [] + pid = fork() + elif how == "unhooked": + registered = list(worker_module._live_workers) + for worker in registered: + worker_module._live_workers.discard(worker) + pid = os.fork() + if pid: + for worker in registered: + worker_module._live_workers.add(worker) + else: + pid = os.fork() + if pid == 0: + code = 1 + try: + target(*args) + code = 0 + except BaseException: + traceback.print_exc() + finally: + with suppress(BaseException): + connections.close_all() + os._exit(code) + self.pid = pid + self.exitcode = None + + def join(self, timeout): + """The exit code, or None if the child is still running at `timeout`.""" + deadline = time.monotonic() + timeout + while self.exitcode is None: + done, status = os.waitpid(self.pid, os.WNOHANG) + if done: + self.exitcode = os.waitstatus_to_exitcode(status) + elif time.monotonic() >= deadline: + return None + else: + time.sleep(0.02) + return self.exitcode + + def kill(self): + if self.exitcode is None: + with suppress(ProcessLookupError): + os.kill(self.pid, signal.SIGKILL) + self.join(LIMIT) + + +def _runs(path): + counts = collections.Counter() + if path.exists(): + for line in path.read_text().splitlines(): + counts[line.split()[0]] += 1 + return counts + + +def _row(result): + return OxTask.objects.get(id=result.id) + + +def _drain(): + """Run whatever is left with a Worker of the parent's own.""" + other = Worker(lock_timeout=300.0, backoff_initial=0) + deadline = time.monotonic() + LIMIT + while time.monotonic() < deadline: + try: + if not other.run_once(): + return + except DatabaseError: + close_old_connections() + + +def _released(caplog): + return [ + r.task_id + for r in caplog.records + if getattr(r, "event", None) == "worker_claim_released" + ] + + +# -- a look in one process never takes the other's row ------------------------- + + +@pytest.mark.django_db(transaction=True) +@pytest.mark.parametrize("how", THREADED_FORKS) +@pytest.mark.parametrize("path", ["loop", "pending", "stop"]) +def test_forked_worker_does_not_recover_other_process_claim( + path, how, tmp_path, settings, caplog, lose_the_reply +): + """ + The child claims the long task L with run_once() and is inside its + body. The parent, with its copy of the same Worker, then runs its loop, + which looks for a claim that raised: + + - loop: the loop's claim of S commits and loses its reply, and the next + pass looks; + - pending: a look is pending from an earlier claim that raised, and the + first pass looks before claiming; + - stop: the loop's claim of S loses its reply and the worker is asked to + stop, so the look is the one it makes on the way out. + + L's body runs once, its row is never released, refunded or moved on, + and the child's outcome is the one recorded. + """ + caplog.set_level("WARNING", logger="django_ox") + _budget(settings, 3) + runs = tmp_path / "runs" + long = tasks.append_line.using(priority=10).enqueue(str(runs), "L", LONG_BODY) + short = tasks.append_line.enqueue(str(runs), "S") + worker = Worker( + lock_timeout=300.0, + poll_interval=30.0 if path == "stop" else 0.05, + backoff_initial=0, + ) + parent_id = worker.worker_id + child = Child(how, worker.run_once) + try: + assert wait_for(lambda: _runs(runs)["L"] == 1, timeout=LIMIT), ( + "the child never started L" + ) + if path == "pending": + worker._claim_unconfirmed_at = time.monotonic() + seam = None + else: + also = (lambda other: worker.request_stop()) if path == "stop" else None + seam = lose_the_reply(WINDOW[connection.vendor], also=also) + thread = start_worker_thread(worker) + try: + if path == "stop": + thread.join(timeout=LIMIT) + else: + assert wait_for( + lambda: _row(short).status == OxTask.Status.SUCCESSFUL, + timeout=LIMIT, + ) + finally: + worker.request_stop() + thread.join(timeout=LIMIT) + assert not thread.is_alive() + if seam is not None: + assert seam.fired, "the parent's claim never lost its reply" + during = _row(long) + finally: + if child.join(LIMIT) is None: + child.kill() + assert child.exitcode == 0 + + _drain() + long_row, short_row = _row(long), _row(short) + counts = _runs(runs) + assert counts["L"] == 1, ( + f"L's body ran {counts['L']} times; after the parent's look L was " + f"{(during.status, during.attempts, during.lease_epoch)}, released " + f"{_released(caplog)}" + ) + assert counts["S"] == 1 + assert str(long.id) not in _released(caplog) + assert (long_row.status, long_row.attempts, long_row.lease_epoch) == ( + OxTask.Status.SUCCESSFUL, + 1, + 1, + ) + assert long_row.worker_ids != [parent_id] + assert short_row.status == OxTask.Status.SUCCESSFUL + assert worker.worker_id == parent_id + + +# -- what the child starts with --------------------------------------------------- + + +def _report_state(worker, report): + """In the child: one call, which a Worker makes its own before claiming.""" + worker.run_once() + worker._beat() + heartbeat = worker._heartbeat + report.write_text( + json.dumps( + { + "pid": os.getpid(), + "worker_id": worker.worker_id, + "sets": [ + sorted(worker._in_flight), + sorted(worker._handed_off), + sorted(worker._unsettled), + ], + "pending": worker._claim_unconfirmed_at, + "claims_in_flight": worker._claims_in_flight, + "watches": len(worker._watches), + "stuck": len(worker._stuck), + "running_on": len(worker._running_on), + "heartbeat_path": heartbeat and heartbeat.path, + "heartbeat_owner": heartbeat and heartbeat.owner, + "dispatch_report_id": worker._dispatch_report.worker_id, + "stopping": worker.stopping, + }, + default=str, + ) + ) + + +@pytest.mark.django_db(transaction=True) +@pytest.mark.parametrize("how", FORKS) +def test_child_reinitializes_inherited_worker_state(how, tmp_path): + """ + The child's copy is a worker of its own before its first claim: a new + id that keeps the slot suffix, nothing in its bookkeeping, no look + pending and no timeout watches. It keeps the heartbeat file and updates + it, under its own id. The parent is untouched. + """ + beat = tmp_path / "heartbeat" + report = tmp_path / "report.json" + worker = Worker(lock_timeout=300.0, worker_index=3, heartbeat_file=str(beat)) + parent_id = worker.worker_id + worker._beat() + past = time.time() - 3600 + os.utime(beat, (past, past)) + before = beat.stat().st_mtime_ns + heartbeat = worker._heartbeat + running, handed_off, unsettled = uuid.uuid4(), uuid.uuid4(), uuid.uuid4() + worker._in_flight.add((running, 1)) + worker._handed_off.add((handed_off, 1)) + worker._unsettled.add((unsettled, 1)) + worker._claim_unconfirmed_at = pending = time.monotonic() + # Claims the parent's threads are making as it forks. + worker._claims_in_flight = 2 + worker._watches[1] = "a watch" + worker._stuck[1] = (running, 1) + worker._running_on[1] = (running, 1) + worker._claimed = 5 + + child = Child(how, _report_state, worker, report) + if child.join(LIMIT) is None: + child.kill() + assert child.exitcode == 0 + state = json.loads(report.read_text()) + + assert state["worker_id"] != parent_id + assert state["worker_id"].endswith("-3") + assert f"-{state['pid']}-" in state["worker_id"] + assert state["sets"] == [[], [], []] + assert state["pending"] is None + assert state["claims_in_flight"] == 0 + assert (state["watches"], state["stuck"], state["running_on"]) == (0, 0, 0) + assert state["heartbeat_path"] == str(beat) + assert state["heartbeat_owner"] == f"Worker {state['worker_id']}" + assert state["dispatch_report_id"] == state["worker_id"] + assert state["stopping"] is False + assert beat.stat().st_mtime_ns != before, "the child did not update the file" + + assert worker.worker_id == parent_id + assert worker._in_flight == {(running, 1)} + assert worker._handed_off == {(handed_off, 1)} + assert worker._unsettled == {(unsettled, 1)} + assert worker._claim_unconfirmed_at == pending + assert worker._claims_in_flight == 2 + assert worker._watches == {1: "a watch"} + assert worker._claimed == 5 + assert worker._heartbeat is heartbeat + assert heartbeat.owner == f"Worker {parent_id}" + assert worker._dispatch_report.worker_id == parent_id + + +def _run_stopped(worker): + worker.request_stop() + return worker.run() + + +#: The first call the child makes, each of which makes the Worker its own +#: before it touches a lock. +ENTRIES = { + "run_once": lambda worker: worker.run_once(), + "run": _run_stopped, + "claim_one": lambda worker: worker.claim_one(), + "look": lambda worker: worker._recover_claims(), +} + + +def _held_locks(worker): + return { + "fence": worker._fence, + "in_flight": worker._in_flight_lock, + "watch": worker._watch_lock, + "backstop_only": worker._backstop_only_lock, + } + + +def _call_then_try_the_locks(worker, entry, report): + try: + outcome = ["returned", repr(ENTRIES[entry](worker))] + except BaseException as exc: + outcome = ["raised", repr(exc)] + acquired = {} + for name, lock in _held_locks(worker).items(): + acquired[name] = lock.acquire(timeout=1.0) + if acquired[name]: + lock.release() + acquired["watch_cv"] = worker._watch_cv.acquire(timeout=1.0) + if acquired["watch_cv"]: + worker._watch_cv.notify_all() + worker._watch_cv.release() + report.write_text( + json.dumps( + {"outcome": outcome, "acquired": acquired, "worker_id": worker.worker_id} + ) + ) + + +@pytest.mark.django_db(transaction=True) +@pytest.mark.parametrize( + ("how", "entry"), + [ + (how, entry) + for how in [*FORKS, "unhooked"] + for entry in ENTRIES + if not (how == "libc" and entry == "run") + ], +) +def test_child_replaces_locks_held_at_fork(how, entry, tmp_path): + """ + Another thread of the parent holds every one of the Worker's locks at + the moment the process forks, and a look is pending. A lock is copied + held, with no thread in the child to release it. Whichever call the + child makes first, a claim, the loop or a look, it neither waits on the + parent's thread nor makes the parent's look, and the Worker's locks are + the child's own afterwards. The parent's locks are still the parent's. + """ + report = tmp_path / "report.json" + worker = Worker(lock_timeout=300.0, backoff_initial=0) + parent_id = worker.worker_id + worker._claim_unconfirmed_at = time.monotonic() + locks = _held_locks(worker) + holding = threading.Event() + release = threading.Event() + + def hold(): + for lock in locks.values(): + lock.acquire() + holding.set() + release.wait(LIMIT) + for lock in locks.values(): + lock.release() + + holder = threading.Thread(target=hold) + holder.start() + child = None + try: + assert holding.wait(LIMIT) + child = Child(how, _call_then_try_the_locks, worker, entry, report) + returned = child.join(CHILD_CALL_LIMIT) + for name, lock in locks.items(): + assert not lock.acquire(blocking=False), f"the parent's {name} lock" + finally: + release.set() + holder.join(LIMIT) + if child is not None and child.join(10) is None: + child.kill() + + assert returned == 0, f"the child's {entry} was still waiting or failed" + state = json.loads(report.read_text()) + assert state["outcome"][0] == "returned", state["outcome"] + assert state["acquired"] == dict.fromkeys([*locks, "watch_cv"], True) + assert state["worker_id"] != parent_id + assert worker.worker_id == parent_id + + +@pytest.mark.django_db(transaction=True) +@pytest.mark.parametrize("how", THREADED_FORKS) +def test_a_forked_child_running_run_updates_the_heartbeat(how, tmp_path): + """ + A launcher builds a Worker with a heartbeat file and forks a child that + runs its loop. The child updates that file, and claims under an id of + its own that keeps the slot suffix, whichever fork made it. + """ + beat = tmp_path / "heartbeat" + runs = tmp_path / "runs" + result = tasks.append_line.enqueue(str(runs), "C") + worker = Worker( + lock_timeout=300.0, + poll_interval=0.05, + worker_index=2, + heartbeat_file=str(beat), + max_tasks=1, + ) + parent_id = worker.worker_id + + child = Child(how, worker.run) + if child.join(LIMIT) is None: + child.kill() + + assert child.exitcode == 0 + assert beat.exists(), "nothing wrote the heartbeat file" + row = _row(result) + assert row.status == OxTask.Status.SUCCESSFUL + (child_id,) = row.worker_ids + assert child_id != parent_id + assert child_id.endswith("-2") + assert f"-{child.pid}-" in child_id + assert _runs(runs)["C"] == 1 + assert worker.worker_id == parent_id + + +# -- the registry --------------------------------------------------------------------- + + +@pytest.mark.django_db(transaction=True) +def test_worker_registry_does_not_retain_workers(): + """ + Every Worker is registered for the fork hook, and none is kept alive by + it: run_tasks() builds a Worker per call, and a long-lived process that + calls it would otherwise hold every one it ever built. + """ + from django_ox import worker as worker_module + + registry = worker_module._live_workers + worker = Worker(lock_timeout=300.0) + assert worker in registry + gone = weakref.ref(worker) + del worker + gc.collect() + assert gone() is None + assert all(w is not None for w in registry) + + gc.collect() + before = len(registry) + for _ in range(5): + assert run_tasks() == [] + gc.collect() + assert len(registry) <= before diff --git a/tests/test_lost_commit_reply.py b/tests/test_lost_commit_reply.py index 3f7fd94..eceda3d 100644 --- a/tests/test_lost_commit_reply.py +++ b/tests/test_lost_commit_reply.py @@ -18,22 +18,25 @@ The loop asserts the outcome: the task's body runs once, the row ends SUCCESSFUL, and the attempts it records are the attempts that ran. The inline -calls raise the claim's error, which is theirs to raise, and the contract is -that the next call runs the released task. +calls raise the claim's error at once and do nothing else, as in 1.6.0: a +claim that landed is the reaper's once its lease expires, with the attempt +spent. """ import logging +import traceback import pytest from django.db import DatabaseError, close_old_connections, connections +from django_ox.actions import expire_lease from django_ox.models import OxTask from django_ox.testing import run_tasks from django_ox.worker import Worker from . import tasks from .conftest import start_worker_thread, wait_for -from .lost_reply import WINDOWS, Seams +from .lost_reply import WINDOWS, LookReads, Seams pytestmark = pytest.mark.django_db(transaction=True) @@ -76,6 +79,13 @@ def lose_the_reply(): seams.remove_all() +@pytest.fixture +def look_reads(): + looks = LookReads() + yield looks.reads + looks.remove() + + def _budget(settings, attempts): settings.TASKS = { "default": { @@ -166,65 +176,102 @@ def test_run_a_claim_whose_reply_is_lost_runs_once_uncharged( assert len(released) == (1 if seam.landed else 0), messages -def _call_raises_then_the_next_runs_it(seam, worker, result, call, caplog): +RECOVERY_EVENTS = { + "worker_claim_released", + "worker_claim_recovery_failed", + "worker_claim_recovery_expired", +} + + +def _recovery_records(caplog): + return [ + r.getMessage() + for r in caplog.records + if getattr(r, "event", None) in RECOVERY_EVENTS + ] + + +def _call_raised_at_once(seam, worker, raised, caplog, look_reads, result): """ - The inline contract. The call whose claim lost its reply raises the - claim's own error; the row is then READY with nothing charged, released - if the claim had landed and untouched if it had not; and the next call - runs it, once. + The inline contract. The call whose claim lost its reply raised the + claim's own error, and made no look for it: nothing read, released or + logged, and nothing left pending. A claim that had landed leaves its row + RUNNING under the worker, the attempt charged; one that had not leaves + it as it was. """ - with pytest.raises(DatabaseError): - call() - # As any caller does after a database error: drop a connection that died. - close_old_connections() + frames = "".join(traceback.format_exception(raised)) + assert "claim_one" in frames, "the error raised is not the claim's" _assert_the_seam_fired_where_intended(seam, worker) + assert look_reads == [], "a look was made for the claim that raised" + assert _recovery_records(caplog) == [] + assert worker._claim_unconfirmed_at is None row = OxTask.objects.get(id=result.id) if seam.landed: - expected = (OxTask.Status.READY, None, 0, 2, [], None) + expected = (OxTask.Status.RUNNING, worker.worker_id, 1, 1, [worker.worker_id]) else: - expected = (OxTask.Status.READY, None, 0, 0, [], None) + expected = (OxTask.Status.READY, None, 0, 0, []) assert ( row.status, row.locked_by, row.attempts, row.lease_epoch, row.worker_ids, - row.started_at, - ) == expected, "the failed call left the row as it was not before the claim" - assert len(_released_records(caplog, worker)) == (1 if seam.landed else 0) + ) == expected assert _runs() == 0 - call() + +def _the_reaper_takes_it_back(result): + """Once its lease expires, the reaper puts the row back, the attempt spent.""" + assert expire_lease(result.id) + assert Worker(lock_timeout=INLINE_LOCK_TIMEOUT).reap() == 1 row = OxTask.objects.get(id=result.id) - assert (row.status, row.attempts, _runs()) == (OxTask.Status.SUCCESSFUL, 1, 1) - assert row.worker_ids == [worker.worker_id] + assert (row.status, row.attempts, row.lease_epoch) == (OxTask.Status.READY, 1, 2) + + +def _ran_once(result, attempts): + row = OxTask.objects.get(id=result.id) + assert (row.status, row.attempts, _runs()) == ( + OxTask.Status.SUCCESSFUL, + attempts, + 1, + ) @pytest.mark.parametrize("window", CLAIM_WINDOWS) -def test_run_once_raises_and_the_next_call_runs_the_task( - window, settings, caplog, lose_the_reply +def test_run_once_raises_at_once_and_leaves_the_row_to_the_reaper( + window, settings, caplog, lose_the_reply, look_reads ): """ run_once() on the test's own thread and connection, which is in - autocommit: nothing reaps, so a row the failed call did not release would - still be RUNNING when the next call looks for work, and that call would - find none. + autocommit. Nothing looks for a claim of run_once()'s that raised: a row + that landed is still RUNNING when the next call looks for work, which + finds none, and runs once the reaper has put it back. """ seam = lose_the_reply(window, on=connections["default"]) caplog.set_level(logging.WARNING, logger="django_ox") - _budget(settings, 1) + _budget(settings, 2) worker = Worker( lock_timeout=INLINE_LOCK_TIMEOUT, poll_interval=0.05, backoff_initial=0 ) result = tasks.record.enqueue("lost-reply") - _call_raises_then_the_next_runs_it( - seam, worker, result, lambda: worker.run_once(), caplog - ) + + with pytest.raises(DatabaseError) as raised: + worker.run_once() + # As any caller does after a database error: drop a connection that died. + close_old_connections() + _call_raised_at_once(seam, worker, raised.value, caplog, look_reads, result) + + if seam.landed: + assert worker.run_once() is False + _the_reaper_takes_it_back(result) + assert worker.run_once() is True + _ran_once(result, 2 if seam.landed else 1) + assert look_reads == [] @pytest.mark.parametrize("window", CLAIM_WINDOWS) -def test_run_tasks_raises_and_the_next_call_runs_the_task( - window, settings, caplog, monkeypatch, lose_the_reply +def test_run_tasks_raises_at_once_and_leaves_the_row_to_the_reaper( + window, settings, caplog, monkeypatch, lose_the_reply, look_reads ): """ run_tasks() in autocommit, as from a TransactionTestCase: the same @@ -232,7 +279,7 @@ def test_run_tasks_raises_and_the_next_call_runs_the_task( """ seam = lose_the_reply(window, on=connections["default"]) caplog.set_level(logging.WARNING, logger="django_ox") - _budget(settings, 1) + _budget(settings, 2) result = tasks.record.enqueue("lost-reply") workers = [] real_init = Worker.__init__ @@ -242,18 +289,17 @@ def remember(self, *args, **kwargs): workers.append(self) monkeypatch.setattr(Worker, "__init__", remember) - with pytest.raises(DatabaseError): + with pytest.raises(DatabaseError) as raised: run_tasks() close_old_connections() monkeypatch.undo() (worker,) = workers - _assert_the_seam_fired_where_intended(seam, worker) - row = OxTask.objects.get(id=result.id) - assert (row.status, row.attempts, row.worker_ids) == (OxTask.Status.READY, 0, []) - assert len(_released_records(caplog, worker)) == (1 if seam.landed else 0) - assert _runs() == 0 + _call_raised_at_once(seam, worker, raised.value, caplog, look_reads, result) + if seam.landed: + assert run_tasks() == [] + _the_reaper_takes_it_back(result) (ran,) = run_tasks() - row = OxTask.objects.get(id=result.id) assert ran.status == "SUCCESSFUL" - assert (row.status, row.attempts, _runs()) == (OxTask.Status.SUCCESSFUL, 1, 1) + _ran_once(result, 2 if seam.landed else 1) + assert look_reads == [] diff --git a/tests/unanswering.py b/tests/unanswering.py index 1025b2d..a5c5bc1 100644 --- a/tests/unanswering.py +++ b/tests/unanswering.py @@ -7,7 +7,10 @@ connections already open stop relaying, in both directions, as a server that stops answering once connected; what a client sends from then on is counted and dropped, so a test can tell its statement went out and was -never answered. +never answered. stall_open(): the same for the connections open at the +call only; one made later is relayed until it is stalled in turn, as a +server that accepts and sets up a session and then answers nothing, or a +pool's idle connections to a host that went away without resetting them. """ import socket @@ -24,6 +27,8 @@ def __init__(self, host, port): self._stalled = threading.Event() self._lock = threading.Lock() self._sockets = [] + #: One flag per relayed connection, set by stall_open(). + self._each_stalled = [] #: Connections accepted and never answered. self.unanswered_connects = 0 #: Bytes a client sent while relaying was stalled, none of them passed on. @@ -36,6 +41,11 @@ def black_hole(self): def stall(self): self._stalled.set() + def stall_open(self): + with self._lock: + for stalled in self._each_stalled: + stalled.set() + def close(self): """Reset every connection, which wakes whatever waits on one.""" with suppress(OSError): @@ -71,15 +81,20 @@ def _accept(self): client.close() continue self._keep(upstream) + stalled = threading.Event() + with self._lock: + self._each_stalled.append(stalled) for source, sink, from_client in ( (client, upstream, True), (upstream, client, False), ): threading.Thread( - target=self._pipe, args=(source, sink, from_client), daemon=True + target=self._pipe, + args=(source, sink, from_client, stalled), + daemon=True, ).start() - def _pipe(self, source, sink, from_client): + def _pipe(self, source, sink, from_client, stalled): while True: try: data = source.recv(65536) @@ -89,7 +104,7 @@ def _pipe(self, source, sink, from_client): with suppress(OSError): sink.shutdown(socket.SHUT_WR) return - if self._stalled.is_set(): + if self._stalled.is_set() or stalled.is_set(): if from_client: with self._lock: self.unanswered_bytes += len(data)