lmxopcua/docs/plans/2026-10-10-questdb-historian-live-gate.md

# 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.