Skip to content

server: log a packet refused by a reason code at debug, without the packet - #522

Open
ifnesi wants to merge 1 commit into
mochi-mqtt:mainfrom
ifnesi:log-packet-refusals-at-debug
Open

ifnesi wants to merge 1 commit into
mochi-mqtt:mainfrom
ifnesi:log-packet-refusals-at-debug

Conversation

@ifnesi

@ifnesi ifnesi commented Aug 16, 2026

Copy link
Copy Markdown
Collaborator

server: log a packet refused by a reason code at debug, without the packet

A client can write 300KB into the server's log with one publish, and
repeat it as fast as it can send. The same distinction #516 drew for a
hook's reason code, one function further out.

What happens

receivePacket reports every error from processPacket at Warn, with
the entire decoded packet formatted into the line:

s.Log.Warn("error processing packet", "error", err, "client", cl.ID, "listener", cl.Net.Listener, "pk", pk)

Most of what reaches it is a packets.Code — a reason code the server has
just 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 to events/a/+:

log total:    311,292 bytes
longest line: 309,419 bytes

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:

  1. An ordinary refusal is reported as a server error. An operator
    watching Warn is told the server failed at the moment it did exactly
    what the specification asks.
  2. The client's payload is written to the log. Whatever devices
    publish — credentials, personal data — lands in a file with different
    retention and access rules than the broker's own storage.
  3. A client controls how much the server writes to disk. That is the
    one that is not a matter of taste.

The change

receivePacket splits the two cases, exactly as hooks.go does since
#516:

  • A packets.Code is a decision. The client has been told precisely
    what was wrong. Logged at debug, with the fields that identify the case —
    code, reason, client, listener, packet type — and not the packet.
  • Anything else is a genuine fault. Unchanged: Warn, with 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", pkx on its debug line. This drops the packet
entirely, 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

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
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 ./... and go test ./... -race all pass.

One note in case it is useful elsewhere: the test waits on the goroutine
before reading the log buffer. DisconnectClient stops the client, so the
io.ReadAll can return while receivePacket has 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: receivePacket
is unchanged in the fork carrying #521 and the ten before it, and the
reproduction above uses no topic alias at all.

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.
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