Repository navigation
Conversation
…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>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
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:
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
msgfiles every one of these underthe 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
ClientAuthset toRequireAndVerifyClientCertorVerifyClientCertIfGiven, a client certificate from an unknown authorityor 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:
Tests
The existing suite passes unchanged (
go test ./... -count=1); no testasserts on the empty message.
Follow-up in this branch: the id was then said twice
The commit above passes
"listener", l.idbeside the reason, and the loggerit writes through already carries that key —
AddListenerbuilds it withs.Log.With(slog.String("listener", l.ID())), andInitis the only place alistener is given a logger. So every line read:
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
Withand the call sites are in different files and each is right on itsown, which is also how the same line came to be written six times.
Six sites, not the four this branch added:
websocket.go:121andhttp_sysinfo.go:94do the same in"failed to serve."and are onmaintoday. 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:
TestListenerLogLineNamesTheListenerOnceserves through a logger builtthe way
AddListenerbuilds it and requireslistener=exactly once.Against the previous commit it fails with that line quoted back. It waits
for the line rather than for
Serveto return, because theWarniswritten from the per-connection goroutine nothing joins.
TestNoListenerLogCallPassesTheListenerKeywalks the syntax tree of everynon-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 ./...andgofmt -l .are clean, and thelog test passes 20 times under
-race.