test(historian): QuestDB live gate PASSED on docker-dev (6/6 legs); RetentionDays compose key

Claude-Session: https://claude.ai/code/session_01Ef2ozxS7QPanGT8uoATbTe
2026-10-11 04:00:03 -04:00
parent 2ebe0a4226
commit 1569a59ad2
2 changed files with 209 additions and 0 deletions
@@ -0,0 +1,205 @@
+# QuestDB historian — live gate (T9), 2026-10-11
+
+**Verdict: PASSED.** All six legs of spec §7 passed on the docker-dev rig. The rig ran `feat/questdb-historian` at
+`2ebe0a42`, with the central pair on image `0701f6a833ea`, rebuilt for this gate. The QuestDB backend pointed at the
+overlay `questdb` service (`questdb/questdb:10.0.1`, `docker-dev/docker-compose.questdb.yml`), with default table
+prefix `hist_`.
+
+The gate also produced two findings, neither in the QuestDB backend. Both are described under "Gate findings" below:
+- A crash failover (SIGKILL of the recording Primary) leaves a recording gap of about 30 s. This is the #537
+  Primary-gated capture waiting for Akka downing; it is backend-independent.
+- One `libgssapi_krb5.so.2` load error is printed per central boot. It is benign.
+
+## Setup
+
+- `docker-dev/docker-compose.yml` gained `ServerHistorian__QuestDb__RetentionDays`
+  (`OTOPCUA_HISTORIAN_QUESTDB_RETENTION_DAYS`, default empty = no TTL) on both centrals, beside the existing
+  `ServerHistorian__QuestDb__ConnectionString` (`OTOPCUA_HISTORIAN_QUESTDB`).
+- Central-1 and central-2 were started with:
+
+  ```
+  OTOPCUA_HISTORIAN_ENABLED=true OTOPCUA_HISTORIAN_BACKEND=QuestDb OTOPCUA_CONTHIST_ENABLED=true \
+  docker compose -f docker-dev/docker-compose.yml -f docker-dev/docker-compose.questdb.yml up -d --no-deps central-1 central-2
+  ```
+
+  With `RetentionDays` empty, both nodes booted cleanly; the empty value binds as "no TTL". Each logged
+  `QuestDB historian connection pool: Maximum Pool Size = 24 (default cap).` (the final-review I-1 fix).
+- Cluster `MAIN` fixtures on `10.100.0.35`: opc-plc (`opcplc/plc/FastUInt1`, UInt32, about 1 Hz) and pymodbus
+  `standard` (`pymodbus/plc/HR5`).
+- Gate configuration, written to the config DB and deployed headlessly (`deploy.sh`, deployment `0b4f5208`):
+  - New Calculation String tag `Calc/eng/FastLabel` = `"v" + FastUInt1` (script `MAIN-script-fastlabel`).
+  - `FastUInt1`, `FastLabel` and `HR5` were marked `isHistorized`.
+  - A UNS reference `a/l/e1/FastUInt1` was added.
+- Tags were provisioned at deploy (`dispatched=3, requested=3, ensured=3, skipped=0, failed=0` on both nodes). `hist_tag`:
+
+  | name | data_type |
+  |---|---|
+  | `Calc/eng/FastLabel` | 9 (String) |
+  | `opcplc/plc/FastUInt1` | 5 (Int64) |
+  | `pymodbus/plc/HR5` | 4 |
+
+- Tables at first boot, from `tables()`:
+  - `hist_sample`, `hist_event`: WAL, `PARTITION BY DAY`, `ttlValue 0`.
+  - `hist_tag`: WAL, `PARTITION BY YEAR`.
+- Two data-plane API keys were minted for the gate, each with a `Cluster`-scoped grant. The ACL flag stayed off, which
+  is the rig default.
+  - `gate-historyupdate`: ReadOnly | HistoryUpdate (4239)
+  - `gate-writeop`: ReadOnly | WriteOperate (159)
+
+Direct queries used QuestDB REST: `curl -G localhost:19000/exec --data-urlencode "query=…"`.
+
+## 1. Recording: Primary-only, typed, real status, one row per value
+
+- **Rows carry real kinds and statuses:**
+  - `kind=2` Int64 `int_value 278` (with `num_value 278.0`), status `0`.
+  - `kind=4` String `v278`, status `0`.
+  - At startup, `kind=0` Empty with `2150760448` (`0x80320000` BadWaitingForInitialData) and `2150694912`
+    (`0x80310000` BadNoCommunication). These match the SQL Server gate.
+- **Primary-only:**
+  - Central-2 was the recording Primary, and its outbox `hlog.log.0` grew.
+  - Central-1 logged "this node is not the recording Primary … suppressing value capture". Its `hlog.log.0` kept its
+    2026-10-09 19:13 mtime and was not written.
+- **One row per value**, from 07:43:20 onwards:
+  - 57 FastUInt1 rows over 57 distinct timestamps; 57 FastLabel rows over 57.
+  - All 57 pair one-to-one: same `ts`, and `str_value = 'v' + int_value`.
+- **Outbox carry-over across a backend switch.** Two rows carry source time `2026-10-09T19:13:40.129127Z` (`296` /
+  `v296`) with `server_ts 07:42:27`, before the deploy. They were un-drained entries left in central-2's outbox by the
+  2026-10-09 SQL Server gate, and they drained into QuestDB at boot. An outbox entry outlives the backend it was
+  captured under, by design: the outbox is backend-neutral.
+
+## 2. HistoryRead through the raw and UNS NodeIds
+
+All reads went to central-1 (`:4840`).
+
+- **Raw read**, 07:44:00–07:44:10, on `ns=2;s=opcplc/plc/FastUInt1` and on `ns=3;s=a/l/e1/FastUInt1`:
+  - Both return the identical 10 rows, `271`…`280`, all Good.
+  - They equal the direct query `select ts, int_value, status from hist_sample where tag=… and not deleted` exactly,
+    at microsecond precision (for example `07:44:00.952990Z`).
+- **Average at 10 s**, 07:44:00–07:44:30, through both NodeIds:
+  - Both return `275.5 / 285.5 / 295.5`, all Good.
+  - The direct `avg(int_value)` per 10 s bucket gives `275.5 / 285.5 / 295.5`, over 10, 10 and 10 samples.
+
+## 3. HistoryUpdate
+
+These calls went to central-1 on `ns=2;s=opcplc/plc/FastUInt1`, with `-U apikey`. Each was checked by `historyread`
+and by a direct query.
+
+| Call | Result | Confirmed |
+|---|---|---|
+| insert 06:00:00 = 42 (`gate-historyupdate`) | `GoodEntryInserted` | row `42`, status 0, `deleted=false` |
+| repeat insert = 43 | `BadEntryExists` | row still `42` |
+| replace 06:00:00 = 99 | `GoodEntryReplaced` | row `99` |
+| replace 06:00:30 (no entry) | `BadNoEntryExists` | — |
+| update 06:01:00 = 11 (absent) | `GoodEntryInserted` | row `11` |
+| delete-at-time 06:00:00 | `Good` | tombstone row: `int_value NULL`, status `0x809B0000`, `deleted=true` |
+| insert over the tombstone, 06:00:00 = 55 | `GoodEntryInserted` (ledger ruling: an insert over a tombstone is an insert) | read returns `55` |
+| delete-at-time 06:00:00 again | `Good` | read returns only `06:01:00 = 11` |
+| insert with `gate-writeop` (WriteOperate only) | Node result `BadUserAccessDenied` | no row |
+| insert, anonymous | Node result `BadUserAccessDenied` | no row |
+| insert at 1969-12-31 (RC1) | `BadOutOfRange` | no row |
+
+No QuestDB `UPDATE` or `DELETE` was issued: every change above is a new row under `DEDUP UPSERT KEYS(ts, tag)`.
+
+### A delete is not resurrected by an outbox redelivery
+
+This was proven with a real replay, not a simulation:
+1. **07:47:26–07:47:35:** `docker stop` QuestDB. The Primary (central-1) kept capturing; its writes failed, so the
+   entries stayed pending in its outbox.
+2. **07:47:35:** the outbox was snapshotted while QuestDB was down (commit point `commit.1303.0`).
+3. **07:47:35:** QuestDB was restarted. The 16-value backlog (`476`…`491`) drained as one batch (`server_ts
+   07:47:41.620267`), with no gap. This is a second result: QuestDB loss is ridden out by the outbox.
+4. **07:50:45–46:** `delete-at-time` on two backlog rows, `07:47:28.950591` (`479`) and `07:47:31.949216` (`482`).
+   Both became tombstones (`deleted=true`, `0x809B0000`).
+5. **07:50:46:** central-1 was stopped. Its outbox directory (on the `otopcua-localdb-central-1` volume) was replaced
+   with the pre-delivery snapshot.
+6. **07:51:15:** central-1 was started. It re-drained the snapshot's entries, and the outbox commit point advanced
+   `1303 → 1328`.
+
+After the replay:
+- Both tombstones are unchanged: same `server_ts 07:50:45.669146 / 07:50:46.074579`, still `deleted=true`.
+- Every other row in the window kept its original `server_ts 07:47:41.620267`, so nothing was re-written.
+- 24 rows over 12 keys (2 tags × 12): no duplicates.
+- `historyread` 07:47:27–07:47:33 returns `478, 480, 481, 483`; `479` and `482` stay deleted.
+
+A first attempt used `ALTER TABLE hist_sample SUSPEND WAL` plus a SIGKILL of the Primary. It could not produce a
+redelivery. The writer deliberately treats a suspended table as committed and acknowledges it (R5: rows committed to
+the WAL become visible later, and are not re-sent). It logged "QuestDB table hist_sample is suspended (writerTxn 327
+< sequencerTxn 337); not waiting" and acked. That attempt exposed the crash-failover finding below.
+
+## 4. Failover
+
+- **07:50:46:** central-1 was stopped (step 5 above). Central-2 logged "now the recording Primary" at 07:50:46.
+- **07:51:57:** `docker stop` central-2, then the Primary. Central-1 logged "this node is now the recording Primary …
+  resuming value capture" at 07:51:57, as central-2 began leaving.
+- **07:52:13:** central-2 was restarted and rejoined as standby ("not the recording Primary"). Its outbox
+  `hlog.log.0` stayed frozen at 57856 bytes (mtime 07:51:58). Central-1's grew from 65536 to 84480.
+- **Rate across both failovers was 1×.** Per-30 s FastUInt1 counts from 07:50:00 to 07:54:30:
+  30, 29, 30, 30, 30, 30, 29, 29, 30.
+  - There was no gap at the boundary: `743`…`754` are contiguous across 07:51:57.
+  - There was no doubling: 267 rows over 267 distinct timestamps.
+
+## 5. Device loss: driver Bad sample and comms-loss outage marker
+
+This leg ran on Modbus (`HR5`). `otopcua-pymodbus-standard` was stopped at 07:54:40 and restarted at 07:56:51.
+
+| ts | kind | value | status | server_ts |
+|---|---|---|---|---|
+| 07:51:18.715101 | 2 | 5 | `0` | 07:51:18 |
+| 07:54:51.960244 | 0 (Empty) | NULL | `0x80050000` BadCommunicationError (the driver's own Bad publish) | 07:56:13 |
+| 07:56:48.652185 | 0 (Empty) | NULL | `0x80310000` BadNoCommunication (the #527 watchdog outage marker) | 07:56:48 |
+| 07:56:58.688150 | 2 | 5 | `0` (recovery re-publish) | 07:56:58 |
+
+Reads over the outage:
+- Raw `historyread` 07:50–07:58 shows Good, Bad, Bad, Good.
+- Average at 120 s, 07:52–07:58, gives `(null) Bad` / `(null) Bad` / `5 Uncertain`. The outage is visible and is not
+  bridged.
+
+The Bad sample's `server_ts` is 82 s after its source time. Its source time is the driver's failed-read stamp; it
+reached the recorder later. Its position in the series is correct either way, because ordering and reads key on
+source time.
+
+## 6. TTL visible in table metadata
+
+Both centrals were recreated with `OTOPCUA_HISTORIAN_QUESTDB_RETENTION_DAYS=30`. At 07:57:41 the bootstrapper logged
+`Applied TTL 30 day(s) to QuestDB table hist_sample.` and the same for `hist_event`. The TTL was applied to the
+already existing tables.
+
+`tables()` before and after:
+
+| table | before | after |
+|---|---|---|
+| `hist_event` | 0 HOUR | 30 DAY |
+| `hist_sample` | 0 HOUR | 30 DAY |
+| `hist_tag` | 0 HOUR | 0 HOUR (no TTL on the tag catalog, by design) |
+
+`SHOW CREATE TABLE hist_sample`:
+`… timestamp(ts) PARTITION BY DAY TTL 30 DAYS DEDUP UPSERT KEYS(ts,tag);`
+
+Recording resumed after the restart: 57 FastUInt1 rows and 56 FastLabel rows in the first minute.
+
+## Gate findings
+
+1. **A crash failover leaves a recording gap of about 30 s. This is backend-independent and predates this work.**
+   - **What happened:** after `docker kill` (SIGKILL) of the recording Primary at 07:45:58, the next FastUInt1 row
+     is at 07:46:29. Central-1 became the recording Primary only at 07:46:30, when the killed node rejoined as a new
+     incarnation.
+   - **Why:** #537 gates capture to the Primary. A crashed Primary stays unreachable but not yet downed for the Akka
+     failure-detector window plus `auto-down-unreachable-after = 15s`, so no node captures during that time.
+   - **Contrast:** a clean `docker stop` hands over at once (leg 4). The SQL Server gate only exercised the clean
+     path.
+   - **Status:** proposed follow-up issue, not fixed here.
+2. **`Cannot load library libgssapi_krb5.so.2` is printed once per central boot.** It does not appear on the site
+   nodes, which have neither a ConfigDb nor a QuestDB client. It is most likely Npgsql's default GSS-encryption probe,
+   which falls back cleanly. Everything worked. If it is confirmed as Npgsql, `GSS Encryption Mode=Disable` in the
+   connection string silences it.
+
+## Restore
+
+- The rig was restored afterwards:
+  - central-1 and central-2 were recreated with the compose defaults (historian off, `Backend=Gateway`).
+  - The gate tag, script, UNS reference, API keys and ACL rows were removed.
+  - The `HR5` and `FastUInt1` TagConfigs were reverted.
+  - The configuration was redeployed.
+  - The overlay `questdb` container was stopped and removed; the `otopcua-questdb-data` volume was kept.
+  - The opc-plc and pymodbus fixtures were stopped (normally down).
+- The compose keys stay: `Backend` defaults to `Gateway`, and `RetentionDays` defaults to empty.