Skip to content

memex self-update is silent: 3 builds behind, roll floor satisfied 5h ago, and ZERO SelfUpdate log lines in 6.7h #2553

Closed

Description

@rbuergi

Summary

memex is three published builds behind, the roll floor has been satisfied for over five hours,
and the self-updater has written zero log lines in 6.7 hours. Silence is the finding: this is not
a hold that was decided and reported, it is a component that appears not to be deciding at all.

Measured 2026-08-27 ~21:15 UTC

What the portal is running (GET https://memex.meshweaver.cloud/api/version):

{"version":"3.0.0-rc8+64b0c39d0d33…","commit":"64b0c39d0d33eaf3135bd3e52dd3c6772a252b68"}

64b0c39d0 merged at 18:42. The deployment agrees:

IMAGE   meshweaver.azurecr.io/memex-portal-ai:3.0.0-rc8.ci.6105
READY   2/2   UPDATED 2          ← healthy, not a stuck rollout

What ACR has published since — az acr repository show-tags -n meshweaver --repository memex-portal-ai --orderby time_desc:

3.0.0-rc8.ci.6178      ← current newest
3.0.0-rc8.ci.6158
3.0.0-rc8.ci.6152
3.0.0-rc8.ci.6105      ← what is running

The roll floor is not the reason. SelfUpdate__MinRollInterval is 1h, and the deployment's own
restart-surviving stamp says the last self-update roll was 6.7 hours ago:

meshweaver.io/self-update-rolled-at: 2026-08-27T14:27:24.500Z

And nothing is being logged. Over the pod's whole lifetime:

kubectl -n memex logs deploy/memex-portal-deployment --since=6h --tail=20000 | grep -ic selfupdate
0

Zero — not "held", not "skipped", not "checked and declined". Per #1773 the updater does one pass at
startup and then a check per publication event; three publications have gone by. Even the
startup pass left no trace.

Why the silence is the important part

A hold that is decided and reported is a working system making a defensible choice — ui.updateHeld
exists precisely so an operator can read it. What is measured here is indistinguishable from the
updater never having run, and those two states have opposite remedies. This is the
absence-of-evidence shape AGENTS.md warns about, pointed at the delivery path: "an install that is
behind is behind for a reason worth reading"
— and there is no reason to read.

Consequence, and why it matters tonight

Every merge that goes green stops in ACR. Concretely, #2534 cannot reach production — the fix for
MeshBuilder.Configuration being null on every deployed portal, which is why /Agent and /Skill
serve the built-in NodeType instead of the durable Store rows. /Agent still returns
og:title="Agent", the pre-fix state, on commit 64b0c39d0.

Candidate causes, in the order worth checking

  1. The publication-event watch is faulted and its backstop is not producing a roll either.
    SelfUpdateOptions.PollInterval no longer exists; RetryInterval (6 h) is the only backstop for a
    faulted watch. Last roll 14:27 + 6 h fell due at ~20:27 and still produced nothing, so if the watch
    is faulted the backstop is not covering it — which would make the 6 h retry the second thing that
    is silent.
  2. The component is not registered or not started at all in this image. That would explain the
    absence of even a startup line, and would be invisible to every health probe — the portal is
    READY 2/2 and serving.
  3. It is logging below Information. Cheapest to falsify, and worth doing first so the other two
    are not chased against a measurement artefact. If that is the answer, the fix is still a change:
    a decision not to roll is exactly the event an operator needs at Information.

What would make this diagnosable next time

Whatever the cause, the updater should emit one line per check with the verdict and the reason —
rolled, held (why), floor not elapsed (until when), no newer build. Right now the only
observable is the image tag, and an operator comparing tags cannot tell a deliberate hold from a dead
component.

Not done here deliberately

No roll was forced. kubectl rollout restart would trigger the startup pass and probably paper over
whichever of the three causes it is — and a prod deploy is its own decision, not a debugging
convenience.

Activity

  1. rbuergi commented on Aug 27, 2026

    @rbuergi
    ContributorAuthor

    Leading candidate found, filed as #2555 — and it makes candidate (1) in this issue concrete.

    MeshWeaver.Plugins/src/MeshWeaver.SelfUpdate.Aks/KubernetesDeploymentUpdater.cs:114-126:

    public async Task PatchToVersionAsync(string versionTag, CancellationToken ct)
    {
        if (!CanPatch) return;
        await PatchDeploymentImageAsync(_options.PortalDeployment,    …, _options.PortalImage(versionTag), ct);
        await PatchDeploymentImageAsync(_options.MigrationDeployment, …, _options.MigrationImage(versionTag), ct);
        _logger?.LogInformation("[SelfUpdate] patched {Portal} + {Migration} to {Tag}.", …);   // ← after BOTH
    }

    Two things are wrong with the second await, and either alone would explain the silence this issue measures:

    The confirmation LogInformation sits after both awaits. So a throw on the second leaves the portal patched, the line unwritten, and an exception heading into the watch — which is precisely the shape of "zero log lines while three builds published".

    Timing lines up: the portal rolled to ci.6105 at 14:27 (the self-update-rolled-at stamp in this issue) and migration Job memex-migration-26 appeared at 14:51, pinned to memex-migration:3.0.0-rc8.ci.6105 — a tag that has never existed. It is now 1699 pull attempts over 6h27m in ImagePullBackOff.

    🚨 Stated as inference, not measurement. I have not confirmed the throw, because there are no logs to confirm it with — which is the circularity this issue is about. Candidate (3) here ("it is logging below Information") is still worth falsifying first, since it is cheapest and would change what the fix is.

    Either way this issue's ask stands on its own: the updater must emit one line per check with its verdict. Had it done so, #2555 would have been visible at 14:27 instead of at 21:20 by someone reading ACR tags.

  2. rbuergi commented on Aug 27, 2026

    @rbuergi
    ContributorAuthor

    Still not rolled, and now four builds behind — re-measured 21:40 UTC:

    /api/version  → commit 64b0c39d0        (unchanged since 18:42)
    ACR newest    → 3.0.0-rc8.ci.6183
    last roll     → 14:27 UTC  (7h ago, against a 1h MinRollInterval)
    

    Main is producing green runs again (9028de32 completed success) and CD is publishing, so the earlier CI-queue stall has cleared. The wall is still between ACR and the cluster.

    A concrete mechanism for the silence, in the code

    KubernetesDeploymentUpdater.cs:76,116:

    public bool CanPatch => _http is not null && _apiBase is not null && !string.IsNullOrEmpty(_namespace);
    
    public async Task PatchToVersionAsync(string versionTag, CancellationToken ct)
    {
        if (!CanPatch)
            return;          // ← no log, no verdict, no trace
        …
    }

    If CanPatch is false the entire roll is a silent no-op. No exception, no warning, nothing to grep — and from outside it is indistinguishable from "there is no newer build", which is precisely the state this issue is trying to tell apart. That is the fail-closed-and-silent shape AGENTS.md names as a defect generator, sitting on the delivery path.

    LastRolledAtAsync has the same gate at :84 and returns null — documented as "cannot tell ⇒ do not hold the roll on evidence we could not gather", which is the right call for that method precisely because a caller still proceeds. PatchToVersionAsync returning silently has no such justification: it is the action, not the evidence.

    This does not prove CanPatch is false on memex — I have no logs to prove anything with, which is the circularity. It does mean candidate (2) and candidate (3) in the issue body collapse into one testable question: is the updater running and deciding nothing observable, or not running at all? And it means the fix in this issue's "what would make this diagnosable" section is not optional polish — CanPatch == false must log which of the three inputs was missing, at Warning, once per check.

    Worth noting the asymmetry that makes this expensive: a portal that fails to roll keeps serving perfectly, so nothing degrades and nobody looks. It took reading ACR tags against /api/version to see it at all.

  3. rbuergi commented on Aug 29, 2026

    @rbuergi
    ContributorAuthor

    Candidate (3) was right, and it is measurable — plus the code half that made a fix necessary anyway. PR: #2657

    The reason there were literally ZERO lines

    MeshWeaver.Plugins/src/Memex.Portal.Distributed/appsettings.json:

    "Default": "Warning",
    "MeshWeaver": "Warning",
    …
    "Memex.Portal.Shared.ShippedReleaseSeedHostedService": "Information",   // ← the sibling IS surfaced
    "Memex": "Warning",                                                     // ← and this catches us

    There is no entry for Memex.Portal.Shared.SelfUpdate. Every line this service has — the [SelfUpdate] starting banner, "applying update", "HOLDING", "deferring", "detect-and-notify" — is LogInformation. Only Warning/Error survive. So the 6.7 h of silence is consistent with the poller running perfectly and reporting into a void, and it also would have been consistent with it not running at all. That is exactly the circularity this issue names, and it means candidates (1), (2) and (3) were never distinguishable from the evidence available.

    That also rules out the fix I would otherwise have written first: a log-only change ships straight back into the same void.

    …and the code half is real regardless

    Even at Information, a check could complete having said nothing. RunOnce returned IObservable<Unit>, and two bare Rx Where clauses discarded whole checks:

    .Where(content => content.Policy != UpdatePolicyKind.None)   // policy None — the most silent path
    .Where(target => !string.IsNullOrEmpty(target))              // nothing newer — the most COMMON outcome

    "We asked and the answer was no" produced the same observation as "nothing ever asked". And the one surface an operator actually reads made it worse — UpdatePolicySettingsTab.StatusMarkdown returned ui.updateNoNewerVersion ("No newer version detected yet") whenever LatestAvailableTag was empty, which is also the state of an install that has never checked. The tab was asserting a fact it had not established.

    What #2657 does

    • RunOnce returns a SelfUpdateVerdict. Every branch names its outcome; DefaultIfEmpty(NoOutcome()) makes "the pipeline produced nothing" itself a reported outcome, so a future filter cannot re-create the silence.
    • The verdict is logged AND stamped on Admin/UpdatePolicy — LastCheckedAt / LastCheckVerdict / LastCheckTrigger. The node write does not depend on a log level anyone remembered to set, which is the whole lesson above. (It cannot feed itself: the trigger is DistinctUntilChanged(c => c.Policy), so a bookkeeping write emits nothing downstream.)
    • The Updates tab now distinguishes "checked at T, nothing newer" from "no check has completed".
    • The trigger is recorded too, which is what makes the sibling defect visible — see 🚨 Prod cannot roll: CD's announcement 404s and self-update is EVENT-DRIVEN (no poll) — PLATFORM_WEBHOOK_URL ≠ memex WebhookInbox:Targets #2494.

    Six tests assert the delivery (a line that reached a logger, a field that landed on the node), never a return value. Run first against origin/main: 5 of 5 time out waiting for a verdict that pre-fix code never emits.

    🚨 Still worth doing, and not in that PR

    The appsettings.json entry, in MeshWeaver.Plugins. The node stamp makes the verdict readable without it, but "the operator's log channel for the update mechanism is off" is worth fixing in its own right — and it is a one-line change in a repo this PR does not touch.

  4. added a commit that references this issue on Aug 29, 2026
  5. rbuergi commented on Aug 30, 2026

    @rbuergi
    ContributorAuthor

    Read live on memex just now — the service is running, and it SAYS so on the node

    // @Admin/UpdatePolicy  (version 1885, lastModifiedBy system-security)
    {
      "policy": "None",
      "requireCiGreen": true,
      "latestAvailableTag": "3.0.0-rc8.ci.6576",
      "checkedAt":     "2026-08-30T07:08:15Z",
      "lastCheckedAt": "2026-08-30T07:58:06Z",     // ← three minutes before this reading
      "lastCheckVerdict": "updates are disabled on this install (Admin/UpdatePolicy = None); the registry was not listed.",
      "lastCheckTrigger": "BuildCompletion"
    }

    That is this issue answered from both ends:

    1. The silence is gone, and the fix works the way #2657 intended — "a check that finds nothing must SAY so". The verdict is written to the NODE, so it is readable without any log access at all. That matters more than the log line this issue originally asked for: the 6.7 hours of nothing were unreadable precisely because the only evidence was LogInformation under a category the appsettings never surfaced. The state is now on an artefact.

    Both halves of the fix are in place: src/Memex.Portal.Distributed/appsettings.json:118 carries "Memex.Portal.Shared.SelfUpdate": "Information" (the missing entry beside the sibling ShippedReleaseSeedHostedService that WAS surfaced), and #2657 merged 2026-08-29T09:36Z.

    2. The reason nothing rolls is now named, and it is not a defect — policy: None, and the verdict says so in words. "Three builds behind" was the symptom of a deliberate operator setting, and the check is running on a BuildCompletion trigger and recording each pass.

    Closing. If memex should actually be following builds, that is a separate operator decision — flip Admin/UpdatePolicy — and the node will then say what it did instead of going quiet.

  6. added a commit that references this issue on Aug 30, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions