Decode the loader status instead of printing a raw Win32 number (#2186)

CHANGELOG.md

@@ -30,6 +30,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ### Fixed
 
+- **A managed-Postgres bootstrap failure now says what went wrong instead of printing a Win32 number** ([#2186], from @jovon44's report in #2185) - a store that could not start reported `initdb failed (exit code -1073741515) for ... Output:` and nothing else. `-1073741515` is `0xC0000135`, `STATUS_DLL_NOT_FOUND`: Windows killed the process in the loader, before a line of its own code ran - which is also why `Output:` was blank and always would be, so the one field an operator reads was guaranteed empty exactly when the failure was a load failure. Their attention then went to the follow-on missing-credential message and `darling.json`, neither of which was the fault. Every bundled-binary failure (initdb, pg_ctl start/status/stop/reload, pg_upgrade and its `--check`, the post-upgrade analyze) now decodes a Windows status into its name, names the two causes that account for nearly all of them - the bundled MSVC runtime absent from `pg-runtime\pgsql\bin`, which means a partial or damaged extract rather than a missing prerequisite, or a service account that cannot read an install tree sitting under a user profile - and gives the two checks that tell them apart, including the caveat that these tools re-execute themselves under a restricted token that drops Administrators, so running the binary by hand succeeding does not clear the permissions theory. An empty `Output:` now says it is empty **because** the process was killed before it could write, rather than looking like data that failed to arrive. Two messages also stopped blaming the wrong thing: `pg_ctl status` no longer calls the data directory unusable when the verdict came from Windows rather than from pg_ctl (that phrasing pointed at deleting a healthy store to fix a missing DLL), and `pg_upgrade --check` no longer reports clusters as incompatible when pg_upgrade never ran to form an opinion. The related [#1738] refusal now quotes and decodes the probe exit code it always had, instead of asserting that the binaries did not run without saying how it knew.
 - **A database observed mid-restore no longer learns RESTORING as its expected state and then alerts forever for being healthy** ([#2189]) - found by dogfooding: the production 52-server box fired 636 Database State alerts in 24 hours from 5 databases, every one of them reading `Expected: RESTORING, Current: ONLINE`. Each had been swept into monitoring during a consolidation while a restore was running, had RESTORING written as its accepted baseline, and had been "deviating" ever since by being healthy - permanently, since the only escape was an operator noticing and re-baselining by hand. Two halves. The seed now refuses to learn the TRANSIENT operational states (RESTORING, RECOVERING) the same way it already refused the integrity ones: a database in the middle of an operation is not a steady state anybody would choose as expected, so it stays pending and silent until it settles into one, and when the restore completes ONLINE is what gets learned. That governs rows that do not exist yet and cannot touch the ones already written, so the second half applies the same rule after the fact - an AUTO-seeded baseline recording a state the seed would refuse to learn is not a baseline anyone chose, and once that database's effective state reaches ONLINE the steady state is learned instead. The already-poisoned rows therefore repair themselves on the next sweep, with no migration and no manual step, and the route that stays open forever is covered too: pressing "reset to current" while a restore is running (or during an outage) records whatever it sees with no state filter at all, and that now un-writes itself. What the repair deliberately does NOT touch is as load-bearing as what it does, because every case here is one where being wrong means silence. It never rewrites a baseline an OPERATOR declared, so #2166's composition contract holds exactly as specified: a database you park at expected OFFLINE stays quiet while parked and still alerts the moment it comes back ONLINE. It never touches an OFFLINE or STANDBY baseline even though the machine inferred those, because both are steady states and leaving one is real news - a STANDBY secondary that turns up truly ONLINE has stopped being a secondary, which means somebody recovered it and log shipping is broken, and an auto-baselined OFFLINE database brought up for an hour of maintenance and re-parked would otherwise come back deviating forever against a baseline it never had. And it matches the EFFECTIVE state rather than `state_desc`, because a standby secondary reports `state_desc = ONLINE` with `is_in_standby` set - matching the raw column would have re-baselined every such secondary and then alerted it forever for being STANDBY, this same bug recreated for the one database family the alert works hardest to keep quiet. A log-shipping secondary restored WITH NORECOVERY, which sits in RESTORING permanently, stays silent forever as before; it now gets there by never being baselined rather than by baselining RESTORING, and an operator who wants deviation coverage on one sets its expected state explicitly. Both SKUs. (This is the seed and baseline logic, not #2166's alerted-state memory, which remains Darling-only until parity lands.)
 
 - **The doc-comment hygiene pin now catches a stacked summary whose first block is never closed** ([#2190]) - `NoMemberCarriesTwoStackedSummaryBlocks` keyed off a `</summary>` immediately followed by a reopening, so it only ever saw a stacked pair when the FIRST block was closed, and two instances were sitting on dev unseen: a duplicated opening tag on `ApplyProcessEnvironment` in the Darling service, and a doc block that #1912's restructure split in `QueryStoreSliceRepairService`, stranding its unclosed head on top of `PromoteRewrittenFileAsync`. The rule now counts `<summary>` OPENINGS inside each contiguous run of `///` lines - a run documents exactly one member, so two openings means two summaries whether or not either is closed, and whether they are written single-line or spread over many. That mixed form is the one a closing-tag matcher cannot see at all, and it is what defeated the first attempt at this fix. Both live instances are repaired: the duplicate tag is deleted, and the stranded head is deleted rather than moved back, because the same restructure had already re-documented `FlushExternalFileCacheAsync` in place with a superset of that one sentence, so moving it would have recreated the exact duplicate this rule exists to forbid. The detector now carries its own self-test as well, pinning the five stacked shapes it must catch and the four legitimate ones it must leave alone, since this was a blind spot in the DETECTOR rather than in anyone's reading of the tree.
@@ -2677,5 +2678,6 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 [#2167]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2167
 [#2138]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2138
 [#2190]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2190
+[#2186]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2186
 [#2187]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2187
 [#2189]: https://github.com/erikdarlingdata/PerformanceMonitor/issues/2189

Darling/Darling.Tests/DarlingManagedPostgresTests.cs

@@ -11,6 +11,7 @@
 using System.IO;
 using System.Net;
 using System.Net.Sockets;
+using System.Runtime.CompilerServices;
 using System.Security.Cryptography;
 using System.Security.Cryptography.X509Certificates;
 using System.Threading;
@@ -906,4 +907,126 @@ private static void TryDeleteRecursive(string path)
             }
         }
     }
+
+    /* ============ #2186: the bootstrap's failure messages, in the operator's words ============
+       These pin the SHIPPED strings, not the decoder — DarlingToolExitCodeTests owns the decode.
+       The distinction is the whole point: #1738 was a correct check that nothing invoked, and a
+       correct decoder no message calls would be the same defect wearing a new hat. */
+
+    private const int StatusDllNotFound = unchecked((int)0xC0000135);
+    private const string FieldBinDirectory = @"C:\PerformanceMonitorDarling\pg-runtime\pgsql\bin";
+    private const string FieldDataDirectory = @"C:\ProgramData\PerformanceMonitorDarling\pg";
+
+    /// <summary>
+    /// The reported failure, rebuilt from the field's own numbers: exit -1073741515 and an empty capture.
+    /// Every clause the report was missing has to be present, and the clause it HAD has to survive — field
+    /// reports and the issue tracker are searchable by "initdb failed (exit code", so the fix must not
+    /// rename the thing operators paste into search.
+    /// </summary>
+    [Fact]
+    public void InitDbFailureMessage_TurnsTheFieldReportIntoADiagnosis()
+    {
+        var message = DarlingManagedPostgres.BuildInitDbFailureMessage(
+            -1073741515, Path.Combine(FieldBinDirectory, "initdb.exe"), FieldDataDirectory, string.Empty);
+
+        Assert.StartsWith("initdb failed (exit code -1073741515", message, StringComparison.Ordinal);
+        Assert.Contains(FieldDataDirectory, message, StringComparison.Ordinal);
+
+        /* What the number means, and that Windows rather than PostgreSQL set it. */
+        Assert.Contains("0xC0000135", message, StringComparison.Ordinal);
+        Assert.Contains("STATUS_DLL_NOT_FOUND", message, StringComparison.Ordinal);
+
+        /* The empty field is stated as expected. The report's "Output:" trailing a blank line is what made
+           the whole thing read as missing data. */
+        Assert.Contains("Output:", message, StringComparison.Ordinal);
+        Assert.DoesNotContain("Output:\n\n", message, StringComparison.Ordinal);
+        Assert.DoesNotContain("Output:\n(none)", message, StringComparison.Ordinal);
+        Assert.Contains("expected", message, StringComparison.OrdinalIgnoreCase);
+
+        /* Both causes, and the directory the DLLs are supposed to be in. */
+        Assert.Contains(FieldBinDirectory, message, StringComparison.Ordinal);
+        Assert.Contains("vcruntime140_1.dll", message, StringComparison.Ordinal);
+        Assert.Contains("NT SERVICE", message, StringComparison.Ordinal);
+    }
+
+    /// <summary>An ordinary initdb failure is left to speak for itself: its own stderr is the diagnosis,
+    /// and it must not be pushed below a screen of loader boilerplate that does not apply.</summary>
+    [Fact]
+    public void InitDbFailureMessage_LeavesARealInitDbErrorAlone()
+    {
+        const string stderr = "initdb: error: directory \"C:\\pg\" exists but is not empty";
+
+        var message = DarlingManagedPostgres.BuildInitDbFailureMessage(
+            1, Path.Combine(FieldBinDirectory, "initdb.exe"), FieldDataDirectory, stderr);
+
+        Assert.Equal($"initdb failed (exit code 1) for {FieldDataDirectory}.\nOutput:\n{stderr}", message);
+    }
+
+    /// <summary>
+    /// pg_ctl status's own exit 4 really does mean the data directory is unusable, and the message keeps
+    /// saying so. A Windows status means pg_ctl never ran — keeping the verdict there would point an
+    /// operator at deleting a healthy store to fix a missing DLL.
+    /// </summary>
+    [Fact]
+    public void StatusFailureMessage_BlamesTheDataDirectoryOnlyWhenPgCtlActuallySaidSo()
+    {
+        var pgCtl = Path.Combine(FieldBinDirectory, "pg_ctl.exe");
+
+        var pgCtlVerdict = DarlingManagedPostgres.BuildStatusFailureMessage(4, pgCtl, FieldDataDirectory, "pg_ctl: could not open ...");
+        Assert.Contains("the data directory is not usable", pgCtlVerdict, StringComparison.Ordinal);
+
+        var loaderFailure = DarlingManagedPostgres.BuildStatusFailureMessage(StatusDllNotFound, pgCtl, FieldDataDirectory, string.Empty);
+        Assert.DoesNotContain("the data directory is not usable", loaderFailure, StringComparison.Ordinal);
+        Assert.Contains("STATUS_DLL_NOT_FOUND", loaderFailure, StringComparison.Ordinal);
+    }
+
+    /// <summary>
+    /// The start failure's log tail has the initdb message's trap in another costume: on a loader status
+    /// pg_ctl never started a postmaster, so "(no server log written)" is true and useless. The diagnosis
+    /// has to arrive BEFORE the tail invites an operator to go read a log that was never going to exist.
+    /// </summary>
+    [Fact]
+    public void StartFailureMessage_DiagnosesBeforeItPointsAtAnEmptyServerLog()
+    {
+        var message = DarlingManagedPostgres.BuildStartFailureMessage(
+            StatusDllNotFound, Path.Combine(FieldBinDirectory, "pg_ctl.exe"), FieldDataDirectory, "(no server log written)");
+
+        var diagnosis = message.IndexOf("STATUS_DLL_NOT_FOUND", StringComparison.Ordinal);
+        var tail = message.IndexOf("Server log tail:", StringComparison.Ordinal);
+
+        Assert.True(diagnosis >= 0, "the start failure must decode a Windows status");
+        Assert.True(tail > diagnosis, "the loader diagnosis has to precede the server-log tail it explains");
+    }
+
+    /// <summary>
+    /// The wiring, pinned at the source: three correct builders that no throw site calls would leave the
+    /// shipped message exactly as it was reported. Behavioral coverage cannot reach these — reproducing
+    /// them needs a bundled Postgres that dies in the Windows loader, which is not something a CI runner
+    /// can be asked to arrange.
+    /// </summary>
+    [Fact]
+    public void TheBootstrapThrowSitesActuallyUseTheseMessages()
+    {
+        var source = ReadManagedPostgresSource();
+
+        Assert.Contains("throw new InvalidOperationException(BuildInitDbFailureMessage(exitCode, initDb, _dataDirectory, output));", source, StringComparison.Ordinal);
+        Assert.Contains("throw new InvalidOperationException(BuildStatusFailureMessage(exitCode, pgCtl, _dataDirectory, output)),", source, StringComparison.Ordinal);
+        Assert.Contains("BuildStartFailureMessage(exitCode, pgCtl, _dataDirectory, ReadServerLogTail())", source, StringComparison.Ordinal);
+
+        /* And that no bootstrap failure went back to interpolating the bare code. */
+        Assert.DoesNotContain("exit code {exitCode}", source, StringComparison.Ordinal);
+    }
+
+    private static string ReadManagedPostgresSource([CallerFilePath] string thisFile = "")
+    {
+        var relative = Path.Combine("Darling", "PerformanceMonitor.Darling.Service", "DarlingManagedPostgres.cs");
+        var dir = Path.GetDirectoryName(thisFile);
+        while (dir is not null && !File.Exists(Path.Combine(dir, relative)))
+        {
+            dir = Path.GetDirectoryName(dir);
+        }
+
+        Assert.False(dir is null, "could not locate the repo root from the test source path");
+        return File.ReadAllText(Path.Combine(dir!, relative));
+    }
 }