fix: make witness transmission teardown deterministic

[kentbull]

Summary

Treat inbound direct-mode TCP receive cutoff as the start of a bounded drain instead of immediate teardown.

• Keep Reactant alive until buffered CESR input is parsed or fails at EOF.
• Wait for response production to settle and HIO txbs to empty.
• End failed drains on HIO txCutoff or one absolute drain deadline.
• Cover EOF, incomplete and multiple messages, multi-response cues, idle boundaries, deadlines, and terminal transmit failure.

Scope

Limited to src/keri/app/directing.py and tests/app/test_directing.py. Sender-side delivery results and other transport follow-ups remain separate.

Validation

./venv/bin/python -m pytest -q tests/app/test_directing.py — 11 passed.

[dhh1128]

This is nice work, Kent. It's going to make things much more robust. The teardown accounting in here was genuinely broken and I'm glad someone took it on. Will we need to do something like it in main and/or 1.3.6, in addition to 1.2.14?

This is tricky stuff that I don't understand very well, but I thought my AI could help me check a few things. I ran an adversarial review with it, and it came up with some findings, but I didn't trust my own human judgment to filter it very well. Thinking about whether I had any value that I could realistically contribute, I decided to demand that my AI write tests that prove the failure modes it was claiming it had found. So, it did that, and I've raised a PR against your PR, with those failing tests. I'm not necessarily hoping that you merge my PR into yours, but that was the most efficient way I could demonstrate the findings, communicate something easy for you to reproduce, and be sure my AI wasn't hallucinating and I wouldn't waste your time. So, take the rest of this in the spirit of, "I'm pretty sure there's an issue here that's at least worth debating, and here is a concrete test that you can run that will let you explore the issue." Sorry for the hedging; I'm just not smart enough yet about the codebase to be more sure of my own judgment at this point...

Everything below was run against the PR head (2bd1cfd) and its merge base (1cd9833), on Python 3.12.13 with hio 0.6.19, which is what CI resolves for this branch, IIRC.

A couple general notes:

First, I think the messageInProgress rework is fixing something real, and that it's worse than it looks. On the merge base, TCPMessenger.idle is len(self.sent) == self.posted, which evaluates 0 == 0 before the messenger has dequeued anything. So Poster's while not witer.idle falls straight through on its first evaluation and the delivery is cued as sent with no TCP connection ever opened. I like making that wait honest.

Second, the local inactivity timeout that Directant.serviceDo keys off is unreachable in production today, on both trees. This isn't something tied to your PR. hio's Server.serviceAxes constructs each accepted Remoter with timeout=self.tymeout (hio 0.6.19, core/tcp/serving.py:284), but Remoter.__init__ names that parameter tymeout (line 621). It's swallowed by **kwa, and tymeout falls back to Remoter.Tymeout = 0.0. So I'm pretty sure every accepted connection gets ix.tymeout == 0.0, the ix.tymeout > 0.0 guard never passes, and keripy's intended one-second timeout (Server.Tymeout = 1.0) never happens. That bounds the first finding below — it's a real regression on a path only tests can reach right now, which goes live the moment hio fixes that kwarg.

---

Here are the specific findings from my adversarial review that I thought were worth sharing.

1. cutoff as the local close marker makes the connection permanently unwritable

This is probably the one worth the most attention. I originally thought it was two separate problems and I think that was wrong — it's one defect with two symptoms.

serviceDo sets ix.cutoff = True by hand to mark a local close request (directing.py:387). But hio's Remoter.serviceSends is:

while self.txbs and not self.cutoff:

so once cutoff is set, nothing can write to that connection again — not closeConnection, not ServerDoer.serviceSendsAllIx. Separately, closeConnection no longer calls serviceSends() before removeIx the way the base did, and removeIx closes the socket and discards remoter.txbs.

The two interact, which is why I think restoring the flush alone wouldn't fix it: by the time closeConnection runs, cutoff is already set, so a restored serviceSends() would be a no-op on that path.

On the timeout path (regression, base green / head red). With a receipt already queued and the inactivity timer expiring, the base delivers 744 bytes to the peer and the head delivers none:

AssertionError: peer received no bytes; 744 bytes were discarded with the
connection, remoter.cutoff=True

The base wins here because base constructs the Reactant before checking the timeout, and Reactant.__init__ calls remoter.wind(...), which restarts the inactivity tymer. That grants a second timeout period in which the Reactant parses the buffered event and cues the receipt, which base's flush then delivers. Moving the timeout check ahead of Reactant construction could make sense in isolation, but it removes that reprieve, and the lost flush means nothing catches the receipt afterwards.

On the peer half-close path (reachable today; fails on both trees, differently). This is the one I think matters most, because it's what production actually hits. With a real ServerDoer servicing sends on every recurrence — the wiring from indirecting.py:111-117 — a peer sends an inception, half-closes, and waits for its receipt:

head:  cutoff True  rxbs 0    txbs 744  peer 0   accepted into bob's KEL: True
base:  cutoff True  rxbs 391  txbs 0    peer 0   accepted into bob's KEL: False

The head does exactly what the PR intends — keeps the Reactant alive, parses the buffered inception after cutoff, accepts it, cues the 744-byte receipt — and then discards those bytes with the connection while serviceSendsAllIx runs on every intervening recurrence. The base never parses the event at all.

So neither tree answers the peer, but the head reaches a state the base doesn't: it has accepted an event into the local KEL and given the sender no evidence it did. I don't think the PR introduced that asymmetry deliberately, and I don't think it's catastrophic — the sender retries — but doing the parsing work and then throwing away its product seems like the opposite of the PR's stated aim, and I couldn't find anything that notices.

Maybe a separate flag for the locally-requested close, leaving cutoff as a peer-observed fact, so serviceSends keeps working until the Reactant reports drained or failed? But you know this code far better than I do and there may be a reason that's wrong.

2. raise witer.error inside a long-lived doer stops the scheduler

forwarding.py:174, :212, :248 and agenting.py:490, :608, :705.

I checked hio 0.6.19 before believing this. It seems to me that the only exception caught around a doer generator's send is StopIteration (base/doing.py:299 in Doist.recur, :1082 in DoDoer.recur); Doist.do has except Exception: raise (:196). And ClosedError and ConfigurationError are siblings under KeriError (kering.py:374-391), so Poster.deliverDo's except kering.ConfigurationError (forwarding.py:94) can't catch it.

With a real Poster, a real Doist and a witness socket that accepts and then resets, the error escapes all the way out:

hio/base/doing.py:175: in do      self.recur()
hio/base/doing.py:299: in recur   tock = dog.send(self.tyme)
hio/base/doing.py:1082: in recur  tock = dog.send(tyme)
src/keri/app/forwarding.py:83:  in deliverDo  yield from self.sendDirect(...)
src/keri/app/forwarding.py:174: ClosedError

keri.kering.ClosedError: TCP connection to ELSJY0Z2AVS32... closed with
7865201 unsent bytes

An unrelated doer sharing that Doist got 4 heartbeats out of ~64 before the scheduler stopped. kli.py:23-32 catches it at top level, prints ERR: <message> and returns -1, so it's a quiet exit rather than a traceback.

To be careful in my description, it appears that the base "survives" the same reset, but only degenerately — per the note above, it never waits on the transport at all, so there's nothing for the failure to interrupt. Your fix is what first makes the delivery loop honest enough to observe a transport failure. I don't think that argues against the fix; it argues that the failure now needs somewhere to go other than out through the Doist. A catch at the delivery boundary that logs, drops the messenger, and re-queues or abandons that one event would keep the process up.

One thing I checked by reading only, and couldn't build a deterministic test for, so this is intended as a question rather than a claim: at WitnessInquisitor.msgDo the loop is while not witer.sent:, which is a genuine wait on both trees. After a cutoff, while client.txbs: yield tock looks like it can never exit, because hio's serviceSends is while self.txbs and self.connected and not self.cutoff (tcp/clienting.py:478) and nothing drains or clears txbs. Does that stall, and is that the case the raise was added for?

3. HTTP cutoff observed before a response is finalized — minor

I'm not sure this matters very much, because it's not that likely to occur. But FWIW...

When a peer terminates the response body by closing the connection (Connection: close, no Content-Length), connector.cutoff becomes visible one service pass before Patron.service calls respondent.close() and finalizes the response. On that pass HTTPMessenger.responseDo sees no responses and waited still True, so it latches self.error — and because the guard is if self.error is None, the error survives the response's arrival:

AssertionError: status 200 reached sent, yet
error=ClosedError('HTTP connection to EIbpFnFyfA1U5... closed before all
responses arrived') and idle=False

HTTPStreamMessenger.recur does worse with the same race — it return Trues on that pass, so the finalizing pass never happens and rep stays None for a response that arrived. The base handles both correctly.

The caveat, which I think is the important half: this only bites close-framed responses. With Content-Length both messengers are clean on both trees, and that's structural rather than lucky — TCP ordering means recv returns b'' only after every byte is already in rxbs, and Patron.serviceResponse parses in the same pass that sets cutoff, so with length framing there's nothing left for the guard to trip on. keripy has no chunked or streamed responses anywhere and hio's own responder sets content-length (core/http/serving.py:486), so a keripy witness never emits the close-framed shape. It'd take a non-keripy proxy or an HTTP/1.0 intermediary in front of a witness. That may be worth nothing to you, in which case please ignore it.

One detail that widens the window rather than causing it: in HTTPMessenger.__init__ the doer order is [msgDo, responseDo, clientDoer], so responseDo reads client state left over from the previous pass every time.

4. Two other bugs that are pre-existing but slightly related

I chased both of these thinking they were regressions and they aren't, so recording them here just so nobody re-treads the ground.

WitnessPublisher.sendDo calls self.remove(witers) after while witers: witer = witers.pop() has emptied the list, so the messengers are never removed from the DoDoer — this creates one leaked messenger and TCP client per publish per witness. git log -S puts it in f141f0492 from 2021, and the base is identical apart from your two new lines. It might be worth a separate fix for this sometime. I'm only noting it here because you removed the comparable leak in HTTPStreamMessenger.recur in this PR, so it seemed like something you'd want to know about.

And if an HTTP peer reaps an idle keep-alive connection, neither tree ever recovers: reconnectable is False by default and keripy never sets it, cutoff never clears connected, so Patron.service can reach neither reopen() nor serviceConnect() and the queued request strands in txbs permanently. Behavior is identical on both trees (accepted=1, served=1, txbs=601, cutoff=True, connected=True) — a hio limitation, not something this PR touches. The only difference is that on your branch it at least records a ClosedError saying so, where the base hangs silently. That's an improvement.

---

The tests are in my PR against your PR and should drop in as-is. To run them:

pytest tests/app/test_pr1614_directing.py tests/app/test_pr1614_error_escape.py tests/app/test_pr1614_http.py -q

They're red on your branch by design — I wrote them to state the behavior I'd expect rather than to lock in current behavior, so they should go green as the underlying issues are addressed. Two of them fail on the merge base too, and I've marked those clearly. They're there to show a failure mode rather than to allege a regression. I'm happy to rework any of them, mark them xfail so your CI stays green, or drop the ones you don't find useful. And if I've misread the scheduling anywhere, I'd genuinely like to know — I found this code subtle and I won't be surprised if I got something wrong.

[kentbull]

This PR uses Directant._serviceSends to set the ix.cutoff var as a workaround to the Hio 0.6.19 Remoter limitation where remoter.cutoff represents only server side cutoff, ignoring client side cutoff, which prevents KERIpy from processing outbound witness receipt responses to the client controller.

This workaround will not be necessary once ioflo/hio#163 is merged and a new version of HIO released.

[kentbull]

@dhh1128 your items #1 through #3 are fully addressed in the updated PR code. I will likely be cutting down this PR to the base fix and choreographing the rest of the changes as follow on PRs. I'll tag you in them accordingly with the fixes that correspond to your comments. I appreciate your review.

At +1461 and -295 this PR is pretty big. I am going to cut that down into smaller, cohesive PRs.

[kentbull]

Reverting so we can get a maintainer review before we merge. @dhh1128 and @daidoji I will mention you on the new PR that is opened after upstream HIO changes land or a workaround is written.