Enabling message_containers feature flag with log.exchange.level = info leads to lock and memory exhaustion

[johanrhodin]

Background

The enabling of the message_containers feature flag contains a deadlock in the (rare) case of when the log exchange is set to debug level. (In a multi-node environment it is enough to set it to info.)

Reproduction

Follow these steps to reproduce the issue:

• Install a late 3.12.x release, such as 3.12.14
• Update to 3.13.4
• Set the log level for the log exchange to debug:

{rabbit, [
    {log, [
      {exchange, [{enabled, true}, {level, debug}, {formatter, {rabbit_logger_text_fmt, #{single_line => true}}}]},
      {file,     [{level, debug}]} %% not needed, but nice to have
    ]}
  ]}

• Enable the feature flag:
  sudo rabbitmqctl enable_feature_flag message_containers
• Watch in observer how all memory is consumed

Logs

See attached log file
rabbit_logger_exchange_h.txt

[gomoripeti]

Tracing the function which does the debug logging of "Feature flags: acquiring lock" it is visible there is an infinite loop in the stacktrace. rabbit_logger_exchange_h:do_log/2 and rabbit_feature_flags:is_enabled/2 mutually call each other:

rabbit_ff_registry_factory:acquire_state_change_lock()
 [{rabbit_feature_flags,is_enabled,2,
                       [{file,"rabbit_feature_flags.erl"},{line,584}]},
 {mc_amqpl,message,4,[{file,"mc_amqpl.erl"},{line,464}]},
 {rabbit_logger_exchange_h,do_log,2,
                           [{file,"rabbit_logger_exchange_h.erl"},{line,58}]},
 {logger_backend,call_handlers,3,[{file,"logger_backend.erl"},{line,51}]},
 {rabbit_ff_registry_factory,acquire_state_change_lock,0,
                             [{file,"rabbit_ff_registry_factory.erl"},
                              {line,37}]},
 {rabbit_feature_flags,is_enabled,2,
                       [{file,"rabbit_feature_flags.erl"},{line,584}]},
 {mc_amqpl,message,4,[{file,"mc_amqpl.erl"},{line,464}]},
 {rabbit_logger_exchange_h,do_log,2,
                           [{file,"rabbit_logger_exchange_h.erl"},{line,58}]}]

[michaelklishin]

The only solution I see is to disable exchange logging before upgrading. Other logging mechanisms do not depend on feature flags, and feature flag changes do and will produce some log entries.

I don't see how the exchange logging path can determine whether it should check for the flag.

[ansd]

For the record, @dumbbell fixed this bug. Since this bug applies only to v3.13.x (not to v4.x.x), the fix will be released in the upcoming Tanzu RabbitMQ 3.13 patch release.

[gomoripeti]

I wonder if a similar bug affecting 4.x could be addressed with a similar solution? ;) #14069

[ansd]

A similar issue exists for feature flag message_containers_deaths_v2.

Enabling feature flags will get stuck because rabbit_ff_controller gets stuck in the following stack trace:

 {current_stacktrace,
     [{global,random_sleep,1,[{file,"global.erl"},{line,3229}]},
      {global,set_lock,4,[{file,"global.erl"},{line,643}]},
      {rabbit_ff_registry_factory,acquire_state_change_lock,0,
          [{file,"rabbit_ff_registry_factory.erl"},{line,41}]},
      {rabbit_feature_flags,is_enabled,2,
          [{file,"rabbit_feature_flags.erl"},{line,584}]},
      {mc_amqpl,message,5,[{file,"mc_amqpl.erl"},{line,488}]},
      {rabbit_logger_exchange_h,do_log,2,
          [{file,"rabbit_logger_exchange_h.erl"},{line,68}]},
      {rabbit_logger_exchange_h,log,2,
          [{file,"rabbit_logger_exchange_h.erl"},{line,51}]},
      {logger_backend,call_handlers,3,
          [{file,"logger_backend.erl"},{line,52}]}]},

This is the stack trace on v3.13.11.

I fixed this for the upcoming VMware Tanzu RabbitMQ 3.13.12 release.

Note that this happened even at info level, not only at debug level.

[ansd]

And a similar issue also exists for feature flag stream_filtering if a stream is bound to the logging exchange (also fixed in the upcoming VMware Tanzu RabbitMQ 3.13.12 release).

[ansd]

#15294 adds the missing test case.

[johanrhodin]

@ansd Thank you for the follow-up! For history reasons I've updated the title to include the info-level where this happened too.