feat(gateway): trace every inbound message end-to-end in gateway.log

[nikitaBarkov]

What does this PR do?

Makes an inbound message traceable end-to-end in gateway.log, keyed by the platform message_id, so that "the bot answered the same message twice" (and its mirror image, "the bot never answered a message that clearly arrived") can be diagnosed from a normal INFO-level log instead of a guess.

Background: in a production Slack session we found user turns duplicated — one message from the user, two identical role=user rows in state.db, two answers from the agent (~10% of user turns in the 20260811 dump; reproduced again on 12.08 and 13.08). The mechanism of the second copy was reconstructible from the code: the redelivered copy arrives while the agent is busy, takes a pending slot (or is accepted by steer()), and the post-turn drain replays it as a brand-new user turn. But the question that actually decides the fix — did the platform deliver the message twice, or did Hermes turn one delivery into two turns? — could not be answered from the logs at all:

• inbound message: (gateway/run.py) is logged only for the message that starts a turn. A copy that arrives while the agent is busy produces no INFO line whatsoever: the busy branches are logger.debug, and busy_ack_enabled: false suppresses even the user-visible Slack bubble.
• run_agent.steer() logs nothing when it accepts text — so "spliced into the live turn" and "accepted microseconds after the turn ended, never injected, and not queued either (the gateway reads the returned True as delivered)" look identical. The second case silently loses the message; we hit it twice.
• The Slack adapter's dedup (team_id:event_ts, TTL 3600s) and its message_changed guard both return silently, so a suppressed redelivery is invisible — "Slack sent it twice and we caught one" cannot be told apart from "Slack sent it once".
• [Slack] event received … exists but sits behind logger.isEnabledFor(DEBUG), and turning DEBUG on for a live gateway is not an option (volume + payload contents).
• The relay ingress (gateway/relay/adapter.py) had no logging at all.
• Post-factum reconstruction from state.db does not work either: messages.platform_message_id is empty on every row (the gateway-side write is skipped because the agent already flushed the rows), so a stored user turn cannot be attributed to a platform message.

This PR is logging only — no behavior change. The duplicate-turn guard itself is deliberately not included: the primary cause of the double ingress is still unknown, and a guard keyed on message_id drops inbound messages, which is a worse failure than a duplicate if the key turns out to be wrong (Slack reuses ts for edits). It is parked on nikita.barkov/gateway-duplicate-turn-guard and will be proposed separately once these logs name the cause. What these lines already produced on a live run: a first delivery with age=8.7s (ingress stall vs ±0.5s on the other 22 messages that day) followed by two Socket Mode redeliveries of the same ts — i.e. the ack-timeout mechanism caught in the act, which is exactly what was missing before.

Related Issue

None in this fork. Upstream tracks the same class as type/bug: NousResearch#84417 (P1, "post-compression session replays an earlier user prompt as a fresh turn") with the open PR NousResearch#84589, which covers the desktop/TUI queue only — the messaging gateway path (gateway/run.py + gateway/platforms/base.py._pending_messages) is not covered there.

Type of Change

• 🐛 Bug fix (non-breaking change that fixes an issue)
• ✨ New feature (non-breaking change that adds functionality)
• 🔒 Security fix
• 📝 Documentation update
• ✅ Tests (adding or improving test coverage)
• ♻️ Refactor (no behavior change) — observability only
• 🎯 New skill (bundled or hub)

Changes Made

• plugins/platforms/slack/adapter.py: new _slack_event_age() helper (Slack ts → seconds since the user pressed Enter) and one INFO line per event that actually reaches the gateway — [Slack] delivering event to gateway: ts=… type=… subtype=… channel=… thread_ts=… user=… age=… ingress=…. ingress is a stopwatch over the adapter leg (thread-parent fetch, users.info, thread-context hydration, attachment downloads): Socket Mode acks an envelope only after that coroutine returns, so ingress above the ack window is the direct cause of a platform redelivery. The two previously silent drops are INFO now: dropped duplicate event (TTL cache) and dropped message_changed for already-delivered ts (edit/unfurl guard).
• gateway/relay/adapter.py: [relay] delivering event to gateway: message_id=… — the same anchor for relay-fronted platforms, wrapped in a try/except so logging can never break ingress. There was no logging on this path at all.
• gateway/run.py: inbound message: now carries message_id; new starting turn: session=… message_id=… right after the session is resolved (the inbound message line is emitted before session resolution, so without this line the id and the session-keyed busy/queue/drain lines cannot be joined); new busy follow-up: session=… message_id=… mode=… steered=… redirected=… text_len=…; queued follow-up on both queue funnels (FIFO and merge-into-slot) and on the queue-cap drop; Draining queued follow-up … as a new turn: message_id=…; the leftover-steer delivery raised from DEBUG to INFO with the session key and length.
• gateway/platforms/base.py: the three pending-slot parking sites (photo burst, text debounce, generic queue) raised to INFO with message_id.
• run_agent.py (AIAgent.steer()): steer received: turn_active=… turn_age=… merging=… len=…. This is the line that separates a real injection from a steer accepted after the turn already ended — the case where the message is lost, because the gateway skips queueing when steer() returns True.
• agent/turn_finalizer.py: Turn ended with an undelivered /steer … — marks the exact moment a user turn is about to be manufactured from steer text (or, when the caller cannot deliver it, where that text is dropped).
• agent/conversation_loop.py + agent/turn_finalizer.py: agent._active_turn_started_at — a wall-clock marker set at turn start and cleared at turn end, read only by the log line above. Nothing branches on it.
• website/docs/user-guide/messaging/index.md: new "Tracing an Inbound Message" section — a table of the lines and how to read them (same message_id in a starting turn line and in a busy follow-up / Draining queued follow-up line = one message answered twice; one delivering event to gateway line + two turns = the duplicate was created inside Hermes; two delivering lines = the platform sent it twice, and type/subtype/age show why the dedup key did not match).

Not included on purpose: persisting messages.platform_message_id (a schema/write-path change, not observability), and any dedup/guard logic.

How to Test

1. scripts/run_tests.sh tests/run_agent tests/agent — 5121 passed. scripts/run_tests.sh tests/plugins — 1306 passed. scripts/run_tests.sh tests/run_agent/test_steer.py tests/agent/test_turn_finalizer_cleanup_guard.py — 31 passed (the steer and finalizer paths that gained the new lines).
2. scripts/run_tests.sh tests/gateway — 6 pre-existing failures on macOS (wecom, readiness, api_server, systemd_notify, shutdown_forensics). Verified as baseline: git stash && scripts/run_tests.sh tests/gateway/test_wecom_callback.py tests/gateway/test_readiness.py fails identically on a clean tree.
3. Live run against a real Slack workspace (macOS 15.6.1, gateway launched from this branch), then:

   RUN=$(ls -1td ~/.junie-live/runs/* | head -1)
   grep -E "delivering event to gateway|dropped duplicate event|inbound message:|starting turn:|busy follow-up:|queued follow-up|Draining queued follow-up|steer received:" \
     "$RUN/.hermes/logs/gateway.log"

   Observed, previously invisible:
   • [Slack] dropped duplicate event ts=1786605877.882029 type=app_mention immediately before [Slack] delivering event to gateway: ts=1786605877.882029 type=message — the message + app_mention pair Slack emits for one mention, with the adapter dedup doing its job;
   • age=8.7s on a first delivery (vs ±0.5s on every other message that day) followed by dropped duplicate event for the same ts at +9s and +67s — a Socket Mode ack timeout and the two redeliveries it caused;
   • busy follow-up: … mode=steer steered=True on a message that never produced a user turn, together with steer received: turn_active=False — the message-loss case, now visible instead of silent.
4. Sanity check that nothing branches on the new marker: grep -n "_active_turn_started_at" -r . --include=*.py shows exactly three sites — set, clear, and the log line.

Checklist

Code

• I've read the Contributing Guide
• My commit message follows Conventional Commits
• I searched for existing PRs to make sure this isn't a duplicate
• This PR contains only the observability change, in one commit — the guard is parked on nikita.barkov/gateway-duplicate-turn-guard
• I've run the affected suites and they pass (see "How to Test"); the tests/gateway failures are a pre-existing macOS baseline, reproduced on a clean tree
• Tests — N/A: no behavior change; the touched behavior paths (steer(), finalize_turn) keep their existing coverage green, and asserting on log strings would be a change-detector test
• I've tested on my platform: macOS 15.6.1

Documentation & Housekeeping

• Documentation updated — website/docs/user-guide/messaging/index.md, new "Tracing an Inbound Message" section
• cli-config.yaml.example — N/A, no config keys added or changed
• CONTRIBUTING.md / AGENTS.md — N/A, no architecture or workflow change
• Cross-platform impact considered — pure Python logging, time.time()/time.monotonic() only
• Tool descriptions/schemas — N/A, no tool changes

Notes

Log volume: these are per-inbound-message lines (one to three per message), not per-token or per-iteration, so the added volume is bounded by chat traffic. No message text is logged beyond what inbound message: already truncates; the steer/leftover lines cap at 40–60 characters.

Next step once the cause is named: either fix the ingress stall so Slack stops redelivering at all (ack the envelope before the network calls in _handle_slack_message), or land the parked idempotency guard — and make steer() return False when no turn is live, which is the message-loss bug these logs surfaced.