Repository navigation
Postgres health check fails intermittently: TLS handshake to PostgreSQL times out on new connector open #5314
Description
What is failing
The PostgreSql health check on the memex-cloud portal pod reported Unhealthy: opening a new Npgsql connector stalled in TLS negotiation and the check's cancellation token fired at ~3.2s (TaskCanceledException inside SslStream.ForceAuthenticationAsync → NpgsqlConnector.NegotiateEncryption). The check reported Unhealthy once; there is no evidence the database itself stayed unreachable.
Probable cause
Medium-low confidence — a transient network/TLS handshake delay to the PostgreSQL host (pod network blip, DNS, or server-side SSL accept) exceeded the health check's timeout. The stack runs entirely through Npgsql's PoolingDataSource.OpenNewConnector, i.e. the first pool open in that window. It is not an application-code defect; the exception message ('A task was canceled') is the health check timing out mid-handshake.
Impact
Single occurrence on a single pod (memex-portal-deployment-7cc85f47c-nm2qp), no recurrence since. At most a momentary liveness-readiness blip; no user-facing failure is evidenced.
Where to look
HealthChecks.NpgSql.NpgSqlHealthCheck.CheckHealthAsync(AspNetCore.Diagnostics.HealthChecks, line 31) — health check entry point.- Npgsql connector open path:
Npgsql.Internal.NpgsqlConnector.Open/NegotiateEncryption. - Consider raising the health check timeout or
NpgsqlTimeoutif Postgres TLS handshakes routinely exceed the current budget, and check pod→Postgres network/DNS at the timestamp.
Note: no application source file in our mesh is implicated — all frames are Npgsql / health-check library internals.
Evidence
| Fingerprint | b2cc907bf65c0478 |
| Category | Microsoft.Extensions.Diagnostics.HealthChecks.DefaultHealthCheckService |
| Severity | Error |
| Exception | System.Threading.Tasks.TaskCanceledException |
| Top frame | HealthChecks.NpgSql.NpgSqlHealthCheck.CheckHealthAsync(HealthCheckContext context, CancellationToken cancellationToken) |
| Namespace | memex-cloud |
| Pods | memex-portal-deployment-7cc85f47c-nm2qp |
| Occurrences | 1 |
| First seen | 2026-09-22 13:42:03Z |
| Last seen | 2026-09-22 13:42:03Z |
| Routing | not determined — no configured route matches the category Microsoft.Extensions.Diagnostics.HealthChecks.DefaultHealthCheckService. This repository is the configured fallback, not a finding about who owns the fault; the category names the LOGGER, which may not be the subject. |
Recent log lines
2026-09-22 13:42:03Z memex-portal-deployment-7cc85f47c-nm2qp fail: Microsoft.Extensions.Diagnostics.HealthChecks.DefaultHealthCheckService[103]
Health check PostgreSql with status Unhealthy completed after 3194.7498ms with message 'A task was canceled.'
System.Threading.Tasks.TaskCanceledException: A task was canceled.
at System.Net.Security.SslStream.ForceAuthenticationAsync[TIOAdapter](Boolean receiveFirst, Byte[] reAuthenticationData, CancellationToken cancellationToken)
at Npgsql.Internal.NpgsqlConnector.NegotiateEncryption(SslMode sslMode, NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)
at Npgsql.Internal.NpgsqlConnector.SetupEncryption(SslMode sslMode, GssEncryptionMode gssEncryptionMode, NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)
at Npgsql.Internal.NpgsqlConnector.<Open>g__OpenCore|209_0(NpgsqlConnector conn, String username, SslMode sslMode, GssEncryptionMode gssEncMode, NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)
at Npgsql.Internal.NpgsqlConnector.Open(NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)
at Npgsql.PoolingDataSource.OpenNewConnector(NpgsqlConnection conn, NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)
at Npgsql.PoolingDataSource.<Get>g__RentAsync|33_0(NpgsqlConnection conn, NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)
at Npgsql.NpgsqlConnection.<Open>g__OpenAsync|42_0(Boolean async, CancellationToken cancellationToken)
at HealthChecks.NpgSql.NpgSqlHealthCheck.CheckHealthAsync(HealthCheckContext context, CancellationToken cancellationToken) in /home/runner/work/AspNetCore.Diagnostics.HealthChecks/AspNetCore.Diagnostics.HealthChecks/src/HealthChecks.NpgSql/NpgSqlHealthCheck.cs:line 31
at HealthChecks.NpgSql.NpgSqlHealthCheck.CheckHealthAsync(HealthCheckContext context, CancellationToken cancellationToken) in /home/runner/work/AspNetCore…[truncated]
Opened automatically from Admin/_LogIncident/b2cc907bf65c0478. Recurrences are folded into this issue rather than opening new ones.
Activity
systemorph-com commentedon Sep 22, 2026
Still occurring: 1 more since the last update (2 total).
memex-portal-deployment-7cc85f47c-nm2qpRecent log lines
systemorph-com commentedon Sep 22, 2026
Still occurring: 1 more since the last update (3 total).
memex-portal-deployment-7cc85f47c-nm2qp,memex-portal-deployment-5c444645f8-8pdzbRecent log lines
rbuergi commentedon Sep 23, 2026
Triage 2026-09-23: #5347 folded in. Root cause NOT established, left open with the post-roll check named
#5347 is closed as a duplicate of this issue. It is the same handshake, cancelled two frames deeper, on the same pod, two minutes after this issue's third sample (details there). The burst is therefore four samples on two pods of two different ReplicaSets, 2026-09-22 13:42–14:44Z:
7cc85f47c-nm2qp7cc85f47c-nm2qp5c444645f8-8pdzb5c444645f8-8pdzbWhat the readings say
/healthrequest's own token. Which caller held it is not recorded. The only kubelet reader of/healthis the startup probe (deploy/helm/values.yamlprobes.startup, 5 s timeout). After a pod has started, the other readers are external: the synthetic probe andSample. A 12.4 s cancel does not fit a 5 s kubelet timeout unless the server was slow to see the client disconnect.SslStream's async handshake resumes on the shared ThreadPool. fix(compiler): keep NodeType compiles off the silo's shared ThreadPool #5327 (merged 2026-09-22 20:27Z asec191c2b61) measured runtime NodeType compiles saturating that pool. Its evidence puts memex-cloud mid-roll for most of 2026-09-22, with thread-shortage[ROUTE]crossings logged during rolls. Four ReplicaSets served inside this issue's two-hour window (5c89c7f5f9,7cc85f47c,69dd75bf49,5c444645f8), so this burst sits inside that roll period.waiting for a pool slot≥ 45). They name5bb495d47b-jntbn(10:56Z),5c89c7f5f9-sddb5(12:39–12:59Z),7f4f9b7689-d67t5and5c99d79997-xs87x(17:35Z). None of them is7cc85f47c-nm2qpor5c444645f8-8pdzb. Starvation is therefore consistent with this issue, not shown for it. A slow Postgres TLS accept or a network blip is not excluded.Why this stays open, and the check that decides it
memex.meshweaver.cloud now runs
39f49494eb(/api/version), which contains #5327 (git merge-base --is-ancestor ec191c2b61 39f49494ebpasses). memex.systemorph.com runs3da3423c4b, which does not. The deciding reading is whether this fingerprint (b2cc907bf65c0478, orc9defbf7ce85d8f9) recurs on memex-cloud during its NEXT roll on a #5327-carrying image:[ROUTE]crossings in the same roll also show no pool shortage: the pool is exonerated as fixed. Close as fixed by fix(compiler): keep NodeType compiles off the silo's shared ThreadPool #5327.waiting for a pool slotin the same minute: starvation is still live from a source fix(compiler): keep NodeType compiles off the silo's shared ThreadPool #5327 does not cover (grain re-activation on roll survivors, which fix(compiler): keep NodeType compiles off the silo's shared ThreadPool #5327 names as unaddressed).Silence alone does not decide it, because the incident pipeline has been dark for hours before (see #1174, 2026-09-19). The control instance that folds recurrences (memex.systemorph.com) was answering 503 to its MCP when this was written, so I could not take a
Logsreading.What I deliberately did NOT do
I did not raise the health check's timeout or Npgsql's
Timeout, which the bot's "where to look" suggests. That would hide a stall, not explain it (seeAProbeMustAnswerInsideItsOwnTimeout).A separate observation, not acted on: a check cancelled by its caller is logged as
UnhealthyatErrorlevel. That makes a slow or disconnecting reader indistinguishable from a database fault in the incident stream. Whether a caller-cancelled check should classify differently is a logging-policy question for the health-check owner, and it would not change this issue's root cause.systemorph-com commentedon Sep 23, 2026
Still occurring: 1 more since the last update (4 total).
memex-portal-deployment-7cc85f47c-nm2qp,memex-portal-deployment-5c444645f8-8pdzb,memex-portal-deployment-5f95fb94dc-pkhncRecent log lines
systemorph-com commentedon Sep 23, 2026
Still occurring: 4 more since the last update (8 total).
memex-portal-deployment-7cc85f47c-nm2qp,memex-portal-deployment-5c444645f8-8pdzb,memex-portal-deployment-5f95fb94dc-pkhnc,memex-portal-deployment-777677694-p6hbn,memex-portal-deployment-6688fb9488-8dn96Recent log lines
rbuergi commentedon Sep 23, 2026
Post-#5327 reading. The 04:37Z comment named the check that decides this issue: does the fingerprint recur on a roll of an image carrying #5327? It did. The 2026-09-23 samples are:
5f95fb94dc-pkhnc5f95fb94dc-pkhnc777677694-p6hbn,6688fb9488-8dn96Each lands in a window where the same pods logged the query fan-in stall:
Sources watcher faultedon5f95fb94dc-pkhncat 13:34:49Z;[ACTIVATE]stalls on5f95fb94dc-t9222at 13:26:31Z.So #5327 alone did not remove it. The co-occurrence still points at process-side contention during a roll rather than at Postgres. The 37 ms cancel says so too: that is the caller giving up, not a TLS timeout.
The per-read backlog being fixed for #5315/#5344 (core #5615, Plugins#2337) is Npgsql-side work on the same pods. Whether it also accounts for the slow handshakes is not established. A handshake needs a ThreadPool continuation, not a
pg-readslot, so the link would be indirect at best.Leaving this open, sev:L. The next reading has the same shape as before: after a roll carrying both halves, does
b2cc907bf65c0478recur, and on the same pod and minute as aQueryProviderStalledException? I took noLogsreading; the control instance was unreachable this session.systemorph-com commentedon Sep 23, 2026
Still occurring: 1 more since the last update (9 total).
memex-portal-deployment-7cc85f47c-nm2qp,memex-portal-deployment-5c444645f8-8pdzb,memex-portal-deployment-5f95fb94dc-pkhnc,memex-portal-deployment-777677694-p6hbn,memex-portal-deployment-6688fb9488-8dn96,memex-portal-deployment-6f497dc9b-j9vq8Recent log lines
docs(health): link the Plugins fix for #5314
rbuergi commentedon Sep 24, 2026
Root cause: the
fail:line is the caller's abandonment, folded into Unhealthy by Aspire's check. Fix in MeshWeaver.Plugins#2344Mechanism (read from the shipped binaries, not assumed):
PostgreSqlcheck is registered byAspire.Npgsql13.4.6 (AddNpgsqlDataSource). It isnew NpgSqlHealthCheck(new NpgSqlHealthCheckOptions(sp.GetRequiredService<NpgsqlDataSource>())), with no tags and no timeout.ConnectionIdleLifetime = 30prunes idle ones.HealthChecks.NpgSql9.0.0CheckHealthAsyncwrapsOpenAsyncandExecuteScalarAsyncin onecatch (Exception ex) => new HealthCheckResult(FailureStatus, ex.Message, ex). The caller'sOperationCanceledExceptionis included in that catch.MapHealthCheckspassesHttpContext.RequestAborted.DefaultHealthCheckService(10.0.11) propagates a caller cancellation (catch (OperationCanceledException) when (!cancellationToken.IsCancellationRequested)only converts a registration timeout). It logs every Unhealthy entry at Error, and that entry is event [103] in this issue./healthreader that stops waiting turns into "PostgreSql Unhealthy … A task was canceled", with whatever frame the connector was in (SslStream handshake,NpgsqlWriteBuffer.Flush). That explains the 37 ms to 12.4 s spread: it measures when the check started relative to the caller's deadline, not Postgres.Fix (MeshWeaver.Plugins#2344):
DisableHealthChecks = trueon both the Azure and the password path).PostgreSqlHealthCheckunder the same name:SELECT 1on the same pooled source.PostgreSqlHealthCheckCancellationTestdrives the realHealthCheckServiceagainst a socket that answers the SSLRequest withSand stalls in the TLS handshake. It passes.No exception was thrownbecause an Unhealthy report comes back.AProbeMustAnswerInsideItsOwnTimeout, "A caller that gives up is not a failed check").Not established / not changed:
Sample./healthwas slow enough for the reader to abort. That is A 13-minute-old Hosting install records FleetWatchCadence.cs and the NODE is absent — three Hosting NodeTypes uncompilable, and memex's roll to the 3.0.0 candidate cannot converge #4588's timing line. The co-occurrence with MessageHubGrain activations fault when query providers stall past the 15s fan-in bound (access/entitlements queries unavailable) #5315/PostgreSQL partitioned mesh query provider exceeds the 15 s Initial budget, faulting space compile watchers #5344 stalls noted above is consistent with process-side contention, which this does not touch.Post-roll check: fingerprint
b2cc907bf65c0478stops recurring on an image carrying #2344. If an UnhealthyPostgreSqlline appears after that, it is a real failure seen by a waiting caller.rbuergi commentedon Sep 24, 2026
MeshWeaver.Plugins#2344 merged (
d28f0ab067, 2026-09-24 07:52Z). It carries a review-driven guard that the host registers exactly onePostgreSqlcheck with Aspire's disabled on both data-source branches, because a duplicate name would take/healthdown entirely. Doc #5644 merged (6844133af7). Leaving this open for the post-roll reading: on an image carryingd28f0ab067,b2cc907bf65c0478should stop folding. APostgreSqlUnhealthy line after that is a real failure seen by a caller that was still waiting.systemorph-com commentedon Sep 26, 2026
Still occurring: 1 more since the last update (10 total).
memex-portal-deployment-7cc85f47c-nm2qp,memex-portal-deployment-5c444645f8-8pdzb,memex-portal-deployment-5f95fb94dc-pkhnc,memex-portal-deployment-777677694-p6hbn,memex-portal-deployment-6688fb9488-8dn96,memex-portal-deployment-6f497dc9b-j9vq8,memex-portal-deployment-75cd8dc74c-pckmhRecent log lines
systemorph-com commentedon Sep 26, 2026
Still occurring: 1 more since the last update (11 total).
memex-portal-deployment-7cc85f47c-nm2qp,memex-portal-deployment-5c444645f8-8pdzb,memex-portal-deployment-5f95fb94dc-pkhnc,memex-portal-deployment-777677694-p6hbn,memex-portal-deployment-6688fb9488-8dn96,memex-portal-deployment-6f497dc9b-j9vq8,memex-portal-deployment-75cd8dc74c-pckmh,memex-portal-deployment-7b6649594-wtnwmRecent log lines
rbuergi commentedon Oct 8, 2026
Closing as fixed by MeshWeaver.Plugins#2344 (merged 2026-09-24 07:52Z).
src/Memex.Portal.Distributed/PostgreSqlHealthCheck.csnow passes a caller's cancellation on as a cancellation instead of reporting Unhealthy, and Aspire's own check is disabled (pinned byPostgreSqlHealthCheckCancellationTest). The last sighting ofb2cc907bf65c0478was 2026-09-24 08:13Z, about 20 minutes after the merge and before any image carrying it could have rolled; none in the two weeks since. A PostgreSql Unhealthy line seen by a caller that was still waiting is a real failure, tracked in #5722.sev:L sweep, Claude Opus 5.5 (agent session).