Repository navigation
Conversation
A reason code is a decision, not a fault. By the time receivePacket sees one the client has already been told precisely what was wrong with its packet, and the server has done what the specification asks of it. Reporting that at Warn tells an operator watching for problems that the server failed when it worked -- and formatting the whole packet to say so writes the client's own payload into the log, at a level that is on by default, at whatever rate a client can reconnect and repeat itself. Measured: one 100KiB publish whose topic name contained a wildcard produced a single log line of over 300KB, the payload expanded into a decimal byte list. Nothing about that publish is exceptional and nothing rate-limits it. This is the same distinction mochi-mqtt#516 drew for a hook returning a reason code, in the same function's caller, and it takes the same treatment: debug, and the fields that identify the case -- code, reason, client, listener, packet type -- rather than the packet that carries it. An error that is not a packets.Code is a genuine fault and keeps both its level and the packet, which is what makes it worth reading. The disconnect is unchanged: same type assertion, same condition, same call. Only the reporting moves. TestReceivePacketLogsARefusalAtDebugWithoutThePacket publishes to a topic name containing a wildcard, with a sentinel payload, and requires the refusal to be logged at debug, no WARN line to be produced, and neither the payload nor the formatted packet to appear. It fails against main, where the sentinel is in the log. The test waits for the goroutine before reading the log buffer. DisconnectClient stops the client, so ReadAll can return while receivePacket has yet to write its line -- and a buffer read at that moment reports an empty log about a server that logged, which is how the first version of this test passed once and then did not.
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.
server: log a packet refused by a reason code at debug, without the packet
What happens
receivePacketreports every error fromprocessPacketat Warn, withthe entire decoded packet formatted into the line:
Most of what reaches it is a
packets.Code— a reason code the server hasjust answered the client with. A wildcard in a topic name, a zero length
topic with no alias, a packet identifier violation: the client is
disconnected with the code, correctly, and then the refusal is written to
the log as though the server had failed.
Measured on
main. One QoS 0 publish of 100KiB toevents/a/+:The payload is in it, expanded to a decimal byte list — 100KiB of message
becomes ~300KB of log, an amplification of about 3x at whatever rate a
client chooses. Nothing rate-limits it and nothing about that publish is
exceptional.
Three separate problems, in increasing order of seriousness:
watching Warn is told the server failed at the moment it did exactly
what the specification asks.
publish — credentials, personal data — lands in a file with different
retention and access rules than the broker's own storage.
one that is not a matter of taste.
The change
receivePacketsplits the two cases, exactly ashooks.godoes since#516:
packets.Codeis a decision. The client has been told preciselywhat was wrong. Logged at debug, with the fields that identify the case —
code, reason, client, listener, packet type — and not the packet.
which is what makes it worth reading.
The disconnect is untouched — same type assertion, same condition, same
call. Only the reporting moves.
One judgement call, and I am happy to take direction
#516 keeps
"packet", pkxon its debug line. This drops the packetentirely, on the reasoning that an operator who turns debug on to diagnose
a misbehaving client should not get 300KB lines and payloads either — the
code, reason, client and packet type identify the case, and the client was
disconnected with that same code. If you would rather it matched #516
exactly and kept the packet at debug, that is a one-line change.
Tests
TestReceivePacketLogsARefusalAtDebugWithoutThePacketpublishes to a topicname containing a wildcard with a sentinel payload, and requires the
refusal to be logged at debug, no Warn line to be produced, and neither the
sentinel nor a formatted packet to appear anywhere in the output. It fails
against
main, where the sentinel is in the log line.It asserts the debug line is present before asserting what is absent, so
that a test logging nothing at all cannot pass for the wrong reason.
go test ./...,go vet ./...andgo test ./... -raceall pass.One note in case it is useful elsewhere: the test waits on the goroutine
before reading the log buffer.
DisconnectClientstops the client, so theio.ReadAllcan return whilereceivePackethas yet to write its line —the first version of this test read an empty buffer from a server that had
logged, and passed or failed depending on scheduling.
How it was found
An MQTT broker built on this server. A client reconnecting and reusing a
topic alias is refused — correctly, and that refusal is #521 — and the
refusal then wrote the client's whole publish into the operator's log. But
the defect is older than that patch and independent of it:
receivePacketis unchanged in the fork carrying #521 and the ten before it, and the
reproduction above uses no topic alias at all.