mirror of
https://gh-proxy.org/https://github.com/klinsmaya/multica.git
synced 2026-11-09 09:56:47 +08:00
a4d4444f80
* feat(wecom): add the MULTICA_WECOM_TRACE operator switch
The wecom adapter logs failures and nothing else. A bad envelope warns, a
non-zero server ack warns, an event and a non-text receipt log at Debug —
but an ordinary inbound message and every single outbound frame produce no
log line at all. So a run that goes wrong QUIETLY leaves nothing behind on
the server: the reply that went to the room instead of the person, the
command that was silently dropped, the receipt that went out twice.
What that costs in practice: verifying any of those needs a person to
describe what they saw on their phone. That is slow, it is lossy, and for
anything about ordering or timing it does not work at all — a user cannot
tell you which of two frames the server took first, or that the frame we
thought we sent was never written.
MULTICA_WECOM_TRACE=1 records every frame the adapter reads and writes:
direction, cmd, req_id, the chat it was addressed to, whether that chat is
a room or a person, the sender, and the server's errcode. Off by default,
and off is the right state outside a debugging session.
Why not slog.Debug, which is how slack and lark get their per-frame lines
(slack_channel.go:162, lark/ws_connector.go:339): logger.parseLevel
defaults LOG_LEVEL to *debug*, so a Debug call is on in every deployment
that has not set LOG_LEVEL. This records a bounded prefix of message text,
which must not be on by default, so the switch has to be its own.
Because it records message text, it must not record credentials:
- The aibot_subscribe body carries the installation's decrypted smart-bot
secret. traceOut walks named fields instead of dumping the frame, so
the secret is never read.
- A binding token is a bearer credential, and the binding prompt fits
inside the preview. sendBindingPrompt builds the prompt copy plus
appURL + "/wecom/bind?token=" + a 43-character token; with a normal
MULTICA_APP_URL the token's last character lands at rune 107-112,
inside the 120-rune cap. An unredacted preview therefore printed the
whole live token. RedeemAndBind only checks that the redeemer belongs
to the token's workspace and the bind page redeems on load as whoever
is signed in, so anyone who could read the log could bind that sender's
WeCom identity to their own Multica account — the same hijack
replier.go:150 already refuses to post the link into a room to prevent.
tracePreview now redacts token= / binding_token= / access_token= /
code= query parameters before the cut.
The preview cap counts runes rather than bytes: a byte cut on Chinese text
truncates at a third of the intended length and can split a character into
invalid UTF-8, in the deployments this switch exists for.
Co-authored-by: multica-agent <[email protected]>
* fix(wecom): record outbound frames under the writer mutex, with an outcome
The outbound trace was taken before the writer mutex, which broke it in the
two ways the switch exists to prevent.
Order. Heartbeats, agent replies and inbox pushes all reach wsSender.write
concurrently on one connection. A goroutine could emit its dir=out line, be
descheduled before taking the mutex, and let another trace-and-write ahead of
it — so the log named the wrong frame as first. The mutex is where those
senders become ordered, so a record taken inside it matches the wire by
construction; one taken outside is only correlated with it. The extraction
stays outside: redacting bearer tokens with a regexp and cutting the body to
120 runes is the expensive half and needs no such guarantee. What runs under
the mutex is a nil check when tracing is off, and two log lines when it is on,
against a socket write already in the same section.
Outcome. A frame rejected by SetWriteDeadline or WriteMessage left a dir=out
line identical to a delivered frame's, so "did this actually reach the wire?"
— the question an operator turns the switch on to ask — had no answer in the
log. Each outbound frame is now recorded twice: dir=out when it is about to be
written, dir=out.done with ok=true/false and, on failure, the stage that
failed and the socket's error. One line would not do either job: written
before the write it cannot report the outcome, and written after it, a write
that hangs or a process killed mid-write leaves nothing at all.
The pair shares a seq rather than a req_id. A pong echoes the server's req_id,
which may be empty or repeated, so req_id is not a key; seq is assigned under
the writer mutex, never goes on the wire, and doubles as the frame's position
in the write order, so a reader can recover the order from the field and can
spot an attempt with no outcome.
Tests: two writers where the first is held inside its own trace emission until
the second has run a whole write() — deterministic, because with the record
under the mutex the second blocks and with the record outside it does not; the
same property under 16 concurrent writers, which also pins seq and the
attempt/outcome pairing; and a socket stub failing WriteMessage and
SetWriteDeadline separately.
Docs: the operational half of the switch — restart to change it, who can read
the logs it writes, and whose retention policy governs them — in
SELF_HOSTING_ADVANCED.md.
Co-authored-by: multica-agent <[email protected]>
* docs(wecom): a written frame is not an accepted frame
The trace section said an out/out.done pair 'tells you what the server
saw'. It does not: ok=true means WriteMessage returned, which is the
local socket accepting the bytes. WeCom's verdict arrives later, on the
dir=in line carrying the same req_id, and a frame can be written
successfully and rejected there. An operator reading ok=true as
'delivered' would stop exactly one step short of the errcode that
explains the failure they are chasing.
Co-authored-by: multica-agent <[email protected]>
---------
Co-authored-by: multica-agent <[email protected]>
Co-authored-by: Bohan-J <[email protected]>