mirror of
https://github.com/OPCFoundation/UA-.NETStandard.git
synced 2026-10-17 05:11:13 +08:00
Marc Schier
b17007bd55
# Description The `Core.Encoders` test job of run [`31249610490`](https://github.com/OPCFoundation/UA-.NETStandard/actions/runs/31249610490) printed nothing for 57 minutes and was killed by the 60-minute job timeout. Issue #4213 recorded that as "hung at or before the first test" — that reading was wrong, and the evidence to disprove it was already in the job's own artifact. The blame collector *had* written a hang dump and it *was* uploaded, inside the ordinary `dotnet-results-Core.Encoders-*` artifact (11 MB of it was the dump), where nobody looked for it. Opening it names the cause precisely. ## What the dump shows 522 threads (408 background) in a process that finishes in 25 seconds when healthy. Every test had already run; NUnit was in `OneTimeTearDown` waiting on its event pump: - the **event pump thread** is blocked in `NUnitEventListener.TestFinished` → `TestRunEventsHandler.HandleLogMessage` → `LengthPrefixCommunicationChannel.Send` → `Socket.Send`, on a socket that never drained. That send holds the channel's lock; - `TestRunCache.SendResults` is blocked on that channel lock, and it holds the cache lock; - `TestRunCache`'s **one-second timer** then fired repeatedly into that held cache lock, and the thread pool injected a fresh worker for each — **399 threads** parked in `Monitor.Enter_Slowpath` behind a single lock; - the NUnit run thread sits in `EventPump.Stop()` → `Thread.Join()`, so the run can never complete. ## What put the socket under that much pressure Volume of test output. Every encoder case dumps its input, its encoded payload and its decoded result, the NUnit adapter forwards each captured line to the runner as an individual message over that socket, and the suite has 2929 cases. This is not marginal: | | Before | After | | --- | --- | --- | | `Core.Encoders` TRX, green local run | **496 MB** | **4 MB** | | `Core.Encoders` published CI artifact | **156 MB** | ~3 MB | | Next-largest test job's artifact, for scale | 15 MB | 15 MB | | `Client.ComplexTypes` TRX | 74 MB | 40 MB | So the suite was shipping half a gigabyte of text through a socket, one message per line, on every run and on every OS — and paying for it in artifact storage even when nothing went wrong. ## The change `EncoderCommon` gains a buffered `TestOutput` writer. The dumps are collected per test and handed to `TestContext.Out` in `TearDown` **only when the test did not pass** — which is the only time anyone reads them. Nothing is lost: a failing test still reports its full input/encoded/decoded dump under *Standard Output Messages*, verified by injecting a deliberate failure. Explicit opt-ins (`PrettifyAndValidateJson(..., outputFormatted: true)`) and the static helpers keep writing immediately. The same base class is shared by the `Client.ComplexTypes` fixtures, so those are moved over too rather than left with half-buffered, half-immediate output. Two supporting changes: - **`.github/workflows/buildandtest.yml`** — `timeout-minutes: 30` on the `Test` step. The blame collector did its job here (dump at +50 min, once the run went quiet), but the run still had not unwound 7 minutes later when the *job* timeout cancelled everything, so the step needs a bound below the job's. `Upload test results` already runs `if: always()`, so the dump is still published. - **`docs/DeveloperGuide.md`** — a "Test output" convention under *Running tests*, so the next data-driven fixture does not re-introduce this. ## Notes for reviewers - `[Parallelizable]` on these fixtures is `ParallelScope.Self`, i.e. fixture-level; tests inside a fixture stay sequential, so the per-fixture buffer is as safe as the existing per-fixture `RandomSource`/`DataGenerator` state that is already reset in `SetUp`. - I separately confirmed that `--blame-hang-timeout` *does* fire on a hang before the first test (minimal NUnit repro, dump at exactly the configured timeout), which is what rules out the original "hung during startup/discovery" theory independently of the dump. - Local verification was scoped to the two affected suites rather than the whole solution: `Opc.Ua.Core.Encoders.Tests` 2929/2929 on **net10.0** *and* **net48**, `Opc.Ua.Client.ComplexTypes.Tests` 2773/2773 on net10.0, all building with 0 warnings. The full `UA.slnx` run is left to CI. ## Related Issues - Fixes #4213 ## Checklist - [x] I have signed the [CLA](https://opcfoundation.org/license/cla/ContributorLicenseAgreementv1.0.pdf) and read the [CONTRIBUTING](https://github.com/OPCFoundation/UA-.NETStandard/blob/master/CONTRIBUTING.md) doc. - [x] I have added tests that prove my fix is effective or that my feature works and increased code coverage. - [x] I have added all necessary documentation. - [x] I have verified that my changes do not introduce (new) build or analyzer warnings. - [ ] I ran **all** tests locally using the **UA.slnx** solution against at least .net **framework** and .net **10**, and all passed. - [ ] I fixed **all** failing and flaky tests in the CI pipelines and **all** CodeQL warnings. - [ ] I have addressed **all** PR feedback received. --------- Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Copilot-Session: da92151a-3da2-4caf-a39c-5556e56f0506