diff --git a/docker-dev/docker-compose.yml b/docker-dev/docker-compose.yml index d6e439b8..42baee8d 100644 --- a/docker-dev/docker-compose.yml +++ b/docker-dev/docker-compose.yml @@ -444,6 +444,8 @@ services: # QuestDb = the QuestDB historian; the `questdb` service comes from the docker-dev/docker-compose.questdb.yml overlay # (add `-f docker-dev/docker-compose.questdb.yml` and OTOPCUA_HISTORIAN_BACKEND=QuestDb). ServerHistorian__QuestDb__ConnectionString: "${OTOPCUA_HISTORIAN_QUESTDB:-Host=questdb;Port=8812;Username=admin;Password=quest;Database=qdb;ServerCompatibilityMode=NoTypeLoading}" + # Empty = no TTL (data kept forever); a positive day count sets the sample/event table TTL. + ServerHistorian__QuestDb__RetentionDays: "${OTOPCUA_HISTORIAN_QUESTDB_RETENTION_DAYS:-}" # Continuous historization of driver tag values (Gitea #491's live gate). Gated on BOTH # ContinuousHistorization:Enabled AND ServerHistorian:Enabled — with either off no recorder is # spawned, so this stays inert on the default rig. OutboxPath is the FasterLog crash boundary and @@ -580,6 +582,8 @@ services: # QuestDb = the QuestDB historian; the `questdb` service comes from the docker-dev/docker-compose.questdb.yml overlay # (add `-f docker-dev/docker-compose.questdb.yml` and OTOPCUA_HISTORIAN_BACKEND=QuestDb). ServerHistorian__QuestDb__ConnectionString: "${OTOPCUA_HISTORIAN_QUESTDB:-Host=questdb;Port=8812;Username=admin;Password=quest;Database=qdb;ServerCompatibilityMode=NoTypeLoading}" + # Empty = no TTL (data kept forever); a positive day count sets the sample/event table TTL. + ServerHistorian__QuestDb__RetentionDays: "${OTOPCUA_HISTORIAN_QUESTDB_RETENTION_DAYS:-}" # Continuous historization — see central-1 for the full note + the gate recipe. Both centrals # carry it so the pair is symmetric; :9200 round-robins them, and the recorder must exist on # whichever node holds the drivers. diff --git a/docs/plans/2026-10-10-questdb-historian-live-gate.md b/docs/plans/2026-10-10-questdb-historian-live-gate.md new file mode 100644 index 00000000..a39d401a --- /dev/null +++ b/docs/plans/2026-10-10-questdb-historian-live-gate.md @@ -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.