diff --git a/docs/agents.md b/docs/agents.md index 3882655..8c6800d 100644 --- a/docs/agents.md +++ b/docs/agents.md @@ -77,13 +77,7 @@ python manage.py ox_health OK: backlog=0 oldest_age=none last_claim_age=none ``` -`manage.py check` reports schedule and backend policy errors through -`django_ox.E002` to `E005`, `E010` and `E011`, and warnings through -`django_ox.W003` and `django_ox.W004`, before deployment. -Database acceptance of schedule arguments is determined at dispatch; -alert on `schedule_dispatch_error` and `schedule_dispatch_failed` at runtime. -Review `django_ox.W003` and `django_ox.W004` warnings too; `W004` asks for -a non-bool integer from 1 to 32767 while retaining compatible legacy values. +`manage.py check` reports schedule and backend policy errors through `django_ox.E002` to `E005`, `E010` and `E011`, and warnings through `django_ox.W003` and `django_ox.W004`, before deployment. Database acceptance of schedule arguments is determined at dispatch. Alert on `schedule_dispatch_error`, `schedule_dispatch_failed` and `schedule_tick_unreadable`. For stored schedules, also alert on `schedule_row_skipped`, `schedule_source_unavailable` and `schedule_boundary_heal_failed`. Review `django_ox.W003` and `django_ox.W004` warnings too; `W004` asks for a non-bool integer from 1 to 32767 while retaining compatible legacy values. Invalid per-task fields raise `InvalidTask` (`InvalidTaskError` on the backport) when the task is built, normally at import, rather than appearing diff --git a/docs/llms-full.txt b/docs/llms-full.txt index be90dfa..792e2b0 100644 --- a/docs/llms-full.txt +++ b/docs/llms-full.txt @@ -2048,11 +2048,7 @@ across backends: python manage.py check ``` -Database acceptance is determined at dispatch after validation. Alert on -`schedule_dispatch_error` for schedule-scoped failures and -`schedule_dispatch_failed` for abandoned passes. For stored schedules, -also alert on `schedule_row_skipped` and `schedule_source_unavailable`. -Use these events for schedule health monitoring. +Database acceptance is determined at dispatch after validation. Alert on `schedule_dispatch_error`, `schedule_dispatch_failed` and `schedule_tick_unreadable`. For stored schedules, also alert on `schedule_row_skipped`, `schedule_source_unavailable` and `schedule_boundary_heal_failed`. These report schedule-scoped failures, abandoned passes, unusable history, skipped rows, source failures and blocked boundary healing. To see what has actually dispatched, read the tick log: @@ -2770,19 +2766,8 @@ Worth knowing before you turn it on: such a write tells a worker to look. Set `OPTIONS["SCHEDULE_RECONCILE_INTERVAL"]` if you want that sooner; it is one indexed read of a small table. -- **One extra query per pass.** Workers read a single row to learn whether - anything changed. They re-read the schedules when it did and at each - reconcile interval. If the change marker cannot be read, full reads still - run at each reconcile interval. -- **Unreadable or invalid rows are skipped.** A row is left out if a value - cannot be converted, its start or end cannot be compared with the worker's - clock, or it cannot be built. The other schedules and the queue keep - running. The skip is logged as `schedule_row_skipped` with `schedule_pk`, - `schedule` and `reason`. If the name cannot be read, `schedule` may be - `None`. A conversion failure's reason names the column. Each row is logged - once, then at most once a minute per worker while it stays skipped. A skip - during the locked dispatch read includes a traceback only on its first - line. +- **Marker reads and reconciles.** Workers read one change-marker row per pass. They re-read schedules when it changes and at `SCHEDULE_RECONCILE_INTERVAL`, normally 60 seconds. If the marker cannot be read, full reads still run at that interval. Stored schedule reads use more CPU than 1.8.0, and full reconciles now use batched queries. Reconciles do not run every tick. Latest tick decoding costs CPU each pass. Dispatch statement counts are unchanged, both with and without a due tick. +- **Stored values django-ox cannot use.** Workers skip unreadable or invalid rows, including incomparable boundaries and a maximum `boundary_generation`; other schedules and the queue continue. `schedule_row_skipped` carries `schedule_pk`, `schedule`, `fields` and `reason`. An unreadable name may be `None`. Stored-value reasons name the field, quote its value and explain the problem. Reporting is once, then at most once a minute per row per worker. Locked dispatch skips include a traceback only on the first line. - **Skipped rows need repair.** Skipping does not repair invalid values. Find the row by `schedule_pk` and correct it in the admin change form or with `update_schedule`. Use SQL if the value is one the ORM cannot read. To pause @@ -2797,23 +2782,16 @@ Worth knowing before you turn it on: and the same connection remains usable, later schedules are still attempted. The failed schedule is retried on subsequent passes under the usual due-tick and deadline rules; only its reporting is rate-limited. -- **Database read failures are not bad rows.** A database error during a full - schedule read or a shared dispatch read, such as a lost connection, missing - table or lock error, is not attributed to an individual row. It stops the - pass rather than skipping a row. -- **An abandoned pass stops further traversal.** A `django.db.DatabaseError` - escaping a shared dispatch read, failed rollback or unusable connection is - reported as `schedule_dispatch_failed`. The stored source's marker read and - boundary heal retain their own events. An unreadable change-marker value - reports `schedule_source_unavailable` once, then at most once a minute while - it remains unreadable, and the worker reads the schedules in full at each - reconcile interval during that time. A database error on the marker read - reports the same event on every dispatch pass, and the worker keeps using - the last schedules it read. A failed boundary heal reports - `schedule_boundary_heal_failed`. Dispatch is retried on a later pass. - Ticks already committed are not undone. Alert on `schedule_row_skipped`, - `schedule_dispatch_error`, `schedule_dispatch_failed` and - `schedule_source_unavailable`. +- **Database read failures are not bad rows.** Database errors during full schedule or shared dispatch reads, including connection, missing-table and lock errors, stop the pass. They are not attributed to a row. Server-side errors propagate unchanged. In autocommit, recognized value-local failures may be isolated by diagnostic re-reads while the connection remains usable. + + Inside a transaction, diagnostic re-reads are restricted: PostgreSQL requires a usable transaction; SQLite permits only its recognized UTF-8 decoding refusal; MySQL permits none. Unwind through the transaction or savepoint boundary before further queries where required. Reads create no savepoints. `update_schedule` and `delete_schedule` have their own atomic blocks; source reads and `ox_prune` do not. Unlike 1.8.0, a source read inside your transaction can leave a server error for you to roll back. +- **An abandoned pass stops further traversal.** An escaping `django.db.Error`, other unhandled exception, failed rollback or unusable connection reports `schedule_dispatch_failed`. Dispatch retries on a later pass; committed ticks remain committed. Marker reads and boundary heals retain their own events. + + An unreadable marker reports `schedule_source_unavailable` once, then at most once a minute; full reads continue at each reconcile interval. A database error on the marker read reports every pass while workers use the last schedules read. Failed boundary healing reports `schedule_boundary_heal_failed`, first with a traceback, then counted summaries at most once a minute per row per worker. Healing retries each pass; the affected schedule cannot dispatch meanwhile. + + An unreadable newest tick within the pass's bound skips only its schedule with `schedule_tick_unreadable`. A settings schedule can also be blocked by its unreadable earliest tick. History is not treated as absent. The pass completes, so this skip does not hold a batch open. Follow the recovery procedure under [Configuration](configuration.md#ox_prune). + + Alert on `schedule_dispatch_error`, `schedule_dispatch_failed` and `schedule_tick_unreadable`. For stored schedules, also alert on `schedule_row_skipped`, `schedule_source_unavailable` and `schedule_boundary_heal_failed`. - **`manage.py check` cannot see rows.** Checks run before `migrate`, so a bad schedule in the database is a log line, not a start-up error. Settings-declared schedules still fail fast for errors their checks can @@ -2840,21 +2818,20 @@ failures. The full set, with every field, is on the | --- | --- | | `schedule_dispatched` | A tick enqueued its task. | | `schedule_tick_dropped` | A tick was past its starting deadline. Carries `late_seconds`. | -| `schedule_row_skipped` | A row could not be built. A skip during a periodic full read carries `schedule`, `schedule_pk` and `reason`. A skip during the locked dispatch read carries `schedule_pk` and a traceback. | +| `schedule_row_skipped` | A row holds values django-ox cannot use, has incomparable boundaries, or cannot be built. Full and locked reads carry `schedule`, `schedule_pk`, `fields` and `reason`. Reporting is rate-limited; locked reads include a traceback only on the first line. | | `schedule_dispatch_error` | A schedule-scoped failure, database or not. Its tick and task rolled back, and the pass continues. The schedule is retried under the usual due-tick and deadline rules. Reporting is rate-limited. | -| `schedule_dispatch_failed` | A dispatch pass was abandoned. It is retried on a later pass. Reporting is rate-limited. | +| `schedule_dispatch_failed` | A pass was abandoned and will be retried. `category` distinguishes `database` from `unexpected_exception`. Reporting is rate-limited. | | `schedule_dispatch_recovered` | A schedule that had failed on this worker committed a tick again. Carries `failures`. | +| `schedule_dispatch_resumed` | A pass completed after abandoned passes. Carries their total in `failures`. | +| `schedule_tick_unreadable` | A schedule was skipped because required tick history could not be read. History was not treated as absent; other schedules continue. | +| `schedule_tick_readable` | This worker read the history again after skipped passes. Carries their total in `failures`. | Pausing a stored schedule preserves its failure state on each worker; deleting the row drops it without an event. A paused, fixed and resumed row reports `schedule_dispatch_recovered` when it next commits a tick on a worker that retained its failure state. -Alert on `schedule_row_skipped`, `schedule_dispatch_error`, -`schedule_dispatch_failed` and `schedule_source_unavailable`, regardless of a -batch's exit code. `schedule_row_skipped` usually means a task key was removed -from the code while a row still names it. A row can pass validation and still -fail at dispatch, so that event alone is not enough. +Alert on `schedule_dispatch_error`, `schedule_dispatch_failed` and `schedule_tick_unreadable`. For stored schedules, also alert on `schedule_row_skipped`, `schedule_source_unavailable` and `schedule_boundary_heal_failed`. Alert regardless of a batch's exit code. For `schedule_row_skipped`, inspect `fields` and `reason`: an unregistered task key is one possible cause. A row can pass validation and still fail at dispatch, so skip alerts alone are insufficient. Read `failures` and `suppressed` on dispatch failure events rather than counting log lines. `ox_health` has no schedule check, and a rolled-back @@ -4327,14 +4304,9 @@ schedule fires its first due tick. Use a long-running worker for more frequent schedule checks, but missed ticks are still coalesced; this does not guarantee that every tick runs. See [Missed ticks](recurring-tasks.md#missed-ticks). -An unreachable server, a lost or changed database session, or a database -error escaping a shared dispatch read does not count as an empty batch pass. -Failed polling passes and abandoned dispatch passes are retried, as they are -for a long-running worker. A batch keeps retrying until a dispatch pass -completes and the normal queue-drain and idle conditions hold. A failed -shared read, failed rollback or unusable session abandons the dispatch pass, -logs `schedule_dispatch_failed` at WARNING and keeps the batch open until a -pass completes. +Failed polling and abandoned dispatch passes do not count as empty batch passes. An unreachable server, lost or changed session, failed shared read, failed rollback or unusable connection causes retries. Other unhandled dispatch exceptions now do too: unlike 1.8.0, they log `schedule_dispatch_failed` with `category=unexpected_exception` instead of ending the worker with exit 1. + +The batch keeps claiming queued work and retries dispatch once per schedule interval. Draining the queue does not end it while dispatch remains owed. Normal completion requires a completed dispatch pass and the usual drain and idle conditions. This includes a custom schedule source whose store fails after startup. Direct calls to `dispatch_schedules()` still raise. There is no failure threshold or new exit code; stopping the batch can return 0 despite continuing dispatch failures. A failure inside one schedule's transaction is reported as `schedule_dispatch_error` at ERROR if rollback succeeds and the same @@ -4348,13 +4320,7 @@ each pass is abandoned at that schedule, preventing later schedules from being reached and holding the batch open. `schedule_dispatch_failed` does not identify the schedule being processed. -Alert on `schedule_dispatch_error` and `schedule_dispatch_failed`, plus -`schedule_row_skipped` and `schedule_source_unavailable` for stored schedules, -regardless of the batch's exit. Each `--batch` invocation starts a new worker, -so a schedule that keeps failing logs its first-failure traceback on every run -and no `schedule_dispatch_recovered` event carries across runs; alert on the -presence of `schedule_dispatch_error` in each run. Give the job runner a -timeout: it is what bounds a run against a failing database. +Alert on `schedule_dispatch_error`, `schedule_dispatch_failed` and `schedule_tick_unreadable`. For stored schedules, also alert on `schedule_row_skipped`, `schedule_source_unavailable` and `schedule_boundary_heal_failed`. Alert regardless of batch exit. Each invocation starts a new worker: continuing schedule failures get a first-failure traceback each run, and `schedule_dispatch_recovered` does not carry across runs. Alert on `schedule_dispatch_error` in each run. Give the job runner its own timeout for database, schedule-source and package faults. Clean termination does not prove successful dispatch. Both flags run a single process. `--processes` above 1 is rejected, because the supervisor restarts a worker that exits on its own; for more throughput in @@ -6284,15 +6250,18 @@ The message text is not part of the contract. The keys are. | `lease_renew_recovered` | INFO | On a pooled PostgreSQL database, renewal succeeded on its private connection again. Includes counts of successful fallback renewals and missed renewals during the degraded period. | | `schedule_dispatched` | INFO | A recurring tick enqueued its task. | | `schedule_tick_dropped` | WARNING | A tick was past its starting deadline and was not run. Carries `late_seconds`. Each worker reports a given tick once, not once per dispatch pass, so a schedule that stays droppable does not repeat the warning every second. | -| `schedule_row_skipped` | WARNING | A row could not be converted, its start or end could not be compared with the worker's clock, or it could not be built. Carries `schedule`, `schedule_pk` and `reason` during both full reads and locked dispatch reads. Logged once, then at most once a minute per row per worker while the row stays skipped. A locked dispatch skip includes a traceback only on its first line. | +| `schedule_row_skipped` | WARNING | A stored row holds a stored value django-ox cannot use, has incomparable boundaries, or cannot be built. Carries `schedule`, `schedule_pk`, `fields` and `reason` on full and locked dispatch reads. This includes `boundary_generation` at its column's maximum. Logged once, then at most once a minute per row per worker. Locked dispatch skips include a traceback only on the first line. | | `schedule_dispatch_error` | ERROR | A schedule-scoped failure, database or not, from any schedule source. This includes a tick that cannot be derived or bounds that cannot be compared with the worker's clock. If a dispatch transaction was started, it rolled back and the same database connection remains usable. The rest of the pass continues. The schedule is retried under the usual due-tick and deadline rules. The first failure has a traceback; continued failures produce at most one summary per 60 seconds. Carries `schedule`, `database`, `error`, `failures` and `suppressed`. | | `schedule_dispatch_recovered` | INFO | A schedule that had been logging `schedule_dispatch_error` on this worker committed a tick again, by enqueueing a task or recording a first-sighting anchor. Logged once per run of failures. Carries `schedule`, `database` and `failures`, the number of failed attempts in that run. | | `schedule_dispatch_callback_failed` | WARNING | A `transaction.on_commit` callback registered by a `task_enqueued` receiver raised after the dispatch transaction committed. The task is enqueued, the tick is recorded and the dispatch is counted; the failure is the callback's. Carries `task_id`. | -| `schedule_dispatch_failed` | WARNING | A dispatch pass was abandoned: a `django.db.DatabaseError` escaped a shared read, rollback failed, the database session changed, or the connection was unusable after rollback. The stored source's marker read and boundary heal retain their own events below. Dispatch is retried on the next pass; an unusable connection is dropped, and the claim still runs. The first abandoned pass has a traceback; continued failures produce at most one summary per 60 seconds. Carries `database`, `error`, `failures` and `suppressed`. | +| `schedule_dispatch_failed` | WARNING | A dispatch pass was abandoned. `category=database` covers `django.db.Error`, including `InterfaceError`; `unexpected_exception` covers other unhandled exceptions. Failed rollback, a changed session or an unusable connection also abandons the pass. An unusable connection is dropped; claiming still runs. Dispatch is retried one schedule interval later. Each category gets a first traceback, then summaries at most once per minute. Carries `worker_id`, `database`, `category`, `error`, `failures` and `suppressed`. Marker reads and boundary heals retain their own events. | +| `schedule_dispatch_resumed` | INFO | A dispatch pass completed after one or more abandoned passes. Logged once for the completed run of failures, covering both categories. Carries `worker_id`, `database` and `failures`, the total abandoned passes in that run. | +| `schedule_tick_unreadable` | WARNING | A schedule was skipped this pass because a tick in its history holds a value that cannot be read. Schedule skipped; tick history was not treated as absent: no tick is recorded and no task is enqueued for it, and the other schedules in the pass are dispatched. `phase` is `latest` for the newest tick within the pass's bound, or `anchor` for the earliest tick, which decides a settings-declared schedule's first sighting. The schedule stays skipped until the tick is repaired or removed. Logged once, then at most one summary per 60 seconds per schedule per worker. Carries `schedule`, `schedule_key`, `schedule_pk`, `phase`, `reason`, `tick_pk`, `database`, `failures` and `suppressed`. | +| `schedule_tick_readable` | INFO | This worker read a schedule's tick history again after skipping it with `schedule_tick_unreadable`. Logged once per run of skipped passes. Carries `worker_id`, `schedule`, `schedule_key`, `schedule_pk`, `database` and `failures`, the number of skipped passes in that run. | | `schedule_source_unavailable` | WARNING | The stored schedules or their change marker could not be read. A change marker holding a value that cannot be read is reported once, then at most once a minute while it remains unreadable. During that time, the worker reads the schedules in full at each reconcile interval instead of relying only on the last set it read. A database error on the marker read is reported on every dispatch pass while it lasts, and the worker keeps running on the last set it read. A database error during a full read stops the pass. A stream of this event right after a deploy can mean the code is running ahead of migration `0007`. | | `schedule_lock_unavailable` | WARNING | The database gave up waiting for a lock another worker held: a stored schedule's row, or the tick row a settings-declared schedule's dispatch claims. MySQL's lock-wait timeout or a deadlock it resolved against this worker, SQLite's busy timeout, PostgreSQL's `lock_timeout` or a deadlock. The schedule is skipped this pass and its tick fires on a later one if still unclaimed. No traceback; a stream can indicate long dispatch transactions, often from a slow `task_enqueued` receiver. On MySQL with three or more dispatchers, a refused settings schedule can also produce 1213 deadlock warnings when the claimant rolls back and workers queued on its tick key deadlock; read these beside `schedule_dispatch_error` for the same schedule. | | `schedule_boundary_healed` | INFO | A stored schedule's timing had changed without its activation boundary moving, so the boundary was moved onto the current timing. Expected after a bulk update; repeated for one schedule is not. | -| `schedule_boundary_heal_failed` | WARNING | That move failed and will be retried. | +| `schedule_boundary_heal_failed` | WARNING | The database refused the boundary move. That schedule cannot dispatch while healing is pending; other schedules continue. Healing is retried every dispatch pass. The first warning includes a traceback; later warnings summarize at most once a minute per row per worker. Carries `schedule_pk`, `error`, `failures` and `suppressed`. Check database errors, constraints, triggers, permissions and locks. | | `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 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. | @@ -6380,13 +6349,19 @@ A failed connect while recording a stuck attempt logs | `refunded_attempts` | `worker_claim_released` | Number of attempts refunded by this release. Always 1. | | `attempts` | `worker_claim_release_refused` | The stored attempt count on the row whose release was refused. No attempt was refunded. | | `worker_ids` | `worker_claim_release_refused` | The stored worker-id history on the row whose release was refused. It must contain one entry per attempt and end with the recovering worker's id. | -| `schedule` | `schedule_dispatched`, `schedule_row_skipped`, `schedule_dispatch_error`, `schedule_dispatch_recovered`, `schedule_dispatch_callback_failed`, `schedule_tick_dropped`, `schedule_lock_unavailable` for a settings-declared schedule | The schedule's name, from `SCHEDULES` or from its row. For `schedule_row_skipped`, this may be `None` if the row's name could not be read. | -| `schedule_pk` | `schedule_row_skipped`, `schedule_lock_unavailable` for a stored schedule, `schedule_boundary_healed` | The stored schedule's row id. Absent for a settings-declared schedule, which has no row. | +| `schedule` | `schedule_dispatched`, `schedule_row_skipped`, `schedule_dispatch_error`, `schedule_dispatch_recovered`, `schedule_dispatch_callback_failed`, `schedule_tick_dropped`, `schedule_tick_unreadable`, `schedule_tick_readable`, `schedule_lock_unavailable` for a settings-declared schedule | The schedule's name, from `SCHEDULES` or from its row. For `schedule_row_skipped`, this may be `None` if the row's name could not be read. | +| `schedule_pk` | `schedule_row_skipped`, `schedule_lock_unavailable` for a stored schedule, `schedule_boundary_healed`, `schedule_boundary_heal_failed`, `schedule_tick_unreadable`, `schedule_tick_readable` | The stored schedule's row id. Absent for a settings-declared schedule, which has no row; on `schedule_tick_unreadable` and `schedule_tick_readable` it is `None` for one. | | `scheduled_for`, `late_seconds` | `schedule_tick_dropped` | The tick that was dropped, and how late it was when the deadline rejected it. | -| `reason` | `schedule_row_skipped` | Why the row could not be used, during either a full read or a locked dispatch read. For a value that could not be converted, the reason names the column. | +| `reason` | `schedule_row_skipped` | Why a full or locked read rejected the row. Stored-value reasons name the field, quote its bounded value and explain the problem, including a maximum `boundary_generation`. Unregistered task keys are identified against this process's registry. | +| `fields` | `schedule_row_skipped` | Fields rejected by the guarded reader, in model order, as a list. Includes a maximum `boundary_generation`. Empty for build failures, including unregistered task keys, or when the read cannot identify a field. | +| `reason` | `schedule_tick_unreadable`, `schedule_tick_history_removed` | Why the tick could not be read. Names the column and quotes the stored value, escaped and shortened. | +| `schedule_key` | `schedule_tick_unreadable`, `schedule_tick_readable` | The key the schedule's ticks are recorded under: a settings-declared schedule's name, or `db:` for a stored schedule. | +| `phase` | `schedule_tick_unreadable` | Worker: `latest` for the newest tick within the pass's bound; `anchor` for a settings schedule's earliest tick. Admin: always `latest`. Absent from prune records. | +| `tick_pk` | `schedule_tick_unreadable` | The primary key of the tick row that could not be read, or `None` when it could not be determined. | +| `category` | `schedule_dispatch_failed` | What abandoned the pass: `database` or `unexpected_exception`. | | `queues` | `worker_started` | The worker's queues. | | `concurrency` | `worker_started`, `connection_pool_too_small` | The worker's task-thread concurrency, set by `--concurrency`. | -| `database` | `connection_pool_too_small`, `worker_connection_hint`, `schedule_dispatch_error`, `schedule_dispatch_failed`, `schedule_dispatch_recovered` | The worker's database alias: `--database`, or the alias used to write `OxTask`. | +| `database` | `connection_pool_too_small`, `worker_connection_hint`, `schedule_dispatch_error`, `schedule_dispatch_failed`, `schedule_dispatch_resumed`, `schedule_dispatch_recovered`, `schedule_tick_unreadable`, `schedule_tick_readable`, `schedule_tick_history_removed` | Worker: `--database`, or the alias used to write `OxTask`. Prune: the alias the command worked on. Admin: the schedule's write alias. | | `vendor` | `worker_connection_hint` | Django's name for the database engine, such as `postgresql` or `mysql`. | | `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. | @@ -6402,9 +6377,9 @@ A failed connect while recording a stuck attempt logs | `worker_indexes` | `supervisor_killed_workers` | The slots that were killed. | | `parent_pid` | `worker_orphaned` | The supervisor pid the worker was started under. | | `exit_code` | `supervisor_stopped` | The code the supervisor exits with. | -| `error` | `lease_renew_degraded`, `lease_renew_fallback`, `lease_renew_missed`, `watchdog_connection_unavailable`, `schedule_dispatch_error`, `schedule_dispatch_failed`, `heartbeat_write_failed`, `heartbeat_invalidate_failed` | Schedule dispatch: the exception class name of the latest failure. Heartbeat: the operating-system error text from the failed update or removal. Renewal and watchdog: the private-connection failure reason, except that a pool-first renewal tick reports that the pool was tried first and gives the remaining lease time. | -| `failures` | `schedule_dispatch_error`, `schedule_dispatch_failed`, `schedule_dispatch_recovered` | On `schedule_dispatch_error`, total failed attempts in this schedule's current run of failures on this worker, including the first. On `schedule_dispatch_failed`, total abandoned passes in the current outage. On `schedule_dispatch_recovered`, failed attempts in the run that just ended. | -| `suppressed` | `schedule_dispatch_error`, `schedule_dispatch_failed` | Failures counted since the previous report and not logged individually. Zero on the first report of a run. | +| `error` | `lease_renew_degraded`, `lease_renew_fallback`, `lease_renew_missed`, `watchdog_connection_unavailable`, `schedule_dispatch_error`, `schedule_dispatch_failed`, `schedule_boundary_heal_failed`, `heartbeat_write_failed`, `heartbeat_invalidate_failed` | Schedule dispatch and boundary heal: the exception class name of the latest failure. Heartbeat: the operating-system error text from the failed update or removal. Renewal and watchdog: the private-connection failure reason, except that a pool-first renewal tick reports that the pool was tried first and gives the remaining lease time. | +| `failures` | `schedule_dispatch_error`, `schedule_dispatch_failed`, `schedule_dispatch_resumed`, `schedule_dispatch_recovered`, `schedule_boundary_heal_failed`, `schedule_tick_unreadable`, `schedule_tick_readable` | Totals for the current run on this worker, including the first failure. Dispatch errors and heal failures count attempts per schedule. Dispatch failures count abandoned passes separately per `category`; resumed counts both categories together. Dispatch recovered counts that schedule's failed attempts. Worker tick-unreadable records count skipped passes; tick-readable records give the final total. Absent from admin and prune records. | +| `suppressed` | `schedule_dispatch_error`, `schedule_dispatch_failed`, `schedule_boundary_heal_failed`, `schedule_tick_unreadable` | Failures since the previous report that were not logged individually, including the attempt triggering a summary. Zero on the first report. Dispatch failures count separately per `category`. Tick records carry this only on workers. | | `fallback` | `lease_renew_degraded` | `succeeded` if pooled renewal succeeded; `failed` if fallback did not renew the leases. | | `fallback_error` | `lease_renew_degraded`, `lease_renew_missed`, `watchdog_connection_unavailable` | The fallback failure reason. On `lease_renew_degraded`, present when `fallback` is `failed`. A borrowed renewal statement failure is reported as "the renewal statement failed". | | `missed` | `lease_renew_missed` | Missed renewal ticks since the last `lease_renew_degraded` or `lease_renew_missed` record, or since recovery if more recent. | @@ -6446,14 +6421,7 @@ connection check establishes usability, not that the failure was caused by invalid arguments or will recur. There is no consecutive-failure cutoff: several failed schedules do not prevent an attempt at a later healthy one. -A failed rollback, changed session or unusable connection abandons the pass. -So does a `django.db.DatabaseError` escaping a shared read, such as the -schedule source's full read or the tick-log read before traversal. A -non-database exception from the schedule source stops the worker with a -traceback and exit 1; a `django.db.InterfaceError` escaping that read is -reported as `worker_poll_failed` instead. The stored source's marker read and -boundary heal retain their separate handling and events. Any exception -escaping dispatch leaves the pass incomplete, whatever its class. +A failed rollback, changed session or unusable connection abandons the pass. So does a `django.db.Error` escaping a shared read, including the schedule source's full read or the tick-log read before traversal. Other unhandled exceptions report `schedule_dispatch_failed` with `category=unexpected_exception`; the worker continues. `KeyboardInterrupt` and `SystemExit` still stop it. The stored source's marker read and boundary heal retain separate handling and events. An unreadable tick skips its schedule without abandoning the pass. Any exception escaping dispatch leaves the pass incomplete. An abandoned pass reports `schedule_dispatch_failed` and stops further traversal. It does not undo earlier committed ticks. Normal batch-empty @@ -6497,10 +6465,9 @@ pause and is dropped without an event only when the row is deleted. If a paused row is fixed and resumed, its next successful tick commit on that worker reports `schedule_dispatch_recovered`. -`schedule_dispatch_failed` uses the same first-traceback and later-summary -pattern at WARNING, per worker. Its `failures` counts abandoned passes in -the outage. A completed dispatch pass ends the outage, so the next abandoned -pass is reported in full. There is no pass recovery event. +`schedule_dispatch_failed` uses the first-traceback and later-summary pattern at WARNING, per worker, separately for each `category`. A completed pass reports `schedule_dispatch_resumed` with the total abandoned passes across both categories. It ends the failure run; the next abandoned pass is reported in full. + +`schedule_boundary_heal_failed` follows this pattern per stored row per worker. Only reporting is throttled; healing is retried every pass. Successful healing reports `schedule_boundary_healed`. Reporting state also clears if another writer moves the boundary, the row disappears, stops reading, or its fields refuse the digest. There is no separate heal-recovery event. These events do not include schedule arguments as fields. The first traceback includes the database's own error message, which can quote part of a rejected @@ -6512,20 +6479,7 @@ and `suppressed` rather than treating each log line as one failed attempt. ## Monitoring recipes -- **Alerting.** Alert on `ready_count` and `oldest_ready_age` (via - `ox_health` thresholds or the functions directly), and on - `failure_rate` rising above your normal baseline. Use last-claim age - only for fleet alerting on queues with steady traffic. Throughput is - better as a dashboard line than an alert: its healthy value depends - entirely on offered load. Also alert on `schedule_dispatch_error` and - `schedule_dispatch_failed`, plus `schedule_row_skipped` for stored - schedules. For stored schedules, also alert on - `schedule_source_unavailable`: a failed marker read leaves dispatch running - from the cached set rather than abandoning the pass. Read `failures` and - `suppressed` rather than counting dispatch error log lines. A rejected - dispatch leaves no task or tick row. `ox_health` has no schedule check, and - neither `worker_batch_empty` nor batch exit 0 certifies that every schedule - dispatched. +- **Alerting.** Alert on `ready_count` and `oldest_ready_age` through `ox_health` thresholds or function calls, and on above-baseline `failure_rate`. Use last-claim age only for fleet alerts on steady-traffic queues. Keep throughput on dashboards; healthy values depend on offered load. Alert on `schedule_dispatch_error`, `schedule_dispatch_failed` and `schedule_tick_unreadable`. For stored schedules, also alert on `schedule_row_skipped`, `schedule_source_unavailable` and `schedule_boundary_heal_failed`. Failed marker reads use cached schedules without abandoning dispatch. Read `failures` and `suppressed`, not log-line counts. Rejected dispatch leaves no task or tick. `ox_health` cannot check schedules; neither `worker_batch_empty` nor batch exit 0 certifies every schedule dispatched. - **Prometheus.** Mount `django_ox.urls` and scrape `/ox/metrics`, or register `django_ox.metrics.collector()` with a registry you already run. Both are covered [above](#prometheus). @@ -7343,13 +7297,7 @@ python manage.py ox_health OK: backlog=0 oldest_age=none last_claim_age=none ``` -`manage.py check` reports schedule and backend policy errors through -`django_ox.E002` to `E005`, `E010` and `E011`, and warnings through -`django_ox.W003` and `django_ox.W004`, before deployment. -Database acceptance of schedule arguments is determined at dispatch; -alert on `schedule_dispatch_error` and `schedule_dispatch_failed` at runtime. -Review `django_ox.W003` and `django_ox.W004` warnings too; `W004` asks for -a non-bool integer from 1 to 32767 while retaining compatible legacy values. +`manage.py check` reports schedule and backend policy errors through `django_ox.E002` to `E005`, `E010` and `E011`, and warnings through `django_ox.W003` and `django_ox.W004`, before deployment. Database acceptance of schedule arguments is determined at dispatch. Alert on `schedule_dispatch_error`, `schedule_dispatch_failed` and `schedule_tick_unreadable`. For stored schedules, also alert on `schedule_row_skipped`, `schedule_source_unavailable` and `schedule_boundary_heal_failed`. Review `django_ox.W003` and `django_ox.W004` warnings too; `W004` asks for a non-bool integer from 1 to 32767 while retaining compatible legacy values. Invalid per-task fields raise `InvalidTask` (`InvalidTaskError` on the backport) when the task is built, normally at import, rather than appearing diff --git a/docs/monitoring.md b/docs/monitoring.md index 9771f1e..3c3218b 100644 --- a/docs/monitoring.md +++ b/docs/monitoring.md @@ -694,15 +694,18 @@ The message text is not part of the contract. The keys are. | `lease_renew_recovered` | INFO | On a pooled PostgreSQL database, renewal succeeded on its private connection again. Includes counts of successful fallback renewals and missed renewals during the degraded period. | | `schedule_dispatched` | INFO | A recurring tick enqueued its task. | | `schedule_tick_dropped` | WARNING | A tick was past its starting deadline and was not run. Carries `late_seconds`. Each worker reports a given tick once, not once per dispatch pass, so a schedule that stays droppable does not repeat the warning every second. | -| `schedule_row_skipped` | WARNING | A row could not be converted, its start or end could not be compared with the worker's clock, or it could not be built. Carries `schedule`, `schedule_pk` and `reason` during both full reads and locked dispatch reads. Logged once, then at most once a minute per row per worker while the row stays skipped. A locked dispatch skip includes a traceback only on its first line. | +| `schedule_row_skipped` | WARNING | A stored row holds a stored value django-ox cannot use, has incomparable boundaries, or cannot be built. Carries `schedule`, `schedule_pk`, `fields` and `reason` on full and locked dispatch reads. This includes `boundary_generation` at its column's maximum. Logged once, then at most once a minute per row per worker. Locked dispatch skips include a traceback only on the first line. | | `schedule_dispatch_error` | ERROR | A schedule-scoped failure, database or not, from any schedule source. This includes a tick that cannot be derived or bounds that cannot be compared with the worker's clock. If a dispatch transaction was started, it rolled back and the same database connection remains usable. The rest of the pass continues. The schedule is retried under the usual due-tick and deadline rules. The first failure has a traceback; continued failures produce at most one summary per 60 seconds. Carries `schedule`, `database`, `error`, `failures` and `suppressed`. | | `schedule_dispatch_recovered` | INFO | A schedule that had been logging `schedule_dispatch_error` on this worker committed a tick again, by enqueueing a task or recording a first-sighting anchor. Logged once per run of failures. Carries `schedule`, `database` and `failures`, the number of failed attempts in that run. | | `schedule_dispatch_callback_failed` | WARNING | A `transaction.on_commit` callback registered by a `task_enqueued` receiver raised after the dispatch transaction committed. The task is enqueued, the tick is recorded and the dispatch is counted; the failure is the callback's. Carries `task_id`. | -| `schedule_dispatch_failed` | WARNING | A dispatch pass was abandoned: a `django.db.DatabaseError` escaped a shared read, rollback failed, the database session changed, or the connection was unusable after rollback. The stored source's marker read and boundary heal retain their own events below. Dispatch is retried on the next pass; an unusable connection is dropped, and the claim still runs. The first abandoned pass has a traceback; continued failures produce at most one summary per 60 seconds. Carries `database`, `error`, `failures` and `suppressed`. | +| `schedule_dispatch_failed` | WARNING | A dispatch pass was abandoned. `category=database` covers `django.db.Error`, including `InterfaceError`; `unexpected_exception` covers other unhandled exceptions. Failed rollback, a changed session or an unusable connection also abandons the pass. An unusable connection is dropped; claiming still runs. Dispatch is retried one schedule interval later. Each category gets a first traceback, then summaries at most once per minute. Carries `worker_id`, `database`, `category`, `error`, `failures` and `suppressed`. Marker reads and boundary heals retain their own events. | +| `schedule_dispatch_resumed` | INFO | A dispatch pass completed after one or more abandoned passes. Logged once for the completed run of failures, covering both categories. Carries `worker_id`, `database` and `failures`, the total abandoned passes in that run. | +| `schedule_tick_unreadable` | WARNING | A schedule was skipped this pass because a tick in its history holds a value that cannot be read. Schedule skipped; tick history was not treated as absent: no tick is recorded and no task is enqueued for it, and the other schedules in the pass are dispatched. `phase` is `latest` for the newest tick within the pass's bound, or `anchor` for the earliest tick, which decides a settings-declared schedule's first sighting. The schedule stays skipped until the tick is repaired or removed. Logged once, then at most one summary per 60 seconds per schedule per worker. Carries `schedule`, `schedule_key`, `schedule_pk`, `phase`, `reason`, `tick_pk`, `database`, `failures` and `suppressed`. | +| `schedule_tick_readable` | INFO | This worker read a schedule's tick history again after skipping it with `schedule_tick_unreadable`. Logged once per run of skipped passes. Carries `worker_id`, `schedule`, `schedule_key`, `schedule_pk`, `database` and `failures`, the number of skipped passes in that run. | | `schedule_source_unavailable` | WARNING | The stored schedules or their change marker could not be read. A change marker holding a value that cannot be read is reported once, then at most once a minute while it remains unreadable. During that time, the worker reads the schedules in full at each reconcile interval instead of relying only on the last set it read. A database error on the marker read is reported on every dispatch pass while it lasts, and the worker keeps running on the last set it read. A database error during a full read stops the pass. A stream of this event right after a deploy can mean the code is running ahead of migration `0007`. | | `schedule_lock_unavailable` | WARNING | The database gave up waiting for a lock another worker held: a stored schedule's row, or the tick row a settings-declared schedule's dispatch claims. MySQL's lock-wait timeout or a deadlock it resolved against this worker, SQLite's busy timeout, PostgreSQL's `lock_timeout` or a deadlock. The schedule is skipped this pass and its tick fires on a later one if still unclaimed. No traceback; a stream can indicate long dispatch transactions, often from a slow `task_enqueued` receiver. On MySQL with three or more dispatchers, a refused settings schedule can also produce 1213 deadlock warnings when the claimant rolls back and workers queued on its tick key deadlock; read these beside `schedule_dispatch_error` for the same schedule. | | `schedule_boundary_healed` | INFO | A stored schedule's timing had changed without its activation boundary moving, so the boundary was moved onto the current timing. Expected after a bulk update; repeated for one schedule is not. | -| `schedule_boundary_heal_failed` | WARNING | That move failed and will be retried. | +| `schedule_boundary_heal_failed` | WARNING | The database refused the boundary move. That schedule cannot dispatch while healing is pending; other schedules continue. Healing is retried every dispatch pass. The first warning includes a traceback; later warnings summarize at most once a minute per row per worker. Carries `schedule_pk`, `error`, `failures` and `suppressed`. Check database errors, constraints, triggers, permissions and locks. | | `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 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. | @@ -790,13 +793,19 @@ A failed connect while recording a stuck attempt logs | `refunded_attempts` | `worker_claim_released` | Number of attempts refunded by this release. Always 1. | | `attempts` | `worker_claim_release_refused` | The stored attempt count on the row whose release was refused. No attempt was refunded. | | `worker_ids` | `worker_claim_release_refused` | The stored worker-id history on the row whose release was refused. It must contain one entry per attempt and end with the recovering worker's id. | -| `schedule` | `schedule_dispatched`, `schedule_row_skipped`, `schedule_dispatch_error`, `schedule_dispatch_recovered`, `schedule_dispatch_callback_failed`, `schedule_tick_dropped`, `schedule_lock_unavailable` for a settings-declared schedule | The schedule's name, from `SCHEDULES` or from its row. For `schedule_row_skipped`, this may be `None` if the row's name could not be read. | -| `schedule_pk` | `schedule_row_skipped`, `schedule_lock_unavailable` for a stored schedule, `schedule_boundary_healed` | The stored schedule's row id. Absent for a settings-declared schedule, which has no row. | +| `schedule` | `schedule_dispatched`, `schedule_row_skipped`, `schedule_dispatch_error`, `schedule_dispatch_recovered`, `schedule_dispatch_callback_failed`, `schedule_tick_dropped`, `schedule_tick_unreadable`, `schedule_tick_readable`, `schedule_lock_unavailable` for a settings-declared schedule | The schedule's name, from `SCHEDULES` or from its row. For `schedule_row_skipped`, this may be `None` if the row's name could not be read. | +| `schedule_pk` | `schedule_row_skipped`, `schedule_lock_unavailable` for a stored schedule, `schedule_boundary_healed`, `schedule_boundary_heal_failed`, `schedule_tick_unreadable`, `schedule_tick_readable` | The stored schedule's row id. Absent for a settings-declared schedule, which has no row; on `schedule_tick_unreadable` and `schedule_tick_readable` it is `None` for one. | | `scheduled_for`, `late_seconds` | `schedule_tick_dropped` | The tick that was dropped, and how late it was when the deadline rejected it. | -| `reason` | `schedule_row_skipped` | Why the row could not be used, during either a full read or a locked dispatch read. For a value that could not be converted, the reason names the column. | +| `reason` | `schedule_row_skipped` | Why a full or locked read rejected the row. Stored-value reasons name the field, quote its bounded value and explain the problem, including a maximum `boundary_generation`. Unregistered task keys are identified against this process's registry. | +| `fields` | `schedule_row_skipped` | Fields rejected by the guarded reader, in model order, as a list. Includes a maximum `boundary_generation`. Empty for build failures, including unregistered task keys, or when the read cannot identify a field. | +| `reason` | `schedule_tick_unreadable`, `schedule_tick_history_removed` | Why the tick could not be read. Names the column and quotes the stored value, escaped and shortened. | +| `schedule_key` | `schedule_tick_unreadable`, `schedule_tick_readable` | The key the schedule's ticks are recorded under: a settings-declared schedule's name, or `db:` for a stored schedule. | +| `phase` | `schedule_tick_unreadable` | Worker: `latest` for the newest tick within the pass's bound; `anchor` for a settings schedule's earliest tick. Admin: always `latest`. Absent from prune records. | +| `tick_pk` | `schedule_tick_unreadable` | The primary key of the tick row that could not be read, or `None` when it could not be determined. | +| `category` | `schedule_dispatch_failed` | What abandoned the pass: `database` or `unexpected_exception`. | | `queues` | `worker_started` | The worker's queues. | | `concurrency` | `worker_started`, `connection_pool_too_small` | The worker's task-thread concurrency, set by `--concurrency`. | -| `database` | `connection_pool_too_small`, `worker_connection_hint`, `schedule_dispatch_error`, `schedule_dispatch_failed`, `schedule_dispatch_recovered` | The worker's database alias: `--database`, or the alias used to write `OxTask`. | +| `database` | `connection_pool_too_small`, `worker_connection_hint`, `schedule_dispatch_error`, `schedule_dispatch_failed`, `schedule_dispatch_resumed`, `schedule_dispatch_recovered`, `schedule_tick_unreadable`, `schedule_tick_readable`, `schedule_tick_history_removed` | Worker: `--database`, or the alias used to write `OxTask`. Prune: the alias the command worked on. Admin: the schedule's write alias. | | `vendor` | `worker_connection_hint` | Django's name for the database engine, such as `postgresql` or `mysql`. | | `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. | @@ -812,9 +821,9 @@ A failed connect while recording a stuck attempt logs | `worker_indexes` | `supervisor_killed_workers` | The slots that were killed. | | `parent_pid` | `worker_orphaned` | The supervisor pid the worker was started under. | | `exit_code` | `supervisor_stopped` | The code the supervisor exits with. | -| `error` | `lease_renew_degraded`, `lease_renew_fallback`, `lease_renew_missed`, `watchdog_connection_unavailable`, `schedule_dispatch_error`, `schedule_dispatch_failed`, `heartbeat_write_failed`, `heartbeat_invalidate_failed` | Schedule dispatch: the exception class name of the latest failure. Heartbeat: the operating-system error text from the failed update or removal. Renewal and watchdog: the private-connection failure reason, except that a pool-first renewal tick reports that the pool was tried first and gives the remaining lease time. | -| `failures` | `schedule_dispatch_error`, `schedule_dispatch_failed`, `schedule_dispatch_recovered` | On `schedule_dispatch_error`, total failed attempts in this schedule's current run of failures on this worker, including the first. On `schedule_dispatch_failed`, total abandoned passes in the current outage. On `schedule_dispatch_recovered`, failed attempts in the run that just ended. | -| `suppressed` | `schedule_dispatch_error`, `schedule_dispatch_failed` | Failures counted since the previous report and not logged individually. Zero on the first report of a run. | +| `error` | `lease_renew_degraded`, `lease_renew_fallback`, `lease_renew_missed`, `watchdog_connection_unavailable`, `schedule_dispatch_error`, `schedule_dispatch_failed`, `schedule_boundary_heal_failed`, `heartbeat_write_failed`, `heartbeat_invalidate_failed` | Schedule dispatch and boundary heal: the exception class name of the latest failure. Heartbeat: the operating-system error text from the failed update or removal. Renewal and watchdog: the private-connection failure reason, except that a pool-first renewal tick reports that the pool was tried first and gives the remaining lease time. | +| `failures` | `schedule_dispatch_error`, `schedule_dispatch_failed`, `schedule_dispatch_resumed`, `schedule_dispatch_recovered`, `schedule_boundary_heal_failed`, `schedule_tick_unreadable`, `schedule_tick_readable` | Totals for the current run on this worker, including the first failure. Dispatch errors and heal failures count attempts per schedule. Dispatch failures count abandoned passes separately per `category`; resumed counts both categories together. Dispatch recovered counts that schedule's failed attempts. Worker tick-unreadable records count skipped passes; tick-readable records give the final total. Absent from admin and prune records. | +| `suppressed` | `schedule_dispatch_error`, `schedule_dispatch_failed`, `schedule_boundary_heal_failed`, `schedule_tick_unreadable` | Failures since the previous report that were not logged individually, including the attempt triggering a summary. Zero on the first report. Dispatch failures count separately per `category`. Tick records carry this only on workers. | | `fallback` | `lease_renew_degraded` | `succeeded` if pooled renewal succeeded; `failed` if fallback did not renew the leases. | | `fallback_error` | `lease_renew_degraded`, `lease_renew_missed`, `watchdog_connection_unavailable` | The fallback failure reason. On `lease_renew_degraded`, present when `fallback` is `failed`. A borrowed renewal statement failure is reported as "the renewal statement failed". | | `missed` | `lease_renew_missed` | Missed renewal ticks since the last `lease_renew_degraded` or `lease_renew_missed` record, or since recovery if more recent. | @@ -856,14 +865,7 @@ connection check establishes usability, not that the failure was caused by invalid arguments or will recur. There is no consecutive-failure cutoff: several failed schedules do not prevent an attempt at a later healthy one. -A failed rollback, changed session or unusable connection abandons the pass. -So does a `django.db.DatabaseError` escaping a shared read, such as the -schedule source's full read or the tick-log read before traversal. A -non-database exception from the schedule source stops the worker with a -traceback and exit 1; a `django.db.InterfaceError` escaping that read is -reported as `worker_poll_failed` instead. The stored source's marker read and -boundary heal retain their separate handling and events. Any exception -escaping dispatch leaves the pass incomplete, whatever its class. +A failed rollback, changed session or unusable connection abandons the pass. So does a `django.db.Error` escaping a shared read, including the schedule source's full read or the tick-log read before traversal. Other unhandled exceptions report `schedule_dispatch_failed` with `category=unexpected_exception`; the worker continues. `KeyboardInterrupt` and `SystemExit` still stop it. The stored source's marker read and boundary heal retain separate handling and events. An unreadable tick skips its schedule without abandoning the pass. Any exception escaping dispatch leaves the pass incomplete. An abandoned pass reports `schedule_dispatch_failed` and stops further traversal. It does not undo earlier committed ticks. Normal batch-empty @@ -907,10 +909,9 @@ pause and is dropped without an event only when the row is deleted. If a paused row is fixed and resumed, its next successful tick commit on that worker reports `schedule_dispatch_recovered`. -`schedule_dispatch_failed` uses the same first-traceback and later-summary -pattern at WARNING, per worker. Its `failures` counts abandoned passes in -the outage. A completed dispatch pass ends the outage, so the next abandoned -pass is reported in full. There is no pass recovery event. +`schedule_dispatch_failed` uses the first-traceback and later-summary pattern at WARNING, per worker, separately for each `category`. A completed pass reports `schedule_dispatch_resumed` with the total abandoned passes across both categories. It ends the failure run; the next abandoned pass is reported in full. + +`schedule_boundary_heal_failed` follows this pattern per stored row per worker. Only reporting is throttled; healing is retried every pass. Successful healing reports `schedule_boundary_healed`. Reporting state also clears if another writer moves the boundary, the row disappears, stops reading, or its fields refuse the digest. There is no separate heal-recovery event. These events do not include schedule arguments as fields. The first traceback includes the database's own error message, which can quote part of a rejected @@ -922,20 +923,7 @@ and `suppressed` rather than treating each log line as one failed attempt. ## Monitoring recipes -- **Alerting.** Alert on `ready_count` and `oldest_ready_age` (via - `ox_health` thresholds or the functions directly), and on - `failure_rate` rising above your normal baseline. Use last-claim age - only for fleet alerting on queues with steady traffic. Throughput is - better as a dashboard line than an alert: its healthy value depends - entirely on offered load. Also alert on `schedule_dispatch_error` and - `schedule_dispatch_failed`, plus `schedule_row_skipped` for stored - schedules. For stored schedules, also alert on - `schedule_source_unavailable`: a failed marker read leaves dispatch running - from the cached set rather than abandoning the pass. Read `failures` and - `suppressed` rather than counting dispatch error log lines. A rejected - dispatch leaves no task or tick row. `ox_health` has no schedule check, and - neither `worker_batch_empty` nor batch exit 0 certifies that every schedule - dispatched. +- **Alerting.** Alert on `ready_count` and `oldest_ready_age` through `ox_health` thresholds or function calls, and on above-baseline `failure_rate`. Use last-claim age only for fleet alerts on steady-traffic queues. Keep throughput on dashboards; healthy values depend on offered load. Alert on `schedule_dispatch_error`, `schedule_dispatch_failed` and `schedule_tick_unreadable`. For stored schedules, also alert on `schedule_row_skipped`, `schedule_source_unavailable` and `schedule_boundary_heal_failed`. Failed marker reads use cached schedules without abandoning dispatch. Read `failures` and `suppressed`, not log-line counts. Rejected dispatch leaves no task or tick. `ox_health` cannot check schedules; neither `worker_batch_empty` nor batch exit 0 certifies every schedule dispatched. - **Prometheus.** Mount `django_ox.urls` and scrape `/ox/metrics`, or register `django_ox.metrics.collector()` with a registry you already run. Both are covered [above](#prometheus). diff --git a/docs/production.md b/docs/production.md index d75a63d..6d1aca7 100644 --- a/docs/production.md +++ b/docs/production.md @@ -369,14 +369,9 @@ schedule fires its first due tick. Use a long-running worker for more frequent schedule checks, but missed ticks are still coalesced; this does not guarantee that every tick runs. See [Missed ticks](recurring-tasks.md#missed-ticks). -An unreachable server, a lost or changed database session, or a database -error escaping a shared dispatch read does not count as an empty batch pass. -Failed polling passes and abandoned dispatch passes are retried, as they are -for a long-running worker. A batch keeps retrying until a dispatch pass -completes and the normal queue-drain and idle conditions hold. A failed -shared read, failed rollback or unusable session abandons the dispatch pass, -logs `schedule_dispatch_failed` at WARNING and keeps the batch open until a -pass completes. +Failed polling and abandoned dispatch passes do not count as empty batch passes. An unreachable server, lost or changed session, failed shared read, failed rollback or unusable connection causes retries. Other unhandled dispatch exceptions now do too: unlike 1.8.0, they log `schedule_dispatch_failed` with `category=unexpected_exception` instead of ending the worker with exit 1. + +The batch keeps claiming queued work and retries dispatch once per schedule interval. Draining the queue does not end it while dispatch remains owed. Normal completion requires a completed dispatch pass and the usual drain and idle conditions. This includes a custom schedule source whose store fails after startup. Direct calls to `dispatch_schedules()` still raise. There is no failure threshold or new exit code; stopping the batch can return 0 despite continuing dispatch failures. A failure inside one schedule's transaction is reported as `schedule_dispatch_error` at ERROR if rollback succeeds and the same @@ -390,13 +385,7 @@ each pass is abandoned at that schedule, preventing later schedules from being reached and holding the batch open. `schedule_dispatch_failed` does not identify the schedule being processed. -Alert on `schedule_dispatch_error` and `schedule_dispatch_failed`, plus -`schedule_row_skipped` and `schedule_source_unavailable` for stored schedules, -regardless of the batch's exit. Each `--batch` invocation starts a new worker, -so a schedule that keeps failing logs its first-failure traceback on every run -and no `schedule_dispatch_recovered` event carries across runs; alert on the -presence of `schedule_dispatch_error` in each run. Give the job runner a -timeout: it is what bounds a run against a failing database. +Alert on `schedule_dispatch_error`, `schedule_dispatch_failed` and `schedule_tick_unreadable`. For stored schedules, also alert on `schedule_row_skipped`, `schedule_source_unavailable` and `schedule_boundary_heal_failed`. Alert regardless of batch exit. Each invocation starts a new worker: continuing schedule failures get a first-failure traceback each run, and `schedule_dispatch_recovered` does not carry across runs. Alert on `schedule_dispatch_error` in each run. Give the job runner its own timeout for database, schedule-source and package faults. Clean termination does not prove successful dispatch. Both flags run a single process. `--processes` above 1 is rejected, because the supervisor restarts a worker that exits on its own; for more throughput in diff --git a/docs/recurring-tasks.md b/docs/recurring-tasks.md index 2c9ad17..44d2021 100644 --- a/docs/recurring-tasks.md +++ b/docs/recurring-tasks.md @@ -301,11 +301,7 @@ across backends: python manage.py check ``` -Database acceptance is determined at dispatch after validation. Alert on -`schedule_dispatch_error` for schedule-scoped failures and -`schedule_dispatch_failed` for abandoned passes. For stored schedules, -also alert on `schedule_row_skipped` and `schedule_source_unavailable`. -Use these events for schedule health monitoring. +Database acceptance is determined at dispatch after validation. Alert on `schedule_dispatch_error`, `schedule_dispatch_failed` and `schedule_tick_unreadable`. For stored schedules, also alert on `schedule_row_skipped`, `schedule_source_unavailable` and `schedule_boundary_heal_failed`. These report schedule-scoped failures, abandoned passes, unusable history, skipped rows, source failures and blocked boundary healing. To see what has actually dispatched, read the tick log: diff --git a/docs/stored-schedules.md b/docs/stored-schedules.md index 3ffba67..d521ea9 100644 --- a/docs/stored-schedules.md +++ b/docs/stored-schedules.md @@ -691,19 +691,8 @@ Worth knowing before you turn it on: such a write tells a worker to look. Set `OPTIONS["SCHEDULE_RECONCILE_INTERVAL"]` if you want that sooner; it is one indexed read of a small table. -- **One extra query per pass.** Workers read a single row to learn whether - anything changed. They re-read the schedules when it did and at each - reconcile interval. If the change marker cannot be read, full reads still - run at each reconcile interval. -- **Unreadable or invalid rows are skipped.** A row is left out if a value - cannot be converted, its start or end cannot be compared with the worker's - clock, or it cannot be built. The other schedules and the queue keep - running. The skip is logged as `schedule_row_skipped` with `schedule_pk`, - `schedule` and `reason`. If the name cannot be read, `schedule` may be - `None`. A conversion failure's reason names the column. Each row is logged - once, then at most once a minute per worker while it stays skipped. A skip - during the locked dispatch read includes a traceback only on its first - line. +- **Marker reads and reconciles.** Workers read one change-marker row per pass. They re-read schedules when it changes and at `SCHEDULE_RECONCILE_INTERVAL`, normally 60 seconds. If the marker cannot be read, full reads still run at that interval. Stored schedule reads use more CPU than 1.8.0, and full reconciles now use batched queries. Reconciles do not run every tick. Latest tick decoding costs CPU each pass. Dispatch statement counts are unchanged, both with and without a due tick. +- **Stored values django-ox cannot use.** Workers skip unreadable or invalid rows, including incomparable boundaries and a maximum `boundary_generation`; other schedules and the queue continue. `schedule_row_skipped` carries `schedule_pk`, `schedule`, `fields` and `reason`. An unreadable name may be `None`. Stored-value reasons name the field, quote its value and explain the problem. Reporting is once, then at most once a minute per row per worker. Locked dispatch skips include a traceback only on the first line. - **Skipped rows need repair.** Skipping does not repair invalid values. Find the row by `schedule_pk` and correct it in the admin change form or with `update_schedule`. Use SQL if the value is one the ORM cannot read. To pause @@ -718,23 +707,16 @@ Worth knowing before you turn it on: and the same connection remains usable, later schedules are still attempted. The failed schedule is retried on subsequent passes under the usual due-tick and deadline rules; only its reporting is rate-limited. -- **Database read failures are not bad rows.** A database error during a full - schedule read or a shared dispatch read, such as a lost connection, missing - table or lock error, is not attributed to an individual row. It stops the - pass rather than skipping a row. -- **An abandoned pass stops further traversal.** A `django.db.DatabaseError` - escaping a shared dispatch read, failed rollback or unusable connection is - reported as `schedule_dispatch_failed`. The stored source's marker read and - boundary heal retain their own events. An unreadable change-marker value - reports `schedule_source_unavailable` once, then at most once a minute while - it remains unreadable, and the worker reads the schedules in full at each - reconcile interval during that time. A database error on the marker read - reports the same event on every dispatch pass, and the worker keeps using - the last schedules it read. A failed boundary heal reports - `schedule_boundary_heal_failed`. Dispatch is retried on a later pass. - Ticks already committed are not undone. Alert on `schedule_row_skipped`, - `schedule_dispatch_error`, `schedule_dispatch_failed` and - `schedule_source_unavailable`. +- **Database read failures are not bad rows.** Database errors during full schedule or shared dispatch reads, including connection, missing-table and lock errors, stop the pass. They are not attributed to a row. Server-side errors propagate unchanged. In autocommit, recognized value-local failures may be isolated by diagnostic re-reads while the connection remains usable. + + Inside a transaction, diagnostic re-reads are restricted: PostgreSQL requires a usable transaction; SQLite permits only its recognized UTF-8 decoding refusal; MySQL permits none. Unwind through the transaction or savepoint boundary before further queries where required. Reads create no savepoints. `update_schedule` and `delete_schedule` have their own atomic blocks; source reads and `ox_prune` do not. Unlike 1.8.0, a source read inside your transaction can leave a server error for you to roll back. +- **An abandoned pass stops further traversal.** An escaping `django.db.Error`, other unhandled exception, failed rollback or unusable connection reports `schedule_dispatch_failed`. Dispatch retries on a later pass; committed ticks remain committed. Marker reads and boundary heals retain their own events. + + An unreadable marker reports `schedule_source_unavailable` once, then at most once a minute; full reads continue at each reconcile interval. A database error on the marker read reports every pass while workers use the last schedules read. Failed boundary healing reports `schedule_boundary_heal_failed`, first with a traceback, then counted summaries at most once a minute per row per worker. Healing retries each pass; the affected schedule cannot dispatch meanwhile. + + An unreadable newest tick within the pass's bound skips only its schedule with `schedule_tick_unreadable`. A settings schedule can also be blocked by its unreadable earliest tick. History is not treated as absent. The pass completes, so this skip does not hold a batch open. Follow the recovery procedure under [Configuration](configuration.md#ox_prune). + + Alert on `schedule_dispatch_error`, `schedule_dispatch_failed` and `schedule_tick_unreadable`. For stored schedules, also alert on `schedule_row_skipped`, `schedule_source_unavailable` and `schedule_boundary_heal_failed`. - **`manage.py check` cannot see rows.** Checks run before `migrate`, so a bad schedule in the database is a log line, not a start-up error. Settings-declared schedules still fail fast for errors their checks can @@ -761,21 +743,20 @@ failures. The full set, with every field, is on the | --- | --- | | `schedule_dispatched` | A tick enqueued its task. | | `schedule_tick_dropped` | A tick was past its starting deadline. Carries `late_seconds`. | -| `schedule_row_skipped` | A row could not be built. A skip during a periodic full read carries `schedule`, `schedule_pk` and `reason`. A skip during the locked dispatch read carries `schedule_pk` and a traceback. | +| `schedule_row_skipped` | A row holds values django-ox cannot use, has incomparable boundaries, or cannot be built. Full and locked reads carry `schedule`, `schedule_pk`, `fields` and `reason`. Reporting is rate-limited; locked reads include a traceback only on the first line. | | `schedule_dispatch_error` | A schedule-scoped failure, database or not. Its tick and task rolled back, and the pass continues. The schedule is retried under the usual due-tick and deadline rules. Reporting is rate-limited. | -| `schedule_dispatch_failed` | A dispatch pass was abandoned. It is retried on a later pass. Reporting is rate-limited. | +| `schedule_dispatch_failed` | A pass was abandoned and will be retried. `category` distinguishes `database` from `unexpected_exception`. Reporting is rate-limited. | | `schedule_dispatch_recovered` | A schedule that had failed on this worker committed a tick again. Carries `failures`. | +| `schedule_dispatch_resumed` | A pass completed after abandoned passes. Carries their total in `failures`. | +| `schedule_tick_unreadable` | A schedule was skipped because required tick history could not be read. History was not treated as absent; other schedules continue. | +| `schedule_tick_readable` | This worker read the history again after skipped passes. Carries their total in `failures`. | Pausing a stored schedule preserves its failure state on each worker; deleting the row drops it without an event. A paused, fixed and resumed row reports `schedule_dispatch_recovered` when it next commits a tick on a worker that retained its failure state. -Alert on `schedule_row_skipped`, `schedule_dispatch_error`, -`schedule_dispatch_failed` and `schedule_source_unavailable`, regardless of a -batch's exit code. `schedule_row_skipped` usually means a task key was removed -from the code while a row still names it. A row can pass validation and still -fail at dispatch, so that event alone is not enough. +Alert on `schedule_dispatch_error`, `schedule_dispatch_failed` and `schedule_tick_unreadable`. For stored schedules, also alert on `schedule_row_skipped`, `schedule_source_unavailable` and `schedule_boundary_heal_failed`. Alert regardless of a batch's exit code. For `schedule_row_skipped`, inspect `fields` and `reason`: an unregistered task key is one possible cause. A row can pass validation and still fail at dispatch, so skip alerts alone are insufficient. Read `failures` and `suppressed` on dispatch failure events rather than counting log lines. `ox_health` has no schedule check, and a rolled-back diff --git a/src/django_ox/stored.py b/src/django_ox/stored.py index 09e273a..0d5ae6b 100644 --- a/src/django_ox/stored.py +++ b/src/django_ox/stored.py @@ -18,7 +18,7 @@ import hashlib import logging import time -from collections.abc import Callable, Iterable, Mapping +from collections.abc import Callable, Iterable, Mapping, Sequence from contextvars import ContextVar from datetime import datetime, timedelta from functools import partial @@ -37,6 +37,12 @@ from django.utils import timezone from . import registry +from ._stored_read import ( + UnreadableRow, + is_unreadable_value, + lock_schedule, + read_schedules, +) from .compat import normalize_json from .cron import CronExpression from .models import OxSchedule, OxScheduleChange, validate_against, validation_alias @@ -171,7 +177,7 @@ # Messages for row isolation, all of them in this block. # The first two are `validate_schedule`'s and reach every path that # validates. The rest are what a worker logs about a stored row it leaves -# out, and about the change marker. +# out, about the change marker, and about a boundary it could not move. #: A start or an end the database at the row's destination would keep #: outside the years 1 to 9999: PostgreSQL stores it and cannot read it @@ -194,6 +200,20 @@ _COLUMNS_UNREADABLE = "its {columns} could not be read: {error}" #: The same, when no single column could be named. _A_VALUE_UNREADABLE = "a value in it could not be read: {error}" +#: The reason for a row holding a value that does not read as its field: +#: what the read said of each such field, field first ("end_time holds +#: '10000-01-01 00:00:00', which is not a date and time"). It covers what +#: Django's SQLite converters read as something else without a word: a +#: start or an end that is text and not a date, read as None, which is a +#: schedule with no boundary or no end, and an `enabled` other than true +#: or false, read as False, which is a pause nobody made. +_FIELDS_UNREADABLE = "its {reason}" +#: The reason for a row whose task_key the registry does not hold. `task_key` +#: is the key as stored, quoted and made safe to print. Not "does not +#: exist": during a rolling deploy it may be one only newer code registers. +_TASK_KEY_NOT_REGISTERED = ( + "its task_key {task_key} is not registered as a schedulable task in this deployment" +) #: The first line about a row left out. The row's name, made safe to print, #: then its primary key, then the reason. _SKIPPING = "Skipping stored schedule %s: %s" @@ -209,6 +229,16 @@ "are read in full every SCHEDULE_RECONCILE_INTERVAL until a schedule is written " "through django_ox.stored." ) +#: The first line about a row whose boundary could not be moved because the +#: database raised an error. `%s` is the row's primary key. +_HEAL_FAILED = "Could not move schedule %s onto its current timing" +#: A later line about the same row, at most once a ROW_REPORT_INTERVAL: the +#: row's primary key, how many times the move has failed since the last +#: line, this time included, and the class of the latest error. +_HEAL_STILL_FAILING = ( + "Still could not move schedule %s onto its current timing: %d more " + "failure(s) since it was last reported, latest error %s" +) #: The note `create_schedules` adds to the database's own error when a row #: of the batch is refused at the write. `index` is the row's position in #: the rows passed, `name` the name it supplied, escaped and cut to length. @@ -225,37 +255,16 @@ ) -#: While a stored row keeps being left out, or the change marker keeps -#: being unreadable, a worker says so in full the first time and after that -#: at most this often, with the number of times since the last line. +#: While a stored row keeps being left out, the change marker keeps being +#: unreadable, or a row's boundary keeps failing to move, a worker says so +#: in full the first time and after that at most this often, with the +#: number of times since the last line. ROW_REPORT_INTERVAL = 60.0 #: The most characters of a row's name or of a reason a line carries. _PRINTABLE_LIMIT = 200 -def _unreadable_value(exc: BaseException) -> bool: - """ - Whether a read failed on a value rather than on the database. - - A value the driver or Django's converters could not turn into Python: - a timestamp PostgreSQL holds and a datetime does not (DataError), a date - SQLite was given that does not exist, text in an integer column, a zero - date PyMySQL hands back as text. Those belong to the row that holds - them. Every other database error belongs to the database: a lost - connection, a missing table, a lock, a statement refused. Those are - raised, never put down to a row. - - One exception to the classes: SQLite's driver reports text it cannot - decode as UTF-8 as an OperationalError, which is a value in one row - and not the database failing. Read off its message, as lock_contention - reads SQLite's. - """ - if isinstance(exc, DataError) or not isinstance(exc, DatabaseError): - return True - return "Could not decode to UTF-8 column" in str(exc) - - def _printable(value: Any, limit: int = _PRINTABLE_LIMIT) -> str: """ Text a log line can carry whatever the database held. @@ -314,15 +323,17 @@ class _RowReport: full the first time, then at most every ROW_REPORT_INTERVAL seconds with how many times it went unsaid. - Keyed on what failed: a stored row by its primary key, or the change - marker. A row that is read and built again is forgotten, so if it breaks - once more it is reported in full. `clock` is time.monotonic outside - tests. + Keyed on what failed: a stored row by its primary key, the move of a + row's boundary by the same, or the change marker. A row that is read and + built again is forgotten, so if it breaks once more it is reported in + full, and so is a boundary once it is moved or no longer has to be. + `clock` is time.monotonic outside tests. """ def __init__(self, clock: Any = time.monotonic) -> None: self.clock = clock - #: When the last line was written, and the times since then unsaid. + #: When the last line was written, the times since then unsaid, and + #: the times in all since the first line, that one counted. self._failing: dict[Any, list[float]] = {} def due(self, key: Any) -> tuple[bool, bool, int]: @@ -330,8 +341,9 @@ def due(self, key: Any) -> tuple[bool, bool, int]: now = self.clock() state = self._failing.get(key) if state is None: - self._failing[key] = [now, 0] + self._failing[key] = [now, 0, 1] return True, True, 0 + state[2] += 1 if now - state[0] >= ROW_REPORT_INTERVAL: unsaid = int(state[1]) state[0], state[1] = now, 0 @@ -339,6 +351,11 @@ def due(self, key: Any) -> tuple[bool, bool, int]: state[1] += 1 return False, False, 0 + def times(self, key: Any) -> int: + """How many times `key` has failed since its first line, that one counted.""" + state = self._failing.get(key) + return 0 if state is None else int(state[2]) + def forget(self, key: Any) -> None: self._failing.pop(key, None) @@ -736,8 +753,13 @@ def _touch_change_row(using: str | None = None) -> None: # own, so the read is what raised and nothing was written. Written # over without reading it: a marker no write can move is one no # worker learns anything from, and every write through this module - # would fail on it. - if not _unreadable_value(exc): + # would fail on it. Only after a failure known to be a value's, + # raised in this process once the database had answered + # (`is_unreadable_value`). An error the database itself raised says + # nothing about what the marker holds, a DataError no more than a + # lock or a lost connection: it is raised as it is, and the write + # this was part of goes back with it. + if not is_unreadable_value(exc, using=alias): raise OxScheduleChange.objects.using(alias).filter(id=1).update(changed_at=now) @@ -1201,6 +1223,35 @@ def _lock_row(pk: int, db_alias: str) -> OxSchedule | None: return rows.first() +def _paused(row: UnreadableRow) -> bool: + """Whether a row that did not read is paused for certain: `enabled` read false.""" + return row.values.get("enabled") is False + + +def _current_row(pk: int, db_alias: str) -> OxSchedule | UnreadableRow | None: + """ + Take this schedule's row lock and read the row as it stands, for a + worker deciding whether to dispatch it or move its boundary: the row, + what of it did not read, or None when it is gone. + + Locked as `_lock_row` locks: a locking read on PostgreSQL and MySQL, + and on SQLite a no-op UPDATE first, which makes the transaction the + writer before it reads. Read as `_stored_read.read_schedules` reads, + each value decoded rather than converted, so a value that does not + read is reported by field instead of raised, and one SQLite's + converters would read as something else (a start that is not a date + read as None, an `enabled` of 2 read as False) does not read either. + + The statements `_lock_row` sends and no more, on every dispatch of a + stored schedule: the one locking read, or on SQLite the UPDATE and + the read. No savepoint is taken around the read, and whether the row + is still there comes from the read itself, which leaves out a row + that is gone. A read the database refuses is raised as it is, for the + dispatch loop to roll this schedule back on. + """ + return lock_schedule(pk, using=db_alias) + + class DatabaseScheduleSource: """ Schedules read from OxSchedule rows. @@ -1267,8 +1318,9 @@ def __init__(self, options: dict[str, Any], backend_alias: str) -> None: #: When the rows were last read in full, on the monotonic clock. #: None means never. self._last_read: float | None = None - #: What this source says about rows it leaves out and about a - #: marker it cannot read: once in full, then in summary. + #: What this source says about rows it leaves out, about a marker + #: it cannot read and about a boundary the database will not let it + #: move: once in full, then in summary. self._report = _RowReport() self._db_alias = schedule_db_alias() #: How often to read every row regardless of the change marker. @@ -1327,8 +1379,15 @@ def _rows(self) -> list[Any]: .first() ) except Exception as exc: - if not _unreadable_value(exc): - return self._marker_unavailable(cast(DatabaseError, exc)) + if not is_unreadable_value(exc, using=self._db_alias): + # Not known to be a value's. What the database raised is the + # database not answering, a DataError of its own as much as + # a lost connection, and says nothing about what the marker + # holds. Anything else is not a reading of the marker at + # all, and goes up as it is. + if not isinstance(exc, DatabaseError): + raise + return self._marker_unavailable(exc) # The marker holds a value that cannot be read: written around # this module, since every write here replaces it. It says # nothing about whether the rows moved, so they are read in full @@ -1419,13 +1478,28 @@ def _heal(self) -> None: re-read, and would go on proposing ticks the row no longer wants. """ for pk, observed in list(self._needs_heal.items()): + name = None try: with transaction.atomic(using=self._db_alias): - row = _lock_row(pk, self._db_alias) + row = _current_row(pk, self._db_alias) if row is None: # The row is gone, so there is no boundary to move. self._settled(pk) continue + if isinstance(row, UnreadableRow): + # It holds a value that does not read, so its + # boundary cannot be moved and it cannot be built + # either. The sighting goes: kept, it would be + # retried under the row's lock on every pass. The + # full read reports the row and leaves it out, and + # finds the boundary stale again once it reads. A + # count of boundary writes at its column's maximum + # is such a value: the move below adds one to the + # count, so it is never tried on one. + self._drop_sighting(pk) + self._unreadable_row(row) + continue + name = row.name # After the lock, per row. The boundary is the moment # the change was found, and a wait for the lock is # time the row can change again in: resumed while the @@ -1472,29 +1546,95 @@ def _heal(self) -> None: _touch_change_row(self._db_alias) self._settled(pk, healed=True) except Exception as exc: - if _unreadable_value(exc): - # The row holds a value that cannot be read, or one its - # digest cannot be taken over, so its boundary cannot be - # moved and it cannot be built either. The sighting goes: - # kept, it would be retried under the row's lock on every - # pass. The full read reports the row and leaves it out, - # and finds the boundary stale again once it reads. - self._needs_heal.pop(pk, None) - self._row_failed( - pk, - self._identify(pk)[0], - exc, - columns=partial(self._unreadable_columns, pk), - ) + if isinstance(exc, ValidationError) or is_unreadable_value( + exc, using=self._db_alias + ): + # A value the digest refused, in a row that read, or one + # that failed in this process where the read under the + # lock could not go on to name its field. The sighting + # goes, as for a row that does not read, and the row is + # reported. + self._drop_sighting(pk) + self._row_failed(pk, name, exc) continue + # What the database raised is not the row's, whatever its + # class: the read under the lock refused, or the write. The + # sighting stays and the move is tried again on the next + # pass. Anything else goes up. if not isinstance(exc, DatabaseError): raise - logger.warning( - "Could not move schedule %s onto its current timing", - pk, - exc_info=True, - extra={"event": "schedule_boundary_heal_failed"}, - ) + self._heal_failed(pk, exc) + + def _heal_failed(self, pk: int, exc: DatabaseError) -> None: + """ + Log a boundary the database would not let this worker move: with its + traceback the first time, then in summary. + + The move is tried again at the start of every dispatch pass, about + once a second, and what refused it once can refuse it every time: a + trigger or a constraint of the project's own on the table refuses + the write for as long as it stands, and so does a permission taken + away. A traceback a pass would crowd every other report out of the + log, so the failures after the first are counted, and said at most + once a ROW_REPORT_INTERVAL, per row. Only the reporting is held + back. The move is tried on every pass all the same, and the sighting + stays until it succeeds or is settled, which is when the count is + forgotten (`_drop_sighting`). + + A count of boundary writes at its column's maximum, which the move + cannot add to, does not come here: a row holding one does not read, + and no move of its boundary is tried (`_heal`). + + `failures` and `suppressed` are what they are on the lines about a + dispatch that keeps failing (`worker._DispatchReport`): every failed + move of this run, and the ones since the last line, this one + included. + """ + key = ("heal", pk) + due, first, unsaid = self._report.due(key) + if not due: + return + error = type(exc).__name__ + # Each record's extra is a literal dict, so the docs test's scan of + # emitted keys can read every key it carries. + if first: + logger.warning( + _HEAL_FAILED, + pk, + exc_info=exc, + extra={ + "event": "schedule_boundary_heal_failed", + "schedule_pk": pk, + "error": error, + "failures": 1, + "suppressed": 0, + }, + ) + return + # The ones that went unsaid, and this one, which has no line of its own. + since = unsaid + 1 + logger.warning( + _HEAL_STILL_FAILING, + pk, + since, + error, + extra={ + "event": "schedule_boundary_heal_failed", + "schedule_pk": pk, + "error": error, + "failures": self._report.times(key), + "suppressed": since, + }, + ) + + def _drop_sighting(self, pk: int) -> None: + """ + Forget a sighting, and with it what was being held back about its + move failing. A boundary that will not move after this is a new + failure, and is reported in full. + """ + self._needs_heal.pop(pk, None) + self._report.forget(("heal", pk)) def _settled(self, pk: int, *, healed: bool = False) -> None: """ @@ -1518,7 +1658,7 @@ def _settled(self, pk: int, *, healed: bool = False) -> None: """ def forget() -> None: - self._needs_heal.pop(pk, None) + self._drop_sighting(pk) if healed: logger.info( "Moved schedule %s to a boundary matching its timing", @@ -1539,21 +1679,18 @@ def _build(self) -> list[Any]: # came due inside the pause. This is the only read that sees a # disabled row at all, which is also why it is the one that says # which rows exist (`_stored_keys`). - for pk, row, unreadable in self._read_every_row(): + for pk, row in self._read_every_row(): # A row that cannot be read is still a row: it exists, so it # keeps its key and its failure report, and it is named by the # key it has rather than dropped as if it were gone. keys.add(f"{STORED_KEY_PREFIX}{pk}") - if row is None: - name, enabled = self._identify(pk) - if enabled is not False: + if isinstance(row, UnreadableRow): + # Left out quietly only when it is paused for certain: an + # `enabled` that read as false. One that did not read is not + # a pause, and is reported like any other value. + if not _paused(row): failing.add(pk) - self._row_failed( - pk, - name, - cast(BaseException, unreadable), - columns=partial(self._unreadable_columns, pk), - ) + self._unreadable_row(row) continue # Checked here, where every row is read whether or not a tick # of it is due. At dispatch it would sit behind the snapshot's @@ -1602,100 +1739,42 @@ def _build(self) -> list[Any]: self._row_keys = keys return built - def _read_every_row( - self, - ) -> list[tuple[int, OxSchedule | None, BaseException | None]]: + def _read_every_row(self) -> list[tuple[int, OxSchedule | UnreadableRow]]: """ - Every row in primary-key order, each with its key, or with the error - that reading it raised. - - One statement, as before, while every value converts. A value that - does not (a PostgreSQL timestamp outside the years a datetime holds, - a date SQLite was given that does not exist, a MySQL zero date) - raised from the driver or a converter in the middle of the result, - and took every row of it with it. Then the keys are read, which - always convert, and the rows again in ranges of keys, halving a range - that does not read until each row that fails is alone. The rows that - read are used, and each one that does not is named by its key. + Every row in primary-key order, each with its key: the row, or what + of it did not read. + + Read as `_stored_read.read_schedules` reads: the keys, which always + read, and then the rows a batch of keys at a time, each value + decoded rather than converted. A value Django's converters raise on + (a PostgreSQL timestamp outside the years a datetime holds, a date + SQLite was given that does not exist, a MySQL zero date) is that + row's, and the rest of the batch still reads. One SQLite's + converters read as something else, a start or an end that is text + and not a date, an `enabled` of 2, does not read either: built from + what the converter said, the row would dispatch with no boundary or + no end, or sit paused with nothing to say so. """ - rows = OxSchedule.objects.using(self._db_alias).order_by("pk") - try: - return [(row.pk, row, None) for row in rows] - except Exception as exc: - if not _unreadable_value(exc): - raise - pks = list( - OxSchedule.objects.using(self._db_alias) - .order_by("pk") - .values_list("pk", flat=True) + rows = read_schedules( + OxSchedule.objects.using(self._db_alias).order_by("pk"), + using=self._db_alias, ) - return self._read_between(pks) - - def _read_between( - self, pks: list[int] - ) -> list[tuple[int, OxSchedule | None, BaseException | None]]: - """The rows from the first of `pks` to the last, or the row that fails.""" - if not pks: - return [] - rows = ( - OxSchedule.objects.using(self._db_alias) - .filter(pk__gte=pks[0], pk__lte=pks[-1]) - .order_by("pk") + return list(rows.items()) + + def _unreadable_row(self, row: UnreadableRow) -> None: + """Log a stored row left out because a value in it does not read.""" + reason = ( + _FIELDS_UNREADABLE.format(reason=row.reason) + if row.unreadable + else row.reason + ) + self._row_failed( + row.pk, + row.values.get("name"), + row.cause or ValueError(reason), + reason=reason, + fields=row.fields, ) - try: - # Each in a savepoint of its own, or a transaction where none is - # open. A failure that is the driver's or a converter's leaves - # the session as it was, but one the server raised would leave - # a transaction the caller owns unusable for every read after it. - with transaction.atomic(using=self._db_alias): - return [(row.pk, row, None) for row in rows] - except Exception as exc: - if not _unreadable_value(exc): - raise - if len(pks) == 1: - return [(pks[0], None, exc)] - middle = len(pks) // 2 - return self._read_between(pks[:middle]) + self._read_between(pks[middle:]) - - def _identify(self, pk: int) -> tuple[Any, Any]: - """The name and the enabled flag of a row whose other values may not read.""" - try: - with transaction.atomic(using=self._db_alias): - found = ( - OxSchedule.objects.using(self._db_alias) - .filter(pk=pk) - .values_list("name", "enabled") - .first() - ) - except Exception as exc: - if not _unreadable_value(exc): - raise - return None, None - return found if found is not None else (None, None) - - def _unreadable_columns(self, pk: int) -> list[str]: - """ - Which of a row's columns do not read, one at a time. - - Asked only when a line about the row is about to be written, which - is once and then at most once a ROW_REPORT_INTERVAL, so the cost of - a statement per column is paid that often and not on every read. - """ - found = [] - for field in OxSchedule._meta.concrete_fields: - try: - with transaction.atomic(using=self._db_alias): - ( - OxSchedule.objects.using(self._db_alias) - .filter(pk=pk) - .values_list(field.attname, flat=True) - .first() - ) - except Exception as exc: - if not _unreadable_value(exc): - raise - found.append(field.name) - return found def _row_failed( self, @@ -1704,6 +1783,8 @@ def _row_failed( exc: BaseException, *, columns: Callable[[], list[str]] | None = None, + reason: str | None = None, + fields: Sequence[str] = (), traceback: bool = False, ) -> None: """ @@ -1714,14 +1795,24 @@ def _row_failed( stored. The reason is cut to a length and escaped the same way: an error message can quote the value that caused it. `columns`, for a row a value of which did not convert, names the columns that did not, - and is asked only when a line is written. + and is asked only when a line is written. `reason`, where the caller + has one, is the reason as it stands. + + The line carries the fields at fault as a list of their names as + well, for whoever reads the record rather than the sentence: those + in `fields`, or the ones `columns` names. The list is empty where no + field is at fault, a row that read and could not be built, and + where the read could not say which field it was. """ due, first, unsaid = self._report.due(("row", pk)) if not due: return - if columns is not None: + if reason is not None: + reason = _printable(reason) + elif columns is not None: error = _printable(f"{type(exc).__name__}: {exc}") named = columns() + fields = named reason = ( _COLUMNS_UNREADABLE.format(columns=", ".join(named), error=error) if named @@ -1742,6 +1833,7 @@ def _row_failed( "schedule": safe_name, "schedule_pk": pk, "reason": reason, + "fields": list(fields), }, ) return @@ -1755,13 +1847,22 @@ def _row_failed( "schedule": safe_name, "schedule_pk": pk, "reason": reason, + "fields": list(fields), }, ) def _to_schedule(self, row: OxSchedule) -> Any: from .schedules import IntervalTrigger, Schedule - kind = registry.get(row.task_key) + # Around the lookup alone: a KeyError from anywhere later, a form's + # own clean among them, is not this, and said to be would send + # someone to check a registration that is fine. + try: + kind = registry.get(row.task_key) + except KeyError: + raise ValueError( + _TASK_KEY_NOT_REGISTERED.format(task_key=_printable(repr(row.task_key))) + ) from None arguments = dict(row.arguments) if isinstance(row.arguments, dict) else None if arguments is None: raise ValueError("arguments must be a mapping") @@ -1819,7 +1920,11 @@ def _to_schedule(self, row: OxSchedule) -> Any: else kind.task.using(backend=self._backend_alias) ) return Schedule( - name=row.name, + # A label, and what every line a worker logs about the schedule + # carries, so made safe to print here: the write functions and + # the admin's form store a name with a line break or an escape + # sequence in it as it is given. + name=_printable(row.name), # The row's identity, not its label. Renaming a schedule must not # change what its ticks are keyed on, or a worker holding the old # label and one holding the new would write two tick rows for the @@ -1853,21 +1958,8 @@ def _current(self, pk: int, db_alias: str) -> Any: a worker with a current view can still act on it. """ try: - row = _lock_row(pk, db_alias) + row = _current_row(pk, db_alias) except Exception as exc: - if _unreadable_value(exc): - # The row holds a value that cannot be read: changed around - # this module since the snapshot was taken. Left out as the - # full read leaves it out, from the snapshot as well, so it - # is not locked again on every pass until that read. - self._row_failed( - pk, - self._identify(pk)[0], - exc, - columns=partial(self._unreadable_columns, pk), - ) - self._leave_out(pk) - return None # A lock-wait timeout, or SQLite reporting the database busy. # One schedule's contention must not end the pass for the rest, # and it is contention, so no traceback. Anything else goes to @@ -1884,6 +1976,17 @@ def _current(self, pk: int, db_alias: str) -> Any: extra={"event": "schedule_lock_unavailable", "schedule_pk": pk}, ) return None + if isinstance(row, UnreadableRow): + # Changed around this module since the snapshot was taken, to a + # value that does not read. Left out as the full read leaves it + # out, from the snapshot as well, so it is not locked again on + # every pass until that read: reported, unless it is paused for + # certain, and with no heal, since its boundary cannot be + # checked. + if not _paused(row): + self._unreadable_row(row) + self._leave_out(pk) + return None digest = None if row is not None: try: diff --git a/src/django_ox/worker.py b/src/django_ox/worker.py index 164b129..bc33266 100644 --- a/src/django_ox/worker.py +++ b/src/django_ox/worker.py @@ -53,7 +53,6 @@ ExpressionWrapper, F, JSONField, - Max, Q, QuerySet, ) @@ -74,11 +73,13 @@ task_started, ) +from ._stored_read import TickRead, earliest_tick, latest_ticks, newest_tick_pk from .backend import OxBackend from .exceptions import TaskAbandoned, TaskTimeout from .heartbeat import HeartbeatFile from .models import OxScheduleTick, OxTask from .schedules import ( + STORED_KEY_PREFIX, Schedule, lock_contention, schedule_name_collisions, @@ -319,6 +320,30 @@ class _NotAdmitted(Exception): """ +class _TickUnreadable(Exception): + """ + Raised inside the dispatch transaction when the earliest tick a first + sighting is decided by holds a value that does not read. + + Like _NotAdmitted, a way out of a tick row already written: the + schedule's transaction rolls back, candidate tick and latch with it, + and the pass goes on to the next schedule. Carries the read, for the + report. + """ + + def __init__(self, read: TickRead) -> None: + super().__init__(read.reason) + self.read = read + + +def _stored_pk(key: str) -> int | None: + """The row id in a stored schedule's dispatch key; None for a settings schedule.""" + if not key.startswith(STORED_KEY_PREFIX): + return None + digits = key[len(STORED_KEY_PREFIX) :] + return int(digits) if digits.isdecimal() else None + + def _latch_instant() -> datetime: """ The fixed instant a first-sighting latch row is written at. @@ -398,10 +423,19 @@ class _DispatchReport: the database's own message, which on PostgreSQL can quote part of the refused value. - Per pass, the same shape for `schedule_dispatch_failed`: the first - abandoned pass of an outage is reported with its traceback, and the - passes after it are counted into a summary at most every interval. A - completed pass ends the run, so the next outage is reported in full. + Per schedule as well, and apart from those, `schedule_tick_unreadable` + for a schedule skipped because its tick history holds a value that + does not read: in full once, then in summary, then + `schedule_tick_readable` on the first pass that reads it again. It is + not a dispatch that failed, and reported as one it would end in a + recovery only when the schedule next commits a tick. + + Per pass, the same shape for `schedule_dispatch_failed`, kept apart by + what abandoned the pass: the database, or an exception nothing + expected. The first abandoned pass of each is reported with its + traceback, and the passes after it are counted into a summary at most + every interval. A completed pass ends the run with one + `schedule_dispatch_resumed`, so the next outage is reported in full. The state is bounded by the schedules that exist: `retain` forgets a schedule that is no longer among them. A stored row that is paused @@ -424,12 +458,14 @@ def __init__( self.db_alias = db_alias self.clock = clock self._schedules: dict[str, _Failing] = {} - self._passes: _Failing | None = None + self._unreadable: dict[str, _Failing] = {} + self._passes: dict[str, _Failing] = {} def retain(self, keys: set[str]) -> None: - """Forget every failing schedule whose key is not in `keys`.""" - for key in [k for k in self._schedules if k not in keys]: - del self._schedules[key] + """Forget every failing or skipped schedule whose key is not in `keys`.""" + for state in (self._schedules, self._unreadable): + for key in [k for k in state if k not in keys]: + del state[key] def schedule_failed(self, schedule: Schedule, exc: BaseException) -> None: """One schedule's dispatch failed and the pass goes on without it.""" @@ -495,20 +531,47 @@ def schedule_dispatched(self, schedule: Schedule) -> None: }, ) - def pass_failed(self, exc: BaseException) -> None: - """A dispatch pass was abandoned.""" + def tick_unreadable( + self, + schedule: Schedule, + read: TickRead, + phase: str, + tick_pk: Callable[[], int | None] | None = None, + ) -> None: + """ + One schedule was skipped because a tick of its history did not read. + + `phase` is the read that met it: `latest`, the bounded read of the + newest tick every pass makes, or `anchor`, the read of the earliest + tick that decides a first sighting. `read` says why and, where the + read that found it also found its row, which tick row it is. + Otherwise `tick_pk` is called to find the row, and only when a line + is written: a skipped schedule is met again by every pass, and the + line is written at most once in `DISPATCH_FAILURE_REPORT_INTERVAL`. + Not finding the row never changes the skip, so a lookup that fails + leaves the line without it. + """ now = self.clock() - state = self._passes + state = self._unreadable.get(schedule.key) + which = "newest" if phase == "latest" else "earliest" if state is None: - self._passes = _Failing(1, 0, now) + self._unreadable[schedule.key] = _Failing(1, 0, now) logger.warning( - "Schedule dispatch failed; retrying next pass", - exc_info=exc, + "Schedule %s skipped; its tick history was not treated as " + "absent. Its %s tick could not be read: %s", + schedule.name, + which, + read.reason, extra={ - "event": "schedule_dispatch_failed", + "event": "schedule_tick_unreadable", + "schedule": schedule.name, + "schedule_key": schedule.key, + "schedule_pk": _stored_pk(schedule.key), + "phase": phase, + "reason": read.reason, + "tick_pk": self._tick_row(read, tick_pk), "worker_id": self.worker_id, "database": self.db_alias, - "error": type(exc).__name__, "failures": 1, "suppressed": 0, }, @@ -519,15 +582,22 @@ def pass_failed(self, exc: BaseException) -> None: if now - state.reported_at < DISPATCH_FAILURE_REPORT_INTERVAL: return logger.warning( - "Schedule dispatch still failing: %d more pass(es) abandoned since " - "the last report, latest error %s", + "Schedule %s still skipped: %d more pass(es) since it was last " + "reported. Its %s tick could not be read: %s", + schedule.name, state.unreported, - type(exc).__name__, + which, + read.reason, extra={ - "event": "schedule_dispatch_failed", + "event": "schedule_tick_unreadable", + "schedule": schedule.name, + "schedule_key": schedule.key, + "schedule_pk": _stored_pk(schedule.key), + "phase": phase, + "reason": read.reason, + "tick_pk": self._tick_row(read, tick_pk), "worker_id": self.worker_id, "database": self.db_alias, - "error": type(exc).__name__, "failures": state.failures, "suppressed": state.unreported, }, @@ -535,9 +605,139 @@ def pass_failed(self, exc: BaseException) -> None: state.reported_at = now state.unreported = 0 + @staticmethod + def _tick_row( + read: TickRead, lookup: Callable[[], int | None] | None + ) -> int | None: + """The unreadable tick's row, from the read or else from `lookup`.""" + if read.pk is not None or lookup is None: + return read.pk + try: + return lookup() + except Exception: + return None + + def tick_readable(self, schedule: Schedule) -> None: + """A schedule's tick history read: if it had been skipped, say so.""" + state = self._unreadable.pop(schedule.key, None) + if state is None: + return + logger.info( + "Schedule %s tick history can be read again after %d skipped pass(es)", + schedule.name, + state.failures, + extra={ + "event": "schedule_tick_readable", + "schedule": schedule.name, + "schedule_key": schedule.key, + "schedule_pk": _stored_pk(schedule.key), + "worker_id": self.worker_id, + "database": self.db_alias, + "failures": state.failures, + }, + ) + + def pass_failed(self, exc: BaseException, *, unexpected: bool = False) -> None: + """ + A dispatch pass was abandoned: by the database, or, `unexpected`, by + an exception that is not a database error and that nothing in the + pass handled. That is a fault in code, not an outage, and it is + reported as neither an outage nor a bad row: it says what it is. + """ + now = self.clock() + category = "unexpected_exception" if unexpected else "database" + state = self._passes.get(category) + if state is None: + self._passes[category] = _Failing(1, 0, now) + if unexpected: + logger.warning( + "Schedule dispatch failed with an unexpected exception (%s); " + "retrying next pass", + type(exc).__name__, + exc_info=exc, + extra={ + "event": "schedule_dispatch_failed", + "category": category, + "worker_id": self.worker_id, + "database": self.db_alias, + "error": type(exc).__name__, + "failures": 1, + "suppressed": 0, + }, + ) + return + logger.warning( + "Schedule dispatch failed; retrying next pass", + exc_info=exc, + extra={ + "event": "schedule_dispatch_failed", + "category": category, + "worker_id": self.worker_id, + "database": self.db_alias, + "error": type(exc).__name__, + "failures": 1, + "suppressed": 0, + }, + ) + return + state.failures += 1 + state.unreported += 1 + if now - state.reported_at < DISPATCH_FAILURE_REPORT_INTERVAL: + return + if unexpected: + logger.warning( + "Schedule dispatch still failing with unexpected exceptions: %d more " + "pass(es) abandoned since the last report. Latest error: %s", + state.unreported, + type(exc).__name__, + extra={ + "event": "schedule_dispatch_failed", + "category": category, + "worker_id": self.worker_id, + "database": self.db_alias, + "error": type(exc).__name__, + "failures": state.failures, + "suppressed": state.unreported, + }, + ) + else: + logger.warning( + "Schedule dispatch still failing: %d more pass(es) abandoned since " + "the last report, latest error %s", + state.unreported, + type(exc).__name__, + extra={ + "event": "schedule_dispatch_failed", + "category": category, + "worker_id": self.worker_id, + "database": self.db_alias, + "error": type(exc).__name__, + "failures": state.failures, + "suppressed": state.unreported, + }, + ) + state.reported_at = now + state.unreported = 0 + def pass_completed(self) -> None: - """A dispatch pass went through every schedule it had.""" - self._passes = None + """ + A dispatch pass went through every schedule it had. If passes before + it had been abandoned, say dispatch is back. + """ + if not self._passes: + return + failures = sum(state.failures for state in self._passes.values()) + self._passes = {} + logger.info( + "Schedule dispatch resumed after %d abandoned pass(es)", + failures, + extra={ + "event": "schedule_dispatch_resumed", + "worker_id": self.worker_id, + "database": self.db_alias, + "failures": failures, + }, + ) @dataclass(slots=True) @@ -5112,10 +5312,11 @@ def _abandon_exhausted( def _latest_ticks( self, schedules: list[Schedule], since: datetime - ) -> dict[str, datetime]: + ) -> dict[str, TickRead]: """ Latest recorded tick per dispatch key, for the pass's schedules, - counting only ticks at or after `since`. + counting only ticks at or after `since`: for each key the tick, no + tick, or a tick that holds a value that does not read. The bound is what keeps this cheap. Asked for the newest tick per schedule over all of history, no database can seek to it: PostgreSQL @@ -5133,36 +5334,35 @@ def _latest_ticks( the caller distinguishes that from a schedule with no ticks at all by asking. - One parameter per key, plus the bound. SQLite before 3.32.0 refuses - a statement carrying more than 999, and Django splits an IN list - only where the backend declares a maximum, which is Oracle. So the - keys are read in slices of what the connection allows, and a - backend that declares no limit answers None and reads them in one. - """ - keys = [schedule.key for schedule in schedules] - limit = connections[self._db_alias].features.max_query_params - step = max(limit - 1, 1) if limit else max(len(keys), 1) - latest: dict[str, datetime] = {} - for start in range(0, len(keys), step): - latest.update( - { - row["schedule_name"]: row["latest"] - for row in OxScheduleTick.objects.using(self._db_alias) - .filter( - schedule_name__in=keys[start : start + step], - scheduled_for__gte=since, - ) - .values("schedule_name") - .annotate(latest=Max("scheduled_for")) - } - ) - return latest + One grouped statement for as many keys as the connection takes + parameters for, one per key plus the bound: SQLite before 3.32.0 + refuses a statement carrying more than 999, and Django splits an IN + list only where the backend declares a maximum, which is Oracle. A + backend that declares no limit reads them in one. + + The newest tick comes back as its text and is decoded per key, so a + value Django's converter would raise on in the middle of the + result, a year past 9999 or a date that does not exist, is that + key's answer rather than the end of the read for every key: the + caller skips that schedule and dispatches the rest. + _stored_read.latest_ticks says how a statement that fails as a + whole is narrowed down to its key. + """ + reads = latest_ticks( + [schedule.key for schedule in schedules], since, using=self._db_alias + ) + return {key: read for key, read in reads.items() if not read.absent} def _anchor_boundary(self, key: str, own_pk: int, now: datetime) -> datetime | None: """ The earliest tick recorded for `key` other than this pass's own row, or None when there is none, which makes this pass the first sighting. + An earliest tick that holds a value that does not read raises + _TickUnreadable, both times it is read. It is history whose meaning + is lost, not an absence of history: read as none, this pass would + anchor the schedule again over a tick it already has. + Called inside the dispatch transaction, after this pass's tick row is in. That row is excluded because it is visible in here, and counting it would make every schedule look like it already had @@ -5199,32 +5399,34 @@ def _anchor_boundary(self, key: str, own_pk: int, now: datetime) -> datetime | N tick read, not ox_prune, not the admin. SQLite has one writer, so the tick INSERT already serialises first sightings there, and the latch is two statements that change nothing. - """ - others = ( - OxScheduleTick.objects.using(self._db_alias) - .filter(schedule_name=key) - .exclude(pk=own_pk) - .order_by("scheduled_for") - .values_list("scheduled_for", flat=True) - ) - earliest = others.first() - if earliest is not None: - return earliest + + Each read is one statement in this transaction, with no savepoint + around it: the tick comes back as text and is decoded here, so a + value that does not read fails no statement. A read the database + itself refuses is raised as it is, and takes this schedule's + transaction with it like any other statement of its dispatch. + """ + earliest = earliest_tick(key, using=self._db_alias, exclude=(own_pk,)) + if earliest.unreadable: + raise _TickUnreadable(earliest) + if not earliest.absent: + return earliest.at latch = OxScheduleTick.objects.using(self._db_alias).create( schedule_name=key, scheduled_for=_latch_instant(), task_id=None, created_at=now, ) - others = others.exclude(pk=latch.pk) - features = connections[self._db_alias].features - if features.has_select_for_update: - others = others.select_for_update( - skip_locked=features.has_select_for_update_skip_locked - ) - earliest = others.first() + earliest = earliest_tick( + key, using=self._db_alias, exclude=(own_pk, latch.pk), lock=True + ) + if earliest.unreadable: + # The rollback this raises into takes the latch with it. No + # anchor is written, so a worker that waited on the latch reads + # the same tick and skips the schedule too. + raise _TickUnreadable(earliest) OxScheduleTick.objects.using(self._db_alias).filter(pk=latch.pk).delete() - return earliest + return earliest.at def _session(self) -> tuple[Any, Any] | None: """ @@ -5415,10 +5617,18 @@ def dispatch_schedules(self) -> int: The pass fails, and this raises, when the failure is not one schedule's: a shared read before the loop (the source's own reads, - the bounded tick read), a rollback that did not go through, or a - connection that does not answer after one. Nothing is given up on - the strength of how many schedules failed before: a run of refused - schedules followed by a healthy one leaves the healthy one to fire. + the bounded tick read) that the database failed, a rollback that + did not go through, or a connection that does not answer after one. + Nothing is given up on the strength of how many schedules failed + before: a run of refused schedules followed by a healthy one leaves + the healthy one to fire. + + A tick in the log that holds a value that does not read is not a + failed read. It belongs to the one schedule whose key it carries, + and that schedule is skipped, `schedule_tick_unreadable`, until the + value is repaired or the tick removed: neither the newest tick nor + the anchor is guessed at, since a guess either fires a tick that + has already run or anchors the schedule over history it has. """ schedules = self._schedule_source.schedules() # Forget schedules that no longer exist, so the failure report @@ -5479,11 +5689,15 @@ def dispatch_schedules(self) -> int: due.append((schedule, scheduled_for)) if not due: return 0 - latest = self._latest_ticks( - schedules, min(scheduled_for for _, scheduled_for in due) - ) + since = min(scheduled_for for _, scheduled_for in due) + latest = self._latest_ticks(schedules, since) dispatched = 0 for schedule, scheduled_for in due: + # Absent from the read: nothing recorded within the bound. + read = latest.get(schedule.key, TickRead(schedule.key)) + # The comparisons with the schedule's bounds and its newest + # tick are its own, like those above: raised from here, they + # would end the pass for every schedule after this one. try: if ( schedule.start_time is not None @@ -5493,14 +5707,34 @@ def dispatch_schedules(self) -> int: continue if schedule.end_time is not None and scheduled_for > schedule.end_time: continue + if read.unreadable: + # Its newest tick is there and does not read. Taken as + # no tick, the schedule would fire one already run, or + # anchor again; it is skipped instead, and the rest of + # the pass goes on. + self._dispatch_report.tick_unreadable( + schedule, + read, + "latest", + functools.partial( + newest_tick_pk, + schedule.key, + since, + using=self._db_alias, + ), + ) + continue + last = read.at + if last is not None or not schedule.anchors: + # Nothing more of its history is read this pass. + self._dispatch_report.tick_readable(schedule) + if last is not None and scheduled_for <= last and last <= now: + continue except DatabaseError: raise except Exception as exc: self._dispatch_report.schedule_failed(schedule, exc) continue - last = latest.get(schedule.key) - if last is not None and scheduled_for <= last and last <= now: - continue result = None # Set once this pass's tick row is in. An IntegrityError arriving # with it clear is the INSERT losing the constraint; with it set, @@ -5656,6 +5890,7 @@ def mark_committed() -> None: anchor = self._anchor_boundary( current.key, tick_row.pk, now ) + self._dispatch_report.tick_readable(schedule) if anchor is None: first_sighting = True elif scheduled_for < anchor: @@ -5700,6 +5935,13 @@ def mark_committed() -> None: # unclaimed so a worker with a current view can still act # on it. continue + except _TickUnreadable as exc: + # The earliest tick, which says whether this is a first + # sighting, does not read. The rollback took this pass's + # tick row and any latch with it, and nothing was enqueued. + # Reported once as what it is, not as a dispatch error too. + self._dispatch_report.tick_unreadable(schedule, exc.read, "anchor") + continue except Exception as exc: if ( not claimed @@ -6175,7 +6417,7 @@ def run(self) -> None: dispatch_owed = True try: self.dispatch_schedules() - except DatabaseError as exc: + except Error as exc: # The pass was abandoned: a shared read failed, # or a schedule's failure left the connection # unusable (dispatch_schedules says which is @@ -6187,9 +6429,32 @@ def run(self) -> None: # claim reconnects rather than failing on it too # and costing the whole poll pass. Reported in # full at the start of an outage and in summary - # while it lasts. + # while it lasts. django.db.Error rather than + # DatabaseError, for the reason the handler of + # the poll pass gives: a connection closed under + # the pass raises InterfaceError, which is the + # database's as much as any. self._dispatch_report.pass_failed(exc) close_old_connections() + except Exception as exc: + # Not the database's, and not handled anywhere + # in the pass: a fault in code, one of this + # package's readers or a project's schedule + # source, that every schedule's own boundary + # missed. It costs this pass and no more. Out of + # run() it would cost the process, and a + # restart repairs nothing a pass reads: the + # supervisor would restart it into the same + # fault until its restart cap stopped every + # worker, the tasks already queued included. So + # the dispatch stays owed, it is tried again a + # schedule_interval later rather than at once, + # and the claim below still runs. Only this + # call: a fault anywhere else in the loop is + # not caught here, and an exception that is not + # an Exception (KeyboardInterrupt, SystemExit) + # keeps its meaning. + self._dispatch_report.pass_failed(exc, unexpected=True) else: dispatch_owed = False self._dispatch_report.pass_completed() diff --git a/tests/settings.py b/tests/settings.py index 3178ff1..5d0ca3b 100644 --- a/tests/settings.py +++ b/tests/settings.py @@ -106,13 +106,14 @@ # A worker process started from the test suite writes bare messages. A test # that times the worker from a record, rather than from when it got round to # reading the line, asks for a format that carries the record's timestamp. One -# that reads which event a line was asks for %(event)s, which a record logged -# without one shows as "-". +# that reads which event a line was asks for %(event)s, and one that reads +# the fields a line names for %(fields)s: a record logged without either +# shows it as "-". if "OX_TEST_LOG_FORMAT" in os.environ: LOGGING["formatters"] = { "test": { "format": os.environ["OX_TEST_LOG_FORMAT"], - "defaults": {"event": "-"}, + "defaults": {"event": "-", "fields": "-"}, } } LOGGING["handlers"]["console"]["formatter"] = "test" diff --git a/tests/sources.py b/tests/sources.py index 4ebd361..4c2afa2 100644 --- a/tests/sources.py +++ b/tests/sources.py @@ -1,8 +1,55 @@ """Schedule sources a test can name in OPTIONS["SCHEDULE_SOURCE"].""" +import builtins +import os + +from django_ox.schedules import SettingsScheduleSource from django_ox.stored import DatabaseScheduleSource +class FailingReadSource(SettingsScheduleSource): + """ + The settings schedules, read by a dispatch pass through a read that + raises: a shared read of the pass that nothing guards, as a reader + added later might be. For worker processes, which take their + configuration from the environment. + + OX_TEST_SOURCE_RAISES names the exception, a builtin class, and + OX_TEST_SOURCE_PASSES how many dispatch passes it fails, or "every". + The read made when the worker is built goes through. + """ + + def __init__(self, options, backend_alias): + super().__init__(options, backend_alias) + self.reads = 0 + + def schedules(self): + self.reads += 1 + error = getattr(builtins, os.environ["OX_TEST_SOURCE_RAISES"]) + passes = os.environ["OX_TEST_SOURCE_PASSES"] + if self.reads > 1 and (passes == "every" or self.reads <= 1 + int(passes)): + raise error("a shared read of the dispatch pass failed") + return super().schedules() + + +class UnavailableAfterStart(SettingsScheduleSource): + """ + A project's own source whose store answers when the worker is built and + never again: every read after the first raises ConnectionError, as a + source backed by a service that has gone away would. + """ + + def __init__(self, options, backend_alias): + super().__init__(options, backend_alias) + self.reads = 0 + + def schedules(self): + self.reads += 1 + if self.reads > 1: + raise ConnectionError("the source's own store stopped answering") + return super().schedules() + + class RowSource(DatabaseScheduleSource): """A project's own source, under a name that is not the base class's.""" diff --git a/tests/test_claim_recovery.py b/tests/test_claim_recovery.py index bf21f93..6c2a1b3 100644 --- a/tests/test_claim_recovery.py +++ b/tests/test_claim_recovery.py @@ -935,16 +935,18 @@ def test_a_pass_that_failed_outside_the_claim_starts_no_look( step, settings, caplog, monkeypatch ): """ - The loop's handler catches the database errors of reap and dispatch as - well as the claim's. Only the claim's can leave a row RUNNING under this - worker's id, so only the claim's starts a look. + The loop's handler catches the database errors of reap as well as the + claim's, and dispatch's own handler catches dispatch's. Only the claim's + can leave a row RUNNING under this worker's id, so only the claim's + starts a look. """ caplog.set_level(logging.WARNING, logger="django_ox") _budget(settings, 1) worker = Worker(lock_timeout=LOCK_TIMEOUT, poll_interval=0.05, batch=True) real = getattr(worker, step) - # A DatabaseError out of dispatch is its own handler's; an InterfaceError - # is not a DatabaseError and reaches the loop's. + # Out of dispatch an InterfaceError, which is not a DatabaseError: a + # connection closed under the pass is the database's all the same, and + # dispatch's handler takes it as it takes any other. error = OperationalError if step == "reap" else InterfaceError failed = [] @@ -972,8 +974,15 @@ def look(**kwargs): thread.join(timeout=60) assert failed == [step] - (poll,) = _events(caplog, "worker_poll_failed", worker) - assert poll.claim_recovery is None + polls = _events(caplog, "worker_poll_failed", worker) + if step == "reap": + (poll,) = polls + assert poll.claim_recovery is None + else: + # The claim ran in the pass dispatch failed in, so the loop's + # handler never saw it. + assert _events(caplog, "schedule_dispatch_failed", worker) + assert polls == [] assert looks == [] assert _row(result).status == OxTask.Status.SUCCESSFUL diff --git a/tests/test_dispatch_statements.py b/tests/test_dispatch_statements.py new file mode 100644 index 0000000..981fa82 --- /dev/null +++ b/tests/test_dispatch_statements.py @@ -0,0 +1,488 @@ +""" +What one dispatch pass sends to the database, statement by statement. + +A worker's pass runs in autocommit, and each schedule's dispatch in a +transaction of its own. On the way to a dispatch the pass reads stored +values it does not trust: the newest tick of every schedule, a stored +schedule's row under its lock, a settings schedule's earliest tick. Each +is fetched as the database holds it and decoded in the worker, and that +has to cost a healthy pass nothing. The pass sends the statements 1.8.0 +sent and no more: no savepoint around a read, and on SQLite no statement +asking whether a row the lock was taken on is there, since the read of +the row says so. + +Counted in autocommit, as a worker runs, with exactly one tick due. Inside +a test's own transaction every schedule's transaction is a savepoint, and +a count taken there says nothing about a worker. + +With no savepoint, a read the database itself refuses inside a schedule's +transaction is not read again more narrowly: on PostgreSQL the transaction +takes nothing more. The database's own error is what reaches the dispatch +loop, which rolls that schedule back, reports it, and goes on to the next. + +A read the database refuses before any schedule's transaction, among the +reads the pass makes for all of its schedules, is not read again more +narrowly either. Its error says nothing of one row or one key, so the pass +is abandoned with it, and the next pass reads again. +""" + +import logging +from datetime import timedelta + +import pytest +from django.db import DataError, connection +from django.test.utils import CaptureQueriesContext +from django.utils import timezone + +from django_ox.models import OxSchedule, OxScheduleTick, OxTask +from django_ox.registry import ScheduleKind, register +from django_ox.stored import boundary_digest, create_schedule +from django_ox.worker import Worker + +from . import tasks +from .conftest import start_worker_thread, wait_for +from .isolation import daily_cron_at, labels, twelve_hours_ago, with_history +from .test_stored_read import Reads, Refusing + +pytestmark = pytest.mark.django_db(transaction=True) + +SCHEDULES = "django_ox_oxschedule" + +#: The statements of one pass with exactly one tick due, by their first +#: word, as 1.8.0 sends them on each database: for a stored schedule, for a +#: settings schedule with a tick older than the pass reads back to, and +#: for a settings schedule at its first sighting. Each begins with the +#: stored source's read of its change marker and the read of the newest +#: ticks. PostgreSQL and MySQL lock a stored row with the read of it; +#: SQLite writes first to become the writer. A first sighting writes its +#: latch, reads again under it, and takes the latch back. +STORED = { + "postgresql": "SELECT SELECT BEGIN SELECT INSERT INSERT UPDATE COMMIT", + "mysql": "SELECT SELECT BEGIN SELECT INSERT INSERT UPDATE COMMIT", + "sqlite": "SELECT SELECT BEGIN UPDATE SELECT INSERT INSERT UPDATE COMMIT", +} +SETTINGS = "SELECT SELECT BEGIN INSERT SELECT INSERT UPDATE COMMIT" +FIRST_SIGHTING = "SELECT SELECT BEGIN INSERT SELECT INSERT SELECT DELETE COMMIT" + + +@pytest.fixture(autouse=True) +def _registry(monkeypatch): + monkeypatch.setattr("django_ox.registry._registry", {}) + monkeypatch.setattr("django_ox.registry._discovered", True) + register(ScheduleKind(key="labelled", task=tasks.labelled)) + + +def tasks_setting(schedules): + return { + "default": { + "BACKEND": "django_ox.backend.OxBackend", + "QUEUES": ["default", "emails"], + "OPTIONS": { + "SCHEDULE_SOURCE": "django_ox.stored.DatabaseScheduleSource", + "SCHEDULES": schedules, + }, + } + } + + +def entry(name, base): + """A settings schedule daily at `base`'s time of day, labelled `name`.""" + return {"task": "tests.tasks.labelled", "cron": daily_cron_at(base), "args": [name]} + + +def a_row(name, base): + """A stored schedule daily at `base`'s time of day, labelled `name`.""" + return create_schedule( + name=name, + task_key="labelled", + trigger="cron", + cron=daily_cron_at(base), + arguments={"label": name}, + start_time=timezone.now() - timedelta(days=1), + ) + + +def one_pass(worker): + """A whole dispatch pass in autocommit: what it dispatched, and its statements.""" + assert connection.get_autocommit() + assert not connection.in_atomic_block + with CaptureQueriesContext(connection) as captured: + dispatched = worker.dispatch_schedules() + return dispatched, [query["sql"] for query in captured.captured_queries] + + +def first_words(statements): + return " ".join(sql.split()[0].upper() for sql in statements) + + +def assert_no_savepoint(statements): + """Not one made, released or gone back to.""" + assert not [sql for sql in statements if "SAVEPOINT" in sql.upper()], statements + + +def on_the_schedule_table(sql): + """Whether a statement is on the schedule table, not on one named after it.""" + others = (f"{SCHEDULES}tick", f"{SCHEDULES}change") + return SCHEDULES in sql.replace(others[0], "").replace(others[1], "") + + +def ticks_of(key): + return OxScheduleTick.objects.filter(schedule_name=key) + + +class TestAHealthyPassSendsWhatItSentBefore: + def test_for_a_stored_schedule(self, settings): + settings.TASKS = tasks_setting({}) + row = a_row("r", twelve_hours_ago()) + worker = Worker(backoff_initial=0) + # The rows are read in full when the marker moves or the reconcile + # is due, not on a pass that has a tick to fire. + worker._schedule_source.schedules() + + dispatched, statements = one_pass(worker) + + assert dispatched == 1 + assert labels() == ["r"] + assert first_words(statements) == STORED[connection.vendor] + assert_no_savepoint(statements) + on_the_row = [sql for sql in statements if on_the_schedule_table(sql)] + if connection.features.has_select_for_update: + # The lock and the row in one read. + (read,) = on_the_row + assert "FOR UPDATE" in read + else: + # The writer first, and then the row, whose absence from that + # read is what would say it had gone: no statement asks. + write, read = on_the_row + assert write.lstrip().upper().startswith("UPDATE") + assert read.lstrip().upper().startswith("SELECT") + assert str(row.pk) in read + + def test_for_a_settings_schedule_with_older_history(self, settings): + settings.TASKS = tasks_setting({"s": entry("s", twelve_hours_ago())}) + with_history("s") + worker = Worker(backoff_initial=0) + + dispatched, statements = one_pass(worker) + + assert dispatched == 1 + assert labels() == ["s"] + assert first_words(statements) == SETTINGS + assert_no_savepoint(statements) + + def test_for_a_settings_schedule_at_its_first_sighting(self, settings): + settings.TASKS = tasks_setting({"s": entry("s", twelve_hours_ago())}) + worker = Worker(backoff_initial=0) + + dispatched, statements = one_pass(worker) + + # Anchored, not fired: the tick is recorded with no task. + assert dispatched == 0 + (anchor,) = ticks_of("s") + assert anchor.task_id is None + assert not OxTask.objects.exists() + assert first_words(statements) == FIRST_SIGHTING + assert_no_savepoint(statements) + + def test_a_pass_with_nothing_due_reads_twice_and_writes_nothing(self, settings): + settings.TASKS = tasks_setting({}) + a_row("r", twelve_hours_ago()) + worker = Worker(backoff_initial=0) + assert worker.dispatch_schedules() == 1 + + dispatched, statements = one_pass(worker) + + assert dispatched == 0 + assert first_words(statements) == "SELECT SELECT" + + +class TestTheReadOfEveryStoredRow: + """ + The stored rows are read in full when their change marker moves and at + each reconcile interval: the marker, the keys, and then the rows five + hundred a statement. That is what a worker pays for a table of any + size, on a pass that has that read to make. + """ + + def test_twelve_hundred_rows_are_their_keys_and_three_statements(self, settings): + settings.TASKS = tasks_setting({}) + now = timezone.now() + rows = [ + OxSchedule( + name=f"r-{index:04}", + task_key="labelled", + trigger="cron", + cron="0 3 * * *", + arguments={"label": f"r-{index:04}"}, + start_time=now, + created_at=now, + updated_at=now, + ) + for index in range(1200) + ] + for row in rows: + # As the write functions leave it, so that no row is met with a + # boundary to move. + row.boundary_for = boundary_digest(row) + OxSchedule.objects.bulk_create(rows) + worker = Worker(backoff_initial=0) + # Read again in full, as it is when the reconcile interval is up. + worker._schedule_source._last_read = None + reads = Reads(SCHEDULES) + + assert connection.get_autocommit() + assert not connection.in_atomic_block + with connection.execute_wrapper(reads): + built = worker._schedule_source.schedules() + + assert len(built) == 1200 + marker, *on_the_rows = reads.sent + assert not on_the_schedule_table(marker[0]) + assert all(on_the_schedule_table(sql) for sql, _params in on_the_rows) + # The keys, which take no parameter, and then the rows, a key a + # parameter. + assert [len(params) for _sql, params in on_the_rows] == [0, 500, 500, 200] + + +def events(caplog, name): + return [r for r in caplog.records if getattr(r, "event", None) == name] + + +def a_pass_with_the_first_read_refused(worker, mentions, caplog): + """ + One pass in which the database refuses the first read whose SQL holds + `mentions`, inside the transaction of the schedule it belongs to. + Returns what was dispatched and the first word of every statement of + the pass, transactions' BEGIN, COMMIT and ROLLBACK among them. The + refused read is "(refused)" there: a driver records a statement that + failed in its own way, or not at all. + """ + refusing = Refusing(mentions) + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + connection.execute_wrapper(refusing), + CaptureQueriesContext(connection) as captured, + ): + assert connection.get_autocommit() + assert not connection.in_atomic_block + dispatched = worker.dispatch_schedules() + assert refusing.refused is not None, "the read was never sent" + assert refusing.after, "the pass ended with the refused read" + sent = [str(query["sql"]).split()[0].upper() for query in captured.captured_queries] + assert not [word for word in sent if word in ("SAVEPOINT", "RELEASE")], sent + # The refused read is the statement the first rollback follows. + sent[sent.index("ROLLBACK") - 1] = "(refused)" + return dispatched, sent + + +def up_to_the_rollback(sent): + """ + The pass from its first BEGIN to the first ROLLBACK: the transaction of + the schedule whose read was refused. The refused read is the last + statement in it, so nothing was read after it, more narrowly or + otherwise, before the transaction was rolled back. + """ + return sent[sent.index("BEGIN") : sent.index("ROLLBACK") + 1] + + +def assert_reported_as_the_databases_own_error(caplog, schedule): + (failed,) = events(caplog, "schedule_dispatch_error") + assert failed.schedule == schedule + assert failed.error == "DataError" + raised = failed.exc_info[1] + assert type(raised) is DataError + # What the database said of the read it refused, not what it says of + # every statement sent into a transaction that has already failed. + assert Refusing.SAYS[connection.vendor] in str(raised) + assert not events(caplog, "schedule_row_skipped") + assert not events(caplog, "schedule_tick_unreadable") + assert not events(caplog, "schedule_dispatch_failed") + + +class TestAReadTheDatabaseRefusesInsideASchedulesTransaction: + """ + On PostgreSQL and MySQL the server refuses the read for real, with a + statement it raises a DataError on, so PostgreSQL's transaction is left + as a refused read leaves it. SQLite has no such statement, and the + error is raised in the read's place. + """ + + def test_the_read_of_a_stored_row_under_its_lock(self, settings, caplog): + settings.TASKS = tasks_setting({}) + base = twelve_hours_ago() + first = a_row("r-first", base) + second = a_row("r-second", base) + worker = Worker(backoff_initial=0) + worker._schedule_source.schedules() + + dispatched, sent = a_pass_with_the_first_read_refused( + worker, "ox_stored_start_time", caplog + ) + + # The first row's dispatch is rolled back, and the second fires. + assert dispatched == 1 + assert labels() == ["r-second"] + assert not ticks_of(f"db:{first.pk}").exists() + assert ticks_of(f"db:{second.pk}").count() == 1 + locked = ( + [] + if connection.features.has_select_for_update + # The no-op write that makes the transaction the writer. + else ["UPDATE"] + ) + assert up_to_the_rollback(sent) == ["BEGIN", *locked, "(refused)", "ROLLBACK"] + # The second row's whole dispatch comes after it. + assert sent[-1] == "COMMIT" + assert_reported_as_the_databases_own_error(caplog, "r-first") + + def test_the_read_of_a_settings_schedules_earliest_tick(self, settings, caplog): + base = twelve_hours_ago() + settings.TASKS = tasks_setting( + {"s-first": entry("s-first", base), "s-second": entry("s-second", base)} + ) + with_history("s-first", "s-second") + (history,) = ticks_of("s-first").values_list("pk", flat=True) + worker = Worker(backoff_initial=0) + + dispatched, sent = a_pass_with_the_first_read_refused( + worker, "ox_stored_scheduled_for", caplog + ) + + assert dispatched == 1 + assert labels() == ["s-second"] + # The tick written for the first schedule before the read went + # with its transaction: what it had before is all it has. + assert list(ticks_of("s-first").values_list("pk", flat=True)) == [history] + assert ticks_of("s-second").exclude(task_id=None).count() == 1 + assert up_to_the_rollback(sent) == ["BEGIN", "INSERT", "(refused)", "ROLLBACK"] + assert sent[-1] == "COMMIT" + assert_reported_as_the_databases_own_error(caplog, "s-first") + + def test_the_next_pass_dispatches_the_schedule_it_cost(self, settings, caplog): + settings.TASKS = tasks_setting({}) + base = twelve_hours_ago() + a_row("r-first", base) + a_row("r-second", base) + worker = Worker(backoff_initial=0) + worker._schedule_source.schedules() + a_pass_with_the_first_read_refused(worker, "ox_stored_start_time", caplog) + + with caplog.at_level(logging.INFO, logger="django_ox"): + dispatched, statements = one_pass(worker) + + assert dispatched == 1 + assert labels() == ["r-first", "r-second"] + assert_no_savepoint(statements) + (recovered,) = events(caplog, "schedule_dispatch_recovered") + assert recovered.schedule == "r-first" + + +class TestAReadTheDatabaseRefusesWithNoTransactionOpen: + """ + The reads a pass makes for all of its schedules run with no transaction + open: the stored rows, read in full when their change marker moves, and + the newest tick of every schedule that is due. One the database refuses + is not one schedule's, and no row or key is looked for in it: the pass + is abandoned with the database's own error, which the worker's loop + takes as it takes any other of the database's, and the next pass reads + again. On PostgreSQL and MySQL the server refuses the read for real; + SQLite has no such statement, and the error is raised in the read's + place. + """ + + #: Each of those reads, by what its statement holds. + READS = [ + pytest.param("ox_stored_start_time", id="the-stored-rows"), + pytest.param("MAX(", id="the-newest-ticks"), + ] + + @pytest.mark.parametrize("mentions", READS) + def test_the_pass_is_abandoned_with_the_databases_own_error( + self, settings, caplog, mentions + ): + settings.TASKS = tasks_setting({}) + base = twelve_hours_ago() + a_row("r-first", base) + worker = Worker(backoff_initial=0) + # Written since the worker read the rows, so its next read of them + # is in full again. + a_row("r-second", base) + if "MAX(" in mentions: + # Made here, so that the pass comes to the newest ticks. + worker._schedule_source.schedules() + refusing = Refusing(mentions) + + assert connection.get_autocommit() + assert not connection.in_atomic_block + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + pytest.raises(DataError) as caught, + connection.execute_wrapper(refusing), + ): + worker.dispatch_schedules() + + # Raised as it was, with no half of the rows or the keys read after. + refusing.assert_raised_as_it_was(caught) + assert not OxTask.objects.exists() + assert not OxScheduleTick.objects.exists() + for event in ( + "schedule_row_skipped", + "schedule_tick_unreadable", + "schedule_dispatch_error", + ): + assert not events(caplog, event), event + + dispatched, statements = one_pass(worker) + + assert dispatched == 2 + assert labels() == ["r-first", "r-second"] + assert_no_savepoint(statements) + + def test_the_workers_loop_reports_it_as_the_databases_and_goes_on( + self, settings, caplog, monkeypatch + ): + settings.TASKS = tasks_setting({}) + a_row("r-due", twelve_hours_ago()) + worker = Worker( + backoff_initial=0, + poll_interval=0.02, + reap_interval=0.0, + schedule_interval=0.1, + ) + refusing = Refusing("MAX(") + dispatch = worker.dispatch_schedules + + def with_the_first_pass_refused(): + # Called on the worker's thread, and so on its own connection. + if refusing.refused is None: + with connection.execute_wrapper(refusing): + return dispatch() + return dispatch() + + monkeypatch.setattr(worker, "dispatch_schedules", with_the_first_pass_refused) + + def ran(): + return OxTask.objects.filter(status=OxTask.Status.SUCCESSFUL).exists() + + with caplog.at_level(logging.INFO, logger="django_ox"): + thread = start_worker_thread(worker) + reached = wait_for(lambda: ran() or not thread.is_alive(), timeout=30) + alive = thread.is_alive() + worker.request_stop() + thread.join(timeout=30) + + assert reached, "the schedule never fired" + assert alive, "run() ended on its own" + (failed,) = events(caplog, "schedule_dispatch_failed") + assert failed.category == "database" + assert failed.error == "DataError" + raised = failed.exc_info[1] + assert type(raised) is DataError + assert Refusing.SAYS[connection.vendor] in str(raised) + # Nothing was read after it in the pass it ended. + assert refusing.after == [] + assert not events(caplog, "schedule_tick_unreadable") + (resumed,) = events(caplog, "schedule_dispatch_resumed") + assert resumed.failures == 1 + assert labels() == ["r-due"] + assert OxSchedule.objects.count() == 1 diff --git a/tests/test_schedules.py b/tests/test_schedules.py index c03b6d0..4dd8635 100644 --- a/tests/test_schedules.py +++ b/tests/test_schedules.py @@ -931,7 +931,7 @@ def test_the_keys_are_read_in_slices_of_the_connections_limit( latest = worker._latest_ticks(schedules, at - timedelta(days=1)) reads = [q for q in captured.captured_queries if "MAX(" in q["sql"].upper()] assert len(reads) == 4, "ten keys in slices of three is four reads" - assert latest == expected + assert {key: read.at for key, read in latest.items()} == expected def test_a_connection_with_no_limit_reads_them_in_one(self, settings): from django.db import connection @@ -949,7 +949,7 @@ def test_a_connection_with_no_limit_reads_them_in_one(self, settings): ) reads = [q for q in captured.captured_queries if "MAX(" in q["sql"].upper()] assert len(reads) == 1 - assert latest == expected + assert {key: read.at for key, read in latest.items()} == expected def test_more_keys_than_sqlite_3_31_allows_are_still_read(self, settings): # The real limit, set on the live connection: 999 is what SQLite @@ -976,4 +976,4 @@ def test_more_keys_than_sqlite_3_31_allows_are_still_read(self, settings): ) finally: raw.setlimit(sqlite3.SQLITE_LIMIT_VARIABLE_NUMBER, before) - assert latest == expected + assert {key: read.at for key, read in latest.items()} == expected diff --git a/tests/test_stored_dispatch.py b/tests/test_stored_dispatch.py index 58fdd6e..3f07f55 100644 --- a/tests/test_stored_dispatch.py +++ b/tests/test_stored_dispatch.py @@ -1093,11 +1093,14 @@ def at(seconds): return base, at - def _lock_that_waits(self, monkeypatch, during_the_wait): - """The first lock taken runs `during_the_wait` before it is granted.""" + def _lock_that_waits(self, monkeypatch, during_the_wait, lock="_lock_row"): + """ + The first lock taken runs `during_the_wait` before it is granted: + the write API's, or with `lock="_current_row"` a worker's. + """ from django_ox import stored - lock_row = stored._lock_row + lock_row = getattr(stored, lock) waited = {"done": False} def lock_row_after_a_wait(pk, alias): @@ -1106,7 +1109,7 @@ def lock_row_after_a_wait(pk, alias): during_the_wait(pk) return lock_row(pk, alias) - monkeypatch.setattr(stored, "_lock_row", lock_row_after_a_wait) + monkeypatch.setattr(stored, lock, lock_row_after_a_wait) def test_a_retime_is_timed_from_the_lock_not_from_before_the_wait( self, worker, monkeypatch @@ -1156,7 +1159,7 @@ def resumed_during_the_wait(pk): OxSchedule.objects.filter(pk=pk).update(enabled=True) at(125) - self._lock_that_waits(monkeypatch, resumed_during_the_wait) + self._lock_that_waits(monkeypatch, resumed_during_the_wait, lock="_current_row") at(75) worker.dispatch_schedules() row.refresh_from_db() @@ -1196,14 +1199,14 @@ def _clock_that_advances_inside_the_lock(self, monkeypatch, before, after): moment = {"now": before} monkeypatch.setattr(worker_module.timezone, "now", lambda: moment["now"]) - lock_row = stored._lock_row + current_row = stored._current_row - def lock_row_after_a_wait(pk, alias): - row = lock_row(pk, alias) + def current_row_after_a_wait(pk, alias): + row = current_row(pk, alias) moment["now"] = after return row - monkeypatch.setattr(stored, "_lock_row", lock_row_after_a_wait) + monkeypatch.setattr(stored, "_current_row", current_row_after_a_wait) def test_a_tick_past_its_deadline_once_the_lock_is_granted_is_refused( self, worker, monkeypatch @@ -1246,10 +1249,10 @@ class TestTheRowLockDistinguishesContentionFromTheDatabase: def _lock_row_raising(self, monkeypatch, exc): from django_ox import stored - def lock_row(pk, alias): + def current_row(pk, alias): raise exc - monkeypatch.setattr(stored, "_lock_row", lock_row) + monkeypatch.setattr(stored, "_current_row", current_row) def test_a_lock_the_database_gave_up_on_skips_the_schedule( self, worker, monkeypatch, caplog @@ -1283,15 +1286,15 @@ def test_a_connection_gone_away_at_the_lock_ends_the_pass( from .isolation import kill a_minutely() - real_lock_row = stored._lock_row + real_current_row = stored._current_row - def lock_row_on_a_dead_session(pk, alias): + def current_row_on_a_dead_session(pk, alias): from django.db import connections kill(connections[alias]) - return real_lock_row(pk, alias) + return real_current_row(pk, alias) - monkeypatch.setattr(stored, "_lock_row", lock_row_on_a_dead_session) + monkeypatch.setattr(stored, "_current_row", current_row_on_a_dead_session) with ( caplog.at_level(logging.WARNING, logger="django_ox"), pytest.raises(Error), @@ -1514,12 +1517,14 @@ def test_the_marker_still_short_circuits_between_reconciles( def test_the_reconcile_reads_the_rows_again( self, worker, django_assert_num_queries ): - # And when it is due, it costs the marker read plus the row read. + # And when it is due, it costs the marker read plus the row read: + # the keys, which always read, and then the rows a batch of a + # hundred at a time. a_minutely() source = worker._schedule_source source._reconcile_interval = 0.0001 source.schedules() - with django_assert_num_queries(2): + with django_assert_num_queries(3): source.schedules() def test_a_disabled_row_leaves_the_cache_when_dispatch_finds_it_gone( diff --git a/tests/test_stored_isolation.py b/tests/test_stored_isolation.py index b780365..3bab9a9 100644 --- a/tests/test_stored_isolation.py +++ b/tests/test_stored_isolation.py @@ -31,18 +31,29 @@ import logging import re +from collections import Counter +from contextlib import contextmanager from datetime import UTC, datetime, timedelta from zoneinfo import ZoneInfo import pytest from django.contrib.auth.models import User from django.core.exceptions import ValidationError -from django.db import OperationalError, connection +from django.db import ( + DataError, + IntegrityError, + InterfaceError, + OperationalError, + ProgrammingError, + connection, + transaction, +) +from django.test.utils import CaptureQueriesContext from django.urls import reverse from django.utils import timezone from django_ox import stored -from django_ox.models import OxSchedule, OxScheduleChange, OxScheduleTick +from django_ox.models import OxSchedule, OxScheduleChange, OxScheduleTick, OxTask from django_ox.registry import ScheduleKind, register from django_ox.schedules import IntervalTrigger, Schedule from django_ox.stored import ( @@ -50,12 +61,14 @@ _export_preflight, create_schedule, create_schedules, + delete_schedule, update_schedule, ) from django_ox.worker import Worker from . import tasks from .conftest import start_worker_thread, wait_for +from .test_stored_read import Refusing, largest_count ADD = "admin:django_ox_oxschedule_add" CHANGE = "admin:django_ox_oxschedule_change" @@ -179,6 +192,13 @@ def only_on(vendor, why): "SQLite keeps text that is not UTF-8, and its driver cannot decode it", id="text that is not utf-8", ), + pytest.param( + "sqlite", + "task_key", + "X'626c6f62'", + "SQLite keeps bytes in a text column", + id="bytes as the task key", + ), pytest.param( "postgresql", "end_time", @@ -508,7 +528,7 @@ def test_the_source_reads_the_rest_and_a_worker_is_built( # Named, and the reason says which column would not convert. first = skipped[0] assert first.schedule == "victim" - assert first.reason.startswith(f"its {column} could not be read: ") + assert first.reason.startswith(f"its {column} ") # The row still exists as far as the worker is concerned. assert f"db:{victim.pk}" in worker._schedule_source._stored_keys() @@ -542,6 +562,23 @@ def test_a_row_whose_name_cannot_be_read_is_named_by_its_key( ) assert skipped.reason.startswith("its name could not be read: ") + def test_a_row_whose_name_is_bytes_is_named_by_its_key(self, settings, caplog): + only_on("sqlite", "SQLite keeps bytes in a text column") + settings.TASKS = stored_tasks() + a_row("beside-it") + victim = a_row("victim") + write_by_sql(TABLE, "name", "X'626c6f622d6e616d65'", victim.pk) + with caplog.at_level(logging.INFO, logger="django_ox"): + built = DatabaseScheduleSource({}, "default").schedules() + assert Worker(backoff_initial=0).dispatch_schedules() == 1 + assert [schedule.name for schedule in built] == ["beside-it"] + skipped = events(caplog, "schedule_row_skipped") + assert {record.schedule_pk for record in skipped} == {victim.pk} + assert {record.schedule for record in skipped} == {None} + assert {record.reason for record in skipped} == { + "its name holds b'blob-name', which is not text" + } + def test_two_bad_rows_among_many_are_each_found(self, settings, caplog): # The read halves a range of keys that does not read; every row # that does is still used, in key order. @@ -577,7 +614,13 @@ def test_a_row_written_around_validation_with_a_zone_and_use_tz_off( skipped = events(caplog, "schedule_row_skipped") assert len(skipped) == 2 assert {(r.schedule_pk, r.reason) for r in skipped} == { - (victim.pk, stored._BOUND_HAS_A_ZONE.format(field="start_time")) + ( + victim.pk, + ( + "its start_time holds '2020-01-01 00:00:00+05:00', which has " + "a time zone, and USE_TZ is off" + ), + ) } def test_a_bound_that_is_not_a_time_or_has_no_zone_with_use_tz_on(self, settings): @@ -601,6 +644,24 @@ def test_a_bound_that_is_not_a_time_or_has_no_zone_with_use_tz_on(self, settings # -- the read under the row's lock, at dispatch ------------------------------- +def a_sighting(settings): + """ + A worker's source that has met `victim` at dispatch with timing its + boundary was not set for, changed by a route that moves no boundary: + the source, holding the sighting its next read heals, and the row. + """ + settings.TASKS = stored_tasks(SCHEDULE_RECONCILE_INTERVAL=3600) + a_row("beside-it") + victim = a_row("victim") + worker = Worker(backoff_initial=0) + source = worker._schedule_source + source.schedules() + OxSchedule.objects.filter(pk=victim.pk).update(every_seconds=120) + worker.dispatch_schedules() + assert victim.pk in source._needs_heal + return source, victim + + @pytest.mark.django_db class TestAtDispatchARowChangedSinceTheSnapshot: """ @@ -629,7 +690,7 @@ def test_a_value_that_cannot_be_read_is_left_out( assert worker.dispatch_schedules() == 1, "the schedule beside it fires" (skipped,) = events(caplog, "schedule_row_skipped") assert (skipped.schedule, skipped.schedule_pk) == ("victim", victim.pk) - assert skipped.reason.startswith(f"its {column} could not be read: ") + assert skipped.reason.startswith(f"its {column} ") assert not events(caplog, "schedule_dispatch_error") # Out of the snapshot, so it is not locked again on every pass. cached = [s.key for s in worker._schedule_source._cached] @@ -645,7 +706,7 @@ def test_a_value_its_field_cannot_convert_is_left_out(self, settings, caplog): assert worker.dispatch_schedules() == 1 (skipped,) = events(caplog, "schedule_row_skipped") assert skipped.schedule_pk == victim.pk - assert skipped.reason.startswith("its every_seconds could not be read: ") + assert skipped.reason.startswith("its every_seconds ") assert len(worker._schedule_source._cached) == 1 def test_a_paused_row_that_cannot_be_converted_is_left_out_quietly( @@ -673,30 +734,25 @@ def test_a_row_that_no_longer_builds_is_left_out_with_its_traceback( assert skipped.exc_info is not None assert len(worker._schedule_source._cached) == 1 - def test_a_heal_that_meets_a_row_that_cannot_be_read(self, settings, caplog): + @pytest.mark.parametrize(("vendor", "column", "literal", "why"), WHILE_RUNNING) + def test_a_heal_that_meets_a_row_that_cannot_be_read( + self, settings, caplog, vendor, column, literal, why + ): """ A row seen at dispatch with its timing changed around the functions is healed on the next pass. Changed again before that, so that it cannot be read, the heal cannot move its boundary: the sighting goes and the row is reported, where before the read raised for every row. """ - only_on("sqlite", "SQLite keeps a date that does not exist") - settings.TASKS = stored_tasks(SCHEDULE_RECONCILE_INTERVAL=3600) - a_row("beside-it") - victim = a_row("victim") - worker = Worker(backoff_initial=0) - source = worker._schedule_source - source.schedules() - OxSchedule.objects.filter(pk=victim.pk).update(every_seconds=120) - worker.dispatch_schedules() - assert victim.pk in source._needs_heal - write_by_sql(TABLE, "end_time", "'2026-02-30 00:00:00'", victim.pk) + only_on(vendor, why) + source, victim = a_sighting(settings) + write_by_sql(TABLE, column, literal, victim.pk) with caplog.at_level(logging.INFO, logger="django_ox"): source.schedules() assert victim.pk not in source._needs_heal - assert { - (r.schedule, r.schedule_pk) for r in events(caplog, "schedule_row_skipped") - } == {("victim", victim.pk)} + (skipped,) = events(caplog, "schedule_row_skipped") + assert (skipped.schedule, skipped.schedule_pk) == ("victim", victim.pk) + assert skipped.reason.startswith(f"its {column} ") assert not events(caplog, "schedule_boundary_heal_failed") @@ -721,8 +777,9 @@ def test_the_rows_are_read_and_a_later_write_is_noticed( assert [s.name for s in source.schedules()] == ["first"] assert [s.name for s in source.schedules()] == ["first"] unreadable = events(caplog, "schedule_source_unavailable") - # Said once, not once a pass. + # Said once, not once a pass, and as a value that does not read. assert len(unreadable) == 1 + assert unreadable[0].msg == stored._MARKER_UNREADABLE # A write through this module replaces the marker, which it # could not have read, and the source notices it at once. a_row("second") @@ -803,17 +860,47 @@ def lost(self, row): @pytest.mark.django_db class TestTheReadInsideACallersTransaction: - def test_a_value_refused_by_the_server_leaves_the_transaction_usable( - self, settings, caplog + @pytest.mark.parametrize(("vendor", "column", "literal", "why"), UNREADABLE) + def test_a_value_that_does_not_read_leaves_the_transaction_usable( + self, settings, caplog, vendor, column, literal, why ): """ - The rows are read again in ranges, each in a savepoint, because a - source may be read inside a transaction the caller owns (this test - runs in one). A value psycopg cannot convert fails on the client - and leaves the transaction as it was; one the server refuses aborts - it, and without the savepoint every read after it in the pass would - fail with it. Made to happen here by having the server refuse the - first range read. + A source may be read inside a transaction the caller owns (this + test runs in one). The rows are read a batch at a time with each + value decoded here, so a value that does not read fails no + statement, and the one failure a driver raises by itself, SQLite's + on text that is not UTF-8, comes once the database has answered. + Either way the transaction is as it was: no savepoint is taken + around a read, and the caller's next statement runs. + """ + only_on(vendor, why) + settings.TASKS = stored_tasks() + a_row("beside-it") + victim = a_row("victim") + write_by_sql(TABLE, column, literal, victim.pk) + assert connection.in_atomic_block + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + CaptureQueriesContext(connection) as queries, + ): + built = DatabaseScheduleSource({}, "default").schedules() + assert [schedule.name for schedule in built] == ["beside-it"] + assert {r.schedule_pk for r in events(caplog, "schedule_row_skipped")} == { + victim.pk + } + assert not [ + q["sql"] for q in queries.captured_queries if "SAVEPOINT" in q["sql"] + ] + assert OxSchedule.objects.filter(pk=victim.pk).update(name="still-here") == 1 + + def test_a_read_the_server_refuses_is_raised_as_it_was(self, settings, caplog): + """ + A read the server itself refuses ends a PostgreSQL transaction for + every statement after it, and there is no savepoint to go back to. + The server's error is raised as it is, for the caller that owns + the transaction to roll it back: nothing is read after it, and no + row is put down as one that does not read. Made to happen here by + having the server refuse the first batch of rows. """ only_on("postgresql", "only PostgreSQL aborts a transaction on an error") settings.TASKS = stored_tasks() @@ -821,23 +908,1167 @@ def test_a_value_refused_by_the_server_leaves_the_transaction_usable( victim = a_row("victim") write_by_sql(TABLE, "end_time", "'infinity'", victim.pk) refused = [] + after = [] - def refuse_the_first_range(execute, sql, params, many, context): - if TABLE in sql and '"id" >= ' in sql and not refused: + def refuse_the_first_batch(execute, sql, params, many, context): + if refused: + after.append(sql) + elif TABLE in sql and "ox_stored_end_time" in sql: refused.append(sql) return execute("SELECT 1/0", None, many, context) return execute(sql, params, many, context) with ( caplog.at_level(logging.INFO, logger="django_ox"), - connection.execute_wrapper(refuse_the_first_range), + pytest.raises(DataError, match="division by zero"), + transaction.atomic(), + connection.execute_wrapper(refuse_the_first_batch), ): - built = DatabaseScheduleSource({}, "default").schedules() + DatabaseScheduleSource({}, "default").schedules() assert refused - assert [schedule.name for schedule in built] == ["beside-it"] - assert {r.schedule_pk for r in events(caplog, "schedule_row_skipped")} == { - victim.pk + assert after == [] + assert not events(caplog, "schedule_row_skipped") + # Rolled back by its owner, the connection reads again. + assert OxSchedule.objects.count() == 2 + + +# -- an error the database raised is not a value ------------------------------ + + +def raising_at(table, error): + """ + connection.execute_wrapper() that raises `error` in place of the first + SELECT on `table`. + """ + met = [] + + def wrapper(execute, sql, params, many, context): + if not met and table in sql and sql.lstrip().upper().startswith("SELECT"): + met.append(sql) + raise error + return execute(sql, params, many, context) + + return wrapper + + +@pytest.mark.django_db(transaction=True) +class TestAnErrorTheDatabaseRaisedIsNotPutDownToAValue: + """ + The change marker and a row whose boundary is being moved are read by + Django's own converters, and a value in either that does not convert + fails in this process, once the database has answered. Only such a + failure is the marker's or the row's. An error the database itself + raised over the same statement, a DataError as much as a lock or a + lost connection, says nothing about what is stored: the marker is not + reported as holding a value that cannot be read, and the row is not + left out as one that does not read. + + On PostgreSQL and MySQL the server refuses the read for real, with a + statement it raises a DataError on; SQLite has no such statement, and + the error is raised in the read's place. With no transaction open, as + a worker reads. + """ + + def test_a_refused_read_of_the_marker_keeps_the_last_known_schedules( + self, settings, caplog + ): + settings.TASKS = stored_tasks(SCHEDULE_RECONCILE_INTERVAL=3600) + a_row("first") + worker = Worker(backoff_initial=0) + source = worker._schedule_source + assert [s.name for s in source.schedules()] == ["first"] + # Written since. A marker taken for unreadable has the rows read + # in full, and this one would be among them. + a_row("second") + refusing = Refusing(MARKER) + + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + connection.execute_wrapper(refusing), + ): + fired = worker.dispatch_schedules() + + assert refusing.refused is not None, "the marker was never read" + assert fired == 1, "the schedule it knew of fires" + assert [s.name for s in source._cached] == ["first"] + (unavailable,) = events(caplog, "schedule_source_unavailable") + assert unavailable.msg != stored._MARKER_UNREADABLE + assert "using the last known schedules" in unavailable.getMessage() + assert Refusing.SAYS[connection.vendor] in unavailable.getMessage() + assert not events(caplog, "schedule_row_skipped") + # Answered on the next pass, the marker has moved and the rows are read. + assert [s.name for s in source.schedules()] == ["first", "second"] + + @pytest.mark.parametrize("write", ["create", "change", "pause", "delete"]) + def test_a_refused_read_of_the_marker_ends_the_write_it_was_part_of( + self, settings, write + ): + settings.TASKS = stored_tasks() + row = a_row("first") + marked = OxScheduleChange.objects.get().changed_at + writes = { + "create": lambda: a_row("second"), + "change": lambda: update_schedule(row, every_seconds=120), + "pause": lambda: update_schedule(row, enabled=False), + "delete": lambda: delete_schedule(row), } + refusing = Refusing(MARKER) + + with pytest.raises(DataError) as caught, connection.execute_wrapper(refusing): + writes[write]() + + assert refusing.refused is not None, "the marker was never read" + assert Refusing.SAYS[connection.vendor] in str(caught.value) + # Not written over, and the row's own write went back with it. + assert not [ + sql + for sql in refusing.after + if sql.lstrip().upper().startswith(("UPDATE", "INSERT", "DELETE")) + ] + assert OxScheduleChange.objects.get().changed_at == marked + (kept,) = OxSchedule.objects.all() + assert (kept.name, kept.every_seconds, kept.enabled) == ("first", 60, True) + + def test_a_refused_read_under_the_lock_leaves_the_heal_for_the_next_pass( + self, settings, caplog + ): + source, victim = a_sighting(settings) + boundary = OxSchedule.objects.get(pk=victim.pk).boundary_for + refusing = Refusing("ox_stored_start_time") + + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + connection.execute_wrapper(refusing), + ): + source.schedules() + + assert refusing.refused is not None, "the row was never read" + # The sighting is kept, and nothing says the row does not read. + assert victim.pk in source._needs_heal + assert not events(caplog, "schedule_row_skipped") + (failed,) = events(caplog, "schedule_boundary_heal_failed") + assert type(failed.exc_info[1]) is DataError + assert Refusing.SAYS[connection.vendor] in str(failed.exc_info[1]) + assert OxSchedule.objects.get(pk=victim.pk).boundary_for == boundary + + caplog.clear() + with caplog.at_level(logging.INFO, logger="django_ox"): + source.schedules() + + assert victim.pk not in source._needs_heal + (healed,) = events(caplog, "schedule_boundary_healed") + assert healed.schedule_pk == victim.pk + moved = OxSchedule.objects.get(pk=victim.pk) + assert moved.boundary_for == stored.boundary_digest(moved) != boundary + + def test_a_refused_read_of_the_marker_takes_a_heal_back_with_it( + self, settings, caplog + ): + source, victim = a_sighting(settings) + before = OxSchedule.objects.get(pk=victim.pk) + refusing = Refusing(MARKER) + + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + connection.execute_wrapper(refusing), + ): + source.schedules() + + # The heal writes the boundary and then the marker, in one + # transaction: the boundary went back with the marker's refusal. + assert victim.pk in source._needs_heal + assert events(caplog, "schedule_boundary_heal_failed") + assert not events(caplog, "schedule_row_skipped") + after = OxSchedule.objects.get(pk=victim.pk) + assert (after.boundary_for, after.boundary_generation) == ( + before.boundary_for, + before.boundary_generation, + ) + + @pytest.mark.parametrize( + "error", [ValueError, TypeError, AttributeError, OverflowError] + ) + def test_a_converters_failure_on_the_marker_is_still_the_markers( + self, settings, caplog, error + ): + settings.TASKS = stored_tasks() + a_row("first") + source = DatabaseScheduleSource( + {"SCHEDULE_RECONCILE_INTERVAL": 3600}, "default" + ) + + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + connection.execute_wrapper(raising_at(MARKER, error("not a date"))), + ): + assert [s.name for s in source.schedules()] == ["first"] + + (unreadable,) = events(caplog, "schedule_source_unavailable") + assert unreadable.msg == stored._MARKER_UNREADABLE + + @pytest.mark.parametrize( + "error", + [InterfaceError("connection already closed"), RuntimeError("a fault in code")], + ids=["a-closed-connection", "a-fault-in-code"], + ) + def test_a_failure_that_is_neither_goes_up_from_the_marker_read( + self, settings, caplog, error + ): + """ + Neither a value's nor an error the database raised: a connection + closed under the read, which the dispatch loop takes with the + database's own, and a fault in code, which costs the pass. Each + goes up as it is, and the marker is not reported for it. + """ + settings.TASKS = stored_tasks() + a_row("first") + source = DatabaseScheduleSource({}, "default") + + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + connection.execute_wrapper(raising_at(MARKER, error)), + pytest.raises(type(error)) as caught, + ): + source.schedules() + + assert caught.value is error + assert not events(caplog, "schedule_source_unavailable") + + @pytest.mark.parametrize( + ("error", "the_rows"), + [ + (ValidationError("not a number"), True), + (ValueError("not a number"), True), + (TypeError("not a number"), True), + (InterfaceError("connection already closed"), False), + (RuntimeError("a fault in code"), False), + ], + ids=[ + "ValidationError", + "ValueError", + "TypeError", + "a-closed-connection", + "a-fault-in-code", + ], + ) + def test_in_a_heal_only_a_failure_known_to_be_a_values_is_the_rows( + self, settings, caplog, monkeypatch, error, the_rows + ): + source, victim = a_sighting(settings) + + def fails(row): + raise error + + monkeypatch.setattr(stored, "boundary_digest", fails) + with caplog.at_level(logging.INFO, logger="django_ox"): + if the_rows: + source.schedules() + else: + with pytest.raises(type(error)) as caught: + source.schedules() + assert caught.value is error + + skipped = events(caplog, "schedule_row_skipped") + assert {r.schedule_pk for r in skipped} == ({victim.pk} if the_rows else set()) + assert (victim.pk in source._needs_heal) is not the_rows + assert not events(caplog, "schedule_boundary_heal_failed") + + +# -- a boundary the database will not let a worker move ----------------------- + + +#: What the trigger below says when it refuses a write. +REFUSED_MOVE = "this boundary is not to be moved" + +#: The class each database's refusal of that write reaches Django as. +MOVE_REFUSED_AS = { + "sqlite": IntegrityError, + "postgresql": ProgrammingError, + "mysql": OperationalError, +} + +#: The trigger's name, and on PostgreSQL its function's. +REFUSES_MOVES = "ox_test_refuses_moves" + + +def _statements_refusing_moves_of(pks): + """The trigger as this run's database writes one.""" + named = ", ".join(str(int(pk)) for pk in pks) + on_the_count = f"BEFORE UPDATE OF boundary_generation ON {TABLE}" + if connection.vendor == "postgresql": + function = ( + f"CREATE FUNCTION {REFUSES_MOVES}() RETURNS trigger LANGUAGE plpgsql " + f"AS $$ BEGIN RAISE EXCEPTION '{REFUSED_MOVE}'; END $$" + ) + trigger = ( + f"CREATE TRIGGER {REFUSES_MOVES} {on_the_count} FOR EACH ROW " + f"WHEN (OLD.id IN ({named})) EXECUTE FUNCTION {REFUSES_MOVES}()" + ) + return [function, trigger] + if connection.vendor == "mysql": + # MySQL has no trigger on one column, so this one asks whether the + # write changes the count. + changes_the_count = ( + f"OLD.id IN ({named}) " + "AND NOT (NEW.boundary_generation <=> OLD.boundary_generation)" + ) + refuse = f"SIGNAL SQLSTATE '45000' SET MESSAGE_TEXT = '{REFUSED_MOVE}'" + trigger = ( + f"CREATE TRIGGER {REFUSES_MOVES} BEFORE UPDATE ON {TABLE} FOR EACH ROW " + f"BEGIN IF {changes_the_count} THEN {refuse}; END IF; END" + ) + return [trigger] + trigger = ( + f"CREATE TRIGGER {REFUSES_MOVES} {on_the_count} WHEN OLD.id IN ({named}) " + f"BEGIN SELECT RAISE(ABORT, '{REFUSED_MOVE}'); END" + ) + return [trigger] + + +def _statements_allowing_moves(): + if connection.vendor == "postgresql": + return [ + f"DROP TRIGGER IF EXISTS {REFUSES_MOVES} ON {TABLE}", + f"DROP FUNCTION IF EXISTS {REFUSES_MOVES}()", + ] + return [f"DROP TRIGGER IF EXISTS {REFUSES_MOVES}"] + + +@contextmanager +def refusing_moves_of(*rows): + """ + A database that refuses to let these rows' boundaries be moved, for as + long as the block lasts: a trigger of a project's own on the schedule + table, raising on every write to a named row's count of boundary + writes, which a move always makes. The refusal is the database's own, + on every engine and to whatever process sends the write, a worker + started from the test among them. Reading the rows, locking them and + writing their other columns go through. + + For a test with no transaction around it: the trigger is made and + dropped by statements that commit on their own. + """ + + def run(statements): + with connection.cursor() as cursor: + for statement in statements: + cursor.execute(statement) + + run(_statements_allowing_moves()) + run(_statements_refusing_moves_of([row.pk for row in rows])) + try: + yield + finally: + run(_statements_allowing_moves()) + + +def refused_as(): + """The class this run's database refuses a move as.""" + return MOVE_REFUSED_AS[connection.vendor] + + +def retime_by_sql(row, seconds, count=None): + """ + Change a row's timing by a route that moves no boundary, which is what + leaves its boundary stale, and first its count of boundary writes when + `count` is given. + """ + if count is not None: + write_by_sql(TABLE, "boundary_generation", str(count), row.pk) + write_by_sql(TABLE, "every_seconds", str(seconds), row.pk) + + +def a_worker_beside(settings, *names): + """ + A worker that has read `beside-it` and a row of each name given, all as + they were written: the worker, its source with the clock its reports go + by, and the rows. A row changed by SQL after this is met at the next + dispatch, under its lock. + """ + settings.TASKS = stored_tasks(SCHEDULE_RECONCILE_INTERVAL=3600) + a_row("beside-it") + rows = [a_row(name) for name in names] + worker = Worker(backoff_initial=0) + source = worker._schedule_source + assert len(source.schedules()) == len(rows) + 1 + clock = [0.0] + source._report.clock = lambda: clock[0] + return worker, source, clock, rows + + +def moves_failed(caplog): + return events(caplog, "schedule_boundary_heal_failed") + + +def said_of(caplog, row): + """Every record about one stored row: by its key, its name or its dispatch key.""" + return [ + record + for record in caplog.records + if getattr(record, "schedule_pk", None) == row.pk + or getattr(record, "schedule", None) == row.name + or getattr(record, "schedule_key", None) == f"db:{row.pk}" + ] + + +class MovesTried: + """ + connection.execute_wrapper() that counts, for each row, the moves of its + boundary a worker sent: the UPDATE that adds one to the row's count of + boundary writes, which is the last thing the statement names. + """ + + def __init__(self): + self.of = Counter() + + def __call__(self, execute, sql, params, many, context): + adds_one = f"{connection.ops.quote_name('boundary_generation')} + " + if sql.lstrip().upper().startswith("UPDATE") and adds_one in sql: + self.of[params[-1]] += 1 + return execute(sql, params, many, context) + + +class RefusingTheLockedReadOf: + """ + connection.execute_wrapper() for a database that refuses, every time, + the read of each of `pks` under its lock: the SELECT that names that row + alone. Refused as `Refusing` refuses one read, and counted for each row. + """ + + def __init__(self, *pks): + self.pks = set(pks) + self.refused = Counter() + + def __call__(self, execute, sql, params, many, context): + named = tuple(params or ()) + if ( + "ox_stored_start_time" in sql + and sql.lstrip().upper().startswith("SELECT") + and len(named) == 1 + and named[0] in self.pks + ): + self.refused[named[0]] += 1 + statement = Refusing.STATEMENT.get(connection.vendor) + if statement is None: + raise DataError(Refusing.SAYS["sqlite"]) + return execute(statement, None, many, context) + return execute(sql, params, many, context) + + +@pytest.mark.django_db(transaction=True) +class TestABoundaryTheDatabaseWillNotLetAWorkerMove: + """ + A boundary found stale is moved at the start of the next dispatch pass. + When the database refuses the move, the sighting stays and the move is + tried again on every pass, about once a second, so it is reported as a + dispatch that keeps failing is: with its traceback the first time, then + at most once a ROW_REPORT_INTERVAL with how many times it has failed + since, for each row and for each worker by itself. Once the boundary + moves, or no longer has to, a failure after that is reported in full. + + The failure that lasts is the database refusing the write itself, here + by a trigger on the table that stands until it is dropped + (`refusing_moves_of`). The one that passes is a read under the row's + lock that the database refuses, made to happen on every engine with + `Refusing`. With no transaction open, as a worker reads. + """ + + def test_a_move_the_database_refuses_is_reported_once_and_then_counted( + self, settings, caplog + ): + worker, source, clock, (victim,) = a_worker_beside(settings, "victim") + retime_by_sql(victim, 120) + tried = MovesTried() + + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + connection.execute_wrapper(tried), + ): + with refusing_moves_of(victim): + # Met at dispatch, and the move is tried at the start of each + # pass after that. + assert worker.dispatch_schedules() == 1, "the schedule beside it fires" + assert victim.pk in source._needs_heal + assert not tried.of + for _ in range(6): + worker.dispatch_schedules() + + # Six passes inside one interval: one line, with its traceback. + failed = moves_failed(caplog) + assert [record.exc_info is not None for record in failed] == [True] + (first,) = failed + assert first.msg == stored._HEAL_FAILED + assert first.levelno == logging.WARNING + assert type(first.exc_info[1]) is refused_as() + assert REFUSED_MOVE in str(first.exc_info[1]) + assert (first.schedule_pk, first.error) == ( + victim.pk, + refused_as().__name__, + ) + assert (first.failures, first.suppressed) == (1, 0) + # Nothing else is said of the row, and it is not put down as + # one that does not read. + assert said_of(caplog, victim) == [first] + assert not events(caplog, "schedule_row_skipped") + # Only the reporting is held back: the move was tried each time. + assert tried.of == {victim.pk: 6} + + # Once the interval has passed, one line more, with the count. + clock[0] = stored.ROW_REPORT_INTERVAL + worker.dispatch_schedules() + first, later = moves_failed(caplog) + assert later.msg == stored._HEAL_STILL_FAILING + assert later.exc_info is None + assert later.levelno == logging.WARNING + assert later.args == (victim.pk, 6, refused_as().__name__) + assert (later.schedule_pk, later.error) == ( + victim.pk, + refused_as().__name__, + ) + assert (later.failures, later.suppressed) == (7, 6) + for _ in range(3): + worker.dispatch_schedules() + assert said_of(caplog, victim) == [first, later] + assert tried.of == {victim.pk: 10} + + # Still waiting to be moved, and still not dispatched. + assert victim.pk in source._needs_heal + kept = OxSchedule.objects.get(pk=victim.pk) + assert kept.boundary_generation == 0 + assert kept.boundary_for != stored.boundary_digest(kept) + assert not OxScheduleTick.objects.filter( + schedule_name=f"db:{victim.pk}" + ).exists() + + # The database takes the write again, and the pass after that + # moves the boundary. + caplog.clear() + worker.dispatch_schedules() + (healed,) = events(caplog, "schedule_boundary_healed") + assert healed.schedule_pk == victim.pk + assert not moves_failed(caplog) + assert not events(caplog, "schedule_row_skipped") + assert victim.pk not in source._needs_heal + moved = OxSchedule.objects.get(pk=victim.pk) + assert moved.boundary_for == stored.boundary_digest(moved) + assert moved.boundary_generation == 1 + + # It fails again after that: a new failure, said in full, well + # inside the interval the last line began. + with refusing_moves_of(victim): + retime_by_sql(victim, 180) + source._last_read = None + caplog.clear() + worker.dispatch_schedules() + (again,) = moves_failed(caplog) + assert again.msg == stored._HEAL_FAILED + assert type(again.exc_info[1]) is refused_as() + assert (again.failures, again.suppressed) == (1, 0) + + def test_two_rows_are_each_reported_for_itself(self, settings, caplog): + worker, source, clock, (victim, another) = a_worker_beside( + settings, "victim", "another" + ) + tried = MovesTried() + + def lines(): + return [ + (r.schedule_pk, r.exc_info is not None, r.failures, r.suppressed) + for r in moves_failed(caplog) + ] + + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + connection.execute_wrapper(tried), + refusing_moves_of(victim, another), + ): + retime_by_sql(victim, 120) + worker.dispatch_schedules() + # Two failed moves of the first before the second row is stale. + worker.dispatch_schedules() + worker.dispatch_schedules() + assert len(moves_failed(caplog)) == 1 + assert lines() == [(victim.pk, True, 1, 0)] + # The second, found by a full read, which tries every move that + # is waiting once more when it is done. + retime_by_sql(another, 120) + source._last_read = None + worker.dispatch_schedules() + worker.dispatch_schedules() + assert lines() == [(victim.pk, True, 1, 0), (another.pk, True, 1, 0)] + assert set(source._needs_heal) == {victim.pk, another.pk} + + clock[0] = stored.ROW_REPORT_INTERVAL + worker.dispatch_schedules() + later = {record.schedule_pk: record for record in moves_failed(caplog)[2:]} + assert len(moves_failed(caplog)) == 4 + + # Each row's line carries that row's own count: every move the + # database refused for it, and those since its first line. + assert tried.of == {victim.pk: 6, another.pk: 3} + for row in (victim, another): + assert later[row.pk].exc_info is None + assert later[row.pk].failures == tried.of[row.pk] + assert later[row.pk].suppressed == tried.of[row.pk] - 1 + assert not events(caplog, "schedule_row_skipped") + + def test_a_row_beside_it_is_moved_and_the_other_schedules_fire( + self, settings, caplog + ): + worker, source, _clock, (victim, another) = a_worker_beside( + settings, "victim", "another" + ) + retime_by_sql(victim, 120) + retime_by_sql(another, 120) + + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + refusing_moves_of(victim), + ): + assert worker.dispatch_schedules() == 1, "the schedule beside them fires" + assert set(source._needs_heal) == {victim.pk, another.pk} + worker.dispatch_schedules() + + (failed,) = moves_failed(caplog) + assert failed.schedule_pk == victim.pk + (healed,) = events(caplog, "schedule_boundary_healed") + assert healed.schedule_pk == another.pk + assert set(source._needs_heal) == {victim.pk} + moved = OxSchedule.objects.get(pk=another.pk) + assert moved.boundary_for == stored.boundary_digest(moved) + assert OxScheduleTick.objects.filter( + schedule_name=f"db:{OxSchedule.objects.get(name='beside-it').pk}", + task__isnull=False, + ).exists() + + def test_each_worker_reports_for_itself(self, settings, caplog): + worker, _source, _clock, (victim,) = a_worker_beside(settings, "victim") + second = Worker(backoff_initial=0) + assert len(second._schedule_source.schedules()) == 2 + retime_by_sql(victim, 120) + + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + refusing_moves_of(victim), + ): + for _ in range(3): + worker.dispatch_schedules() + second.dispatch_schedules() + + # The row has failed four times, twice for each worker, and each + # worker has said so once. + assert len(moves_failed(caplog)) == 2 + assert [ + (r.schedule_pk, r.exc_info is not None, r.failures) + for r in moves_failed(caplog) + ] == [(victim.pk, True, 1), (victim.pk, True, 1)] + + def test_a_move_that_fails_once_and_then_succeeds_is_one_line_and_one_move( + self, settings, caplog + ): + source, victim = a_sighting(settings) + refusing = Refusing("ox_stored_start_time") + + with caplog.at_level(logging.INFO, logger="django_ox"): + with connection.execute_wrapper(refusing): + source.schedules() + assert refusing.refused is not None, "the row was never read" + for _ in range(3): + source.schedules() + + (failed,) = moves_failed(caplog) + assert failed.msg == stored._HEAL_FAILED + assert Refusing.SAYS[connection.vendor] in str(failed.exc_info[1]) + assert (failed.schedule_pk, failed.error) == (victim.pk, "DataError") + assert (failed.failures, failed.suppressed) == (1, 0) + (healed,) = events(caplog, "schedule_boundary_healed") + assert said_of(caplog, victim) == [failed, healed] + assert victim.pk not in source._needs_heal + + def test_a_read_under_the_lock_refused_on_every_pass_is_counted_too( + self, settings, caplog + ): + source, victim = a_sighting(settings) + clock = [0.0] + source._report.clock = lambda: clock[0] + + def a_pass_the_database_refuses(nth=1): + refusing = Refusing("ox_stored_start_time", nth=nth) + with connection.execute_wrapper(refusing): + source.schedules() + assert refusing.refused is not None, "the row was never read" + + with caplog.at_level(logging.INFO, logger="django_ox"): + for _ in range(5): + a_pass_the_database_refuses() + failed = moves_failed(caplog) + assert [record.exc_info is not None for record in failed] == [True] + (first,) = failed + assert type(first.exc_info[1]) is DataError + assert Refusing.SAYS[connection.vendor] in str(first.exc_info[1]) + assert (first.failures, first.suppressed) == (1, 0) + assert said_of(caplog, victim) == [first] + assert victim.pk in source._needs_heal + + clock[0] = stored.ROW_REPORT_INTERVAL + a_pass_the_database_refuses() + first, later = moves_failed(caplog) + assert later.msg == stored._HEAL_STILL_FAILING + assert later.exc_info is None + assert later.args == (victim.pk, 5, "DataError") + assert (later.failures, later.suppressed) == (6, 5) + assert not events(caplog, "schedule_row_skipped") + + # The database answers: the boundary moves, and that is said. + caplog.clear() + source.schedules() + (healed,) = events(caplog, "schedule_boundary_healed") + assert healed.schedule_pk == victim.pk + assert not moves_failed(caplog) + assert victim.pk not in source._needs_heal + + # Changed by SQL again and refused again: a new failure, said in + # full. A full read finds the row stale and tries the move at + # once, so the read under the lock is the second to name the row. + retime_by_sql(victim, 180) + source._last_read = None + caplog.clear() + a_pass_the_database_refuses(nth=2) + (again,) = moves_failed(caplog) + assert again.msg == stored._HEAL_FAILED + assert again.exc_info is not None + assert (again.failures, again.suppressed) == (1, 0) + assert victim.pk in source._needs_heal + + def test_of_two_rows_refused_at_once_the_one_that_moves_ends_only_its_own_count( + self, settings, caplog + ): + worker, source, clock, (victim, another) = a_worker_beside( + settings, "victim", "another" + ) + retime_by_sql(victim, 120) + retime_by_sql(another, 120) + assert worker.dispatch_schedules() == 1, "the schedule beside them fires" + assert set(source._needs_heal) == {victim.pk, another.pk} + both = RefusingTheLockedReadOf(victim.pk, another.pk) + one = RefusingTheLockedReadOf(victim.pk) + + with caplog.at_level(logging.INFO, logger="django_ox"): + with connection.execute_wrapper(both): + for _ in range(3): + source.schedules() + assert len(moves_failed(caplog)) == 2 + assert [ + (r.schedule_pk, r.exc_info is not None, r.failures, r.suppressed) + for r in moves_failed(caplog) + ] == [(victim.pk, True, 1, 0), (another.pk, True, 1, 0)] + + # The database answers for one of them. It is moved, and the + # other is still refused and still counted. + with connection.execute_wrapper(one): + for _ in range(2): + source.schedules() + (healed,) = events(caplog, "schedule_boundary_healed") + assert healed.schedule_pk == another.pk + assert set(source._needs_heal) == {victim.pk} + assert len(moves_failed(caplog)) == 2 + + clock[0] = stored.ROW_REPORT_INTERVAL + with connection.execute_wrapper(one): + source.schedules() + + _first, _other, later = moves_failed(caplog) + refused = both.refused[victim.pk] + one.refused[victim.pk] + assert refused > both.refused[another.pk] == 3 + assert later.schedule_pk == victim.pk + assert later.exc_info is None + assert (later.failures, later.suppressed) == (refused, refused - 1) + assert not events(caplog, "schedule_row_skipped") + + def test_a_row_gone_while_its_move_kept_failing_is_forgotten( + self, settings, caplog + ): + source, victim = a_sighting(settings) + + with caplog.at_level(logging.INFO, logger="django_ox"): + with connection.execute_wrapper(Refusing("ox_stored_start_time")): + source.schedules() + assert len(moves_failed(caplog)) == 1 + OxSchedule.objects.filter(pk=victim.pk).delete() + source.schedules() + + # Settled with nothing to move, and nothing is kept about the row. + assert victim.pk not in source._needs_heal + assert len(moves_failed(caplog)) == 1 + assert not events(caplog, "schedule_boundary_healed") + assert ("heal", victim.pk) not in source._report._failing + + @pytest.mark.parametrize(("vendor", "column", "literal", "why"), WHILE_RUNNING) + def test_so_is_a_row_that_stops_reading_while_its_move_kept_failing( + self, settings, caplog, vendor, column, literal, why + ): + only_on(vendor, why) + source, victim = a_sighting(settings) + + with caplog.at_level(logging.INFO, logger="django_ox"): + with connection.execute_wrapper(Refusing("ox_stored_start_time")): + source.schedules() + assert len(moves_failed(caplog)) == 1 + write_by_sql(TABLE, column, literal, victim.pk) + source.schedules() + + # Left out as a row that does not read: there is no boundary to + # move, and nothing is kept about the moves that failed. + assert victim.pk not in source._needs_heal + (skipped,) = events(caplog, "schedule_row_skipped") + assert (skipped.schedule_pk, skipped.fields) == (victim.pk, [column]) + assert len(moves_failed(caplog)) == 1 + assert ("heal", victim.pk) not in source._report._failing + + def test_and_a_row_whose_fields_the_boundary_cannot_be_taken_from( + self, settings, caplog, monkeypatch + ): + source, victim = a_sighting(settings) + + def refuses(row): + raise ValidationError("not a number") + + with caplog.at_level(logging.INFO, logger="django_ox"): + with connection.execute_wrapper(Refusing("ox_stored_start_time")): + source.schedules() + assert len(moves_failed(caplog)) == 1 + monkeypatch.setattr(stored, "boundary_digest", refuses) + source.schedules() + + assert victim.pk not in source._needs_heal + (skipped,) = events(caplog, "schedule_row_skipped") + assert skipped.schedule_pk == victim.pk + assert len(moves_failed(caplog)) == 1 + assert ("heal", victim.pk) not in source._report._failing + + +# -- a count of boundary writes that cannot be raised --------------------------- + + +def count_as_stored(row): + """A row's count of boundary writes as the database holds it, and its type there.""" + kind = "typeof(boundary_generation)" if connection.vendor == "sqlite" else "NULL" + statement = f"SELECT boundary_generation, {kind} FROM {TABLE} WHERE id = %s" # noqa: S608 + with connection.cursor() as cursor: + cursor.execute(statement, [row.pk]) + return cursor.fetchone() + + +def a_whole_number_still(): + """How SQLite says a value is kept as an integer; the others have no other way.""" + return "integer" if connection.vendor == "sqlite" else None + + +def full(): + """What a worker says of a row whose count is the most its column can hold.""" + return ( + f"its boundary_generation holds {largest_count()}, the most its column " + "can hold, so the count cannot be raised" + ) + + +def assert_named_once_for_its_count(caplog, row): + (skipped,) = events(caplog, "schedule_row_skipped") + assert skipped.msg == stored._SKIPPING + assert skipped.levelno == logging.WARNING + assert (skipped.schedule, skipped.schedule_pk) == (row.name, row.pk) + assert skipped.fields == ["boundary_generation"] + assert skipped.reason == full() + assert skipped.exc_info is None + # Nothing else is said of the row. + assert said_of(caplog, row) == [skipped] + return skipped + + +@pytest.mark.django_db(transaction=True) +class TestACountOfBoundaryWritesAtItsMaximum: + """ + A row whose count of boundary writes is the most its column can hold is + one whose boundary cannot be moved: the move adds one to the count, and + PostgreSQL and MySQL refuse that write every time it is tried, while + SQLite keeps the sum as a float, a count that no longer reads. SQL writes + such a count, or one below it, from which the next move reaches it. + + A worker leaves the row out as it leaves out any row that does not + read, named by that field and said once, and tries no move of its + boundary however stale the boundary is. Lowering the count by SQL, or + deleting the row, is what ends it. With no transaction open, as a + worker reads. + """ + + @pytest.mark.parametrize("stale", [True, False], ids=["stale", "current"]) + def test_met_at_a_full_read_it_is_named_once_and_no_move_is_tried( + self, settings, caplog, stale + ): + worker, source, clock, (victim,) = a_worker_beside(settings, "victim") + if stale: + retime_by_sql(victim, 120) + write_by_sql(TABLE, "boundary_generation", str(largest_count()), victim.pk) + as_sql_left_it = OxSchedule.objects.filter(pk=victim.pk).values().get() + tried = MovesTried() + + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + connection.execute_wrapper(tried), + ): + for _ in range(6): + # Every pass reads every row again. + source._last_read = None + worker.dispatch_schedules() + + assert_named_once_for_its_count(caplog, victim) + assert not moves_failed(caplog) + assert not events(caplog, "schedule_boundary_healed") + assert not tried.of + assert victim.pk not in source._needs_heal + + # Past the interval, the one line a row still left out gets. + clock[0] = stored.ROW_REPORT_INTERVAL + source._last_read = None + worker.dispatch_schedules() + _first, later = events(caplog, "schedule_row_skipped") + assert later.msg == stored._STILL_SKIPPING + assert later.fields == ["boundary_generation"] + assert not tried.of + + # The row is as SQL left it, its count a whole number still. + assert OxSchedule.objects.filter(pk=victim.pk).values().get() == as_sql_left_it + assert count_as_stored(victim) == (largest_count(), a_whole_number_still()) + # It is not dispatched, and the schedule beside it is. + assert [s.name for s in source._cached] == ["beside-it"] + assert not OxScheduleTick.objects.filter( + schedule_name=f"db:{victim.pk}" + ).exists() + assert OxScheduleTick.objects.filter( + schedule_name=f"db:{OxSchedule.objects.get(name='beside-it').pk}", + task__isnull=False, + ).exists() + + def test_met_at_dispatch_it_is_named_and_no_move_is_left_waiting( + self, settings, caplog + ): + worker, source, _clock, (victim,) = a_worker_beside(settings, "victim") + retime_by_sql(victim, 120, count=largest_count()) + tried = MovesTried() + + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + connection.execute_wrapper(tried), + ): + # Under its lock, before any full read has seen the change. + assert worker.dispatch_schedules() == 1, "the schedule beside it fires" + assert victim.pk not in source._needs_heal + for _ in range(5): + worker.dispatch_schedules() + + assert_named_once_for_its_count(caplog, victim) + assert not moves_failed(caplog) + assert not events(caplog, "schedule_boundary_healed") + assert not tried.of + assert victim.pk not in source._needs_heal + # Out of the snapshot, so it is not locked again on every pass. + assert [s.name for s in source._cached] == ["beside-it"] + assert count_as_stored(victim) == (largest_count(), a_whole_number_still()) + + def test_a_move_already_waiting_is_given_up_without_being_tried( + self, settings, caplog + ): + worker, source, _clock, (victim,) = a_worker_beside(settings, "victim") + retime_by_sql(victim, 120) + assert worker.dispatch_schedules() == 1, "the schedule beside it fires" + assert victim.pk in source._needs_heal + write_by_sql(TABLE, "boundary_generation", str(largest_count()), victim.pk) + tried = MovesTried() + + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + connection.execute_wrapper(tried), + ): + for _ in range(5): + worker.dispatch_schedules() + + assert_named_once_for_its_count(caplog, victim) + assert not moves_failed(caplog) + assert not events(caplog, "schedule_boundary_healed") + assert not tried.of + assert victim.pk not in source._needs_heal + assert ("heal", victim.pk) not in source._report._failing + assert count_as_stored(victim) == (largest_count(), a_whole_number_still()) + + def test_one_below_the_maximum_the_heal_takes_the_count_to_it( + self, settings, caplog + ): + """ + SQL can leave the count one below the maximum. The move of a stale + boundary adds one and succeeds, and the row it leaves is the one + above: at its maximum, left out at the next read, and not one a + later change can go on from. + """ + worker, source, _clock, (victim,) = a_worker_beside(settings, "victim") + retime_by_sql(victim, 120, count=largest_count() - 1) + + with caplog.at_level(logging.INFO, logger="django_ox"): + assert worker.dispatch_schedules() == 1, "the schedule beside it fires" + assert victim.pk in source._needs_heal + assert not events(caplog, "schedule_boundary_healed") + worker.dispatch_schedules() + (healed,) = events(caplog, "schedule_boundary_healed") + assert healed.schedule_pk == victim.pk + assert not moves_failed(caplog) + assert count_as_stored(victim) == (largest_count(), a_whole_number_still()) + + # The write succeeded; what it left is read as a full count. + for _ in range(4): + source._last_read = None + worker.dispatch_schedules() + + (skipped,) = events(caplog, "schedule_row_skipped") + assert skipped.fields == ["boundary_generation"] + assert skipped.reason == full() + assert count_as_stored(victim) == (largest_count(), a_whole_number_still()) + assert [s.name for s in source._cached] == ["beside-it"] + + def test_paused_it_is_left_out_without_a_word_and_still_not_moved( + self, settings, caplog + ): + worker, source, _clock, (victim,) = a_worker_beside(settings, "victim") + retime_by_sql(victim, 120, count=largest_count()) + write_by_sql(TABLE, "enabled", "FALSE", victim.pk) + tried = MovesTried() + + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + connection.execute_wrapper(tried), + ): + for _ in range(4): + source._last_read = None + worker.dispatch_schedules() + + assert said_of(caplog, victim) == [] + assert not tried.of + assert victim.pk not in source._needs_heal + assert count_as_stored(victim) == (largest_count(), a_whole_number_still()) + + def test_two_such_rows_are_each_named_and_the_others_fire(self, settings, caplog): + worker, source, _clock, (victim, another) = a_worker_beside( + settings, "victim", "another" + ) + for row in (victim, another): + retime_by_sql(row, 120, count=largest_count()) + tried = MovesTried() + + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + connection.execute_wrapper(tried), + ): + assert worker.dispatch_schedules() == 1, "the schedule beside them fires" + for _ in range(3): + source._last_read = None + worker.dispatch_schedules() + + skipped = events(caplog, "schedule_row_skipped") + assert [(r.schedule_pk, r.fields) for r in skipped] == [ + (victim.pk, ["boundary_generation"]), + (another.pk, ["boundary_generation"]), + ] + assert not moves_failed(caplog) + assert not tried.of + assert not source._needs_heal + + def test_one_below_it_the_boundary_is_moved_once_and_the_row_is_then_full( + self, settings, caplog + ): + worker, _source, _clock, (victim,) = a_worker_beside(settings, "victim") + retime_by_sql(victim, 120, count=largest_count() - 1) + tried = MovesTried() + + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + connection.execute_wrapper(tried), + ): + for _ in range(5): + worker.dispatch_schedules() + + # A count below the most reads as any count does: the boundary is + # moved, which is the last write the count has room for. + (healed,) = events(caplog, "schedule_boundary_healed") + assert healed.schedule_pk == victim.pk + assert tried.of == {victim.pk: 1} + assert not moves_failed(caplog) + (skipped,) = events(caplog, "schedule_row_skipped") + assert (skipped.schedule_pk, skipped.fields) == ( + victim.pk, + ["boundary_generation"], + ) + assert skipped.reason == full() + assert count_as_stored(victim) == (largest_count(), a_whole_number_still()) + + def test_with_the_count_lowered_by_sql_the_row_is_moved_and_built_again( + self, settings, caplog + ): + worker, source, _clock, (victim,) = a_worker_beside(settings, "victim") + retime_by_sql(victim, 120, count=largest_count()) + with caplog.at_level(logging.INFO, logger="django_ox"): + source._last_read = None + worker.dispatch_schedules() + assert_named_once_for_its_count(caplog, victim) + + write_by_sql(TABLE, "boundary_generation", "5", victim.pk) + source._last_read = None + caplog.clear() + worker.dispatch_schedules() + + # Found stale by the read that could read it again, and moved by it. + (healed,) = events(caplog, "schedule_boundary_healed") + assert healed.schedule_pk == victim.pk + assert not events(caplog, "schedule_row_skipped") + assert not moves_failed(caplog) + moved = OxSchedule.objects.get(pk=victim.pk) + assert moved.boundary_for == stored.boundary_digest(moved) + assert moved.boundary_generation == 6 + assert sorted(s.name for s in source._cached) == ["beside-it", "victim"] + + # Full once more: a row that was built again is said in full again. + write_by_sql(TABLE, "boundary_generation", str(largest_count()), victim.pk) + source._last_read = None + caplog.clear() + worker.dispatch_schedules() + assert_named_once_for_its_count(caplog, victim) + + def test_on_sqlite_a_count_that_is_already_a_float_is_left_out_as_it_was( + self, settings, caplog + ): + only_on("sqlite", "SQLite keeps a number past its largest integer as a float") + worker, source, _clock, (victim,) = a_worker_beside(settings, "victim") + # One more than SQLite's largest integer, which is what adding one to + # a full count left behind. + retime_by_sql(victim, 120, count=largest_count() + 1) + tried = MovesTried() + + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + connection.execute_wrapper(tried), + ): + assert worker.dispatch_schedules() == 1, "the schedule beside it fires" + for _ in range(3): + source._last_read = None + worker.dispatch_schedules() + + (skipped,) = events(caplog, "schedule_row_skipped") + assert skipped.schedule_pk == victim.pk + assert skipped.fields == ["boundary_generation"] + assert skipped.reason.endswith("which is not a whole number") + assert not moves_failed(caplog) + assert not events(caplog, "schedule_boundary_healed") + assert not tried.of + assert victim.pk not in source._needs_heal + assert count_as_stored(victim) == (float(largest_count() + 1), "real") + assert [s.name for s in source._cached] == ["beside-it"] # -- how it is said ---------------------------------------------------------- @@ -902,6 +2133,24 @@ def test_a_name_is_printed_safely(self, settings, caplog): assert record.schedule == stored._printable(hostile) assert record.schedule.isprintable() + def test_a_name_is_printed_safely_by_a_worker_that_dispatches_it( + self, settings, caplog + ): + # Stored through the write function, with no SQL, on a row that + # reads and runs: a worker names it on every tick it dispatches. + settings.TASKS = stored_tasks() + hostile = "nightly\r\nCRITICAL forged line\x1b[2J" + a_row(hostile) + with caplog.at_level(logging.INFO, logger="django_ox"): + Worker(backoff_initial=0).dispatch_schedules() + (record,) = events(caplog, "schedule_dispatched") + line = record.getMessage() + assert line.isprintable() + assert "nightly\\r\\nCRITICAL forged line" in line + assert record.schedule == stored._printable(hostile) + assert record.schedule.isprintable() + assert OxTask.objects.count() == 1 + def test_a_long_name_and_reason_are_cut(self, settings, caplog): only_on("sqlite", "SQLite keeps a name longer than its column") settings.TASKS = stored_tasks() @@ -924,6 +2173,94 @@ def test_the_printable_form(self): assert stored._printable("x" * 10, limit=8) == "xxxxx..." +@pytest.mark.django_db +class TestASkipNamesTheFieldsAtFault: + """ + `schedule_row_skipped` carries the fields whose values did not read as + a list of their names, beside the reason that says the same in a + sentence. Always a list, and empty where no field is at fault. + """ + + @pytest.mark.parametrize(("vendor", "column", "literal", "why"), UNREADABLE) + def test_at_the_full_read(self, settings, caplog, vendor, column, literal, why): + only_on(vendor, why) + settings.TASKS = stored_tasks() + victim = a_row("victim") + write_by_sql(TABLE, column, literal, victim.pk) + with caplog.at_level(logging.INFO, logger="django_ox"): + DatabaseScheduleSource({}, "default").schedules() + (skipped,) = events(caplog, "schedule_row_skipped") + assert type(skipped.fields) is list + assert skipped.fields == [column] + assert skipped.schedule_pk == victim.pk + assert skipped.reason.startswith(f"its {column} ") + + @pytest.mark.parametrize(("vendor", "column", "literal", "why"), WHILE_RUNNING) + def test_at_the_read_under_the_lock( + self, settings, caplog, vendor, column, literal, why + ): + only_on(vendor, why) + settings.TASKS = stored_tasks(SCHEDULE_RECONCILE_INTERVAL=3600) + victim = a_row("victim") + worker = Worker(backoff_initial=0) + assert len(worker._schedule_source.schedules()) == 1 + write_by_sql(TABLE, column, literal, victim.pk) + with caplog.at_level(logging.INFO, logger="django_ox"): + assert worker.dispatch_schedules() == 0 + (skipped,) = events(caplog, "schedule_row_skipped") + assert skipped.fields == [column] + assert skipped.schedule_pk == victim.pk + + @pytest.mark.parametrize(("vendor", "column", "literal", "why"), WHILE_RUNNING) + def test_two_fields_are_named_in_the_models_order( + self, settings, caplog, vendor, column, literal, why + ): + only_on(vendor, why) + settings.TASKS = stored_tasks() + victim = a_row("victim") + # The end, and the start before it: every engine's own value is one + # either column keeps. + write_by_sql(TABLE, "end_time", literal, victim.pk) + write_by_sql(TABLE, "start_time", literal, victim.pk) + with caplog.at_level(logging.INFO, logger="django_ox"): + DatabaseScheduleSource({}, "default").schedules() + (skipped,) = events(caplog, "schedule_row_skipped") + assert skipped.fields == ["start_time", "end_time"] + assert skipped.reason.startswith("its start_time ") + assert "; end_time " in skipped.reason + + def test_a_row_that_reads_and_cannot_be_built_names_none(self, settings, caplog): + settings.TASKS = stored_tasks() + victim = a_row("victim") + write_by_sql(TABLE, "task_key", "'only.in.new.code'", victim.pk) + with caplog.at_level(logging.INFO, logger="django_ox"): + DatabaseScheduleSource({}, "default").schedules() + (skipped,) = events(caplog, "schedule_row_skipped") + assert skipped.fields == [] + assert skipped.schedule_pk == victim.pk + assert "is not registered as a schedulable task" in skipped.reason + + def test_a_later_line_about_the_row_carries_them_too(self, settings, caplog): + only_on("sqlite", "SQLite keeps text in an integer column") + settings.TASKS = stored_tasks() + victim = a_row("victim") + write_by_sql(TABLE, "every_seconds", "'abc'", victim.pk) + source = DatabaseScheduleSource( + {"SCHEDULE_RECONCILE_INTERVAL": 0.001}, "default" + ) + clock = [0.0] + source._report.clock = lambda: clock[0] + with caplog.at_level(logging.INFO, logger="django_ox"): + source.schedules() + clock[0] = stored.ROW_REPORT_INTERVAL + source._last_read = None + source.schedules() + first, later = events(caplog, "schedule_row_skipped") + assert (first.msg, later.msg) == (stored._SKIPPING, stored._STILL_SKIPPING) + assert first.fields == later.fields == ["every_seconds"] + assert first.reason == later.reason + + # -- the dispatch pass ------------------------------------------------------- @@ -1158,3 +2495,5 @@ def test_the_messages_name_their_placeholders(): assert stored._SKIPPING.count("%s") == 2 assert stored._STILL_SKIPPING.count("%") == 3 assert stored._MARKER_UNREADABLE.count("%s") == 1 + assert stored._HEAL_FAILED.count("%") == 1 + assert stored._HEAL_STILL_FAILING.count("%") == 3 diff --git a/tests/test_stored_source_integrity.py b/tests/test_stored_source_integrity.py new file mode 100644 index 0000000..83b6ade --- /dev/null +++ b/tests/test_stored_source_integrity.py @@ -0,0 +1,233 @@ +""" +A stored row that holds a value its field does not hold is left out and +named, never dispatched from what a converter made of it. + +SQLite keeps whatever it is given, and Django's SQLite converters read +some of it as something else without a word: a start or an end that is +text and not a date reads as None, and an `enabled` of 2 or 'abc' reads as +False. A schedule built from that has no activation boundary, no end, or +a pause nobody made. The worker's full read of the rows and its read of +one row under its lock at dispatch both decode each value instead, and +leave such a row out with `schedule_row_skipped` naming the field. A row +that really is paused stays quiet, and an end that really is NULL still +means the schedule never ends. + +A row whose task_key this deployment does not register is left out with +that said in so many words. +""" + +import logging +from datetime import timedelta + +import pytest +from django import forms +from django.db import connection +from django.utils import timezone + +from django_ox.models import OxSchedule, OxScheduleTick, OxTask +from django_ox.registry import ArgsForm, ScheduleKind, register +from django_ox.stored import create_schedule +from django_ox.worker import Worker + +from . import tasks +from .test_stored_read import only_on, set_column + +SQLITE_ONLY = "SQLite keeps this, and its converter reads it as something else" + +#: (engine, column, SQL literal), each a value the read must refuse. +MISREAD = [ + pytest.param("sqlite", "start_time", "'banana'", id="sqlite-start-text"), + pytest.param( + "sqlite", "start_time", "'10000-01-01 00:00:00'", id="sqlite-start-year-10000" + ), + pytest.param("sqlite", "end_time", "'banana'", id="sqlite-end-text"), + pytest.param( + "sqlite", "end_time", "'10000-01-01 00:00:00'", id="sqlite-end-year-10000" + ), + pytest.param("sqlite", "enabled", "2", id="sqlite-enabled-2"), + pytest.param("sqlite", "enabled", "'abc'", id="sqlite-enabled-text"), + pytest.param("mysql", "enabled", "2", id="mysql-enabled-2"), +] + + +class RegionArgs(ArgsForm): + """A form whose own clean raises KeyError, as a lookup in one might.""" + + label = forms.CharField() + + def clean(self): + raise KeyError("region") + + +@pytest.fixture(autouse=True) +def _registry(monkeypatch): + monkeypatch.setattr("django_ox.registry._registry", {}) + monkeypatch.setattr("django_ox.registry._discovered", True) + register(ScheduleKind(key="labelled", task=tasks.labelled)) + + +@pytest.fixture +def stored(settings): + settings.TASKS = { + "default": { + "BACKEND": "django_ox.backend.OxBackend", + "QUEUES": ["default", "emails"], + "OPTIONS": { + "SCHEDULE_SOURCE": "django_ox.stored.DatabaseScheduleSource", + "SCHEDULE_RECONCILE_INTERVAL": 3600, + }, + } + } + + +def a_row(name): + """Every minute since ten minutes ago, so a tick is due on every pass.""" + return create_schedule( + name=name, + task_key="labelled", + trigger="cron", + cron="* * * * *", + arguments={"label": name}, + start_time=timezone.now() - timedelta(minutes=10), + end_time=timezone.now() + timedelta(days=1), + ) + + +def events(caplog, name): + return [r for r in caplog.records if getattr(r, "event", None) == name] + + +def fired(): + return sorted(task.kwargs["label"] for task in OxTask.objects.all()) + + +@pytest.mark.django_db +@pytest.mark.usefixtures("stored") +class TestAValueTheConverterWouldMisread: + @pytest.mark.parametrize(("vendor", "column", "literal"), MISREAD) + def test_the_full_read_leaves_the_row_out_and_names_the_field( + self, caplog, vendor, column, literal + ): + only_on(vendor, SQLITE_ONLY) + a_row("beside-it") + victim = a_row("victim") + set_column(victim.pk, column, literal) + worker = Worker(backoff_initial=0) + with caplog.at_level(logging.INFO, logger="django_ox"): + assert worker.dispatch_schedules() == 1 + assert fired() == ["beside-it"] + assert not OxScheduleTick.objects.filter( + schedule_name=f"db:{victim.pk}" + ).exists() + (skipped,) = events(caplog, "schedule_row_skipped") + assert (skipped.schedule, skipped.schedule_pk) == ("victim", victim.pk) + assert skipped.reason.startswith(f"its {column} holds ") + # It still exists, so its report and its key are kept. + assert f"db:{victim.pk}" in worker._schedule_source._stored_keys() + + @pytest.mark.parametrize(("vendor", "column", "literal"), MISREAD) + def test_the_read_under_the_lock_at_dispatch_leaves_it_out_too( + self, caplog, vendor, column, literal + ): + only_on(vendor, SQLITE_ONLY) + a_row("beside-it") + victim = a_row("victim") + worker = Worker(backoff_initial=0) + # The snapshot holds the row as it was; the value is changed after. + assert len(worker._schedule_source.schedules()) == 2 + set_column(victim.pk, column, literal) + with caplog.at_level(logging.INFO, logger="django_ox"): + assert worker.dispatch_schedules() == 1 + assert fired() == ["beside-it"] + (skipped,) = events(caplog, "schedule_row_skipped") + assert skipped.schedule_pk == victim.pk + assert skipped.reason.startswith(f"its {column} holds ") + assert not events(caplog, "schedule_dispatch_error") + assert [s.key for s in worker._schedule_source._cached] == [ + f"db:{OxSchedule.objects.get(name='beside-it').pk}" + ] + + def test_an_end_that_is_null_still_never_ends(self, caplog): + victim = a_row("no-end") + set_column(victim.pk, "end_time", "NULL") + with caplog.at_level(logging.INFO, logger="django_ox"): + assert Worker(backoff_initial=0).dispatch_schedules() == 1 + assert fired() == ["no-end"] + assert not events(caplog, "schedule_row_skipped") + + @pytest.mark.parametrize(("literal", "fires"), [("0", False), ("1", True)]) + def test_enabled_0_and_1_are_paused_and_running(self, caplog, literal, fires): + victim = a_row("victim") + set_column( + victim.pk, + "enabled", + literal + if connection.vendor != "postgresql" + else {"0": "FALSE", "1": "TRUE"}[literal], + ) + with caplog.at_level(logging.INFO, logger="django_ox"): + Worker(backoff_initial=0).dispatch_schedules() + assert fired() == (["victim"] if fires else []) + assert not events(caplog, "schedule_row_skipped"), "a pause is not a skip" + + def test_a_paused_row_with_a_value_that_does_not_read_stays_quiet(self, caplog): + only_on("sqlite", SQLITE_ONLY) + victim = a_row("victim") + set_column(victim.pk, "enabled", "0") + set_column(victim.pk, "start_time", "'banana'") + with caplog.at_level(logging.INFO, logger="django_ox"): + assert Worker(backoff_initial=0).dispatch_schedules() == 0 + assert not events(caplog, "schedule_row_skipped") + + +@pytest.mark.django_db +@pytest.mark.usefixtures("stored") +class TestATaskKeyThisDeploymentDoesNotRegister: + def test_the_reason_says_it_is_not_registered(self, caplog): + a_row("beside-it") + victim = a_row("victim") + set_column(victim.pk, "task_key", "'only.in.newer.code'") + with caplog.at_level(logging.INFO, logger="django_ox"): + assert Worker(backoff_initial=0).dispatch_schedules() == 1 + assert fired() == ["beside-it"] + (skipped,) = events(caplog, "schedule_row_skipped") + assert skipped.schedule_pk == victim.pk + assert skipped.reason == ( + "its task_key 'only.in.newer.code' is not registered as a " + "schedulable task in this deployment" + ) + assert skipped.getMessage() == ( + f"Skipping stored schedule victim (pk {victim.pk}): {skipped.reason}" + ) + + def test_a_key_that_cannot_print_is_escaped(self, caplog): + victim = a_row("victim") + OxSchedule.objects.filter(pk=victim.pk).update(task_key="bad\x1b[2Jkey") + with caplog.at_level(logging.INFO, logger="django_ox"): + Worker(backoff_initial=0).dispatch_schedules() + (skipped,) = events(caplog, "schedule_row_skipped") + assert "\x1b" not in skipped.reason + assert "not registered as a schedulable task" in skipped.reason + + def test_a_key_error_from_the_task_s_form_is_not_called_a_registry_miss( + self, caplog + ): + register(ScheduleKind(key="regional", task=tasks.labelled, form=RegionArgs)) + a_row("beside-it") + now = timezone.now() + victim = OxSchedule.objects.create( + name="victim", + task_key="regional", + trigger="cron", + cron="* * * * *", + arguments={"label": "victim"}, + start_time=now - timedelta(minutes=10), + created_at=now, + updated_at=now, + ) + with caplog.at_level(logging.INFO, logger="django_ox"): + assert Worker(backoff_initial=0).dispatch_schedules() == 1 + (skipped,) = events(caplog, "schedule_row_skipped") + assert skipped.schedule_pk == victim.pk + assert "not registered" not in skipped.reason + assert skipped.reason == "'region'" diff --git a/tests/test_tick_history.py b/tests/test_tick_history.py new file mode 100644 index 0000000..f1dfca7 --- /dev/null +++ b/tests/test_tick_history.py @@ -0,0 +1,799 @@ +""" +A schedule whose tick history holds a value that does not read is skipped, +and every other schedule in the pass is dispatched. + +The tick log is read twice on the way to a dispatch: the newest tick of +every schedule in the pass, one grouped statement per slice of keys, and, +for a settings schedule with nothing inside the pass's bound, the earliest +tick, which decides whether this pass is its first sighting. A value in +either that Django's converter cannot turn into a datetime (PostgreSQL's +year 10000, 'infinity' and '-infinity', a date SQLite holds that does not +exist or text that is not a date, a MySQL zero date) belongs to the one +schedule whose key the tick carries. That schedule is skipped with +`schedule_tick_unreadable` and never read as having no history. + +A fault in code that escapes the dispatch pass costs that pass and no +more: run() reports it, keeps the dispatch owed, and goes on claiming. + +Values are written by SQL, as only SQL can write them, each in the form +the engine that keeps it keeps it. A test for another engine's value +skips and says why. +""" + +import logging +import sqlite3 +import time +from datetime import timedelta + +import pytest +from django.db import ( + DataError, + Error, + InterfaceError, + OperationalError, + connection, +) +from django.test.utils import CaptureQueriesContext +from django.utils import timezone + +from django_ox import worker as worker_module +from django_ox._stored_read import newest_tick_pk +from django_ox.cron import CronExpression +from django_ox.models import OxScheduleTick, OxTask +from django_ox.registry import ScheduleKind, register +from django_ox.schedules import Schedule +from django_ox.stored import create_schedule +from django_ox.worker import Worker + +from . import tasks +from .conftest import start_worker_thread, wait_for +from .isolation import daily_cron_at, kill, twelve_hours_ago, with_history +from .test_stored_read import insert_tick, only_on + +#: How long a test waits for a worker thread before calling it stuck: a +#: deadlock guard, never a measurement. +GUARD = 30 + +#: A newest tick that does not read, per engine, as SQL: (engine, literal, +#: why only that engine, USE_TZ). Each sorts after any tick a schedule can +#: be due at, so it is the newest within any bound. +NEWEST = [ + pytest.param( + "postgresql", + "'10000-01-01 00:00:00+00'", + "PostgreSQL keeps a year past 9999", + True, + id="postgresql-year-10000", + ), + pytest.param( + "postgresql", + "'infinity'", + "PostgreSQL keeps 'infinity'", + True, + id="postgresql-infinity", + ), + pytest.param( + "sqlite", "'banana'", "SQLite keeps any text", True, id="sqlite-banana" + ), + pytest.param( + "sqlite", + "'9999-02-30 00:00:00'", + "SQLite keeps a date that does not exist", + True, + id="sqlite-does-not-exist", + ), + pytest.param( + "sqlite", + "CAST(X'FF61' AS TEXT)", + "SQLite keeps text that is not UTF-8", + True, + id="sqlite-not-utf-8", + ), + pytest.param( + "sqlite", + "'9999-01-01 00:00:00+00:00'", + "SQLite keeps an offset in a column read as naive", + False, + id="sqlite-offset-with-use-tz-off", + ), + pytest.param( + "mysql", + "'9999-00-00 00:00:00'", + "MySQL keeps a zero month and day", + True, + id="mysql-zero-in-date", + ), +] + +#: An earliest tick that does not read, per engine: each sorts before any +#: tick a schedule can be due at, so no bounded read sees it and only the +#: first-sighting read does. +EARLIEST = [ + pytest.param( + "postgresql", + "'-infinity'", + "PostgreSQL keeps '-infinity'", + id="postgresql-minus-infinity", + ), + pytest.param( + "sqlite", + "'0000-02-30 00:00:00'", + "SQLite keeps a year 0 that does not exist", + id="sqlite-year-0", + ), + pytest.param( + "sqlite", + "'10000-01-01 00:00:00'", + "SQLite sorts this text before any date", + id="sqlite-year-10000", + ), + pytest.param( + "mysql", "'0000-00-00 00:00:00'", "MySQL keeps a zero date", id="mysql-zero" + ), +] + +#: One newest tick that does not read on whichever engine this run is on. +ANY_NEWEST = { + "postgresql": "'infinity'", + "sqlite": "'banana'", + "mysql": "'9999-00-00 00:00:00'", +} + +#: And one earliest tick. +ANY_EARLIEST = { + "postgresql": "'-infinity'", + "sqlite": "'0000-02-30 00:00:00'", + "mysql": "'0000-00-00 00:00:00'", +} + + +@pytest.fixture(autouse=True) +def _registry(monkeypatch): + monkeypatch.setattr("django_ox.registry._registry", {}) + monkeypatch.setattr("django_ox.registry._discovered", True) + register(ScheduleKind(key="labelled", task=tasks.labelled)) + + +def tasks_setting(schedules): + return { + "default": { + "BACKEND": "django_ox.backend.OxBackend", + "QUEUES": ["default", "emails"], + "OPTIONS": { + "SCHEDULE_SOURCE": "django_ox.stored.DatabaseScheduleSource", + "SCHEDULES": schedules, + }, + } + } + + +def entry(name, base): + """A settings schedule daily at `base`'s time of day, labelled `name`.""" + return {"task": "tests.tasks.labelled", "cron": daily_cron_at(base), "args": [name]} + + +def a_row(name, base): + """A stored schedule daily at `base`'s time of day, labelled `name`.""" + return create_schedule( + name=name, + task_key="labelled", + trigger="cron", + cron=daily_cron_at(base), + arguments={"label": name}, + start_time=timezone.now() - timedelta(days=1), + ) + + +def label(task): + return task.args[0] if task.args else task.kwargs.get("label") + + +def fired(): + return sorted(label(task) for task in OxTask.objects.all()) + + +def ticks_of(key): + return sorted( + OxScheduleTick.objects.filter(schedule_name=key).values_list("pk", flat=True) + ) + + +def events(caplog, name): + return [r for r in caplog.records if getattr(r, "event", None) == name] + + +def a_pass_with_a_blocked_row(settings, literal, *, use_tz=True): + """ + A settings schedule and a stored row that fire, and a stored row whose + newest tick is `literal`. Returns the blocked row and its tick's key. + """ + settings.USE_TZ = use_tz + base = twelve_hours_ago() + settings.TASKS = tasks_setting({"s-healthy": entry("s-healthy", base)}) + with_history("s-healthy") + a_row("r-healthy", base) + blocked = a_row("r-blocked", base) + return blocked, insert_tick(f"db:{blocked.pk}", literal) + + +@pytest.mark.django_db +class TestAnUnreadableNewestTick: + @pytest.mark.parametrize(("vendor", "literal", "why", "use_tz"), NEWEST) + def test_only_its_schedule_is_skipped( + self, settings, caplog, vendor, literal, why, use_tz + ): + only_on(vendor, why) + blocked, bad = a_pass_with_a_blocked_row(settings, literal, use_tz=use_tz) + with caplog.at_level(logging.INFO, logger="django_ox"): + assert Worker(backoff_initial=0).dispatch_schedules() == 2 + assert fired() == ["r-healthy", "s-healthy"] + # No candidate tick and no task: the unreadable one is all there is. + assert ticks_of(f"db:{blocked.pk}") == [bad] + (skipped,) = events(caplog, "schedule_tick_unreadable") + assert skipped.schedule == "r-blocked" + assert skipped.schedule_key == f"db:{blocked.pk}" + assert skipped.schedule_pk == blocked.pk + assert skipped.phase == "latest" + assert skipped.tick_pk == bad + assert skipped.database == "default" + assert skipped.reason.startswith("scheduled_for ") + assert "not treated as absent" in skipped.getMessage() + assert skipped.exc_info is None + # Reported once, as what it is, and not as a failed dispatch too. + assert not events(caplog, "schedule_dispatch_error") + + @pytest.mark.parametrize(("vendor", "literal", "why", "use_tz"), NEWEST) + def test_the_pass_after_still_skips_it_and_fires_nothing_twice( + self, settings, vendor, literal, why, use_tz + ): + only_on(vendor, why) + blocked, bad = a_pass_with_a_blocked_row(settings, literal, use_tz=use_tz) + worker = Worker(backoff_initial=0) + assert worker.dispatch_schedules() == 2 + assert worker.dispatch_schedules() == 0 + assert fired() == ["r-healthy", "s-healthy"] + assert ticks_of(f"db:{blocked.pk}") == [bad] + + +@pytest.mark.django_db +class TestAnUnreadableEarliestTick: + """ + A settings schedule with nothing inside the pass's bound is asked for + its earliest tick, inside its dispatch transaction and after its + candidate tick is written. One that does not read rolls that back: the + schedule is neither anchored again nor fired. + """ + + @pytest.mark.parametrize(("vendor", "literal", "why"), EARLIEST) + def test_its_schedule_is_skipped_and_nothing_of_it_is_written( + self, settings, caplog, vendor, literal, why + ): + only_on(vendor, why) + base = twelve_hours_ago() + settings.TASKS = tasks_setting( + { + "s-anchor": entry("s-anchor", base), + "s-healthy": entry("s-healthy", base), + } + ) + with_history("s-healthy") + a_row("r-healthy", base) + bad = insert_tick("s-anchor", literal) + worker = Worker(backoff_initial=0) + with caplog.at_level(logging.INFO, logger="django_ox"): + assert worker.dispatch_schedules() == 2 + assert worker.dispatch_schedules() == 0 + assert fired() == ["r-healthy", "s-healthy"] + # No anchor, no candidate tick and no latch left behind. + assert ticks_of("s-anchor") == [bad] + skipped = events(caplog, "schedule_tick_unreadable") + assert len(skipped) == 1, "the second pass is counted, not reported again" + (first,) = skipped + assert (first.schedule, first.schedule_key) == ("s-anchor", "s-anchor") + assert first.schedule_pk is None + assert first.phase == "anchor" + assert first.tick_pk == bad + assert not events(caplog, "schedule_dispatch_error") + + def test_once_the_tick_is_removed_the_schedule_anchors_as_one_never_seen( + self, settings, caplog + ): + settings.TASKS = tasks_setting( + {"s-anchor": entry("s-anchor", twelve_hours_ago())} + ) + bad = insert_tick("s-anchor", ANY_EARLIEST[connection.vendor]) + worker = Worker(backoff_initial=0) + with caplog.at_level(logging.INFO, logger="django_ox"): + assert worker.dispatch_schedules() == 0 + assert ticks_of("s-anchor") == [bad] + OxScheduleTick.objects.filter(pk=bad).delete() + assert worker.dispatch_schedules() == 0 + # With no history left this is a first sighting: the due tick is + # recorded as the anchor and nothing is fired for it. + (anchor,) = OxScheduleTick.objects.filter(schedule_name="s-anchor") + assert anchor.task_id is None + assert fired() == [] + (readable,) = events(caplog, "schedule_tick_readable") + assert (readable.schedule, readable.schedule_pk) == ("s-anchor", None) + assert readable.failures == 1 + + def test_a_readable_old_tick_still_anchors_the_schedule_as_before(self, settings): + # The control: history before the bound that reads is history, and + # the due tick after it fires. + base = twelve_hours_ago() + settings.TASKS = tasks_setting({"s-anchor": entry("s-anchor", base)}) + with_history("s-anchor") + assert Worker(backoff_initial=0).dispatch_schedules() == 1 + assert fired() == ["s-anchor"] + + +@pytest.mark.django_db +class TestTheSkipIsReportedLikeAFailure: + """Once in full, then in summary, then once when the history reads again.""" + + def test_first_then_summary_then_readable(self, settings, caplog, monkeypatch): + blocked, bad = a_pass_with_a_blocked_row( + settings, ANY_NEWEST[connection.vendor] + ) + worker = Worker(backoff_initial=0) + key = f"db:{blocked.pk}" + with caplog.at_level(logging.INFO, logger="django_ox"): + worker.dispatch_schedules() + worker.dispatch_schedules() + assert len(events(caplog, "schedule_tick_unreadable")) == 1 + monkeypatch.setattr(worker_module, "DISPATCH_FAILURE_REPORT_INTERVAL", 0) + worker.dispatch_schedules() + first, summary = events(caplog, "schedule_tick_unreadable") + assert (first.failures, first.suppressed) == (1, 0) + assert (summary.failures, summary.suppressed) == (3, 2) + assert summary.getMessage().startswith("Schedule r-blocked still skipped") + # The tick removed by its key, as only its key can remove it. + OxScheduleTick.objects.filter(pk=bad).delete() + assert worker.dispatch_schedules() == 1, "the row fires again" + (readable,) = events(caplog, "schedule_tick_readable") + assert (readable.schedule, readable.schedule_key) == ("r-blocked", key) + assert readable.failures == 3 + assert fired() == ["r-blocked", "r-healthy", "s-healthy"] + + +def tick_reads(queries): + """The statements of `queries` that read the tick log.""" + return [ + q["sql"] + for q in queries.captured_queries + if q["sql"].lstrip().upper().startswith("SELECT") + and "django_ox_oxscheduletick" in q["sql"] + ] + + +# Autocommit, as a worker reads. +@pytest.mark.django_db(transaction=True) +class TestTheUnreadableTicksRowIsNamedOnlyWhereALineIsWritten: + """ + Which tick row it is appears in the line a skip writes, at most once a + minute for a schedule. Passes that skip the schedule and write no line + read the tick log once, as a pass with nothing unreadable does. + """ + + SKIPPED = 3 + + def blocked_rows(self, settings): + settings.TASKS = tasks_setting({}) + base = twelve_hours_ago() + with_history("unrelated") + rows = [a_row(f"r-{index}", base) for index in range(self.SKIPPED)] + ticks = { + row.pk: insert_tick(f"db:{row.pk}", ANY_NEWEST[connection.vendor]) + for row in rows + } + return rows, ticks + + def test_a_pass_that_writes_the_lines_looks_each_row_up_and_the_next_does_not( + self, settings, caplog, monkeypatch + ): + _, ticks = self.blocked_rows(settings) + worker = Worker(backoff_initial=0) + with caplog.at_level(logging.INFO, logger="django_ox"): + with CaptureQueriesContext(connection) as first: + worker.dispatch_schedules() + with CaptureQueriesContext(connection) as quiet: + worker.dispatch_schedules() + worker.dispatch_schedules() + monkeypatch.setattr(worker_module, "DISPATCH_FAILURE_REPORT_INTERVAL", 0) + with CaptureQueriesContext(connection) as summary: + worker.dispatch_schedules() + + # The grouped read, and one lookup for each line written. + assert len(tick_reads(first)) == 1 + self.SKIPPED + # Two passes, one grouped read each, and no lookup. + assert len(tick_reads(quiet)) == 2 + assert len(tick_reads(summary)) == 1 + self.SKIPPED + lines = events(caplog, "schedule_tick_unreadable") + assert len(lines) == 2 * self.SKIPPED + assert {line.schedule_pk: line.tick_pk for line in lines} == ticks + assert all(line.phase == "latest" for line in lines) + + def test_a_lookup_that_fails_leaves_the_skip_and_the_line_as_they_were( + self, settings, caplog, monkeypatch + ): + rows, ticks = self.blocked_rows(settings) + + def refused(*args, **kwargs): + raise OperationalError("the lookup was refused") + + monkeypatch.setattr(worker_module, "newest_tick_pk", refused) + with caplog.at_level(logging.INFO, logger="django_ox"): + Worker(backoff_initial=0).dispatch_schedules() + + lines = events(caplog, "schedule_tick_unreadable") + assert sorted(line.schedule_pk for line in lines) == sorted(ticks) + assert {line.tick_pk for line in lines} == {None} + assert all("not treated as absent" in line.getMessage() for line in lines) + # Skipped, as when the row is named: nothing fired and nothing written. + assert fired() == [] + for row in rows: + assert ticks_of(f"db:{row.pk}") == [ticks[row.pk]] + + +def many_schedules(count): + return [ + Schedule( + name=f"s{index:04d}", + task=tasks.add, + trigger=CronExpression("* * * * *"), + args=(), + kwargs={}, + ) + for index in range(count) + ] + + +def seed(schedules, at, every=7): + for schedule in schedules[::every]: + OxScheduleTick.objects.create( + schedule_name=schedule.key, scheduled_for=at, task_id=None, created_at=at + ) + return {schedule.key: at for schedule in schedules[::every]} + + +# Autocommit, as a worker reads. +@pytest.mark.django_db(transaction=True) +class TestTheHealthyReadIsOneStatementPerSlice: + def test_beyond_sqlite_3_31s_limit(self, settings): + only_on("sqlite", "SQLite's parameter limit") + settings.TASKS = tasks_setting({}) + schedules = many_schedules(1200) + at = timezone.now().replace(second=0, microsecond=0) + expected = seed(schedules, at) + connection.ensure_connection() + raw = connection.connection + before = raw.getlimit(sqlite3.SQLITE_LIMIT_VARIABLE_NUMBER) + raw.setlimit(sqlite3.SQLITE_LIMIT_VARIABLE_NUMBER, 999) + try: + assert connection.features.max_query_params == 999 + worker = Worker(backoff_initial=0) + with CaptureQueriesContext(connection) as captured: + latest = worker._latest_ticks(schedules, at - timedelta(days=1)) + finally: + raw.setlimit(sqlite3.SQLITE_LIMIT_VARIABLE_NUMBER, before) + # 1200 keys at 998 a statement: two statements and nothing else, no + # savepoint and no read per key. + statements = [q["sql"] for q in captured.captured_queries] + assert len(statements) == 2, statements + assert all("MAX(" in sql.upper() for sql in statements) + assert {key: read.at for key, read in latest.items()} == expected + + def test_in_slices_of_the_connections_limit(self, settings, monkeypatch): + settings.TASKS = tasks_setting({}) + schedules = many_schedules(10) + at = timezone.now().replace(second=0, microsecond=0) + expected = seed(schedules, at, every=3) + # Three keys and the bound per statement. On the class, and the + # instance's cached value dropped, as test_schedules does it. + monkeypatch.setattr(type(connection.features), "max_query_params", 4) + connection.features.__dict__.pop("max_query_params", None) + worker = Worker(backoff_initial=0) + with CaptureQueriesContext(connection) as captured: + latest = worker._latest_ticks(schedules, at - timedelta(days=1)) + statements = [q["sql"] for q in captured.captured_queries] + assert len(statements) == 4, statements + assert {key: read.at for key, read in latest.items()} == expected + + +@pytest.mark.django_db +class TestAnUnreadableKeyAnywhereInASlice: + """ + One key's newest tick that does not read, first, in the middle or last + of a slice, costs that key alone. Most such values are decoded per key + from the one grouped statement; text SQLite cannot hand over as UTF-8 + fails the statement, which is read again in halves down to the key. + """ + + VALUES = [ + pytest.param("postgresql", "'infinity'", id="postgresql-infinity"), + pytest.param("sqlite", "'9999-02-30 00:00:00'", id="sqlite-does-not-exist"), + pytest.param("sqlite", "CAST(X'FF61' AS TEXT)", id="sqlite-not-utf-8"), + pytest.param("mysql", "'9999-00-00 00:00:00'", id="mysql-zero-in-date"), + ] + + @pytest.mark.parametrize("position", [0, 3, 6], ids=["first", "middle", "last"]) + @pytest.mark.parametrize(("vendor", "literal"), VALUES) + def test_every_other_key_is_answered(self, settings, vendor, literal, position): + only_on(vendor, f"a value only {vendor} keeps") + settings.TASKS = tasks_setting({}) + schedules = many_schedules(7) + at = timezone.now().replace(second=0, microsecond=0) + expected = seed(schedules, at, every=1) + bad_key = schedules[position].key + bad = insert_tick(bad_key, literal) + latest = Worker(backoff_initial=0)._latest_ticks( + schedules, at - timedelta(days=1) + ) + assert latest[bad_key].unreadable + # Which row it is is looked up where a line names it, not here. + assert latest[bad_key].pk is None + assert newest_tick_pk(bad_key, at - timedelta(days=1), using="default") == bad + del expected[bad_key] + assert { + key: read.at for key, read in latest.items() if key != bad_key + } == expected + + +def failing_before(marker, how): + """ + An execute wrapper that fails the first statement on the tick log whose + SQL carries `marker`: by losing the connection for real (`kill`), or by + raising an error the database raises that is not about any value + (`refuse`). + """ + met = [] + + def wrapper(execute, sql, params, many, context): + if not met and "oxscheduletick" in sql and marker in sql: + met.append(sql) + if how == "kill": + kill(context["connection"]) + else: + raise OperationalError("database disk image is malformed") + return execute(sql, params, many, context) + + return wrapper, met + + +@pytest.mark.django_db(transaction=True) +class TestAFailedReadIsNotAnUnreadableTick: + """ + A read of the tick log that fails because the connection went, or + because the database refused it for a reason that is not a value, is + the database's and never a tick that does not read. The shared read of + the newest ticks abandons the pass for run() to report and reconnect. + The earliest-tick read is inside one schedule's transaction, where the + connection decides as for any statement there: lost, the pass is + abandoned; still answering, it is that schedule's dispatch error. + """ + + @pytest.mark.parametrize("how", ["kill", "refuse"]) + @pytest.mark.parametrize( + ("marker", "schedules"), + [ + pytest.param("MAX(", "stored", id="newest"), + pytest.param("ox_stored_scheduled_for", "settings", id="earliest"), + ], + ) + def test_no_schedule_is_skipped_for_it( + self, settings, caplog, marker, schedules, how + ): + if how == "kill" and connection.vendor == "sqlite": + pytest.skip( + "SQLite has no connection to lose; closing its handle under " + "Django is not a shape a worker meets" + ) + base = twelve_hours_ago() + if schedules == "stored": + settings.TASKS = tasks_setting({}) + a_row("r-due", base) + else: + settings.TASKS = tasks_setting({"s-new": entry("s-new", base)}) + worker = Worker(backoff_initial=0) + wrapper, met = failing_before(marker, how) + abandoned = how == "kill" or schedules == "stored" + with ( + caplog.at_level(logging.INFO, logger="django_ox"), + connection.execute_wrapper(wrapper), + ): + if abandoned: + with pytest.raises(Error): + worker.dispatch_schedules() + else: + assert worker.dispatch_schedules() == 0 + assert met, "the read was never made" + assert not events(caplog, "schedule_tick_unreadable") + reported = [r.schedule for r in events(caplog, "schedule_dispatch_error")] + assert reported == ([] if abandoned else ["s-new"]) + connection.close() + assert not OxTask.objects.exists() + assert not OxScheduleTick.objects.exists() + + +# -- run(): a fault in code costs the pass ------------------------------------ + + +class _Halt(BaseException): + """Not an Exception: what run() must let through.""" + + +@pytest.fixture +def due_worker(settings): + """A worker with one settings schedule due, and history so it fires.""" + base = twelve_hours_ago() + settings.TASKS = tasks_setting({"s-due": entry("s-due", base)}) + with_history("s-due") + return Worker( + backoff_initial=0, poll_interval=0.02, reap_interval=0.0, schedule_interval=0.1 + ) + + +def a_reader_that_fails(worker, monkeypatch, error, times=1): + """ + Make the schedule source's answer raise `error` on the first `times` + dispatch passes, or on every one when `times` is None: a shared read of + the pass that nothing guards, as a reader added later might be. The + worker has asked it once already, when it was built. Returns the calls. + """ + source = worker._schedule_source + real = source.schedules + calls = [] + + def schedules(): + calls.append(time.monotonic()) + if times is None or len(calls) <= times: + raise error("a shared read of the pass failed") + return real() + + monkeypatch.setattr(source, "schedules", schedules) + return calls + + +def run_until(worker, predicate, caplog): + with caplog.at_level(logging.INFO, logger="django_ox"): + thread = start_worker_thread(worker) + reached = wait_for(lambda: predicate() or not thread.is_alive(), timeout=GUARD) + alive = thread.is_alive() + worker.request_stop() + thread.join(timeout=GUARD) + assert reached, "the worker never got there" + assert alive, "run() ended on its own" + assert not thread.is_alive(), "run() did not stop when asked" + + +def all_succeeded(count): + return lambda: ( + OxTask.objects.filter(status=OxTask.Status.SUCCESSFUL).count() >= count + ) + + +@pytest.mark.django_db(transaction=True) +class TestAFaultInADispatchReaderCostsThePass: + @pytest.mark.parametrize( + "error", + [AttributeError, TypeError, ValueError, KeyError, RuntimeError, LookupError], + ) + def test_the_worker_claims_and_then_dispatches( + self, due_worker, monkeypatch, caplog, error + ): + queued = tasks.add.enqueue(1, 2) + calls = a_reader_that_fails(due_worker, monkeypatch, error) + run_until(due_worker, all_succeeded(2), caplog) + assert OxTask.objects.get(id=queued.id).status == OxTask.Status.SUCCESSFUL + assert OxTask.objects.filter(args=["s-due"]).exists() + assert len(calls) >= 2 + (failed,) = events(caplog, "schedule_dispatch_failed") + assert failed.category == "unexpected_exception" + assert failed.error == error.__name__ + assert failed.exc_info is not None, "the first is reported in full" + assert "unexpected" in failed.getMessage() + (resumed,) = events(caplog, "schedule_dispatch_resumed") + assert resumed.failures == 1 + assert caplog.records.index(resumed) > caplog.records.index(failed) + + def test_one_that_keeps_failing_costs_each_pass_and_no_more( + self, due_worker, monkeypatch, caplog + ): + queued = tasks.add.enqueue(1, 2) + calls = a_reader_that_fails(due_worker, monkeypatch, AttributeError, None) + started = time.monotonic() + run_until( + due_worker, + lambda: all_succeeded(1)() and len(calls) >= 4, + caplog, + ) + elapsed = time.monotonic() - started + assert OxTask.objects.get(id=queued.id).status == OxTask.Status.SUCCESSFUL + # At most one attempt a schedule_interval, and a slack of two: a + # loop retrying at once would make far more in the same time. + assert len(calls) <= elapsed / due_worker.schedule_interval + 2, ( + len(calls), + elapsed, + ) + # In full once, and no summary inside the report interval. + (failed,) = events(caplog, "schedule_dispatch_failed") + assert failed.category == "unexpected_exception" + assert not events(caplog, "schedule_dispatch_resumed") + + def test_it_holds_a_batch_open_and_the_queue_still_runs( + self, settings, monkeypatch, caplog + ): + settings.TASKS = tasks_setting({}) + queued = tasks.add.enqueue(1, 2) + worker = Worker( + backoff_initial=0, + poll_interval=0.02, + reap_interval=0.0, + schedule_interval=0.1, + batch=True, + ) + calls = a_reader_that_fails(worker, monkeypatch, AttributeError, None) + started = time.monotonic() + with caplog.at_level(logging.INFO, logger="django_ox"): + thread = start_worker_thread(worker) + # The queue drained and the dispatch failed again and again: a + # batch that could end on a failed dispatch has had the chance. + wait_for( + lambda: ( + (all_succeeded(1)() and len(calls) >= 4) or not thread.is_alive() + ), + timeout=GUARD, + ) + alive = thread.is_alive() + elapsed = time.monotonic() - started + worker.request_stop() + thread.join(timeout=GUARD) + assert alive, "the batch ended with a dispatch still owed" + assert OxTask.objects.get(id=queued.id).status == OxTask.Status.SUCCESSFUL + # Tried again at most once a schedule_interval, with a slack of two. + assert len(calls) <= elapsed / worker.schedule_interval + 2, ( + len(calls), + elapsed, + ) + assert not events(caplog, "worker_batch_empty") + + @pytest.mark.parametrize("error", [OperationalError, InterfaceError, DataError]) + def test_a_database_error_is_the_databases( + self, due_worker, monkeypatch, caplog, error + ): + a_reader_that_fails(due_worker, monkeypatch, error) + run_until(due_worker, all_succeeded(1), caplog) + (failed,) = events(caplog, "schedule_dispatch_failed") + assert failed.category == "database" + assert failed.error == error.__name__ + assert "unexpected" not in failed.getMessage() + # Inside the dispatch handler, so the claim still ran that pass: + # not the poll handler's, which loses the claim with it. + assert not events(caplog, "worker_poll_failed") + assert events(caplog, "schedule_dispatch_resumed") + + @pytest.mark.parametrize("error", [_Halt, SystemExit]) + def test_an_exception_that_is_not_an_exception_still_ends_run( + self, due_worker, monkeypatch, error + ): + a_reader_that_fails(due_worker, monkeypatch, error) + with pytest.raises(error): + due_worker.run() + + +def test_the_report_keeps_the_categories_apart(caplog): + # A fault in code during an outage is still reported in full. + report = worker_module._DispatchReport("w", "default", clock=lambda: 0.0) + with caplog.at_level(logging.INFO, logger="django_ox"): + report.pass_failed(OperationalError("gone")) + report.pass_failed(OperationalError("gone")) + report.pass_failed(AttributeError("x"), unexpected=True) + report.pass_completed() + report.pass_completed() + failed = events(caplog, "schedule_dispatch_failed") + assert [(r.category, r.exc_info is not None) for r in failed] == [ + ("database", True), + ("unexpected_exception", True), + ] + (resumed,) = events(caplog, "schedule_dispatch_resumed") + assert resumed.failures == 3 diff --git a/tests/test_tick_history_worker.py b/tests/test_tick_history_worker.py new file mode 100644 index 0000000..b5cdca7 --- /dev/null +++ b/tests/test_tick_history_worker.py @@ -0,0 +1,752 @@ +""" +Stored values that do not read, through real `manage.py ox_worker` +processes against whichever database the suite runs on. + +What is asserted is what a job runner and an operator see: the exit code, +whether the supervisor restarted anything, the committed tick rows and the +tasks they point at, and the log. Every wait is a deadlock guard with a +bound, never a measurement: a batch that exits does so on its own, and one +that does not has failed. +""" + +import json +import os +import signal +import subprocess +import sys +import time +from datetime import timedelta +from pathlib import Path + +import pytest +from django.conf import settings +from django.db import connection +from django.utils import timezone + +from django_ox.models import OxSchedule, OxScheduleTick, OxTask +from django_ox.registry import ScheduleKind, register +from django_ox.stored import create_schedule + +from . import tasks +from .conftest import wait_for +from .isolation import daily_cron_at, twelve_hours_ago, with_history +from .test_stored_isolation import refused_as, refusing_moves_of +from .test_stored_read import ( + ONE_PER_ENGINE, + insert_tick, + largest_count, + only_on, + set_column, +) +from .test_stored_source_integrity import MISREAD, SQLITE_ONLY +from .test_supervisor import child_pids +from .test_tick_history import EARLIEST, NEWEST + +REPO = Path(__file__).resolve().parent.parent + +pytestmark = [ + pytest.mark.django_db(transaction=True), + pytest.mark.skipif(os.name != "posix", reason="worker processes"), +] + +#: Every batch here finishes in a second or two, and a long-running worker +#: reaches what a test waits for in a few. This is how long a test waits +#: before calling one stuck. +GUARD = 30 + +#: Starts every record in a worker's log, followed by its event. +RECORD = "@@ " + +STORED = "django_ox.stored.DatabaseScheduleSource" + +#: The suite's settings module, for the workers' settings to re-export. Read +#: here, since inside a test that overrides a setting it reads as None. +SUITE_SETTINGS = settings.SETTINGS_MODULE + +#: One unreadable newest tick per engine for the --processes runs: the +#: values that ended the process (SQLite, MySQL) or every pass (PostgreSQL). +REPRESENTATIVE = [ + pytest.param("sqlite", "'banana'", id="sqlite-banana"), + pytest.param("postgresql", "'10000-01-01 00:00:00+00'", id="postgresql-year-10000"), + pytest.param("mysql", "'9999-00-00 00:00:00'", id="mysql-zero-in-date"), +] + + +@pytest.fixture(autouse=True) +def _registry(monkeypatch): + # For create_schedule in this process. The workers read the same kind + # from SCHEDULABLE_TASKS in their settings. + monkeypatch.setattr("django_ox.registry._registry", {}) + monkeypatch.setattr("django_ox.registry._discovered", True) + register(ScheduleKind(key="labelled", task=tasks.labelled)) + + +def project(tmp_path, schedules, *, source=STORED, report_every=None, use_tz=None): + """ + A deployment's shape: its own manage.py and settings package, the + settings re-exporting the suite's so the workers reach the test + database. `report_every` sets the worker's interval between summaries + of a failure that goes on, once Django is set up: at 0 every failed + or skipped pass is a line, so a test can count passes. `use_tz` sets + USE_TZ for the workers, for a test that has set it for itself. + """ + root = tmp_path / "proj" + (root / "tickproj").mkdir(parents=True) + control = "" + if report_every is not None: + control = ( + "import django\n" + "django.setup()\n" + "import django_ox.worker\n" + f"django_ox.worker.DISPATCH_FAILURE_REPORT_INTERVAL = {report_every!r}\n" + ) + (root / "manage.py").write_text( + "import os, sys\n" + "os.environ.setdefault('DJANGO_SETTINGS_MODULE', 'tickproj.settings')\n" + f"{control}" + "from django.core.management import execute_from_command_line\n" + "execute_from_command_line(sys.argv)\n" + ) + (root / "tickproj" / "__init__.py").write_text("") + (root / "tickproj" / "settings.py").write_text( + "import json, sys\n" + f"sys.path.insert(0, {str(REPO)!r})\n" + f"from {SUITE_SETTINGS} import * # noqa: F403\n" + "TASKS = {'default': {\n" + " 'BACKEND': 'django_ox.backend.OxBackend',\n" + " 'QUEUES': ['default', 'emails'],\n" + " 'OPTIONS': {\n" + f" 'SCHEDULES': json.loads({json.dumps(schedules)!r}),\n" + f" 'SCHEDULE_SOURCE': {source!r},\n" + " 'SCHEDULABLE_TASKS': {'labelled': 'tests.tasks.labelled'},\n" + " },\n" + "}}\n" + ("" if use_tz is None else f"USE_TZ = {use_tz!r}\n") + ) + return root + + +def start(root, log_path, *flags, batch=True, env=None): + environ = dict(os.environ) + environ["DJANGO_SETTINGS_MODULE"] = "tickproj.settings" + environ["OX_TEST_DB_NAME"] = str(connection.settings_dict["NAME"]) + environ["OX_TEST_LOG_LEVEL"] = "INFO" + environ["OX_TEST_LOG_FORMAT"] = RECORD + "%(event)s %(message)s" + environ.update(env or {}) + log = log_path.open("wb") + try: + # The arguments that are not literals are this test's own flags. + return subprocess.Popen( # noqa: S603 + [ + sys.executable, + "manage.py", + "ox_worker", + *(["--batch"] if batch else []), + "--interval", + "0.05", + *flags, + ], + cwd=root, + env=environ, + stdout=log, + stderr=log, + ) + finally: + log.close() + + +def finish(proc, log_path): + """The exit code of a process that ended on its own, or a failed test.""" + try: + return proc.wait(timeout=GUARD) + except subprocess.TimeoutExpired: + proc.kill() + proc.wait(timeout=10) + pytest.fail( + f"the worker did not finish within {GUARD}s:\n" + f"{log_path.read_text()[-4000:]}" + ) + + +def run_batch(root, log_path, env=None): + proc = start(root, log_path, env=env) + return finish(proc, log_path), log_path.read_text() + + +def stop(proc, log_path): + if proc.poll() is None: + proc.send_signal(signal.SIGTERM) + return finish(proc, log_path), log_path.read_text() + + +def lines(log, event): + return [line for line in log.splitlines() if line.startswith(f"{RECORD}{event} ")] + + +def counted(log_path, event): + """The records of `event` a running worker has written so far.""" + return lines(log_path.read_text() if log_path.exists() else "", event) + + +def entry(name, base): + return {"task": "tests.tasks.labelled", "cron": daily_cron_at(base), "args": [name]} + + +def a_row(name, base): + return create_schedule( + name=name, + task_key="labelled", + trigger="cron", + cron=daily_cron_at(base), + arguments={"label": name}, + start_time=timezone.now() - timedelta(days=1), + ) + + +def every_second(): + """A stored schedule due every second: each tick of it is a dispatch pass.""" + return create_schedule( + name="every-second", + task_key="labelled", + trigger="interval", + every_seconds=1, + arguments={"label": "every-second"}, + start_time=timezone.now() - timedelta(days=1), + ) + + +def label(task): + return task.args[0] if task.args else task.kwargs.get("label") + + +def ticks_of(key): + return sorted( + OxScheduleTick.objects.filter(schedule_name=key).values_list("pk", flat=True) + ) + + +def assert_fired_once_each(expected): + """ + Each key fired exactly one tick, that tick's task carries the schedule's + own label and ran, and no labelled task exists that no tick points at. + """ + pointed_at = set() + for key, name in expected.items(): + (tick,) = OxScheduleTick.objects.filter(schedule_name=key).exclude(task_id=None) + task = OxTask.objects.get(id=tick.task_id) + assert label(task) == name, (key, label(task)) + assert task.status == OxTask.Status.SUCCESSFUL, (name, task.status) + pointed_at.add(task.id) + labelled = OxTask.objects.filter(task_path="tests.tasks.labelled") + assert set(labelled.values_list("id", flat=True)) == pointed_at + + +class TestABatchWithAnUnreadableTick: + @pytest.mark.parametrize(("vendor", "literal", "why", "use_tz"), NEWEST) + def test_the_newest_tick_skips_its_schedule_alone( + self, tmp_path, settings, vendor, literal, why, use_tz + ): + only_on(vendor, why) + # For this process and the worker alike: both write and read the + # same columns, and a time has a zone in them or it does not. + settings.USE_TZ = use_tz + base = twelve_hours_ago() + root = project(tmp_path, {"s-healthy": entry("s-healthy", base)}, use_tz=use_tz) + with_history("s-healthy") + healthy = a_row("r-healthy", base) + blocked = a_row("r-blocked", base) + bad = insert_tick(f"db:{blocked.pk}", literal) + + code, log = run_batch(root, tmp_path / "run.log") + assert code == 0, log + assert_fired_once_each( + {"s-healthy": "s-healthy", f"db:{healthy.pk}": "r-healthy"} + ) + assert ticks_of(f"db:{blocked.pk}") == [bad], "the blocked row fired" + (skipped, *_) = lines(log, "schedule_tick_unreadable") + assert "Schedule r-blocked skipped" in skipped, skipped + assert "r-blocked could not be dispatched" not in log, log + assert "Schedule dispatch failed" not in log, log + assert "found nothing to claim" in log + + @pytest.mark.parametrize(("vendor", "literal", "why"), EARLIEST) + def test_the_earliest_tick_blocks_its_settings_schedule_alone( + self, tmp_path, vendor, literal, why + ): + only_on(vendor, why) + base = twelve_hours_ago() + root = project( + tmp_path, + { + "s-anchor": entry("s-anchor", base), + "s-healthy": entry("s-healthy", base), + }, + ) + with_history("s-healthy") + healthy = a_row("r-healthy", base) + bad = insert_tick("s-anchor", literal) + + code, log = run_batch(root, tmp_path / "run.log") + assert code == 0, log + assert_fired_once_each( + {"s-healthy": "s-healthy", f"db:{healthy.pk}": "r-healthy"} + ) + # Not anchored again, and no candidate tick or latch left behind. + assert ticks_of("s-anchor") == [bad] + (skipped, *_) = lines(log, "schedule_tick_unreadable") + assert "Schedule s-anchor skipped" in skipped, skipped + assert "Its earliest tick could not be read" in skipped, skipped + assert "s-anchor could not be dispatched" not in log, log + assert "Schedule dispatch failed" not in log, log + + +class TestABatchWithARowTheConverterWouldMisread: + @pytest.mark.parametrize(("vendor", "column", "literal"), MISREAD) + def test_the_row_is_skipped_by_field_and_never_dispatched( + self, tmp_path, vendor, column, literal + ): + only_on(vendor, SQLITE_ONLY) + base = twelve_hours_ago() + root = project(tmp_path, {}) + healthy = a_row("r-healthy", base) + victim = a_row("victim", base) + set_column(victim.pk, column, literal) + + code, log = run_batch(root, tmp_path / "run.log") + assert code == 0, log + assert_fired_once_each({f"db:{healthy.pk}": "r-healthy"}) + assert ticks_of(f"db:{victim.pk}") == [], "the row was dispatched" + (skipped, *_) = lines(log, "schedule_row_skipped") + said = f"Skipping stored schedule victim (pk {victim.pk}): its {column} holds " + assert said in skipped, skipped + + +class TestABatchWithARowThatDoesNotRead: + def test_the_skip_carries_the_field_as_a_list(self, tmp_path): + column, literal = ONE_PER_ENGINE[connection.vendor] + base = twelve_hours_ago() + root = project(tmp_path, {}) + healthy = a_row("r-healthy", base) + victim = a_row("victim", base) + set_column(victim.pk, column, literal) + + code, log = run_batch( + root, + tmp_path / "run.log", + env={"OX_TEST_LOG_FORMAT": RECORD + "%(event)s %(fields)s %(message)s"}, + ) + assert code == 0, log + assert_fired_once_each({f"db:{healthy.pk}": "r-healthy"}) + assert ticks_of(f"db:{victim.pk}") == [], "the row was dispatched" + (skipped, *_) = lines(log, "schedule_row_skipped") + said = ( + f"{RECORD}schedule_row_skipped ['{column}'] Skipping stored schedule " + f"victim (pk {victim.pk}): its {column} holds " + ) + assert skipped.startswith(said), skipped + + +class TestTwoProcessesWithAnUnreadableTick: + """ + Under --processes 2 a child that a stored value ended would be + restarted into the same value until the supervisor's restart cap + stopped it. Both children keep their process: the same two pids before + and after several dispatch passes, and no restart at all. + """ + + @pytest.mark.parametrize(("vendor", "literal"), REPRESENTATIVE) + def test_no_child_is_restarted(self, tmp_path, vendor, literal): + only_on(vendor, f"a value only {vendor} keeps") + base = twelve_hours_ago() + root = project( + tmp_path, {"s-healthy": entry("s-healthy", base)}, report_every=0 + ) + with_history("s-healthy") + healthy = a_row("r-healthy", base) + blocked = a_row("r-blocked", base) + bad = insert_tick(f"db:{blocked.pk}", literal) + log_path = tmp_path / "worker.log" + proc = start(root, log_path, "--processes", "2", batch=False) + try: + done = OxTask.objects.filter(status=OxTask.Status.SUCCESSFUL) + + def skips(): + return len(counted(log_path, "schedule_tick_unreadable")) + + reached = wait_for( + lambda: done.count() == 2 and skips() >= 4, timeout=GUARD + ) + assert reached, log_path.read_text()[-4000:] + before = sorted(child_pids(proc)) + seen = skips() + # Both children through more passes, each one a line. + assert wait_for(lambda: skips() >= seen + 4, timeout=GUARD), ( + log_path.read_text()[-4000:] + ) + after = sorted(child_pids(proc)) + finally: + code, log = stop(proc, log_path) + assert code == 0, log + assert len(before) == 2, before + assert before == after, "a child was replaced" + assert not lines(log, "worker_process_restarted"), log + assert not lines(log, "supervisor_restart_cap"), log + assert_fired_once_each( + {"s-healthy": "s-healthy", f"db:{healthy.pk}": "r-healthy"} + ) + assert ticks_of(f"db:{blocked.pk}") == [bad] + + +def failing(error, passes): + return {"OX_TEST_SOURCE_RAISES": error, "OX_TEST_SOURCE_PASSES": passes} + + +class TestAFaultInADispatchReader: + """ + A shared read of the dispatch pass that raises something no handler in + the pass expects, as a reader added later might: tests.sources' + FailingReadSource. The pass is lost and reported; the process is not. + """ + + def test_a_batch_claims_its_work_dispatches_and_exits_0(self, tmp_path): + base = twelve_hours_ago() + root = project( + tmp_path, + {"s-due": entry("s-due", base)}, + source="tests.sources.FailingReadSource", + ) + with_history("s-due") + queued = tasks.add.enqueue(1, 2) + + code, log = run_batch( + root, tmp_path / "run.log", env=failing("AttributeError", "1") + ) + assert code == 0, log + assert OxTask.objects.get(id=queued.id).status == OxTask.Status.SUCCESSFUL + assert_fired_once_each({"s-due": "s-due"}) + (failed,) = lines(log, "schedule_dispatch_failed") + assert "unexpected exception (AttributeError)" in failed, failed + assert "Traceback" in log + assert lines(log, "schedule_dispatch_resumed"), log + + def test_one_on_every_pass_leaves_polling_alive_without_a_busy_loop(self, tmp_path): + root = project( + tmp_path, + {"s-due": entry("s-due", twelve_hours_ago())}, + source="tests.sources.FailingReadSource", + report_every=0, + ) + queued = tasks.add.enqueue(1, 2) + log_path = tmp_path / "worker.log" + started = time.monotonic() + proc = start( + root, log_path, batch=False, env=failing("AttributeError", "every") + ) + try: + done = OxTask.objects.filter(id=queued.id, status=OxTask.Status.SUCCESSFUL) + assert wait_for( + lambda: ( + done.exists() + and len(counted(log_path, "schedule_dispatch_failed")) >= 3 + ), + timeout=GUARD, + ), log_path.read_text()[-4000:] + finally: + code, log = stop(proc, log_path) + elapsed = time.monotonic() - started + assert code == 0, log + # Each failed pass is a line here, and a pass comes at most once a + # second (the default schedule interval): a retry at once would be + # hundreds in the same time. + assert len(lines(log, "schedule_dispatch_failed")) <= elapsed + 2, log + assert log.count("Traceback") == 1, "a traceback per pass" + + def test_one_on_every_pass_holds_a_batch_open_and_its_queue_still_runs( + self, tmp_path + ): + """ + A batch ends once its queue is drained and no dispatch is owed. A + pass that fails stays owed, so a fault on every pass holds the + batch open, as a database failing every pass does: it goes on + claiming what is queued, tries the dispatch again once a schedule + interval, and stays up until something stops it. + """ + root = project( + tmp_path, + {"s-due": entry("s-due", twelve_hours_ago())}, + source="tests.sources.FailingReadSource", + report_every=0, + ) + with_history("s-due") + first = tasks.add.enqueue(1, 2) + log_path = tmp_path / "worker.log" + + def failed(): + return len(counted(log_path, "schedule_dispatch_failed")) + + def ran(task): + done = OxTask.objects.filter(id=task.id, status=OxTask.Status.SUCCESSFUL) + return done.exists() + + started = time.monotonic() + proc = start(root, log_path, env=failing("AttributeError", "every")) + try: + # The queue is drained, and the dispatch has failed and failed + # again: a batch that could end has had every chance to. + assert wait_for(lambda: ran(first) and failed() >= 2, timeout=GUARD), ( + log_path.read_text()[-4000:] + ) + assert proc.poll() is None, "the batch ended with its dispatch owed" + # Still claiming: what is queued while it is held open is run. + seen = failed() + second = tasks.add.enqueue(3, 4) + assert wait_for( + lambda: ran(second) and failed() >= seen + 2, timeout=GUARD + ), log_path.read_text()[-4000:] + assert proc.poll() is None, "the batch ended with its dispatch owed" + finally: + code, log = stop(proc, log_path) + elapsed = time.monotonic() - started + assert code == 0, log + assert not lines(log, "worker_batch_empty"), log + # Each failed pass is a line here, and a pass comes at most once a + # second (the default schedule interval): a retry at once would be + # hundreds in the same time. + assert len(lines(log, "schedule_dispatch_failed")) <= elapsed + 2, log + assert log.count("Traceback") == 1, "a traceback per pass" + # Nothing was dispatched: the schedule's history is what it was. + assert not OxScheduleTick.objects.exclude(task_id=None).exists() + assert not OxTask.objects.filter(task_path="tests.tasks.labelled").exists() + + def test_two_processes_lose_one_pass_each_and_no_child(self, tmp_path): + base = twelve_hours_ago() + root = project( + tmp_path, + {"s-due": entry("s-due", base)}, + source="tests.sources.FailingReadSource", + ) + with_history("s-due") + queued = tasks.add.enqueue(1, 2) + log_path = tmp_path / "worker.log" + proc = start( + root, + log_path, + "--processes", + "2", + batch=False, + env=failing("AttributeError", "1"), + ) + try: + done = OxTask.objects.filter(status=OxTask.Status.SUCCESSFUL) + assert wait_for( + lambda: ( + done.count() == 2 + and len(counted(log_path, "schedule_dispatch_resumed")) >= 2 + ), + timeout=GUARD, + ), log_path.read_text()[-4000:] + before = sorted(child_pids(proc)) + finally: + code, log = stop(proc, log_path) + assert code == 0, log + assert len(before) == 2, before + assert len(lines(log, "schedule_dispatch_failed")) == 2, log + assert not lines(log, "worker_process_restarted"), log + assert not lines(log, "supervisor_restart_cap"), log + assert OxTask.objects.get(id=queued.id).status == OxTask.Status.SUCCESSFUL + assert_fired_once_each({"s-due": "s-due"}) + + +def processes_of(marker): + """The pids of every process whose command line holds this marker.""" + found = subprocess.run( # noqa: S603 + ["pgrep", "-f", str(marker)], # noqa: S607 + capture_output=True, + text=True, + check=False, + ).stdout.split() + return [int(pid) for pid in found] + + +class TestACustomSourceWhoseStoreStopsAnswering: + """ + tests.sources' UnavailableAfterStart answers when the worker is built + and raises ConnectionError on every read after that. Dispatching + directly raises it. A `--batch` worker does not end on it: it reports + the lost pass and stays up, polling, until it is stopped, so a wrapper + that starts one cannot take a prompt non-zero exit as the sign of a + source that is down. + """ + + SOURCE = "tests.sources.UnavailableAfterStart" + + def test_direct_dispatch_raises(self, settings): + from django_ox.worker import Worker + + settings.TASKS = { + "default": { + "BACKEND": "django_ox.backend.OxBackend", + "QUEUES": ["default"], + "OPTIONS": { + "SCHEDULES": { + "s-due": { + "task": "tests.tasks.labelled", + "cron": "* * * * *", + "args": ["s-due"], + } + }, + "SCHEDULE_SOURCE": self.SOURCE, + }, + } + } + worker = Worker(poll_interval=0.02, reap_interval=0.0, schedule_interval=0.0) + + with pytest.raises(ConnectionError, match="stopped answering"): + worker.dispatch_schedules() + + def test_a_batch_reports_it_and_stays_alive_until_it_is_stopped(self, tmp_path): + root = project( + tmp_path, + {"s-due": entry("s-due", twelve_hours_ago())}, + source=self.SOURCE, + report_every=0, + ) + queued = tasks.add.enqueue(1, 2) + log_path = tmp_path / "worker.log" + # A path no other process has, so that every process of this worker + # can be found by its command line. + marker = tmp_path / "heartbeat" + proc = start(root, log_path, "--heartbeat-file", str(marker)) + try: + done = OxTask.objects.filter(id=queued.id, status=OxTask.Status.SUCCESSFUL) + assert wait_for( + lambda: ( + done.exists() + and len(counted(log_path, "schedule_dispatch_failed")) >= 2 + ), + timeout=GUARD, + ), log_path.read_text()[-4000:] + # The queue is drained and the dispatch has failed more than + # once: a batch that could end has had every chance to. + assert proc.poll() is None, log_path.read_text()[-4000:] + assert processes_of(marker), "the worker is not running" + finally: + code, log = stop(proc, log_path) + assert code == 0, log + (first, *_) = lines(log, "schedule_dispatch_failed") + assert "unexpected exception (ConnectionError)" in first, first + assert not lines(log, "worker_batch_empty"), log + assert not OxScheduleTick.objects.exclude(task_id=None).exists() + assert not processes_of(marker), "a process of the worker is still running" + + +class TestAWorkerWhoseDatabaseWillNotMoveABoundary: + """ + A stored row retimed by SQL, on a database that refuses to let its + boundary be moved for as long as a trigger on the table stands. The move + is tried at the start of every dispatch pass, about once a second, and + refused each time. The worker says so once with the traceback, and after + that at most once a minute in a line that carries none; the move is + still tried, and the rest is dispatched. + """ + + def test_it_is_said_in_full_once_and_the_schedule_beside_it_keeps_firing( + self, tmp_path + ): + base = twelve_hours_ago() + root = project(tmp_path, {}) + beside = every_second() + victim = a_row("victim", base) + set_column(victim.pk, "cron", f"'{daily_cron_at(base - timedelta(hours=1))}'") + log_path = tmp_path / "worker.log" + fired = OxScheduleTick.objects.filter(schedule_name=f"db:{beside.pk}").exclude( + task_id=None + ) + + with refusing_moves_of(victim): + proc = start(root, log_path, batch=False) + try: + assert wait_for( + lambda: counted(log_path, "schedule_boundary_heal_failed"), + timeout=GUARD, + ), log_path.read_text()[-4000:] + # Each tick of the schedule beside it is a dispatch pass, and + # a pass tries the move before it dispatches anything. + seen = fired.count() + assert wait_for(lambda: fired.count() >= seen + 3, timeout=GUARD), ( + log_path.read_text()[-4000:] + ) + finally: + code, log = stop(proc, log_path) + assert code == 0, log + said = lines(log, "schedule_boundary_heal_failed") + in_full = f"Could not move schedule {victim.pk} onto its current timing" + assert [line for line in said if line.endswith(f" {in_full}")] == said[:1], said + # Any line after the first is the summary a minute on, and the + # database's error was printed with the first alone. + assert all(" Still could not move schedule " in line for line in said[1:]), said + assert log.count(f"django.db.utils.{refused_as().__name__}: ") == 1, log + assert not lines(log, "schedule_row_skipped"), log + assert ticks_of(f"db:{victim.pk}") == [], "the row was dispatched" + + +class TestAWorkerBesideACountOfBoundaryWritesAtItsMaximum: + """ + A stored row retimed by SQL whose count of boundary writes is the most + its column can hold. Moving its boundary would add one to the count, + which PostgreSQL and MySQL refuse and SQLite keeps as a float. So the + worker tries no move: it names the row once, by that field, leaves it + out and as it is, and dispatches the rest. + """ + + def test_the_row_is_named_once_and_left_as_it_is(self, tmp_path): + base = twelve_hours_ago() + root = project(tmp_path, {}) + beside = every_second() + victim = a_row("victim", base) + set_column(victim.pk, "boundary_generation", largest_count()) + set_column(victim.pk, "cron", f"'{daily_cron_at(base - timedelta(hours=1))}'") + as_sql_left_it = OxSchedule.objects.filter(pk=victim.pk).values().get() + log_path = tmp_path / "worker.log" + fired = OxScheduleTick.objects.filter(schedule_name=f"db:{beside.pk}").exclude( + task_id=None + ) + + proc = start( + root, + log_path, + batch=False, + env={"OX_TEST_LOG_FORMAT": RECORD + "%(event)s %(fields)s %(message)s"}, + ) + try: + assert wait_for( + lambda: counted(log_path, "schedule_row_skipped"), timeout=GUARD + ), log_path.read_text()[-4000:] + # Each tick of the schedule beside it is a dispatch pass. + seen = fired.count() + assert wait_for(lambda: fired.count() >= seen + 3, timeout=GUARD), ( + log_path.read_text()[-4000:] + ) + finally: + code, log = stop(proc, log_path) + assert code == 0, log + (skipped,) = lines(log, "schedule_row_skipped") + assert skipped == ( + f"{RECORD}schedule_row_skipped ['boundary_generation'] Skipping stored " + f"schedule victim (pk {victim.pk}): its boundary_generation holds " + f"{largest_count()}, the most its column can hold, so the count cannot " + "be raised" + ) + # No move of its boundary was tried, so none failed and none was made. + assert not lines(log, "schedule_boundary_heal_failed"), log + assert not lines(log, "schedule_boundary_healed"), log + assert "Traceback" not in log, log + assert OxSchedule.objects.filter(pk=victim.pk).values().get() == as_sql_left_it + if connection.vendor == "sqlite": + with connection.cursor() as cursor: + cursor.execute( + "SELECT typeof(boundary_generation) FROM django_ox_oxschedule " + "WHERE id = %s", + [victim.pk], + ) + assert cursor.fetchone() == ("integer",) + assert ticks_of(f"db:{victim.pk}") == [], "the row was dispatched"