Skip to content

ci(seekdb): retain migration timeout diagnostics - #1945

Draft
Zxf-xufeng wants to merge 3 commits into
masterfrom
codex/fix-1920-seekdb-ddl-hang
Draft

Zxf-xufeng wants to merge 3 commits into
masterfrom
codex/fix-1920-seekdb-ddl-hang

Conversation

@Zxf-xufeng

@Zxf-xufeng Zxf-xufeng commented Oct 12, 2026 •

Copy link
Copy Markdown
Member

Which issue or RFC does this PR close?

Refs #1920. The reopen/DDL hang is caused by a seekdb transaction-recovery bug, identified in oceanbase/seekdb#1499. This PR preserves diagnostic evidence; it does not implement or deliver the upstream engine fix and does not close the issue. See the investigation evidence and reproduction procedure for the reproduction commands and the distinction between the CI and local lock owners.

Rationale for this change

When embedded seekdb stalls on CREATE TABLE pc_schema_revision, the existing 8 MiB log tails can lose the earlier transaction that acquired the lock. Preserve the available native history and capture live lock evidence before terminating the stalled test so the next Ubuntu CI failure can be investigated.

Confirmed root cause

After a data directory is reopened, seekdb reconstructs undecided transactions and their locks from redo. The recovered transactions remain marked for_replay, but both garbage collection and timeout handling exclude those replay contexts. Without takeover into local transaction completion, the recovered transaction can retain row or MDS table locks indefinitely. This explains why closing and reopening the engine did not clear the RUNTIME:1 exclusive lock blocking CREATE TABLE pc_schema_revision; the problem is missing recovery completion, rather than evidence of an unusually slow rollback. The root cause and proposed fix are documented in seekdb PR #1499.

The upstream fix takes over recovered transactions after the replay barrier and log-append activation, before admitting new transactions. It durably aborts recovered INIT transactions and undecided MDS table-lock transactions, resumes the existing commit protocol for other complete REDO_COMPLETE contexts, and arms completion retries before leaving replay mode. Incomplete or unexpected contexts retain replay protection and fail activation.

Our extended Ubuntu/Python 3.11 observation, using reproduction commit 0b4dd71c0e5f8189096f2958e79007440c438da2 and pylibseekdb==1.4.0.post1, passed 10 attempts and reproduced the hang on attempt 11. All 22 snapshots from 45 through 990 seconds showed transaction 1000002 holding the same RUNTIME:1 X lock, created at 2026-10-12T11:16:33.254907Z. After two subsequent close/reopen cycles, the last valid snapshot at 2026-10-12T11:32:57.764578Z still showed it held: a confirmed lower bound of 984.51 seconds. The DDL then returned (4012, 'Timeout') after approximately 1000 seconds; the attempt exited after 1010.55 seconds with timed_out: false, before the 1200-second probe deadline. No valid lock-absent snapshot was captured, so SQL timeout and subsequent teardown do not establish a lock-release time. Evidence: seekdb-lock-observation-38235338219-1.

At the time of this update, seekdb PR #1499 is open. Its reported regressions cover uncommitted row-redo recovery and preservation of committed data; a separate MDS table-lock recovery case is not included. The original PowerContext reproduction still needs validation against a seekdb build containing the fix. This diagnostic PR does not change the seekdb dependency or establish that a released binding contains the fix.

What changes are included in this PR?

  • Run each migration runner case through a supervisor that captures sessions, locks, transactions, and startup jobs after 90 seconds and retains the 180-second test deadline. The diagnostic connection uses the existing Unix socket without opening another native lifecycle handle.

  • Keep the text log tails and upload seekdb-native.tar.gz with complete available native log files, including timestamped rotations, from disposable migration test instances. Database data files are excluded; log files already removed by native rotation or fixture cleanup cannot be recovered.

  • Upload the live diagnostic snapshot alongside the existing Python and SQL logs. GitHub artifact retention settings are unchanged.

  • Run the baseline-adoption recovery case three times in each Python 3.11/3.14 job. These are required independent runs, not retries; a failed run stops the job.

  • Add a separate Ubuntu/Python 3.11 observation workflow pinned to the documented reproduction snapshot 0b4dd71c. It collects snapshots every 45 seconds and allows up to 1200 seconds per attempt to distinguish recovery from SQL timeout. Ordinary migration CI retains its 180-second deadline.

Are there any user-facing changes?

No runtime API, persisted schema, or business database changes. CI artifacts contain more diagnostic history and may be larger. The additional runs add CI time.

How was this change tested?

  • After rebasing onto 4ae1371c: UV_NO_SYNC=1 UV_OFFLINE=1 PREK_NO_CONCURRENCY=1 make check passed, including lock consistency, 110 workflow action references, all pre-commit checks, type checks, and 49 integration-manifest tests.
  • On that base, the supervised original failure case passed in 24.27 seconds on macOS ARM64, Python 3.14.6, and pylibseekdb==1.4.0.post1.
  • On the preceding base, the CI migration prerequisite selection passed 19 cases; sequential migration runners passed 11 cases and skipped one OceanBase-only case. The original failure case passed six independent runs. These runs did not reproduce the Ubuntu hang.
  • Manual supervisor checks preserved success/failure exit codes and returned 124 for a deliberately stalled test. Archive checks retained all bytes of a 13.3 MB log plus rotated logs, excluded database files and symlinks, and handled an empty log directory. Executing the workflow's EXIT collector preserved the original timeout exit code 124 while producing both artifacts.
  • Ruff and ty passed for the new script; the workflow shell passed bash -n; git diff --check passed.
  • Ubuntu CI and Python 3.11 execution of the new supervisor remain to be validated by this PR. Local Python 3.14 success does not establish that the intermittent issue is resolved.

AI usage statement

Implemented and validated with OpenAI Codex.

@Zxf-xufeng

Copy link
Copy Markdown
Member Author

SeekDB RUNTIME:1 lock stall: evidence and reproduction

Refs #1920 and #1716. The stall has now been observed in Ubuntu CI, and a related lock-stall symptom was reproduced in an isolated macOS test. The underlying defect is not fixed, and the current reproducer is probabilistic, not deterministic. These observations do not establish that #1945's diagnostic changes have passed their own CI or fixed the issue.

Confirmed CI failure

  • Run 38220933107, reproduce job 114716751150, triggered for PR feat(dream): expand reviewed artifact and tag revisions #1716 head 0b4dd71c0e5f8189096f2958e79007440c438da2. The artifact is named for CI merge SHA 00212472940c8f53fa4043720ffa0631525dc65d.
  • Ubuntu GitHub runner, Python 3.11.17, locked Python package pylibseekdb==1.4.0.post1; SELECT VERSION() reports seekdb-v1.4.0.0.
  • Test: tests/builtin/persistence/test_mysql_migration_runner.py::test_mysql_baseline_adoption_recovers_an_empty_committed_version_table[seekdb].
  • Attempts 1–3 passed; attempt 4 exceeded the 180-second deadline. result.json: passed=false, timed_out=true, exit_code=-15, duration 180.09576494799998 seconds. This is the supervisor terminating the stalled pytest process, not a native SeekDB crash exit code.

All times in this timeline are 2026-10-12 UTC:

Time Evidence
08:03:59.182208–08:03:59.182348 Native thread T1_MaintainDepI requests and successfully acquires the RUNTIME:1 X lock in transaction 1000002, session 159. pack_and_execute_task_ reports ret=0, OB_SUCCESS.
08:03:59.207994 The lifecycle recorder records closing, approximately 26 ms after lock acquisition. close_returned follows at 08:03:59.208183; reopening starts at 08:03:59.209969.
08:04:02.049068 / 08:04:02.082661 Reopening completes; native logs still show create_trans_id=1000002, RUNTIME:1, X, IN_TRANS_COMMON_LOCK, DOING, with the original lock creation timestamp.
08:04:02.114040–08:04:05.150878 Another close/reopen cycle occurs. The same old lock appears again at 08:04:05.191986 and in subsequent request-worker logs.
Snapshots at 45, 90 and 135 seconds Connection 85 remains on the same CREATE TABLE pc_schema_revision statement, with query ages 32, 77, and 122 seconds. All three snapshots show transaction 1000002 holding RUNTIME:1 in X mode.
120 / 180 seconds Pytest emits a faulthandler stack; the supervisor subsequently terminates the stalled test at its deadline.

The transaction snapshots also show session_id=0, is_decided=0, state=10, replay_complete=1, is_exiting=0, and expired_time=null for transaction 1000002. These are raw diagnostic fields, not proof of a particular recovery-code defect. The empty __all_virtual_lock_wait_stat result does not negate the runtime-object-lock evidence.

The CI lock owner is the dependency-information maintenance background thread (T1_MaintainDepI), not SystemPkgLoad. In the separate macOS reproduction, transaction 1159 acquired the same runtime lock from SystemPkgLoad while loading dbms_stats, immediately before a no-client exit. Do not substitute that local thread identity for the CI finding or assume both runs have an identical root cause.

Reproduction procedure

Use a disposable Linux checkout with Git, uv and Python 3.11 available. The commands below install the repository's locked dependencies, start temporary native SeekDB instances and write potentially large diagnostic logs. They do not require an external database or production credentials. Each attempt uses its own temporary database.

The reproducible source snapshot below is the #1716 head associated with the failure; the original GitHub run used the CI merge commit noted above. The probe is linked explicitly because it is a separate script from #1945's supervisor.

repro_root="$(mktemp -d /tmp/pc-seekdb-repro.XXXXXX)"
git clone https://github.com/oceanbase/powercontext.git "$repro_root/repo"
cd "$repro_root/repo"
git checkout --detach 0b4dd71c0e5f8189096f2958e79007440c438da2

uv run --python 3.11 --locked --extra seekdb \
  python scripts/probe_seekdb_migration_lock.py \
  --attempts 12 \
  --timeout 180 \
  --output "$repro_root/evidence"
probe_exit=$?
printf 'Probe exit: %s\nEvidence: %s\n' "$probe_exit" "$repro_root/evidence"

Probe source · CI workflow · Test source

The probe runs the selected test sequentially, with a fresh disposable database per attempt, and stops at the first failure. The test loads the pre-migration schema and sample rows, runs migration planning/application across native close/reopen cycles, and tests recovery after a committed DDL interruption. The observed stall occurs while executing CREATE TABLE pc_schema_revision, before the test's after-DDL interruption hook can run.

The probe retains:

  • environment.json: platform, Python and package version.
  • attempt-XX/pytest.log: SQL trace and the 120-second faulthandler dump.
  • lifecycle.jsonl: native open/close events.
  • native-*.gz: captured native logs, including early history and observed rotations. The first successful baseline and failing attempt retain these archives; later successful attempts discard theirs.
  • snapshot-45.jsonl, snapshot-90.jsonl, snapshot-135.jsonl: live sessions, transactions and locks when an attempt lasts long enough.
  • result.json: pass/fail, process exit code and timeout status.

Temporary engine files are removed after log collection; the evidence directory is retained. Use a fresh output directory for each invocation.

Matching the failure and interpreting the result

A timeout alone is insufficient. Confirm the combination of a stalled DDL, a RUNTIME:1 X lock held by a pre-reopen transaction, and the same lock persisting after reopening. Transaction IDs are not fixed. A different failed assertion, missing dependency or unrelated timeout is not this reproduction.

Twelve successful attempts do not prove the defect absent. The fourth-attempt failure is one observed run, not a measured failure rate. A deterministic reproducer would need a validated native synchronization/fault-injection point that closes the instance after the background transaction acquires the lock; no such deterministic reproducer has been established.

Evidence location and remaining investigation

Artifact ID 11734103392, seekdb-lock-probe-00212472940c8f53fa4043720ffa0631525dc65d, on the linked run. Relevant members are attempt-04/native-000-seekdb.log.gz, lifecycle.jsonl, pytest.log, snapshot-*.jsonl and result.json. The native file was inspected through the startup/acquisition/reopen interval using range extraction; the entire native archive has not been exhaustively reviewed. Artifacts are subject to GitHub retention; the key fields and timeline above preserve the essential finding here.

The evidence supports investigating unfinished background transactions across embedded close/reopen and recovery. Why SeekDB does not promptly commit/abort this transaction and release the lock remains unresolved. Lock acquisition by a background task is not itself proof of a defect; the persistence and cleanup behavior require investigation. Increasing the test timeout or observing a later passing run would not establish a fix.

@AlexStocks AlexStocks added the 1.4.0 v1.4.0 release tracking label Oct 14, 2026

This branch has not been deployed

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

Labels

1.4.0 v1.4.0 release tracking

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants