From c512dc975b02c5c2f2976604b511e1c0099aa92c Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 23 Oct 2026 20:53:15 +0000 Subject: [PATCH] Port did.fun.timestamp, the leap-second datestamp clamp, and SQLite BUSY/READONLY retry Brings the three entries bin/check_bridge_coverage.py reported against DID-matlab main back in sync. timestamp (new, DID-matlab bb29861): did.fun.timestamp(raw=None) returns the current UTC time as 'yyyy-mm-ddTHH:MM:SS.fffZ' and clamps a ':60' leap second (with or without a fraction or trailing Z) to ':59.999' with MATLAB's regex. document (bb29861): Document stamps base.datestamp with did.fun.timestamp(). The private _utc_timestamp it replaces had a looser clamp (':60.123' -> ':59.999123'), so it is removed. sqlitedb (decd155, da83fa3): 30 s busy timeout on open; do_run_sql_query retries BUSY/READONLY with MATLAB's backoff schedule, reopening the connection first for READONLY (poisoned handle / DBMOVED); exhausted retries print the filesystem diagnostics. Because SQLiteDB groups writes into transactions where mksqlite autocommits, the statement retry runs only with no transaction open, and COMMIT is retried (never reopened) through a new _commit(). Deviations are recorded in the bridge entry. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_012Dn4gCNCU2jUGdmfPVCAGK --- src/did/did_matlab_python_bridge.yaml | 13 +- ..._matlab_python_bridge_implementations.yaml | 64 ++++- src/did/did_matlab_python_bridge_util.yaml | 35 +++ src/did/document.py | 21 +- src/did/fun.py | 31 ++ src/did/implementations/sqlitedb.py | 243 +++++++++++++++- tests/test_sqlitedb_transient_errors.py | 269 ++++++++++++++++++ tests/test_timestamp.py | 68 +++++ 8 files changed, 715 insertions(+), 29 deletions(-) create mode 100644 tests/test_sqlitedb_transient_errors.py create mode 100644 tests/test_timestamp.py diff --git a/src/did/did_matlab_python_bridge.yaml b/src/did/did_matlab_python_bridge.yaml index 5e2e58a..d7d29d2 100644 --- a/src/did/did_matlab_python_bridge.yaml +++ b/src/did/did_matlab_python_bridge.yaml @@ -939,7 +939,7 @@ classes: - name: document type: class matlab_path: "+did/document.m" - matlab_last_sync_hash: "c95b4f2" + matlab_last_sync_hash: "bb29861" status: ported python_path: "did/document.py" python_class: "Document" @@ -1414,6 +1414,17 @@ classes: Both languages now accept NAME_ as a numbered entry only when is a non-negative integer. + Sync hash bumped to bb29861 on 2026-10-23. That commit replaced the + constructor's inline char(datetime('now','TimeZone','UTCLeapSeconds')) + with did.fun.timestamp(), which clamps a ':60' leap second to + ':59.999' (DID-matlab issue #53). Ported the same way: Document.__init__ + now stamps base.datestamp with did.fun.timestamp() (see the timestamp + entry in did_matlab_python_bridge_util.yaml). The module-private + document._utc_timestamp it replaces had its own clamp, a plain + ':60.' -> ':59.999' substitution that would have turned ':60.123' into + ':59.999123'; it is removed rather than kept beside the port. + Coverage: tests/test_timestamp.py. + # ----------------------------------------------------------------------- # did.query # ----------------------------------------------------------------------- diff --git a/src/did/did_matlab_python_bridge_implementations.yaml b/src/did/did_matlab_python_bridge_implementations.yaml index 282a03c..d809086 100644 --- a/src/did/did_matlab_python_bridge_implementations.yaml +++ b/src/did/did_matlab_python_bridge_implementations.yaml @@ -29,7 +29,7 @@ classes: - name: sqlitedb type: class matlab_path: "+did/+implementations/sqlitedb.m" - matlab_last_sync_hash: "8bea92c" + matlab_last_sync_hash: "da83fa3" status: ported python_path: "did/implementations/sqlitedb.py" python_class: "SQLiteDB" @@ -133,6 +133,60 @@ classes: new tests, including the acceptance case, the "one fetch shared across members" cache guarantee, and the handler-refused failure). + 2026-10-23: synced through DID-matlab decd155 and da83fa3 (PRs #206, + #207), the slow-drive SQLITE_READONLY work. MATLAB (1) sets + busy_timeout=30000 in open_db, (2) retries a BUSY / READONLY failure in + run_sql_noOpen with backoffs 0.1, 0.2, 0.5, 1, 2, 4 s, (3) closes and + reopens the connection before each READONLY retry (a poisoned handle, + SQLITE_READONLY_DBMOVED, which waiting never clears), and (4) prints + filesystem diagnostics to stderr when the retries are exhausted. + Ported: _open_db passes timeout=30.0 to sqlite3.connect (the same + busy_timeout); do_run_sql_query retries on the same schedule, reopening + first for READONLY; _is_retryable_sql_error, _is_readonly_error and + _collect_readonly_diagnostics mirror the three new MATLAB helpers; the + debug-gated progress messages are printed when self.debug is set. + The three helpers are protected in MATLAB and so carry no member + entries here. _is_retryable_sql_error and _is_readonly_error are + staticmethods (MATLAB's take ~ for the object). The diagnostics run the + same four probes -- db file and time, -journal/-wal/-shm siblings with + sizes, the file's write permission (os.access for fileattrib's + UserWrite), and a temp-file write probe of the directory -- but print + the time as ISO-8601 UTC rather than MATLAB's local datestr. + + DEVIATION -- where the retry may run. mksqlite autocommits every + statement, so in MATLAB a failed statement is the whole unit of work + and re-running it (even after a reopen) is safe. SQLiteDB groups each + add/remove/branch operation into one sqlite3 transaction. Rolling back + or reopening mid-transaction would silently discard the statements + already pending, and a retried tail would then commit a partial + operation. So do_run_sql_query retries only when the connection had no + uncommitted work before the statement; inside a transaction the error + is reported (with diagnostics) and raised at once, and the caller's + existing rollback runs. + + DEVIATION -- the commit is retried too. Because Python's writes reach + the disk at COMMIT rather than at each statement, that is where a + slow-drive failure lands here. Every commit now goes through + _commit(), which retries a BUSY / READONLY COMMIT on the same schedule + while the transaction is still open. It never reopens -- that would + lose the transaction -- so a genuinely poisoned handle (DBMOVED) is not + recovered at COMMIT: the error is raised and the operation rolled back. + Replaying a whole operation after a reopen would cover that case, but + _do_add_doc also copies ingested files, so it is not obviously + idempotent; not attempted. + + DEVIATION -- classification. Like MATLAB, BUSY vs READONLY is judged + from the error message (sqlite3.Error.sqlite_errorcode would be exact + but is 3.11+ only, and this package supports 3.10). Unlike MATLAB, only + sqlite3.Error instances qualify, so an unrelated Python exception whose + text says "read only" is never retried. + + Not ported: MATLAB's run_sql_noOpen also prints every failing query + and its bound values to stderr. That predates these commits, and + Python never did it; only the new diagnostics block is printed here. + Coverage: tests/test_sqlitedb_transient_errors.py (real lock and + read-only-handle failures, with time.sleep replaced). + properties: - name: FileDir python_name: ~ # not ported @@ -174,6 +228,10 @@ classes: Python: do_run_sql_query(query_str, params=()). Python uses parameterized queries. Synchronized 2026-03-15. + Carries MATLAB run_sql_noOpen's BUSY / READONLY retry (decd155, + da83fa3), restricted to statements run with no transaction open; + see the entry-level sync_notes, 2026-10-23. + - name: do_add_doc python_name: _do_add_doc out_of_sync: false @@ -571,6 +629,10 @@ classes: combined "open_db / close_db" entry 2026-08-28 so each method resolves on its own. + Both set a 30 s busy timeout (decd155): MATLAB with pragma + busy_timeout=30000, Python with sqlite3.connect(timeout=30.0), + which is the same setting. Python's previous default was 5 s. + - name: close_db python_name: _close_db decision_log: > diff --git a/src/did/did_matlab_python_bridge_util.yaml b/src/did/did_matlab_python_bridge_util.yaml index 68ba553..71bd4af 100644 --- a/src/did/did_matlab_python_bridge_util.yaml +++ b/src/did/did_matlab_python_bridge_util.yaml @@ -178,6 +178,41 @@ functions: Both provide interactive document graph visualization. Synchronized 2026-03-15. + # ----------------------------------------------------------------------- + # did.fun.timestamp + # ----------------------------------------------------------------------- + - name: timestamp + type: function + matlab_path: "+did/+fun/timestamp.m" + matlab_last_sync_hash: "bb29861" + status: ported + python_path: "did/fun.py" + python_name: "timestamp" + + input_arguments: + - name: raw + type_matlab: "(1,:) char, default char(datetime('now','TimeZone','UTCLeapSeconds'))" + type_python: "str | None, default None (the current UTC time)" + output_arguments: + - name: ts + type_matlab: "char" + type_python: "str" + + decision_log: > + Ported 2026-10-23 from DID-matlab bb29861 (issue #53). Same regex, + (T\d{2}:\d{2}:)60(\.\d+)? -> \g<1>59.999, so a leap second with or + without a fraction and with or without a trailing 'Z' clamps exactly as + in MATLAB, and nothing outside the seconds field is touched. The + default value is the current UTC time as 'yyyy-mm-ddTHH:MM:SS.fffZ', + the shape MATLAB's UTCLeapSeconds char renders. One difference, of + fact rather than of design: Python's datetime cannot represent a leap + second, so the default path never produces ':60' and the clamp only + ever acts on a supplied raw string (e.g. one written by MATLAB). + Python's validator (validate._parses_as_timestamp, via + datetime.fromisoformat) rejects ':60' as java.time.LocalDateTime.parse + does, so the clamp is needed on that path for the same reason. + Coverage: tests/test_timestamp.py, mirroring MATLAB's TestTimestamp. + # ========================================================================= # did.datastructures — Data structure utilities # ========================================================================= diff --git a/src/did/document.py b/src/did/document.py index 8fb58da..1d74115 100644 --- a/src/did/document.py +++ b/src/did/document.py @@ -1,26 +1,9 @@ import contextlib import os -from datetime import datetime, timezone from . import ido from .common import PathConstants - - -def _utc_timestamp(): - """Return the current UTC time as an ISO-8601 millisecond string with 'Z'. - - Ported from NDI-python (ndi.fun.timestamp) with the leap-second guard. - ``str(datetime.utcnow())`` previously emitted a space-separated, - timezone-less string ('2026-07-20 22:36:19.611068') that diverges from the - DID-matlab UTCLeapSeconds ISO-8601 output and from base.schema.json's own - default ('2018-12-05T18:36:47.241Z'); a JS ``new Date()`` parses the - tz-less form as LOCAL time. Emit '%Y-%m-%dT%H:%M:%S.%fZ' truncated to - milliseconds, clamping the (theoretical) leap-second :60 to :59.999. - """ - now = datetime.now(timezone.utc) - ts = now.strftime("%Y-%m-%dT%H:%M:%S.%f")[:-3] - ts = ts.replace(":60.", ":59.999") - return ts + "Z" +from .fun import timestamp class Document: @@ -30,7 +13,7 @@ def __init__(self, document_type="base", **kwargs): else: self.document_properties = self.read_blank_definition(document_type) self.document_properties["base"]["id"] = ido.IDO.unique_id() - self.document_properties["base"]["datestamp"] = _utc_timestamp() + self.document_properties["base"]["datestamp"] = timestamp() for key, value in kwargs.items(): path = key.split(".") diff --git a/src/did/fun.py b/src/did/fun.py index 01060e4..e65f4c2 100644 --- a/src/did/fun.py +++ b/src/did/fun.py @@ -1,5 +1,36 @@ +import re +from datetime import datetime, timezone + import networkx as nx +# A leap-second seconds field (':60' with an optional fraction), kept with its +# 'T HH:MM:' prefix so the date portion is never touched. +_LEAP_SECOND = re.compile(r"(T\d{2}:\d{2}:)60(\.\d+)?") + + +def timestamp(raw=None): + """ + A current UTC timestamp string that is safe for DID schema validation. + + Returns the current time in the ISO-8601 form used throughout DID, + ``'2026-09-18T21:37:45.123Z'``. ``timestamp(raw)`` sanitizes the given + string instead of the current time, which is mainly useful for testing. + + A leap second (``':60'``, with or without a fraction) is clamped back to + ``':59.999'``: the schema validator parses timestamps the way MATLAB's + ``java.time.LocalDateTime.parse`` does, which rejects any seconds value + above 59. Python's ``datetime`` never renders a leap second itself, so on + the default path the clamp is a guard rather than a fix; it matters for + strings that came from MATLAB's ``UTCLeapSeconds`` clock. + + This function mimics the behavior of the Matlab `did.fun.timestamp` + function (DID-matlab issue #53). + """ + if raw is None: + now = datetime.now(timezone.utc) + raw = now.strftime("%Y-%m-%dT%H:%M:%S.%f")[:-3] + "Z" + return _LEAP_SECOND.sub(r"\g<1>59.999", raw) + def docs_to_graph(document_objs): """ diff --git a/src/did/implementations/sqlitedb.py b/src/did/implementations/sqlitedb.py index ce4545f..97efe69 100644 --- a/src/did/implementations/sqlitedb.py +++ b/src/did/implementations/sqlitedb.py @@ -4,7 +4,11 @@ import shutil import sqlite3 import struct +import sys +import tempfile +import time import warnings +from datetime import datetime, timezone from ..database import Database @@ -26,6 +30,17 @@ def _sql_escape(value): return str(value).replace("'", "''") +# How long a statement waits for another connection's lock before SQLite gives +# up with SQLITE_BUSY ("database is locked"). DID-matlab's open_db sets +# ``pragma busy_timeout=30000``; sqlite3.connect's ``timeout`` is the same +# setting, in seconds. +_BUSY_TIMEOUT = 30.0 + +# Seconds to wait between attempts at a transient BUSY / READONLY failure -- +# the schedule DID-matlab's run_sql_noOpen uses. +_RETRY_BACKOFFS = (0.1, 0.2, 0.5, 1, 2, 4) + + # Escape character used in LIKE patterns (see _sql_like_escape / ESCAPE clauses). _LIKE_ESCAPE_CHAR = "\\" @@ -134,7 +149,10 @@ def _open_db(self): return is_new = not os.path.exists(self.connection) - self.dbid = sqlite3.connect(self.connection) + # Wait (rather than fail at once) while another connection holds a + # lock: on a slow, networked or removable drive a lock can take a + # noticeable time to release. Mirrors DID-matlab's busy_timeout=30000. + self.dbid = sqlite3.connect(self.connection, timeout=_BUSY_TIMEOUT) self.dbid.execute("PRAGMA foreign_keys = ON") self.dbid.row_factory = sqlite3.Row @@ -171,7 +189,7 @@ def _ensure_indexes(self): cursor.execute( 'CREATE INDEX IF NOT EXISTS "doc_data_doc_idx" ON doc_data(doc_idx)' ) - self.dbid.commit() + self._commit() def _close_db(self): if self.dbid: @@ -257,13 +275,222 @@ class TEXT NOT NULL, # never re-used -- see _do_add_doc (DID-matlab issue #55). self._create_deleted_docs_table(cursor) - self.dbid.commit() + self._commit() def do_run_sql_query(self, query_str, params=()): + """Run one SQL statement and return its rows. + + A transient BUSY / READONLY failure is retried with backoff, as + DID-matlab's run_sql_noOpen does -- but only when the connection had + no uncommitted work before the statement ran. A retry rolls back, and + a READONLY retry reopens the connection; either would silently discard + statements earlier in an open transaction, so in that case the error + is reported and raised at once for the caller to roll back. + """ + was_idle = not self.dbid.in_transaction + try: + return self._fetchall(query_str, params) + except sqlite3.Error as err: + if not (was_idle and self._is_retryable_sql_error(err)): + self._report_sql_error(err) + raise + last_err = err + + # Nothing was pending, and SQLite statements are atomic, so the failed + # statement applied nothing: re-running it is safe even for an INSERT. + for attempt, backoff in enumerate(_RETRY_BACKOFFS, start=1): + reopen_first = self._is_readonly_error(last_err) + if self.debug: + print( + f"DID:SQLITEDB retryable SQL error (attempt {attempt}/" + f"{len(_RETRY_BACKOFFS)}, {backoff:g} s backoff): " + f"{str(last_err).strip()}\n" + f"{self._collect_readonly_diagnostics()}", + file=sys.stderr, + ) + time.sleep(backoff) + + # A persistent READONLY on a writable file and directory is a + # poisoned connection (SQLITE_READONLY_DBMOVED: SQLite believes + # the file moved out from under the handle). Waiting never clears + # it; reopening does. A plain BUSY needs only the wait, plus a + # rollback of the implicit BEGIN so the retry starts afresh. + if reopen_first or self.dbid is None: + self._reopen_db() + elif self.dbid.in_transaction: + self.dbid.rollback() + if self.dbid is None: + continue # reopen failed; wait and try again + + try: + rows = self._fetchall(query_str, params) + except sqlite3.Error as err: + last_err = err + else: + if self.debug: + print( + f"DID:SQLITEDB query succeeded on retry attempt " + f"{attempt}/{len(_RETRY_BACKOFFS)}" + + (" (after reopen)" if reopen_first else ""), + file=sys.stderr, + ) + return rows + if not self._is_retryable_sql_error(last_err): + break # a different, non-transient error - stop retrying + + if self.dbid is None: + # Leave the object usable for the next call if the path recovers. + with contextlib.suppress(Exception): + self._open_db() + self._report_sql_error(last_err) + raise last_err + + def _fetchall(self, query_str, params=()): cursor = self.dbid.cursor() cursor.execute(query_str, params) return cursor.fetchall() + def _commit(self): + """Commit, retrying a transient BUSY / READONLY failure with backoff. + + In DID-matlab every statement autocommits, so the statement retry in + run_sql_noOpen covers the write that reaches the disk. Here writes + are grouped into a transaction and reach the disk at COMMIT, so the + commit is retried too. It is never reopened: that would discard the + transaction. If SQLite has already rolled the transaction back there + is nothing left to commit, and the error is raised for the caller. + """ + try: + self.dbid.commit() + return + except sqlite3.Error as err: + last_err = err + if self._is_retryable_sql_error(last_err): + for attempt, backoff in enumerate(_RETRY_BACKOFFS, start=1): + if not self.dbid.in_transaction: + break + if self.debug: + print( + f"DID:SQLITEDB retryable COMMIT error (attempt " + f"{attempt}/{len(_RETRY_BACKOFFS)}, {backoff:g} s " + f"backoff): {str(last_err).strip()}", + file=sys.stderr, + ) + time.sleep(backoff) + try: + self.dbid.commit() + return + except sqlite3.Error as err: + last_err = err + if not self._is_retryable_sql_error(last_err): + break + self._report_sql_error(last_err) + raise last_err + + def _reopen_db(self): + """Close and reopen the connection, leaving dbid None if that fails.""" + with contextlib.suppress(Exception): + self._close_db() + self.dbid = None # force a real reopen even if close failed + try: + if self.debug: + print( + "DID:SQLITEDB reopening connection before retry " + "(readonly - likely DBMOVED)", + file=sys.stderr, + ) + self._open_db() + except (sqlite3.Error, OSError): + # Fall through and let the retry (and the final report) run. + self.dbid = None + + @staticmethod + def _is_retryable_sql_error(err): + """Is this a transient SQLite error worth retrying? + + True for SQLITE_BUSY / SQLITE_LOCKED ("database is locked", + "database table is locked") and the SQLITE_READONLY family ("attempt + to write a readonly database"). On a slow drive READONLY's usual + cause is a hot journal awaiting rollback or a transient lock, both of + which clear on their own; a permanently read-only file or mount + simply exhausts the retries and is raised. Only sqlite3 errors count: + a Python exception whose text mentions "read only" is not one. + """ + if not isinstance(err, sqlite3.Error): + return False + msg = str(err).strip().lower() + return SQLiteDB._is_readonly_error(err) or any( + phrase in msg + for phrase in ( + "database is locked", + "database is busy", + "database table is locked", + ) + ) + + @staticmethod + def _is_readonly_error(err): + """Is this the SQLITE_READONLY family specifically? + + Distinguished from BUSY / locked because READONLY on a writable file + means the connection is poisoned (typically SQLITE_READONLY_DBMOVED) + and must be reopened, not merely waited out. + """ + if not isinstance(err, sqlite3.Error): + return False + msg = str(err).strip().lower() + return any(p in msg for p in ("readonly", "read-only", "read only")) + + def _collect_readonly_diagnostics(self): + """Filesystem state behind an "attempt to write a readonly database". + + SQLITE_READONLY has extended causes that need opposite fixes. This + tells them apart without relying on the extended result code: + a hot rollback journal / WAL beside the database (an interrupted + write), a database directory that is no longer writable (a drive + remounted read-only), or a read-only database file. Runs only on the + error path. + """ + filename = self.connection or "" + lines = [ + f" db file: {filename}", + f" time : {datetime.now(timezone.utc).isoformat(timespec='milliseconds')}", + ] + + # Hot journal / WAL siblings left next to the database + for suffix in ("-journal", "-wal", "-shm"): + with contextlib.suppress(OSError): + if os.path.isfile(filename + suffix): + size = os.path.getsize(filename + suffix) + lines.append(f" sibling {suffix} present ({size} bytes)") + + # Is the DB file itself writable? + if os.path.exists(filename): + lines.append(f" db file UserWrite={int(os.access(filename, os.W_OK))}") + + # Is the DB directory still writable? Probe by creating a temp file. + # This is the key discriminator for a drive that remounted read-only. + db_dir = os.path.dirname(filename) or os.getcwd() + try: + with tempfile.NamedTemporaryFile(dir=db_dir, prefix=".did_write_probe_"): + pass + lines.append(" db dir writable: yes") + except OSError as probe_err: + lines.append(f" db dir writable: NO ({probe_err})") + + return "\n".join(lines) + + def _report_sql_error(self, err): + """For a BUSY / READONLY failure that survived the retries, print + filesystem state so the cause can be identified (DID-matlab does the + same, to stderr).""" + if self._is_retryable_sql_error(err): + print( + "SQLite readonly/busy diagnostics:\n" + + self._collect_readonly_diagnostics(), + file=sys.stderr, + ) + # The abstract methods from the Database class will be implemented here. # For brevity, I will start with a few key methods. @@ -299,7 +526,7 @@ def _do_add_branch(self, branch_id, parent_branch_id): (branch_id, doc_idx, time.time()), ) - self.dbid.commit() + self._commit() def _do_get_doc_ids(self, branch_id=None): """Document ids on a branch, or -- with no branch -- in the database. @@ -539,7 +766,7 @@ def _do_add_doc( # 'ignore'/'warn': no-op (do not rewrite content). Commit so any # docs/doc_data rows inserted above for a brand-new doc_id are # persisted, then return. - self.dbid.commit() + self._commit() return # Record the document's file locations. MATLAB's do_open_doc @@ -557,7 +784,7 @@ def _do_add_doc( "INSERT INTO branch_docs (branch_id, doc_idx, timestamp) VALUES (?, ?, ?)", (branch_id, doc_idx, time.time()), ) - self.dbid.commit() + self._commit() except Exception: # Every failure path rolls back so no partial rows survive into the # next transaction, and the fields cache is restored to match. @@ -2320,7 +2547,7 @@ def _do_remove_doc(self, document_id, branch_id, **kwargs): cursor, doc_idx, document_id ) - self.dbid.commit() + self._commit() except Exception: # As in _do_add_doc: a failure part-way through must not leave # the branch_docs delete sitting in an open transaction for the @@ -2374,7 +2601,7 @@ def _do_delete_branch(self, branch_id): self._reclaim_unreferenced_doc(cursor, doc_idx, doc_id) ) - self.dbid.commit() + self._commit() except Exception: self.dbid.rollback() raise diff --git a/tests/test_sqlitedb_transient_errors.py b/tests/test_sqlitedb_transient_errors.py new file mode 100644 index 0000000..dea3c9e --- /dev/null +++ b/tests/test_sqlitedb_transient_errors.py @@ -0,0 +1,269 @@ +"""Retry, reopen and diagnostics for transient SQLite write failures. + +Ported from DID-matlab decd155 and da83fa3 (sqlitedb.m). On a slow, networked +or removable drive a write can fail with SQLITE_BUSY ("database is locked") or +SQLITE_READONLY ("attempt to write a readonly database") and succeed moments +later. DID-matlab now: + +* sets ``busy_timeout=30000`` on open, so a lock is waited for; +* retries a BUSY / READONLY statement with backoff (0.1 .. 4 s); +* reopens the connection before retrying a READONLY, which a poisoned handle + (SQLITE_READONLY_DBMOVED) needs and waiting never cures; +* prints filesystem diagnostics when the retries are exhausted. + +The failures here are real sqlite3 errors, not mocks: a second connection +holds the lock, or the handle is swapped for a read-only one. Only +``time.sleep`` is replaced, so a test never waits out the backoff -- and the +fake sleep is the hook that releases the lock "while we waited". +""" + +import os +import sqlite3 + +import pytest + +from did.implementations import sqlitedb as sqlitedb_module +from did.implementations.sqlitedb import SQLiteDB + +INSERT_BRANCH = ( + "INSERT INTO branches (branch_id, parent_id, timestamp) VALUES (?, ?, ?)" +) + + +@pytest.fixture +def db(tmp_path): + database = SQLiteDB(str(tmp_path / "transient.sqlite")) + # Fail at once on a lock instead of waiting 30 s, so the retry loop -- not + # SQLite's busy handler -- is what each test exercises. + database.dbid.execute("PRAGMA busy_timeout = 0") + yield database + database._close_db() + + +class _Sleeps(list): + """The backoffs requested, plus side effects to run on the next sleeps.""" + + def __init__(self): + super().__init__() + self.on_sleep = [] + + def __call__(self, seconds): + self.append(seconds) + if self.on_sleep: + self.on_sleep.pop(0)() + + +@pytest.fixture +def sleeps(monkeypatch): + """Record each backoff instead of sleeping.""" + fake = _Sleeps() + monkeypatch.setattr(sqlitedb_module.time, "sleep", fake) + return fake + + +def _hold_write_lock(path): + """A second connection holding the RESERVED lock until rolled back.""" + other = sqlite3.connect(path, isolation_level=None) + other.execute("BEGIN IMMEDIATE") + return other + + +def _branch_ids(path): + with sqlite3.connect(path) as check: + return {row[0] for row in check.execute("SELECT branch_id FROM branches")} + + +class TestBusyTimeout: + def test_open_sets_a_30_second_busy_timeout(self, tmp_path): + database = SQLiteDB(str(tmp_path / "timeout.sqlite")) + try: + timeout = database.dbid.execute("PRAGMA busy_timeout").fetchone()[0] + assert timeout == 30000 + finally: + database._close_db() + + +class TestErrorClassification: + @pytest.mark.parametrize( + "message", + [ + "attempt to write a readonly database", + "database is locked", + "database table is locked", + "Database is BUSY", + ], + ) + def test_transient_sqlite_errors_are_retryable(self, message): + assert SQLiteDB._is_retryable_sql_error(sqlite3.OperationalError(message)) + + @pytest.mark.parametrize( + "message", ['near "SELEC": syntax error', "no such table: nope"] + ) + def test_other_sqlite_errors_are_not(self, message): + assert not SQLiteDB._is_retryable_sql_error(sqlite3.OperationalError(message)) + + def test_only_sqlite_errors_count(self): + assert not SQLiteDB._is_retryable_sql_error(ValueError("read only")) + assert not SQLiteDB._is_readonly_error(OSError("read-only file system")) + + def test_readonly_is_distinguished_from_busy(self): + assert SQLiteDB._is_readonly_error( + sqlite3.OperationalError("attempt to write a readonly database") + ) + assert not SQLiteDB._is_readonly_error( + sqlite3.OperationalError("database is locked") + ) + + +class TestStatementRetry: + def test_busy_write_is_retried_until_the_lock_is_released(self, db, sleeps): + other = _hold_write_lock(db.connection) + sleeps.on_sleep.append(other.rollback) + handle = db.dbid + + db.do_run_sql_query(INSERT_BRANCH, ("b1", None, 0.0)) + db._commit() + + assert sleeps == [0.1] + assert db.dbid is handle # BUSY is waited out, never reopened + assert "b1" in _branch_ids(db.connection) + other.close() + + def test_readonly_handle_is_reopened_before_the_retry(self, db, sleeps): + # A handle that refuses writes on a file that is perfectly writable -- + # what SQLITE_READONLY_DBMOVED looks like from the caller's side. + db.dbid.close() + db.dbid = sqlite3.connect(f"file:{db.connection}?mode=ro", uri=True) + db.dbid.row_factory = sqlite3.Row + poisoned = db.dbid + + db.do_run_sql_query(INSERT_BRANCH, ("b1", None, 0.0)) + db._commit() + + assert sleeps == [0.1] + assert db.dbid is not poisoned + assert "b1" in _branch_ids(db.connection) + + def test_reopened_connection_keeps_the_busy_timeout(self, db, sleeps): + db.dbid.close() + db.dbid = sqlite3.connect(f"file:{db.connection}?mode=ro", uri=True) + db.do_run_sql_query(INSERT_BRANCH, ("b1", None, 0.0)) + assert db.dbid.execute("PRAGMA busy_timeout").fetchone()[0] == 30000 + + def test_retries_are_exhausted_then_the_error_is_raised(self, db, sleeps, capsys): + other = _hold_write_lock(db.connection) + try: + with pytest.raises(sqlite3.OperationalError, match="locked"): + db.do_run_sql_query(INSERT_BRANCH, ("b1", None, 0.0)) + finally: + other.rollback() + other.close() + + assert sleeps == [0.1, 0.2, 0.5, 1, 2, 4] + err = capsys.readouterr().err + assert "SQLite readonly/busy diagnostics:" in err + assert f"db file: {db.connection}" in err + + def test_a_non_transient_error_is_not_retried(self, db, sleeps, capsys): + with pytest.raises(sqlite3.OperationalError, match="no such table"): + db.do_run_sql_query("SELECT * FROM no_such_table") + assert sleeps == [] + assert "diagnostics" not in capsys.readouterr().err + + def test_no_retry_inside_an_open_transaction(self, db, sleeps, capsys): + # Rolling back or reopening to retry would silently drop work already + # pending in this transaction, so the error goes straight to the + # caller, who rolls back the whole unit. + db.dbid.execute("BEGIN") + db.do_run_sql_query("SELECT * FROM branches") + handle = db.dbid + other = _hold_write_lock(db.connection) + try: + with pytest.raises(sqlite3.OperationalError, match="locked"): + db.do_run_sql_query(INSERT_BRANCH, ("b1", None, 0.0)) + finally: + other.rollback() + other.close() + + assert sleeps == [] + assert db.dbid is handle + assert db.dbid.in_transaction # left for the caller to roll back + # Not retried, but still reported. + assert "SQLite readonly/busy diagnostics:" in capsys.readouterr().err + db.dbid.rollback() + + +class TestCommitRetry: + def test_busy_commit_is_retried_and_the_transaction_lands(self, db, sleeps): + # In Python the write reaches the disk at COMMIT, so that is where a + # slow drive's transient failure shows up. + db.do_run_sql_query(INSERT_BRANCH, ("b1", None, 0.0)) + reader = sqlite3.connect(db.connection, isolation_level=None) + reader.execute("BEGIN") + reader.execute("SELECT * FROM branches").fetchall() # SHARED lock + sleeps.on_sleep.append(reader.rollback) + handle = db.dbid + + db._commit() + + assert sleeps == [0.1] + assert db.dbid is handle # never reopened: that would lose the write + assert "b1" in _branch_ids(db.connection) + reader.close() + + def test_exhausted_commit_retries_raise_with_diagnostics(self, db, sleeps, capsys): + db.do_run_sql_query(INSERT_BRANCH, ("b1", None, 0.0)) + reader = sqlite3.connect(db.connection, isolation_level=None) + reader.execute("BEGIN") + reader.execute("SELECT * FROM branches").fetchall() + try: + with pytest.raises(sqlite3.OperationalError, match="locked"): + db._commit() + finally: + reader.rollback() + reader.close() + assert sleeps == [0.1, 0.2, 0.5, 1, 2, 4] + assert "SQLite readonly/busy diagnostics:" in capsys.readouterr().err + db.dbid.rollback() + + def test_add_branch_commits_through_the_retry(self, db, sleeps): + reader = sqlite3.connect(db.connection, isolation_level=None) + reader.execute("BEGIN") + reader.execute("SELECT * FROM branches").fetchall() + sleeps.on_sleep.append(reader.rollback) + + db.add_branch("b1") + + assert sleeps == [0.1] + assert "b1" in _branch_ids(db.connection) + reader.close() + + +class TestReadonlyDiagnostics: + def test_reports_the_file_and_a_writable_directory(self, db): + diag = db._collect_readonly_diagnostics() + assert f"db file: {db.connection}" in diag + assert "db file UserWrite=1" in diag + assert "db dir writable: yes" in diag + + def test_the_directory_probe_leaves_nothing_behind(self, db): + before = set(os.listdir(os.path.dirname(db.connection))) + db._collect_readonly_diagnostics() + assert set(os.listdir(os.path.dirname(db.connection))) == before + + def test_reports_a_hot_journal_beside_the_database(self, db): + with open(db.connection + "-journal", "wb") as journal: + journal.write(b"x" * 7) + try: + diag = db._collect_readonly_diagnostics() + finally: + os.remove(db.connection + "-journal") + assert "sibling -journal present (7 bytes)" in diag + + def test_reports_an_unwritable_directory(self, db, monkeypatch): + def refuse(*args, **kwargs): + raise PermissionError("Read-only file system") + + monkeypatch.setattr(sqlitedb_module.tempfile, "NamedTemporaryFile", refuse) + diag = db._collect_readonly_diagnostics() + assert "db dir writable: NO (Read-only file system)" in diag diff --git a/tests/test_timestamp.py b/tests/test_timestamp.py new file mode 100644 index 0000000..01289af --- /dev/null +++ b/tests/test_timestamp.py @@ -0,0 +1,68 @@ +"""Tests for ``did.fun.timestamp``, the datestamp every new document carries. + +Ported from DID-matlab's TestTimestamp (bb29861, issue #53). A +``UTCLeapSeconds`` clock can render a ``':60'`` leap second, which the schema +validator rejects -- MATLAB parses with ``java.time.LocalDateTime.parse``, and +Python's ``_parses_as_timestamp`` with ``datetime.fromisoformat``, which both +refuse seconds above 59. The helper must clamp it to ``':59.999'``. +""" + +import re + +from did.document import Document +from did.fun import timestamp +from did.validate import _parses_as_timestamp + + +class TestTimestamp: + def test_current_timestamp_is_schema_valid(self): + ts = timestamp() + assert isinstance(ts, str) + assert _parses_as_timestamp(ts) + + def test_current_timestamp_has_matlabs_shape(self): + # char(datetime('now','TimeZone','UTCLeapSeconds')) renders as + # 'yyyy-MM-ddTHH:mm:ss.SSSZ'. + assert re.fullmatch(r"\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z", timestamp()) + + def test_leap_second_is_clamped(self): + raw = "2026-09-18T21:37:60.000Z" + assert not _parses_as_timestamp(raw) + ts = timestamp(raw) + assert ts == "2026-09-18T21:37:59.999Z" + assert _parses_as_timestamp(ts) + + def test_leap_second_without_trailing_z_is_clamped(self): + assert timestamp("2026-09-18T21:37:60.000") == "2026-09-18T21:37:59.999" + + def test_leap_second_without_fraction_is_clamped(self): + assert timestamp("2026-09-18T21:37:60Z") == "2026-09-18T21:37:59.999Z" + + def test_leap_second_fraction_is_replaced_not_appended(self): + # The fraction is part of what is clamped: ':60.123' becomes ':59.999', + # never ':59.999123'. + assert timestamp("2026-09-18T21:37:60.123Z") == "2026-09-18T21:37:59.999Z" + + def test_normal_timestamp_is_unchanged(self): + raw = "2026-09-18T21:37:45.123Z" + assert timestamp(raw) == raw + assert _parses_as_timestamp(raw) + + def test_a_60_outside_the_seconds_field_is_untouched(self): + # Only the seconds field is a leap second; the regex is anchored on + # 'THH:MM:' so a 60 elsewhere is not rewritten. + raw = "2060-06-06T06:06:06.060Z" + assert timestamp(raw) == raw + + +class TestDocumentDatestamp: + def test_new_document_is_stamped_by_timestamp(self, monkeypatch): + # did.document stamps base.datestamp through did.fun.timestamp, so the + # leap-second clamp applies to every generated document. + monkeypatch.setattr( + "did.document.timestamp", lambda: timestamp("2026-09-18T21:37:60.000Z") + ) + doc = Document("base") + assert doc.document_properties["base"]["datestamp"] == ( + "2026-09-18T21:37:59.999Z" + )