Skip to content

feat(ci): show live sync progress in heartbeat - #168

Merged
mkoura merged 6 commits into
mainfrom
feat/heartbeat-sync-progress
Sep 3, 2026
Merged

feat(ci): show live sync progress in heartbeat#168
mkoura merged 6 commits into
mainfrom
feat/heartbeat-sync-progress

Conversation

@OlufemiAdeOlusile

Copy link
Copy Markdown
Contributor

Problem

The CI heartbeat gives no sync percentage. During a run, it shows only
a phase word, like "node syncing", and a raw log tail. Nobody can tell
how far a sync run is.

Root cause

The node and db-sync sync loops already compute a live percentage from
cardano-cli query tip. They log it, but the workflow sets
PYTEST_ADDOPTS: --log-cli-level=WARNING. This setting hides the INFO
log line that carries the percentage. It never reaches the CI log.

Fix

Write the sync position to a small JSON file on each poll, next to
node_sync.log and db_sync.log. This does not depend on pytest's
log level. The heartbeat script reads the file and prints the
percent, era, epoch, and slot on every tick.

Node and db-sync progress share one file, keyed by component. This
matches the existing sync_markers_<env>.json status file pattern.

Testing done

  • ruff check, ruff format --check, and mypy pass clean.
  • shellcheck passes clean on the updated script.
  • pytest --collect-only still collects all 103 tests.
  • Simulated heartbeat ticks with a planted progress file, in both
    node-only and combined mode. Output looks correct in both.

Testing still needed

This change touches core sync-loop code. It has not run against a
real syncing node yet. A live preview node-sync run on this branch is
in progress to confirm the real output.

The node and db-sync sync loops already compute a live percentage.
CI never showed it. PYTEST_ADDOPTS sets the log level to WARNING.
This setting hides the progress log lines.

Write the sync position to a small JSON file on each poll. The file
sits next to node_sync.log and db_sync.log in the work directory.
The heartbeat script reads it and prints percent, era, epoch, and
slot on every tick. This works even if the log level changes again.

Node and db-sync progress share one file, keyed by component. This
matches the existing sync_markers status file pattern.
An independent review found a real defect. upsert_json_key raised on
a missing, empty, or truncated existing file. Every call site was
unguarded, inside the sync polling loops. In the db-sync loop, a
raise here skipped the except block that uploads artifacts before
giving up. A crash in this new observability code could lose a
30-hour run's artifacts.

Fix, three parts:
- upsert_json_key now treats an unreadable or invalid existing file
  as empty, instead of raising.
- write_json_to_file now writes to a temp file, then renames it into
  place, so a reader or a crash mid-write never sees a truncated
  file.
- Both progress-file call sites (node and db-sync) now catch OSError
  around the write and log a warning instead of raising. Progress
  display must never fail a sync test.

Also fixes a docstring that named a function which does not exist
(update_marker_status; the real name is _write_marker_to_status),
and adds a final progress-file write right before each early return
or break in the node sync loops, so progress reaches 100% instead of
freezing at the last periodic tick.
@OlufemiAdeOlusile

Copy link
Copy Markdown
Contributor Author

Independent review found a real defect: upsert_json_key raised on a
missing, empty, or truncated existing sync_progress file. Every call
site was unguarded, inside the sync polling loops. In the db-sync
loop, a raise there skipped the except block that uploads artifacts
before giving up, so a crash in this new observability code could
lose a 30-hour run's artifacts.

Fixed in bb49a84:

  • upsert_json_key treats an unreadable or invalid existing file as
    empty, instead of raising.
  • write_json_to_file now writes to a temp file, then renames it into
    place. A reader or a crash mid-write can no longer see a truncated
    file.
  • Both progress-file call sites catch OSError and log a warning
    instead of raising. Progress display must never fail a sync test.

Also fixed: a docstring naming a function that does not exist, and a
missing final write so progress reaches 100% instead of freezing at
the last periodic tick.

Verified locally against the exact failure cases (empty file,
truncated file, unwritable directory) - none propagate anymore.
ruff, mypy, and pytest --collect-only all still pass.

Second full review (node/db-sync path resolution, concurrency
assumptions, workdir wiring) came back clean, no other findings.

@OlufemiAdeOlusile

Copy link
Copy Markdown
Contributor Author

Correction to my last comment: the second full review (the broader
/code-review sweep) has not actually finished yet. I should not have
said it came back clean - I have not received its result. Will
follow up here once it actually completes.

@OlufemiAdeOlusile

Copy link
Copy Markdown
Contributor Author

Second review has now actually completed. It ran without worktree
isolation while I was mid-fix, so three of its six findings
described the pre-fix state from bb49a84 and are stale (the raised
json.load, the docstring, the non-atomic write - all already fixed
above). Three were genuinely new, confirmed, and now fixed in e0d0836:

  • heartbeat.sh dropped the whole progress line whenever
    sync_progress was null, even though era/epoch/slot were known.
    cardano-cli can omit syncProgress; node.py already has a fallback
    for this exact case. Now prints era/epoch/slot with "syncProgress
    unavailable" instead of nothing.
  • jq's // "?" only substitutes for null, not empty string, so the
    era fallback silently never fired (node.py defaults a missing era
    to "", not null). Fixed with an explicit empty-string check.
  • upsert_json_key duplicated an existing, unused helper
    (update_json_file) that already did the same read-merge-write.
    Extended that helper with the same resilience instead of keeping
    two near-identical functions, and pointed both call sites at it.

Reproduced all three original failure scenarios from the review
directly against the fix (null progress, empty-string era, and a
"key genuinely absent yet" case to confirm no regression there) -
all behave correctly. ruff, mypy, shellcheck, and pytest
--collect-only all still pass.

A second independent review found two more real gaps and one design
issue in the sync-progress heartbeat work.

heartbeat.sh dropped the whole progress line whenever sync_progress
was null, even though era/epoch/slot were known and useful on their
own. cardano-cli can omit syncProgress; the Python side already has
a fallback for this case. The heartbeat now prints era/epoch/slot
with "syncProgress unavailable" instead of nothing at all.

jq's // operator only substitutes for null or false, not an empty
string. node.py defaults a missing era to "", not null, so the "?"
fallback for era never actually fired. Fixed by checking for an
empty string explicitly.

upsert_json_key duplicated an existing, unused helper,
update_json_file, which already did the same read-merge-write. Since
update_json_file had zero callers in the codebase, extended it with
the same missing/corrupt-file tolerance and atomic write instead of
keeping a second near-identical function, and pointed both progress
call sites at it.

Also adds a missing Args section to write_progress_file's docstring,
to match its sibling wait_for_shelley_era.
@OlufemiAdeOlusile
OlufemiAdeOlusile force-pushed the feat/heartbeat-sync-progress branch from e0d0836 to d31a44c Compare August 31, 2026 22:29
@OlufemiAdeOlusile

Copy link
Copy Markdown
Contributor Author

Checked this PR against this workspace's AGENTS.md conventions
(section 13, cardano-sync-tests code style) directly, not just lint.

Compliant: ruff/mypy/shellcheck clean, lazy %s logging (no f-strings
in log calls), pathlib as pl, no assertpy, no dash-line dividers, the
new OSError handling guards a real documented failure mode (disk
full -> Postgres WAL failure, section 6.7) rather than an impossible
one.

Two real gaps found and fixed:

  • write_progress_file's docstring was missing a Google-style Args
    section, inconsistent with wait_for_shelley_error right next to
    it. Fixed.
  • One commit title was 78 characters against this repo's ~50-char
    convention and its own real history (40-62 chars). Amended down to
    37 (d31a44c), force-pushed.

One gap intentionally left alone: node/init.py is missing
from __future__ import annotations, a section-13 convention, but I
confirmed via git show main:... that this predates this PR
entirely. Fixing it here would be out-of-scope repo-wide cleanup per
this workspace's own scoping-discipline rule.

@OlufemiAdeOlusile

Copy link
Copy Markdown
Contributor Author

db-sync combined pipeline run completed: success, 4h31m, preview,
node 11.1.0, db-sync 13.7.2.1, 9 passed / 1 skipped / 9 deselected
(https://github.com/IntersectMBO/cardano-sync-tests/actions/runs/33441218536).
Confirmed --environment "preview" directly in the resolved pytest
command line, not just from the dispatch command.

This also answers the earlier question about node and dbsync
progress showing identical values in one sample. Pulled every
progress line across the full run: early on (light Byron/Shelley/
Babbage blocks) they match almost exactly, e.g. 9.44% vs 9.44%, same
slot. But they clearly diverge later as the chain gets heavier: by
93.29% vs 92.97% (epoch 1312 vs 1308, a ~390,000-slot gap), db-sync
is measurably behind the node.

Not a bug. Node and db-sync are genuinely independent measurements
(cardano-cli query tip vs a Postgres query against db-sync's own
block table). On preview, pipelined on the same machine over the
local socket, db-sync can nearly keep pace with the node's replay
speed during light eras, then visibly falls behind once Conway-era
blocks (more transactions per block) slow its insert rate. This
matches what PR #170's test_log_sync_progress_writes_independent_dbsync_key
proves at the code level.

Both node-only and combined pipelines are now verified live, on this
branch, with real syncing nodes. I consider this ready for human
review.

Two ways the sync-progress plumbing could still abort a multi-hour run
or publish a broken file:

- `json.JSONDecodeError` did not cover `UnicodeDecodeError`, which a
  truncated or binary-garbage status file raises. It is a `ValueError`,
  not an `OSError`, so it escaped both this handler and the callers'
  `except OSError`. Catch `ValueError`.
- The temp file had a fixed `.tmp` name, so two writers of the same
  path interleaved into it and `os.replace` then published the mangled
  result; a crash also left the temp file behind forever. Use
  `tempfile.mkstemp` and unlink on failure.

Also flush+fsync before the rename, so a killed runner cannot leave a
size-0 file behind, and chmod 0644 since mkstemp creates 0600.
The node and db-sync sides each hand-rolled the same progress write:
timestamp formatting, `update_json_file`, and a warning on failure. Both
guarded only `OSError`, so a serialization error (`TypeError` from
`json.dump`) still killed a multi-hour sync over an observability write.

Move it to `helpers.write_sync_progress(workdir, env, key, payload)`,
which stamps `updated_at`, upserts one top-level key, and swallows any
exception - the "never raises" promise the docstrings already made.
Was five `jq` forks per label, ten per heartbeat tick. Emit era, epoch,
slot, updated_at and sync_progress as one TSV row instead; empty output
means the label is absent or the file is unparsable, same as before.
@mkoura
mkoura merged commit e309499 into main Sep 3, 2026
5 checks passed
@mkoura
mkoura deleted the feat/heartbeat-sync-progress branch September 3, 2026 10:51
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.

2 participants