A server-initiated channel.close frame can be sent together with other operations in a single TCP segment

[anton-ryzhov]

Describe the bug

Hello folks,

I've encountered a strange behavior of the server that causes aio_pika to misbehave as well. Is the way it currently works intended and the bug is caused only by the library? Or both sides have issues here?

Reproduction steps

1. Consume from a non-empty queue to generate server→client traffic
2. Trigger server-side channel close (e.g. by publishing an incorrect message)
3. Server sends Channel.Close frame but then continues sending other frames over this channel.
4. Client library is confused by unexpected frames from a closed channel. It also can't reopen new channel because it expects Channel.Open-Ok but receives Basic.Publish or so instead.

Here is a script that reproduces the issue (python, aio_pika, docker):
write-to-closed-channel.zip

Expected behavior

The server should stop writing any frames after it has closed the channel

Additional context

I've tested that on 4.0.6 and 4.1.0-beta.4 using the script from above.

Traffic dump from my test (see frame # 47)
close+delivery.zip

[michaelklishin]

@anton-ryzhov you have multiple AMQP 0-9-1 frames in frame 47, starting with a basic.deliver followed by content frames and a content body. This can happen when multiple events are "dispatched" at the same time, including a server-initiated channel.close.

Queues and streams do not verify if a channel is closed in order to avoid overhead that won't detect any issues an absolute majority of the time. They expect the channel process to shut down, which takes a moment, even if that means a few milliseconds.

rabbit_writer, the process that serializes all outgoing frames and writes them to the socket (for a specific connection), is not concurrent but won't verify whether all the frames are on the same channel or not, whether one of the frames is a channel.close, and so on, again, to not introduce any overhead that won't have any effect an absolute majority of the time.

Simply ignore those frames in aio-pika when the channel is not open according to the library's connection state.

[lukebakken]

For what it's worth, I do not see Basic.Deliver after Channel.Close in my environment. This is an interesting case I'll check with other AMQP 0.9.1 libraries.

[anton-ryzhov]

Not even in the same TCP packet? I also do not have any following TCP packets in the dump above, but the problem is already caused by next AMQP frames within the same TCP packet.

That's strange, it was happening every single time with my test script. Is it's a race condition issue, so it could depend on machines performance and/or network latency.

[anton-ryzhov]

@michaelklishin yeah, I see, that explains. Then I'll report the bug to aio_pika/aiormq and refer your comment 👍

[anton-ryzhov]

Related question. If it is expected to have frames sent to a closed channel — then the server doesn't follow this rule.
I'm querying that in my dump:

(frame.number >= 47)  && (frame.number <= 64) && !(tcp.len == 0)

The server receives such frames and then terminates the whole connection (which also affects other channels).
I don't know if that was already caused by frames 48-58 or only by 61-63.

Shouldn't the server also ignore such frames or reply with Channel.Close (as TCP does with RST flag) instead of Connection.Close?

[michaelklishin]

@anton-ryzhov my point was that it likely can happen, and I tried to explain why.

Not everything checks if the channel is closed at the last moment before writing the socket. But since the channel process will stop fractions of a second later, the rest of the system will notice and the delivery will stop.

I have also explained what several other clients do with such frames (for the closed/unknown channels): ignore them, optionally with a warning.

[anton-ryzhov]

@lukebakken , yeah, I understand what do you mean here. Important question if the connection was closed because of frames 61 and 63? These really look like a library's issue as they come after Channel.Close-Ok.
But if the disconnect was already caused by frame 48 — it's clearly to me that it's a server bug. The server requested Channel.Close but the client doesn't yet know that (until Close-ok confirmation was sent). The server must not drop the connection because of that

[lukebakken]

@anton-ryzhov you can review RabbitMQ's code if you like. I'm pretty sure that if the server dropped connections prior to receiving Close-Ok (or after some sort of timeout), we'd have heard about it by now. It's almost certainly due to the Basic.Publish. I could expand the log message to say expected 'X', got 'Y'

[anton-ryzhov]

@michaelklishin ,

I have also explained what several other clients do with such frames (for the closed/unknown channels): ignore them, optionally with a warning

That's exactly what aiormq does by design — ignores and logs. There is just an issue with channel reopening that needs a fix.

But still — is it fine to have writers a bit unsynchronized? Then the other party should handle frames sent right after Close less aggressive. It seems that is not the case for the server right now.

[michaelklishin]

Synchronizing rabbit_writer with every channel would carry significant overhead and clients can handle it perfectly fine. The condition lasts for fractions of a second while the channel process stops.

This issue comes up once a year or so.

[lukebakken]

@anton-ryzhov yep, it's the basic.publish that causes the connection to be closed. I hacked in the info in my local dev setup:

2025-02-21 12:32:27.151750-08:00 [error] <0.667.0> Channel error on connection <0.657.0> ([::1]:58172 -> [::1]:5672, vhost: '/', user: 'guest'), channel 1:
2025-02-21 12:32:27.151750-08:00 [error] <0.667.0> operation basic.publish caused a channel exception precondition_failed: invalid expiration '-1000': {value_negative,-1000}
2025-02-21 12:32:27.197039-08:00 [error] <0.657.0> Error on AMQP connection <0.657.0> ([::1]:58172 -> [::1]:5672, vhost: '/', user: 'guest', state: running), channel 1:
2025-02-21 12:32:27.197039-08:00 [error] <0.657.0>  operation basic.publish caused a connection exception channel_error: "expected 'channel.open', got '{'basic.publish',0,<<>>,<<>>,true,false}'"
2025-02-21 12:32:27.199158-08:00 [info] <0.657.0> closing AMQP connection ([::1]:58172 -> [::1]:5672, vhost: '/', user: 'guest', duration: '150ms')

I reviewed the interaction between rabbit_reader / rabbit_writer and channels, and @michaelklishin's explanation here is a good one.

Client libraries must stop sending frames as soon as possible after receiving Channel.Close, other than sending Channel.Close-Ok, of course.

[anton-ryzhov]

Thanks for double-checking that

[lukebakken]

You'll find this interesting: rabbitmq/rabbitmq-dotnet-client#1791

Here's a packet capture while running that integration test:
dotnet-client-packet-trace.zip

You can see that the client does not send any frames after the channel is closed. What's interesting is that deliveries do continue to happen (due to the prefech), it's just that when the code tries to BasicAckAsync them in the delivery callback method, the library knows the channel is already closed, and raises an exception. Verbose logging shows 10 exceptions raised, one for each message to be handled by the application. Applications could then handle that exception to realize that they could not possibly ack those messages.

[michaelklishin]

I guess one thing channels could do is attach their state to the frame they want serialized and delivered. But that would entail extra GC pressure and memory copying for no benefit an overwhelming majority of the time.