Skip to content

listeners: name the connection failure instead of logging an empty message - #526

Open
ifnesi wants to merge 3 commits into
mochi-mqtt:mainfrom
ifnesi:listeners-name-the-establish-failure
Open

ifnesi wants to merge 3 commits into
mochi-mqtt:mainfrom
ifnesi:listeners-name-the-establish-failure

Conversation

@ifnesi

@ifnesi ifnesi commented Aug 19, 2026 •

Copy link
Copy Markdown
Collaborator

listeners: name the connection failure instead of logging an empty message

What happens

Every failure to establish a connection is logged with an empty message:

l.log.Warn("", "error", err)

listeners/tcp.go:87, listeners/websocket.go:103, listeners/net.go:70,
listeners/unixsock.go:80 — all four identical.

The reason is complete in error=, so nothing is lost from the line itself.
What is lost is finding it: an operator grepping their log for words matches
nothing, and a log pipeline keyed on msg files every one of these under
the empty string, where they cannot be told apart from each other or from
anything else that forgot a message.

It matters more than a cosmetic usually would because of what arrives here.
With ClientAuth set to RequireAndVerifyClientCert or
VerifyClientCertIfGiven, a client certificate from an unknown authority
or an expired one is refused during the handshake — and this line is the
only record the server keeps of it. "Why can this device not connect" is
answered by a log line with no message.

The change

Four one-word messages, plus the listener id beside the reason so a server
with more than one listener says which one refused:

l.log.Warn("failed to establish connection", "error", err, "listener", l.id)

Tests

The existing suite passes unchanged (go test ./... -count=1); no test
asserts on the empty message.

Follow-up in this branch: the id was then said twice

The commit above passes "listener", l.id beside the reason, and the logger
it writes through already carries that key — AddListener builds it with
s.Log.With(slog.String("listener", l.ID())), and Init is the only place a
listener is given a logger. So every line read:

level=WARN msg="failed to establish connection" listener=t1 error=ending listener=t1

Nothing wrong or missing in it; said twice, which an operator reads past and
a pipeline keyed on the field records twice. Found on a terminal — the
With and the call sites are in different files and each is right on its
own, which is also how the same line came to be written six times.

Six sites, not the four this branch added: websocket.go:121 and
http_sysinfo.go:94 do the same in "failed to serve." and are on main
today. The listener id stays on every line — it belongs to the logger, and
the call sites stop repeating it.

Two tests, because the shape recurs rather than the instance:

  • TestListenerLogLineNamesTheListenerOnce serves through a logger built
    the way AddListener builds it and requires listener= exactly once.
    Against the previous commit it fails with that line quoted back. It waits
    for the line rather than for Serve to return, because the Warn is
    written from the per-connection goroutine nothing joins.
  • TestNoListenerLogCallPassesTheListenerKey walks the syntax tree of every
    non-test file in the package and fails on the literal key at any log call,
    so a seventh site cannot be added quietly. It counts what it read and
    fails on an implausible number, so a walk that finds nothing because it
    looked nowhere cannot pass as a clean one.

go test ./... -count=1, go vet ./... and gofmt -l . are clean, and the
log test passes 20 times under -race.

ifnesi added 3 commits August 19, 2026 16:27
…ssage

Every failure to establish a connection is logged as `msg=""` with the
reason in `error=`. The four listeners do it identically:

    l.log.Warn("", "error", err)

The reason is complete, but an operator grepping their log for words finds
nothing, and a pipeline keyed on `msg` files every one of these under the
empty string. It is the only record of a refused client certificate: with
ClientAuth set, a certificate from an unknown authority or an expired one is
refused during the handshake, and this line is where it lands.

Four one-word changes, and the listener id beside the reason so a server
with more than one listener says which.
The commit before this one names the connection failure and passes
`"listener", l.id` beside the reason. The logger it writes through already
carries that key — `AddListener` builds it with
`s.Log.With(slog.String("listener", l.ID()))` and `Init` is the only place a
listener is given one — so every line reads:

    level=WARN msg="failed to establish connection" listener=t1 error=ending listener=t1

Nothing is wrong or missing in it. It is said twice, which an operator reads
past as ordinary and a pipeline keyed on the field records twice.

Six sites, not the four this branch added: `websocket.go:121` and
`http_sysinfo.go:94` do the same in `"failed to serve."` and are on main
today. The id stays on every line — it is the logger's, and the call sites
stop repeating it.

Visible only on a terminal. The `With` and the call sites are in different
files and each is right on its own, which is how the same line came to be
written six times.

So a test that reads one, and a test that asks the question of the package.
TestListenerLogLineNamesTheListenerOnce serves through a logger built the
way AddListener builds it and requires `listener=` exactly once; against the
previous commit it fails with the line above quoted back. It waits for the
line rather than for Serve to return, because the Warn is written from the
per-connection goroutine that nothing joins — waiting on Serve reads an
empty buffer often enough to matter, and then the assertion turns on the
scheduler rather than on the code.

TestNoListenerLogCallPassesTheListenerKey walks the syntax tree of every
non-test file in the package and fails on the literal key at any log call,
so that a seventh site cannot be added quietly. The tree rather than the
text, so a call gofmt has wrapped is not invisible; and it counts the files
it read and fails on an implausible number, so a walk that finds nothing
because it looked nowhere cannot pass as a clean one.

Signed-off-by: Italo Nesi <inesi@confluent.io>
The message this branch chose is wrong for most of what reaches it.
`Serve` calls `establish(l.id, conn)` once per connection and that call runs
the *whole* session — it returns when the session ends, at any point. So a
publish refused an hour into a healthy connection is logged as:

    msg="failed to establish connection" error="packet too large"

which reads as a client that never got in. An operator chasing why a device
cannot connect finds these and is looking at the wrong thing entirely.

"connection ended with an error" is true wherever the error came from — a
handshake refused, a malformed packet, a keepalive expiry — and that is the
most the listener can honestly say, because the listener cannot see which
of them happened. Only the error beside it can, and it is already there.

Found by an oversized publish on an established connection, which is the
case that makes the difference visible: everything else this line reports
does happen at connect time, which is presumably how the wording was chosen.

Signed-off-by: Italo Nesi <inesi@confluent.io>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant