Closing connection in EventingBasicConsumer.Received event handler freezes execution of event handler and connection is never closed

[Leemellaret]

RabbitMQ 3.9.8
Erlang 24.0
Windows 10 22H2
OS build 19045.2486
Library used RabbitMQ.Client 6.4.0
enabled_plugins file content:

[rabbitmq_management].

Minimal reproducable example

            var cf = new ConnectionFactory()
            {
                HostName = "localhost",
                VirtualHost = "/",
                Port = 5672,
                UserName = "guest",
                Password = "guest",
            };

            var connection = cf.CreateConnection("Test");
            connection.ConnectionShutdown += (s, e) => { Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] connection.shutdown"); };

            var model = connection.CreateModel();
            model.ModelShutdown += (s, e) => { Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] model.shutdown"); };
            var consumer = new EventingBasicConsumer(model);

            string? consumerTag = null;

            consumer.Received += (s, e) =>
            {
                Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] received");

                model.BasicAck(e.DeliveryTag, false);
                Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] acked");

                model.BasicCancel(consumerTag!);
                Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] consumer cancelled");

                Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] before conn.close");
                connection.Close();
                Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] after conn close");

                Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] before conn.dispose");
                connection.Dispose();
                Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] after conn.dispose");

                Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] received handler done");
            };

            consumerTag = model.BasicConsume("TestQueue", false, consumer);
            Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] consumed");

            Console.ReadLine();

            connection.Close();
            connection.Dispose();
            Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] done executing");

Console output

[10:58:08.07752] consumed
[10:58:43.94631] received
[10:58:43.94778] acked
[10:58:43.95422] consumer cancelled
[10:58:43.95436] before conn.close
[10:58:43.95887] connection.shutdown
[10:58:43.96158] model.shutdown

Server logs

2023-01-24 10:58:07.874000+05:00 [info] <0.20062.22> accepting AMQP connection <0.20062.22> ([::1]:50093 -> [::1]:5672)
2023-01-24 10:58:07.982000+05:00 [info] <0.20062.22> Connection <0.20062.22> ([::1]:50093 -> [::1]:5672) has a client-provided name: Test
2023-01-24 10:58:08.016000+05:00 [info] <0.20062.22> connection <0.20062.22> ([::1]:50093 -> [::1]:5672 - Test): user 'guest' authenticated and granted access to vhost '/'
2023-01-24 10:59:24.867000+05:00 [error] <0.836.0> Could not find handle.exe, please install from sysinternals
2023-01-24 11:05:28.363000+05:00 [warning] <0.20062.22> closing AMQP connection <0.20062.22> ([::1]:50093 -> [::1]:5672 - Test, vhost: '/', user: 'guest'):
2023-01-24 11:05:28.363000+05:00 [warning] <0.20062.22> client unexpectedly closed TCP connection

Connection was closed because i stopped program using Stop button in Visual Studio

From console output I realized that execution of event handler froze at connection.Close(); because there is no log after conn close.
I think this is a bug because I need to close all connections to RabbitMQ because there will be no messages anymore so i do not need to keep all connections.

[Zerpet]

The problem seems to be on shutting down the IModel associated to the basic deliver event. The model shutdown event handler is called, as it prints "model.shutdown", but then it does not complete. I suspect that a consumer dispatcher is waiting for the event handler of basic deliver to finish, before it completes the shutdown of the model.

In short, it's sort of a catch 101 where the event handler waits for Close and Close waits for the event handler. I'm not 100% sure of this tho.

Good news is there's a solution to your use case, which is to close the model before calling connection.Close(). You have to change your event handler to close the model first.

consumer.Received += (s, e) =>
{
    Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] received");
    EventingBasicConsumer c = (EventingBasicConsumer)s!;

    model.BasicAck(e.DeliveryTag, false);
    Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] acked");

    model.BasicCancel(consumerTag!);
    Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] consumer cancelled");

    Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] before model.close");
    model.Close();
    Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] after model close");

    Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] before conn.close");
    connection.Close();
    Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] after conn close");
    
    Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] before conn.dispose");
    connection.Dispose();
    Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] after conn.dispose");
    Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fffff}] received handler done");
};

[lukebakken]

@Leemellaret as @Zerpet said, you really shouldn't close IModel and connections within callbacks.

Please see my code which shows the correct way to synchronize events and your program flow:

https://github.com/lukebakken/rabbitmq-dotnet-client-1292/blob/main/Program.cs

Thank you for taking the time to provide code to reproduce what you see! We appreciate it a LOT.