Reader Loop: undefined method handle_frameset for nil:NilClass

[milgner]

Bunny version: 2.22.0
RabbitMQ version: 3.12.4-1.el8

Recent RabbitMQ log file contents:

2023-09-27 12:02:16.343241+02:00 [warning] <0.142669.0> Consumer 261209 on channel 2 has timed out waiting for delivery acknowledgement. Timeout used: 1800000 ms. This timeout value can be configured, see consumers doc guide to learn more
2023-09-27 12:02:19.603581+02:00 [error] <0.142669.0> Channel error on connection <0.142655.0> ([::1]:38200 -> [::1]:5672, vhost: '/', user: '***'), channel 2:
2023-09-27 12:02:19.603581+02:00 [error] <0.142669.0> operation none caused a channel exception precondition_failed: delivery acknowledgement on channel 2 timed out. Timeout value used: 1800000 ms. This timeout value can be configured, see consumers doc guide to learn more
2023-09-27 12:02:20.019994+02:00 [error] <0.169645.0> Channel error on connection <0.142655.0> ([::1]:38200 -> [::1]:5672, vhost: '/', user: '***'), channel 1:
2023-09-27 12:02:20.019994+02:00 [error] <0.169645.0> operation basic.ack caused a channel exception precondition_failed: unknown delivery tag 261377

Full exception stack traces:

/app/vendor/bundle/ruby/3.0.0/gems/bunny-2.22.0/lib/bunny/session.rb:722:in `handle_frameset': undefined method `handle_frameset' for nil:NilClass (NoMethodError)
/app/vendor/bundle/ruby/3.0.0/gems/bunny-2.22.0/lib/bunny/reader_loop.rb:90:in `run_once'
/app/vendor/bundle/ruby/3.0.0/gems/opentelemetry-instrumentation-bunny-0.20.0/lib/opentelemetry/instrumentation/bunny/patches/reader_loop.rb:16:in `block in run_once'
/app/vendor/bundle/ruby/3.0.0/gems/opentelemetry-api-1.1.0/lib/opentelemetry/trace.rb:72:in `block in with_span'
/app/vendor/bundle/ruby/3.0.0/gems/opentelemetry-api-1.1.0/lib/opentelemetry/context.rb:87:in `with_value'
/app/vendor/bundle/ruby/3.0.0/gems/opentelemetry-api-1.1.0/lib/opentelemetry/trace.rb:72:in `with_span'
/app/vendor/bundle/ruby/3.0.0/gems/opentelemetry-api-1.1.0/lib/opentelemetry/trace/tracer.rb:29:in `in_span'
/app/vendor/bundle/ruby/3.0.0/gems/opentelemetry-instrumentation-bunny-0.20.0/lib/opentelemetry/instrumentation/bunny/patches/reader_loop.rb:15:in `run_once'
/app/vendor/bundle/ruby/3.0.0/gems/bunny-2.22.0/lib/bunny/reader_loop.rb:39:in `block in run_loop'
/app/vendor/bundle/ruby/3.0.0/gems/bunny-2.22.0/lib/bunny/reader_loop.rb:36:in `loop'

I still have to find out where the timeout in the server log comes from: the application was running fine and all messages had been processed up to that point.

[michaelklishin]

@milgner if there were any false positives around delivery acknowledgement timeouts, Team RabbitMQ would be flooded with complaints but that is not the case.

Most likely you have N consumers and some were making progress but others did not. The channel was closed and one way or another, this resulted in a double ack.

Neither Bunny nor RabbitMQ can do much about this. This is developer's responsibility to handle such timeouts and double acks.

[milgner]

I'm having a hard time putting together the logs of the Ruby application with the ones from the server.

There is only one consumer in this Ruby application and nothing in its logs suggests that a timeout happened or something went wrong at all.
Especially since the server log mentions a timeout of 1800000ms: this equates 30 minutes and 30 minutes before the error there weren't even any messages that would have required processing and which could have gotten lost before ack-ing.

Finally, even if there is a timeout, I don't understand why it would produce undefined method 'handle_frameset' for nil:NilClass (NoMethodError) about 4 seconds (a.k.a. an eternity) later? The timeout reported in the server logs was at 12:02:16 whereas the exception in Bunny was reported at 12:02:20.

[michaelklishin]

When a consumer timeout hits, Bunny treats it like any other channel exception.

undefined method 'handle_frameset' for nil:NilClass (NoMethodError)

means that there was no channel instance when a connection had a delivery to dispatch.

That's as much as I can tell from one stack trace alone. You are welcome to investigate how this can be reproduced and take a traffic capture if you can. You don't have to wait for 30 minutes at a time, just lower the timeout and if something in a client library like Bunny causes it, it should hit 10 seconds later vs. 30 minutes by default.