Skip to content

Fix: stop one DB failure from ending the whole monitor - #679

Open
rhaegar325 wants to merge 1 commit into
mainfrom
update_monitor
Open

Fix: stop one DB failure from ending the whole monitor#679
rhaegar325 wants to merge 1 commit into
mainfrom
update_monitor

Conversation

@rhaegar325

Copy link
Copy Markdown
Collaborator

Fix #627

Problem

A sqlite3.DatabaseError: database disk image is malformed raised while
reconciling the first of 100 sub-jobs killed the monitor 4m42s into a
24h30m walltime (Exit Status: 1, not a PBS kill). The other 99 outcomes were
never recorded and had to be recovered by parsing logs/*/cmor_*.err.

batch_cmoriser.py:1102  monitor_loop     reconcile_one(...)
batch_cmoriser.py:557   reconcile_one    tracker.set_pbs_info(...)
tracking.py             _execute_with_retry
sqlite3.DatabaseError: database disk image is malformed

Four defects turned one bad row into a total loss. All predate this PR; none
are regressions.

Changes

1. monitor_loop — per-sub-job guard

The per-job body made two unguarded DB calls (reconcile_one, get_status).
Either raising ended the loop for every remaining sub-job. Each sub-job is
now guarded on its own.

A sub-job that cannot be reconciled is dropped, not retried every poll:
anything that gets past TaskTracker's retry wrapper is not transient, and a
permanently broken DB would otherwise pin the loop until walltime. Its
variable, job id, PBS state and exit status go to stderr, so the outcome
survives even when the DB write does not.

2. monitor_mainfinalize_monitor moved into a finally

finalize_monitor sat after monitor_loop in the try body, so the one
function written to reclassify exactly these lost-write rows never ran. It now
runs on every exit path, wrapped so its own failure cannot mask the exception
already on its way out.

Side effect: it also runs on the SystemExit from shutdown_handler, which
removes the sidecar that otherwise blocks the output directory permanently.

3. finalize_monitor — per-variable guard

Without this, change 2 fixes nothing. A corrupt DB is not uniformly
corrupt. Measured against the real database from the incident:

get_status over 100 variables:  ok=50  raised=50
mark_failed over 100 variables: ok=50  raised=50

The unguarded sweep died on the first bad row — reachable or not, it would
have reclassified nothing, written no report, and left the sidecar behind.
Guarded per variable, the same database now yields:

Batch monitor done. completed=0, failed=50, fixed_stuck=12, unreadable=50
Wrote batch coordination report: moppy_batch_report_...json
sidecar removed  →  output directory unblocked

unreadable is a new summary field; unreadable variables are named on stderr.

4. TaskTracker._execute_with_retry / _init_db — correct exception class

Both caught sqlite3.OperationalError, a subclass of DatabaseError, so
"database disk image is malformed" passed straight through the wrapper. Now
caught as DatabaseError. The _TRANSIENT message check is unchanged, so the
retry path behaves identically; only the blind spot for non-OperationalError
DB failures is closed.

Need further investigate and update related to DB and lustre system

Gadi mounts every Lustre filesystem with localflock:

/scratch/tm70   lustre  rw,nosuid,nodev,localflock,lazystatfs
/g/data/tm70    lustre  rw,nosuid,nodev,localflock,lazystatfs

localflock makes fcntl/flock node-local: they are not coordinated
across nodes. SQLite's entire concurrency model rests on POSIX advisory locks,
so ~100 workers on ~100 different compute nodes can each hold an "EXCLUSIVE"
lock on the same file and write simultaneously.

Evidence from the incident database:

On tree page 14 cell 7:  Rowid 83 out of order
On tree page  2 cell 18: 2nd reference to page 14   ← two writers, same page
wrong # of entries in index idx_var_exp

100 rows, 86 still readable. All 100 workers ran 13:10:14–13:14:40, ~90 of
them writing within the first 60 seconds; the monitor hit the damaged page at
13:10:44.

A second run (1pctCO2-01, 66 nodes) shows the milder form of the same fault:
integrity_check: ok, but 14 of 100 start_time values silently lost. SQLite
writes whole pages, not rows — 99 rows share one 4096-byte leaf page, so
two nodes read the page, each edit their own row, and the later write-back
discards the earlier one. Reproduced with 20 writers over strictly disjoint
rows under nolock=1: 6–10% of writes lost, integrity_check still ok.

What still needs to change

Retries cannot help and synchronous=FULL cannot help — the fault is locking,
not durability. The only real fix is to remove concurrent cross-node writes:

  • Single-writer (recommended). Workers stop writing SQLite and drop a
    per-variable logs/<var>/status.json; the monitor ingests these each poll
    and is the sole writer.
  • Also required for that to be real: --append-variable writes
    add_task + enqueue_monitor_request from the login node while the
    monitor is running
    (batch_cmoriser.py:1381-1397) — it needs a file-based
    queue. qc/backfill_compliance.py needs the same convention.
  • Then synchronous=OFF (tracking.py:60) can go back to NORMAL; it was
    only turned off to dodge fsync EIO under concurrency.

This is deliberately a separate PR: it changes the worker template, so every
sub-job script changes and it needs a real multi-node PBS run to validate.
Landing it on top of this PR means its new failure modes are already guarded.

@codecov

codecov Bot commented Aug 28, 2026

Copy link
Copy Markdown

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 78.2%. Comparing base (9938f8a) to head (d7bcc47).

Additional details and impacted files
@@          Coverage Diff          @@
##            main    #679   +/-   ##
=====================================
  Coverage   78.2%   78.2%           
=====================================
  Files         40      40           
  Lines       8827    8842   +15     
  Branches    1665    1665           
=====================================
+ Hits        6901    6916   +15     
  Misses      1591    1591           
  Partials     335     335           
Flag Coverage Δ
unit 78.2% <100.0%> (+<0.1%) ⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Harness.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Monitor dies on the first DB error, skipping finalize_monitor and leaving the batch unreconciled

1 participant