Production host writes no log on wonder-app-vd03 — file sink opens a 0-byte file, zero events flow #561

New Issue

2026-08-11T04:58:52-04:00

dohertj2 commented

2026-08-11 04:58:52 -04:00

Found during the 2026-08-11 production upgrade (4e22f024 → e82881c1) by the deploy verification pass, pre-existing on the old binary — not a regression from the deploy.

Observed on the box (E:\ApiInstall\OtOpcUa\):

E:\ApiInstall\OtOpcUa\logs\otopcua-20260811.log exists and is 0 bytes — created by the freshly-deployed binary at boot, so the rolling-file sink IS instantiated and CAN write to the right directory.
The old C:\Windows\System32\logs\ scatter location has been stale since 2026-06-27 — consistent with the Directory.SetCurrentDirectory(AppContext.BaseDirectory) anchor (Program.cs:115-123) reaching the box in whatever build was deployed then, after which nothing was ever written to either location.
Net effect: any incident on this production host is un-diagnosable after the fact. The server otherwise works (live OPC UA reads against the real Makino verified during the deploy).

Why this is NOT the path-scatter defect again: the anchor fix worked — the file lands in the install dir. A 0-byte file means the pipeline delivers no events to the sink: the host boots, serves, and polls (all of which log at Information in this codebase), yet nothing reaches the file.

Where to look:

The OtOpcUaHost service key carries 23 environment variables (HKLM:\SYSTEM\CurrentControlSet\Services\OtOpcUaHost → Environment multi-string). Any Serilog__* override there (e.g. MinimumLevel, a WriteTo index override) layers over appsettings.json via ReadFrom.Configuration and could silence the file sink while the process appears healthy. Enumerate and check.
AddZbSerilog (shared ZB.MOM.WW.Telemetry bootstrap) layers config on top of the appsettings sinks (Program.cs:125-128) — verify the layering can't drop the file sink when an override is present.
The deployed appsettings*.json on the box vs the repo's ("path": "logs/otopcua-.log", "rollingInterval": "Day").

Acceptance: after a service restart on wonder, the day's log file contains the boot banner and steady-state entries; ideally add a startup self-check that logs one line and verifies the file grew, warning to console/EventLog if not — this failure mode (0-byte file, healthy process) is otherwise invisible from outside.

Related, other repo: MxGateway on the same box has the identical symptom (seven 0-byte NSSM stderr files since May) — two of the four apps on wonder have no error capture. That half belongs to the MxAccessGateway tracker.

Reported by the scadaproj deploy session; filed from the OtOpcUa session.

Found during the 2026-08-11 production upgrade (`4e22f024` → `e82881c1`) by the deploy verification pass, **pre-existing on the old binary** — not a regression from the deploy. **Observed on the box** (`E:\ApiInstall\OtOpcUa\`): - `E:\ApiInstall\OtOpcUa\logs\otopcua-20260811.log` exists and is **0 bytes** — created by the freshly-deployed binary at boot, so the rolling-file sink IS instantiated and CAN write to the right directory. - The old `C:\Windows\System32\logs\` scatter location has been **stale since 2026-06-27** — consistent with the `Directory.SetCurrentDirectory(AppContext.BaseDirectory)` anchor (`Program.cs:115-123`) reaching the box in whatever build was deployed then, after which nothing was ever written to either location. - Net effect: **any incident on this production host is un-diagnosable after the fact.** The server otherwise works (live OPC UA reads against the real Makino verified during the deploy). **Why this is NOT the path-scatter defect again:** the anchor fix worked — the file lands in the install dir. A 0-byte file means the pipeline delivers **no events** to the sink: the host boots, serves, and polls (all of which log at Information in this codebase), yet nothing reaches the file. **Where to look:** - The `OtOpcUaHost` service key carries **23 environment variables** (`HKLM:\SYSTEM\CurrentControlSet\Services\OtOpcUaHost` → `Environment` multi-string). Any `Serilog__*` override there (e.g. `MinimumLevel`, a `WriteTo` index override) layers over `appsettings.json` via `ReadFrom.Configuration` and could silence the file sink while the process appears healthy. Enumerate and check. - `AddZbSerilog` (shared `ZB.MOM.WW.Telemetry` bootstrap) layers config on top of the appsettings sinks (`Program.cs:125-128`) — verify the layering can't drop the file sink when an override is present. - The deployed `appsettings*.json` on the box vs the repo's (`"path": "logs/otopcua-.log", "rollingInterval": "Day"`). **Acceptance:** after a service restart on wonder, the day's log file contains the boot banner and steady-state entries; ideally add a startup self-check that logs one line **and verifies the file grew**, warning to console/EventLog if not — this failure mode (0-byte file, healthy process) is otherwise invisible from outside. **Related, other repo:** MxGateway on the same box has the identical symptom (seven 0-byte NSSM stderr files since May) — two of the four apps on wonder have no error capture. That half belongs to the MxAccessGateway tracker. Reported by the scadaproj deploy session; filed from the OtOpcUa session.

dohertj2 commented

2026-08-11 05:00:58 -04:00

Narrowing from two directions (2026-08-11):

Service-key env is ruled out — the deploy session's pre-deploy capture enumerated all 23 names on the service key's Environment multi-string: zero Serilog__* entries. (Caveats: name-only capture, and machine-level env was not grepped for Serilog specifically — close that gap on the box.)

The shared AddZbSerilog layering is ruled out as a general defect — the docker-dev rig at the same tip (e82881c1) runs the identical bootstrap and writes a 1 MB logs/otopcua-20260811.log with the boot banner at [INF] from the first second. Also checked: none of the repo's environment/role appsettings (admin, driver, admin-driver, Development) touches WriteTo — they override MinimumLevel only, none above Information. So a stock config cannot silence the file sink.

(Related note: MxGateway's seven 0-byte NSSM stderr files and HistorianGateway's 0-byte stderr.log are a different mechanism — empty stderr capture is the normal healthy shape for an app whose console sink writes stdout. They are not evidence of a family-wide AddZbSerilog hole; whether those apps' own Serilog file sinks produce output is a separate check.)

Surviving search space, all box-local:

The value of DOTNET_ENVIRONMENT on the service key, and any appsettings.<env>.json as deployed on the box (the deployed copies can differ from the repo's).
File-sink write failure after open — Serilog's File sink swallows I/O errors silently (visible only via Serilog.Debugging.SelfLog). A 0-byte file the sink created but can never append to (ACL on E:\ApiInstall\OtOpcUa\logs\, AV interference, disk quota) matches the symptom exactly. Enable SelfLog to console/EventLog as part of the fix.
Compare the 0-byte file's creation timestamp against service start — created-at-boot confirms the sink instantiated this run; an old timestamp means today's process never even opened it and the search moves to config binding on the box.

Given 1–3, the acceptance criterion stands: boot banner in the day's file after a restart, plus a startup self-check that verifies the file grew.

Narrowing from two directions (2026-08-11): **Service-key env is ruled out** — the deploy session's pre-deploy capture enumerated all 23 names on the service key's `Environment` multi-string: zero `Serilog__*` entries. (Caveats: name-only capture, and machine-level env was not grepped for `Serilog` specifically — close that gap on the box.) **The shared `AddZbSerilog` layering is ruled out as a general defect** — the docker-dev rig at the same tip (`e82881c1`) runs the identical bootstrap and writes a 1 MB `logs/otopcua-20260811.log` with the boot banner at `[INF]` from the first second. Also checked: none of the repo's environment/role appsettings (`admin`, `driver`, `admin-driver`, `Development`) touches `WriteTo` — they override `MinimumLevel` only, none above Information. So a stock config cannot silence the file sink. (Related note: MxGateway's seven 0-byte NSSM **stderr** files and HistorianGateway's 0-byte `stderr.log` are a different mechanism — empty stderr capture is the normal healthy shape for an app whose console sink writes stdout. They are not evidence of a family-wide `AddZbSerilog` hole; whether those apps' own Serilog *file* sinks produce output is a separate check.) **Surviving search space, all box-local:** 1. The **value** of `DOTNET_ENVIRONMENT` on the service key, and any `appsettings.<env>.json` **as deployed on the box** (the deployed copies can differ from the repo's). 2. **File-sink write failure after open** — Serilog's File sink swallows I/O errors silently (visible only via `Serilog.Debugging.SelfLog`). A 0-byte file the sink created but can never append to (ACL on `E:\ApiInstall\OtOpcUa\logs\`, AV interference, disk quota) matches the symptom exactly. Enable SelfLog to console/EventLog as part of the fix. 3. Compare the 0-byte file's **creation timestamp** against service start — created-at-boot confirms the sink instantiated this run; an old timestamp means today's process never even opened it and the search moves to config binding on the box. Given 1–3, the acceptance criterion stands: boot banner in the day's file after a restart, plus a startup self-check that verifies the file grew.

dohertj2 commented

2026-08-11 05:06:59 -04:00

The on-box data (deploy session, read-only) eliminates my hypotheses 1–3 and, combined with the code, leaves one specific testable culprit.

On-box facts: PROCSTART 04:45:25; otopcua-20260811.log created 04:45:27, 0 B; scripts-20260811.log created 04:45:31, 76 B written. DOTNET_ENVIRONMENT=Production, no appsettings.Production.json on the box; all five deployed configs are from this deploy; only appsettings.json carries WriteTo and its Serilog section has no MinimumLevel, no filters.

Deduction:

File created at boot+2s ⇒ the DI logger built and the File sink constructed (that's Program.cs:708, GetRequiredService<Serilog.ILogger>(), forcing the AddZbSerilog lambda). The pipeline exists and points at the right file.
The startup banner (Program.cs:777) is a static Log.Information running after the 708 assignment — it bypasses MEL entirely. Zero bytes therefore means the drop happens inside the Serilog pipeline, not in MEL's Logging:LogLevel filtering (which static calls never traverse).
Sinks are isolated in Serilog (SafeAggregateSink) — a broken Console sink can't block the File sink. The only pipeline stage that silences every sink at once while leaving them constructed is the minimum-level filter.
ScriptRootLoggerFactory.Build (Logging/ScriptRootLoggerFactory.cs:39-44) hard-codes MinimumLevel.Verbose() and never touches ReadFrom.Configuration — so a config-carried level filter silences the main logger while the scripts logger keeps writing. That asymmetry is exactly what the box shows, and it is the observation that rules everything else out.
The repo-shipped configs can't be the carrier (role overlays set Default: Information; the banner is Information). The docker-dev rig at the same commit logs fine, so the carrier is host-local state the rig lacks.

The one unchecked vehicle matching all of this: a Serilog__MinimumLevel__* (or Serilog__MinimumLevel) machine-level environment variable — the exact gap the deploy session flagged (machine env was grepped for Cluster|Mesh|OTOPCUA|ConfigSource|Telemetry|OpcUa but not Serilog; the service-key's 23 names are clean). Program.cs:90 re-appends env vars with top precedence, so a machine-level Serilog__MinimumLevel__Default=Fatal (or similar) reaches ReadFrom.Configuration above everything. Timeline circumstantially fits too: the System32 scatter went quiet 2026-06-27 — if the variable was set around then (perhaps in an attempt to manage the System32 log noise the CWD bug was causing at the time), it has silenced every build since.

Falsifiable check (one line, machine env + the service account's user env):

[Environment]::GetEnvironmentVariables('Machine').Keys | Where-Object { $_ -match 'Serilog' }
[Environment]::GetEnvironmentVariables('User').Keys | Where-Object { $_ -match 'Serilog' }

Non-empty ⇒ culprit found; delete the variable, restart the service, banner appears. Empty ⇒ this hypothesis dies and the next step is enabling Serilog.Debugging.SelfLog on the box, because we would then be in genuinely strange territory.

Hardening worth doing regardless of the outcome (this failure mode was invisible for ~6 weeks): a startup self-check after Log.Logger assignment — log one line, verify the day's file grew, and if it did not, write a warning to the Windows EventLog naming the effective minimum level. Cheap, and it converts every future variant of "healthy process, silent log" into a visible signal.

The on-box data (deploy session, read-only) eliminates my hypotheses 1–3 and, combined with the code, leaves **one specific testable culprit**. **On-box facts:** `PROCSTART 04:45:25`; `otopcua-20260811.log` created **04:45:27**, 0 B; `scripts-20260811.log` created 04:45:31, **76 B written**. `DOTNET_ENVIRONMENT=Production`, no `appsettings.Production.json` on the box; all five deployed configs are from this deploy; only `appsettings.json` carries `WriteTo` and its Serilog section has **no `MinimumLevel`, no filters**. **Deduction:** - File created at boot+2s ⇒ the DI logger built and the File sink constructed (that's `Program.cs:708`, `GetRequiredService<Serilog.ILogger>()`, forcing the `AddZbSerilog` lambda). The pipeline exists and points at the right file. - The startup banner (`Program.cs:777`) is a **static `Log.Information`** running after the 708 assignment — it bypasses MEL entirely. Zero bytes therefore means the drop happens **inside the Serilog pipeline**, not in MEL's `Logging:LogLevel` filtering (which static calls never traverse). - Sinks are isolated in Serilog (`SafeAggregateSink`) — a broken Console sink can't block the File sink. The only pipeline stage that silences **every** sink at once while leaving them constructed is the **minimum-level filter**. - `ScriptRootLoggerFactory.Build` (`Logging/ScriptRootLoggerFactory.cs:39-44`) hard-codes `MinimumLevel.Verbose()` and **never touches `ReadFrom.Configuration`** — so a config-carried level filter silences the main logger while the scripts logger keeps writing. That asymmetry is exactly what the box shows, and it is the observation that rules everything else out. - The repo-shipped configs can't be the carrier (role overlays set `Default: Information`; the banner is Information). The docker-dev rig at the same commit logs fine, so the carrier is host-local state the rig lacks. **The one unchecked vehicle matching all of this:** a `Serilog__MinimumLevel__*` (or `Serilog__MinimumLevel`) **machine-level environment variable** — the exact gap the deploy session flagged (machine env was grepped for `Cluster|Mesh|OTOPCUA|ConfigSource|Telemetry|OpcUa` but **not** `Serilog`; the service-key's 23 names are clean). `Program.cs:90` re-appends env vars with top precedence, so a machine-level `Serilog__MinimumLevel__Default=Fatal` (or similar) reaches `ReadFrom.Configuration` above everything. Timeline circumstantially fits too: the System32 scatter went quiet 2026-06-27 — if the variable was set around then (perhaps in an attempt to manage the System32 log noise the CWD bug was causing at the time), it has silenced every build since. **Falsifiable check (one line, machine env + the service account's user env):** ```powershell [Environment]::GetEnvironmentVariables('Machine').Keys | Where-Object { $_ -match 'Serilog' } [Environment]::GetEnvironmentVariables('User').Keys | Where-Object { $_ -match 'Serilog' } ``` Non-empty ⇒ culprit found; delete the variable, restart the service, banner appears. Empty ⇒ this hypothesis dies and the next step is enabling `Serilog.Debugging.SelfLog` on the box, because we would then be in genuinely strange territory. **Hardening worth doing regardless of the outcome** (this failure mode was invisible for ~6 weeks): a startup self-check after `Log.Logger` assignment — log one line, verify the day's file grew, and if it did not, write a warning to the Windows EventLog naming the effective minimum level. Cheap, and it converts every future variant of "healthy process, silent log" into a visible signal.

dohertj2 commented

2026-08-11 05:11:55 -04:00

Correction to both prior comments — a local experiment falsifies the minimum-level hypothesis AND the premise both investigations shared.

I tested the load-bearing assumption nobody had checked: does Serilog's rolling file sink (Serilog.Sinks.File 6.0.0, the version this solution pins) create the file at construction? Three cases, exact behavior:

Case	Result
A — `MinimumLevel.Fatal`, one Information event	no file created
B — sink constructed, zero events, disposed	no file created
C — one Information event, no filter	file created with 51 bytes immediately

Consequences for the wonder box (otopcua-20260811.log created 04:45:27 = PROCSTART+2s, 0 bytes, LastWrite = creation):

The minimum-level hypothesis is dead (case A): a filtered pipeline never creates the file. Consistent with the env sweep finding no Serilog var in any scope — Machine, User, Process, service key, and LocalSystem's own HKEY_USERS\S-1-5-18 hive.
"Sink constructed, zero events" — the premise of my first two comments — was wrong (case B): construction creates nothing. The file's existence proves an event passed the filter and reached the sink.
Case C proves open+write are observably atomic on success — so on wonder, the first emit opened the file and the content write/flush failed, and every subsequent write has failed the same way, silently (Serilog isolates per-sink failures; only SelfLog sees them).
This resurrects the post-open write-failure hypothesis, whose earlier elimination was at the wrong granularity: the 76-byte scripts-*.log proves the directory writable, not this file handle — the two sinks are separate handles, and the failure is per-handle.
One refinement narrowing it further: Serilog's file sink opens with FileShare.Read. If the open had failed (handle contention — e.g. an overlapping old process instance during the 04:16 deploy restart window), the rolling sink would have fallen back to otopcua-20260811_001.log. No _001 exists ⇒ the open succeeded ⇒ the failure is strictly in the write path of a successfully-opened handle. That is a short list: AV/EDR interference keyed on the file, an NTFS quota/attribute anomaly on that specific file, or an I/O-layer failure that spares the scripts handle.

Next step is decided, and it is a code change, not a probe: enable Serilog.Debugging.SelfLog at startup (to a secondary channel — EventLog and/or a logs/serilog-selflog.txt), plus the startup growth self-check from the first comment (log one line, verify the day's file grew, warn to EventLog naming the failure if not). SelfLog will print the actual exception the File sink is swallowing on every write, which converts this from hypothesis-ranking to reading an error message. Needs a service restart on wonder to take effect, so it rides the next planned deploy.

(Method note for the record: the experiment that broke the deadlock was testing the shared premise, not adding a fourth hypothesis — both investigations had inherited "file exists ⇒ sink constructed ⇒ no events flowed" without checking which sink behaviors actually produce a 0-byte file.)

**Correction to both prior comments — a local experiment falsifies the minimum-level hypothesis AND the premise both investigations shared.** I tested the load-bearing assumption nobody had checked: does Serilog's rolling file sink (`Serilog.Sinks.File` 6.0.0, the version this solution pins) create the file at construction? Three cases, exact behavior: | Case | Result | |---|---| | A — `MinimumLevel.Fatal`, one Information event | **no file created** | | B — sink constructed, zero events, disposed | **no file created** | | C — one Information event, no filter | file created **with 51 bytes immediately** | Consequences for the wonder box (`otopcua-20260811.log` created 04:45:27 = PROCSTART+2s, 0 bytes, LastWrite = creation): 1. **The minimum-level hypothesis is dead** (case A): a filtered pipeline never creates the file. Consistent with the env sweep finding no `Serilog` var in any scope — Machine, User, Process, service key, and LocalSystem's own `HKEY_USERS\S-1-5-18` hive. 2. **"Sink constructed, zero events" — the premise of my first two comments — was wrong** (case B): construction creates nothing. The file's existence proves an event **passed the filter and reached the sink**. 3. **Case C proves open+write are observably atomic on success** — so on wonder, the first emit opened the file and the **content write/flush failed**, and every subsequent write has failed the same way, silently (Serilog isolates per-sink failures; only `SelfLog` sees them). 4. This **resurrects the post-open write-failure hypothesis**, whose earlier elimination was at the wrong granularity: the 76-byte `scripts-*.log` proves the *directory* writable, not *this file handle* — the two sinks are separate handles, and the failure is per-handle. 5. One refinement narrowing it further: Serilog's file sink opens with `FileShare.Read`. If the open had **failed** (handle contention — e.g. an overlapping old process instance during the 04:16 deploy restart window), the rolling sink would have fallen back to `otopcua-20260811_001.log`. **No `_001` exists** ⇒ the open succeeded ⇒ the failure is strictly in the write path of a successfully-opened handle. That is a short list: AV/EDR interference keyed on the file, an NTFS quota/attribute anomaly on that specific file, or an I/O-layer failure that spares the scripts handle. **Next step is decided, and it is a code change, not a probe:** enable `Serilog.Debugging.SelfLog` at startup (to a secondary channel — EventLog and/or a `logs/serilog-selflog.txt`), plus the startup growth self-check from the first comment (log one line, verify the day's file grew, warn to EventLog naming the failure if not). `SelfLog` will print the actual exception the File sink is swallowing on every write, which converts this from hypothesis-ranking to reading an error message. Needs a service restart on wonder to take effect, so it rides the next planned deploy. (Method note for the record: the experiment that broke the deadlock was testing the shared premise, not adding a fourth hypothesis — both investigations had inherited "file exists ⇒ sink constructed ⇒ no events flowed" without checking which sink behaviors actually produce a 0-byte file.)

dohertj2 referenced this issue from a commit

2026-08-11 06:03:05 -04:00

fix(logging): #561 — SelfLog to file+stderr and a startup file-sink growth self-check

dohertj2 commented

2026-08-11 06:03:29 -04:00

Fix implemented and pushed: 29a202f5 (master). Both instruments from the previous comment, in src/Server/ZB.MOM.WW.OtOpcUa.Host/Logging/LogPipelineDiagnostics.cs, wired in Program.cs:

SelfLog, enabled before the first logger builds — to logs/serilog-selflog.txt (relative to the install dir via the existing CWD anchor; rotated by deletion at 5 MB, since a broken sink fails every event and would grow it unboundedly) plus stderr. This is the channel that will finally carry the actual exception the file sink has been swallowing on wonder — the next service restart there ends the hypothesis-ranking.
Startup growth self-check, after the banner — reads the Serilog:WriteTo File entries from config, measures each template's rolled-file family (otopcua-*.log glob, which covers rolled, _NNN-sequence, and un-rolled names), emits a marker event, and re-measures. A template that did not grow is reported through SelfLog + stderr + the normal logger (for the console sink's benefit). Buffered sinks are skipped rather than false-alarmed; no configured file sink ⇒ no check; both instruments swallow their own failures so a diagnostics defect can never fail or delay host start.

Design points that came straight from this thread:

Growth across the marker, not existence/size — a previous run's bytes on disk must not mask a silent sink (the false pass an existence check would have given here), pinned by A_preexisting_file_does_not_mask_a_silent_sink.
The load-bearing test is the failure case (A_sink_that_writes_nothing_is_reported) — a check that can only pass is indistinguishable from no check, which is how the original defect ran silent for six weeks.
Family-glob attribution pinned by The_rolled_and_sequenced_family_counts_as_the_template (a healthy rolling deployment must not false-alarm just because the literal template name never exists).

7 new tests; full Host.Tests 103/103 green; docker-dev live verification of the healthy path (self-check silent, selflog file present, log growing) in progress on the rebuilt rig — evidence to follow in this thread.

Remaining to close #561: deploy 29a202f5+ to wonder-app-vd03 (next planned deploy — needs the service restart anyway), then read E:\ApiInstall\OtOpcUa\logs\serilog-selflog.txt: it will name the exact exception behind the silent writes. Expect the growth self-check warning on stderr/SelfLog at that boot too, proving the detection works against the real defect before the root cause is fixed.

**Fix implemented and pushed: `29a202f5`** (`master`). Both instruments from the previous comment, in `src/Server/ZB.MOM.WW.OtOpcUa.Host/Logging/LogPipelineDiagnostics.cs`, wired in `Program.cs`: 1. **SelfLog, enabled before the first logger builds** — to `logs/serilog-selflog.txt` (relative to the install dir via the existing CWD anchor; rotated by deletion at 5 MB, since a broken sink fails every event and would grow it unboundedly) **plus stderr**. This is the channel that will finally carry the actual exception the file sink has been swallowing on wonder — the next service restart there ends the hypothesis-ranking. 2. **Startup growth self-check, after the banner** — reads the `Serilog:WriteTo` File entries from config, measures each template's rolled-file family (`otopcua-*.log` glob, which covers rolled, `_NNN`-sequence, and un-rolled names), emits a marker event, and re-measures. A template that did not grow is reported through SelfLog + stderr + the normal logger (for the console sink's benefit). Buffered sinks are skipped rather than false-alarmed; no configured file sink ⇒ no check; both instruments swallow their own failures so a diagnostics defect can never fail or delay host start. Design points that came straight from this thread: - **Growth across the marker, not existence/size** — a previous run's bytes on disk must not mask a silent sink (the false pass an existence check would have given here), pinned by `A_preexisting_file_does_not_mask_a_silent_sink`. - **The load-bearing test is the failure case** (`A_sink_that_writes_nothing_is_reported`) — a check that can only pass is indistinguishable from no check, which is how the original defect ran silent for six weeks. - Family-glob attribution pinned by `The_rolled_and_sequenced_family_counts_as_the_template` (a healthy rolling deployment must not false-alarm just because the literal template name never exists). 7 new tests; full `Host.Tests` 103/103 green; docker-dev live verification of the healthy path (self-check silent, selflog file present, log growing) in progress on the rebuilt rig — evidence to follow in this thread. **Remaining to close #561:** deploy `29a202f5`+ to wonder-app-vd03 (next planned deploy — needs the service restart anyway), then read `E:\ApiInstall\OtOpcUa\logs\serilog-selflog.txt`: it will name the exact exception behind the silent writes. Expect the growth self-check warning on stderr/SelfLog at that boot too, proving the detection works against the real defect before the root cause is fixed.

dohertj2 commented

2026-08-11 06:13:51 -04:00

Healthy-path live gate PASSED on the docker-dev rig, both centrals rebuilt on the same image at 8ab520ef:

logs/serilog-selflog.txt present on both nodes, 0 bytes — the correct healthy state (no swallowed sink errors to report), and the eager open means the channel is proven writable before it is ever needed.
The growth self-check ran (marker line present in otopcua-20260811.log) and emitted no failure warning on either node; the main log grew normally (29 KB within seconds of boot).
Both nodes on image 9db569f6… (parity checked — the :9200 round-robin rule).

With the offline failure-case tests (A_sink_that_writes_nothing_is_reported, A_preexisting_file_does_not_mask_a_silent_sink) this covers both directions reachable without a deliberately-broken filesystem. The remaining leg stays as stated: deploy to wonder-app-vd03 on the next planned pass and read the selflog there — on that box the growth check should FIRE and the selflog should be non-empty, naming the real exception.

**Healthy-path live gate PASSED** on the docker-dev rig, both centrals rebuilt on the same image at `8ab520ef`: - `logs/serilog-selflog.txt` present on both nodes, **0 bytes** — the correct healthy state (no swallowed sink errors to report), and the eager open means the channel is proven writable before it is ever needed. - The growth self-check ran (marker line present in `otopcua-20260811.log`) and emitted **no failure warning** on either node; the main log grew normally (29 KB within seconds of boot). - Both nodes on image `9db569f6…` (parity checked — the `:9200` round-robin rule). With the offline failure-case tests (`A_sink_that_writes_nothing_is_reported`, `A_preexisting_file_does_not_mask_a_silent_sink`) this covers both directions reachable without a deliberately-broken filesystem. The remaining leg stays as stated: deploy to wonder-app-vd03 on the next planned pass and read the selflog there — on that box the growth check should FIRE and the selflog should be non-empty, naming the real exception.

dohertj2 referenced this issue from a commit

2026-08-12 02:09:29 -04:00

fix(logging): #561 was a measurement artifact — measure sink growth through an open handle

dohertj2 commented

2026-08-12 04:10:22 -04:00

Closing as not a defect — the reported symptom was a measurement artifact.

The log was never empty. E:\ApiInstall\OtOpcUa\logs\otopcua-20260811.log held 4.66 MB of normal, current log content — boot banner, steady-state entries, the lot. The Serilog file sink was working correctly the whole time, on both the old and the new binary.

Why it looked like 0 bytes. On Windows, a file held open by a running process reports a stale directory entry: Get-ChildItem / FileInfo.Length read cached metadata that is not refreshed until the handle is closed, so a live-held log lists as Length = 0 with LastWriteTime == CreationTime. That is exactly the signature reported here. The correct measurement is to open the file yourself with sharing that tolerates the writer:

$fs = [System.IO.File]::Open(
    'E:\ApiInstall\OtOpcUa\logs\otopcua-20260811.log',
    [System.IO.FileMode]::Open,
    [System.IO.FileAccess]::Read,
    [System.IO.FileShare]::ReadWrite -bor [System.IO.FileShare]::Delete)
$fs.Length          # the real size
$fs.Close()

Everything the issue body proposed investigating is void, because all of it was reasoned backwards from that one unvalidated measurement: the 23 OtOpcUaHost service environment variables carry no Serilog__* override that silences the sink; the AddZbSerilog layering does not drop the appsettings file sink; the deployed appsettings*.json matches the repo. None of these were ever the cause, and no change was needed in any of them. The same goes for the cross-app correlation in the last paragraph — the MxGateway "seven 0-byte NSSM stderr files" observation on the same box was made with the same tool and carries the same artifact, so it is not corroborating evidence and should be re-measured before anything is filed against that tracker.

What did ship, and why it was still worth doing (29a202f5): the issue's own acceptance criteria asked for "a startup self-check that logs one line and verifies the file grew, warning to console/EventLog if not." That landed, along with Serilog SelfLog routed to file + stderr. A genuinely silent sink is invisible from outside the process, so the self-check is real value independent of this false alarm — and had it existed on 2026-08-11 it would have reported the sink healthy and ended this investigation in one step.

Method note for whoever hits this next: the acceptance criterion here ("the day's log file contains the boot banner") was always checkable directly by reading the file, which is a stronger and cheaper observation than inspecting its size. When a metric and the underlying artifact disagree about whether something happened, read the artifact.

Closing as **not a defect — the reported symptom was a measurement artifact.** **The log was never empty.** `E:\ApiInstall\OtOpcUa\logs\otopcua-20260811.log` held **4.66 MB** of normal, current log content — boot banner, steady-state entries, the lot. The Serilog file sink was working correctly the whole time, on both the old and the new binary. **Why it looked like 0 bytes.** On Windows, a file held open by a running process reports a **stale directory entry**: `Get-ChildItem` / `FileInfo.Length` read cached metadata that is not refreshed until the handle is closed, so a live-held log lists as `Length = 0` with `LastWriteTime == CreationTime`. That is exactly the signature reported here. The correct measurement is to open the file yourself with sharing that tolerates the writer: ```powershell $fs = [System.IO.File]::Open( 'E:\ApiInstall\OtOpcUa\logs\otopcua-20260811.log', [System.IO.FileMode]::Open, [System.IO.FileAccess]::Read, [System.IO.FileShare]::ReadWrite -bor [System.IO.FileShare]::Delete) $fs.Length # the real size $fs.Close() ``` **Everything the issue body proposed investigating is void**, because all of it was reasoned backwards from that one unvalidated measurement: the 23 `OtOpcUaHost` service environment variables carry no `Serilog__*` override that silences the sink; the `AddZbSerilog` layering does not drop the appsettings file sink; the deployed `appsettings*.json` matches the repo. None of these were ever the cause, and no change was needed in any of them. The same goes for the cross-app correlation in the last paragraph — the MxGateway "seven 0-byte NSSM stderr files" observation on the same box was made with the same tool and carries the same artifact, so it is not corroborating evidence and should be re-measured before anything is filed against that tracker. **What did ship, and why it was still worth doing** (`29a202f5`): the issue's own acceptance criteria asked for "a startup self-check that logs one line **and verifies the file grew**, warning to console/EventLog if not." That landed, along with Serilog `SelfLog` routed to file + stderr. A genuinely silent sink is invisible from outside the process, so the self-check is real value independent of this false alarm — and had it existed on 2026-08-11 it would have reported the sink healthy and ended this investigation in one step. **Method note for whoever hits this next:** the acceptance criterion here ("the day's log file contains the boot banner") was always checkable directly by *reading the file*, which is a stronger and cheaper observation than inspecting its size. When a metric and the underlying artifact disagree about whether something happened, read the artifact.

dohertj2 closed this issue

2026-08-12 04:10:27 -04:00

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: dohertj2/lmxopcua#561