Timeout when opening a new channel after channel exception

[lukebakken]

Code to reproduce issue - https://github.com/lukebakken/rabbitmq-dotnet-client-1245

Discussed in #1245

^{Originally posted by pabermod September 1, 2022}
Hi, I have the following scenario:

• Connection configured with publisher acks.
• Auto recover connection is enabled
• With an open connection and IModel I try to send a message bigger than the default message max size with the method BasicPublish
• This method does not fail. Instead the event ModelShutdown of the IModel is fired.

I have a handler for that event that opens a new channel for the same connection. When openning the new channel I get the following error:

System.TimeoutException: Se excedió el tiempo de espera de la operación.
en RabbitMQ.Util.BlockingCell`1.WaitForValue(TimeSpan timeout)
en RabbitMQ.Client.Impl.SimpleBlockingRpcContinuation.GetReply(TimeSpan timeout)
en RabbitMQ.Client.Impl.ModelBase.ModelRpc(MethodBase method, ContentHeaderBase header, Byte[] body)
en RabbitMQ.Client.Framing.Impl.Model._Private_ChannelOpen(String outOfBand)
en RabbitMQ.Client.Framing.Impl.AutorecoveringConnection.CreateNonRecoveringModel()
en RabbitMQ.Client.Framing.Impl.AutorecoveringConnection.CreateModel()`

I attach .Net project example for the problem that uses:

• Net461 (but also happens in Net6)
• Latest RabbitMQ.Client package
• Latest rabbitmq docker image: docker run --hostname my-rabbit --name some-rabbit -p 5672:5672 -p 15672:15672 rabbitmq:3-management

The example sends the content of the given file. Will close the channel is size is bigger than 134217728 bytes:

RabbitMQError.zip

[lukebakken]

cc @pabermod I think what you're doing in your code is not allowed.

First of all, in #1245, you state this -

Auto recover connection is enabled

...but your code has these lines which disable connection recovery and topology recovery:

AutomaticRecoveryEnabled = false,
TopologyRecoveryEnabled = false,

At any rate, my guess is that creating a new IModel from within a callback is A Bad Thing To Be Avoided (@bording, @danielmarbach, @stebet could comment on that I'm sure).

I'm updating my code with a better method.

[michaelklishin]

Creating a model from within a callback is highly unusual. Usually consumer operation dispatch implementations do not expect that. Java client, for example, had to be changed so that such synchronous methods (in protocol terms, that is, a method requiring a response) can be used from consumer callbacks without blocking the I/O loop.

[lukebakken]

@pabermod please see my commit which shows one way to respond to ModelShutdown:

lukebakken/rabbitmq-dotnet-client-1245@db4bc2a

[pabermod]

Hi, i think i disabled autorecovery for testing. The timeout is thrown both when disabled and enabled. I will take a look at your code

[pabermod]

Hi, Your test projects is throwing an exception in a loop when trying to declare the exchange after the channel is shutdown. I have moved the creation of the channel to the beginning of the loop (if channel shutdown). It is still throwing an exception when it tries to create the channel after the channel is shutdown (Both autorecover enabled and disabled):

Creating new channel
RabbitMQ.Client.Exceptions.AlreadyClosedException: Already closed: The AMQP operation was interrupted: AMQP close-reason, initiated by Library, code=0, text='End of stream', classId=0, methodId=0, cause=System.IO.EndOfStreamException: Reached the end of the stream. Possible authentication failure.
at RabbitMQ.Client.Impl.InboundFrame.ReadFrom(Stream reader, Byte[] frameHeaderBuffer, ArrayPool`1 pool, UInt32 maxMessageSize)
at RabbitMQ.Client.Impl.SocketFrameHandler.ReadFrame()
at RabbitMQ.Client.Framing.Impl.Connection.MainLoopIteration()
at RabbitMQ.Client.Framing.Impl.Connection.MainLoop()
at RabbitMQ.Client.Framing.Impl.Connection.EnsureIsOpen()
at RabbitMQ.Client.Framing.Impl.AutorecoveringConnection.EnsureIsOpen()
at RabbitMQ.Client.Framing.Impl.AutorecoveringConnection.CreateModel()
at RabbitMQError.Program.CreateChannel() in C:\Users\pablo\Downloads\rabbitmq-dotnet-client-1245-main\Program.cs:line 101
at RabbitMQError.Program.Main(String[] args) in C:\Users\pablo\Downloads\rabbitmq-dotnet-client-1245-main\Program.cs:line 57

[lukebakken]

How are you running the test program and RabbitMQ?

I am running everything on Windows 10 pro. RabbitMQ 3.10.7, Erlang 25.0.4.

Here is the output from running the code as is:

C:\Users\bakkenl\development\lukebakken\rabbitmq-dotnet-client-1245 [main ≡]
> dotnet run C:\Users\bakkenl\file.txt
Sending message
Running...
Channel shutdown
Creating new channel
Channel created
Sending message
Running...
Channel shutdown
Creating new channel
Channel created
Sending message
Running...
CTRL-C pressed, exiting!
Sending message
Running...
Exiting...
Channel shutdown
C:\Users\bakkenl\development\lukebakken\rabbitmq-dotnet-client-1245 [main ≡]
> dotnet --version
6.0.303

This is what RabbitMQ logs:

2022-09-10 16:59:14.552000-07:00 [error] <0.575.0> operation basic.publish caused a channel exception precondition_failed: message size 243283364 is larger than configured max size 134217728
2022-09-10 16:59:17.787000-07:00 [error] <0.582.0> Channel error on connection <0.530.0> ([::1]:63291 -> [::1]:5672, vhost: '/', user: 'guest'), channel 1:
2022-09-10 16:59:17.787000-07:00 [error] <0.582.0> operation basic.publish caused a channel exception precondition_failed: message size 243283364 is larger than configured max size 134217728
2022-09-10 16:59:21.033000-07:00 [error] <0.589.0> Channel error on connection <0.530.0> ([::1]:63291 -> [::1]:5672, vhost: '/', user: 'guest'), channel 1:
2022-09-10 16:59:21.033000-07:00 [error] <0.589.0> operation basic.publish caused a channel exception precondition_failed: message size 243283364 is larger than configured max size 134217728
2022-09-10 16:59:21.056000-07:00 [info] <0.530.0> closing AMQP connection <0.530.0> ([::1]:63291 -> [::1]:5672 - TestClient, vhost: '/', user: 'guest')
2022-09-10 16:59:21.056000-07:00 [debug] <0.594.0> Closing all channels from connection '[::1]:63291 -> [::1]:5672' because it has been closed

Here's how I created the large file using Powershell:

$out = new-object byte[] 134217728; (new-object Random).NextBytes($out); [IO.File]::WriteAllBytes('file.txt', $out)

[lukebakken]

I see the same behavior on Linux:

lbakken@shostakovich ~/development/lukebakken/rabbitmq-dotnet-client-1245 (main =)
$ dd if=/dev/random of="$HOME/file.txt" bs=1024 count=131072
131072+0 records in
131072+0 records out
134217728 bytes (134 MB, 128 MiB) copied, 0.915862 s, 147 MB/s
lbakken@shostakovich ~/development/lukebakken/rabbitmq-dotnet-client-1245 (main =)
$ dotnet run $HOME/file.txt
Sending message
Running...
Channel shutdown
Creating new channel
Channel created
Sending message
Running...
Channel shutdown
Creating new channel
Channel created
^CCTRL-C pressed, exiting!
Sending message
Running...
Exiting...
Channel shutdown

It'll be interesting to see what's different in your environment.

[pabermod]

With your example file it is working, but with a bigger file is raising the excepion i mentioned.

For example with a file if 708.199.808 bytes

In RabbitMQ log i can see:

2022-09-12 13:26:31.062081+00:00 [info] <0.647.0> connection <0.647.0> (172.17.0.1:36956 -> 172.17.0.2:5672) has a client-provided name: TestClient
2022-09-12 13:26:31.064385+00:00 [info] <0.647.0> connection <0.647.0> (172.17.0.1:36956 -> 172.17.0.2:5672 - TestClient): user 'guest' authenticated and granted access to vhost '/'
2022-09-12 13:27:11.067867+00:00 [error] <0.647.0> closing AMQP connection <0.647.0> (172.17.0.1:36956 -> 172.17.0.2:5672 - TestClient):
2022-09-12 13:27:11.067867+00:00 [error] <0.647.0> missed heartbeats from client, timeout: 10s

[lukebakken]

Hi, Your test projects is throwing an exception in a loop when trying to declare the exchange after the channel is shutdown.

This is what you originally indicated is not working in your environment, but now you show a heartbeat timeout. Which is it?

missed heartbeats from client, timeout: 10s

Where did you indicate that you adjusted the heartbeat settings? The default should be 30 (or 60 seconds) I believe.

RabbitMQ is not designed for huge file uploads. Compress the data, or split it up.

At this point the example code I provide appears to show how to correctly open a new channel when a channel exception happens and auto recovery is disabled.

If you wish to continue, start a new discussion and provide complete information (code and reproduction steps).

[michaelklishin]

Heartbeat timeouts for messaging client connections are entirely orthogonal to HTTP API or CLI tool operations on definitions.