rabbit_mgmt_external_stats terminating with badmatch

[Gama11]

Notably, it seems these terminations (3 so far in 2 days) started happening since we switched to the /metrics/per-object endpoint.

We're using RabbitMQ 3.10.7 with the prometheus plugin:

ARG RABBITMQ_VERSION=3.10.7

FROM rabbitmq:${RABBITMQ_VERSION}-management-alpine

RUN rabbitmq-plugins enable --offline rabbitmq_prometheus

Is this simply a bug in RabbitMQ / the prometheus plugin?

2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2> ** Generic server rabbit_mgmt_external_stats terminating
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2> ** Last message in was emit_update
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2> ** When Server state == {state,1048576,
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                [{{io_sync,count},194215},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                 {{io_file_handle_open_attempt,count},2},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                 {{queue_index_read,count},0},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                 {{msg_store_read,count},0},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                 {{io_read,count},1},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                 {{queue_index_write,count},169},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                 {{msg_store_write,count},8},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                 {{io_write,count},194215},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                 {{io_seek,time},273964},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                 {{mnesia_ram_tx,count},63},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                 {{mnesia_disk_tx,count},15},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                 {{io_read,bytes},1},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                 {{io_write,bytes},10958078247},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                 {{io_seek,count},4629},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                 {{io_sync,time},554807530},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                 {{io_reopen,count},0},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                 {{io_file_handle_open_attempt,time},84},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                 {{io_read,time},25},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                 {{io_write,time},64288204}],
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                {set,0,16,16,8,80,48,
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                     {[],[],[],[],[],[],[],[],[],[],[],[],[],
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                      [],[],[]},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                     {{[],[],[],[],[],[],[],[],[],[],[],[],[],
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                       [],[],[]}}},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                undefined,5000,undefined}
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2> ** Reason for termination ==
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2> ** {{badmatch,[]},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>     [{rabbit_net,dist_info,4,[{file,"rabbit_net.erl"},{line,354}]},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>      {rabbit_net,'-dist_info/0-lc$^1/1-1-',2,
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                  [{file,"rabbit_net.erl"},{line,341}]},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>      {rabbit_mgmt_external_stats,emit_node_node_stats,1,
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                  [{file,"rabbit_mgmt_external_stats.erl"},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                   {line,436}]},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>      {rabbit_mgmt_external_stats,handle_info,2,
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                  [{file,"rabbit_mgmt_external_stats.erl"},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>                                   {line,410}]},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>      {gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,695}]},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>      {gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,771}]},
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>      {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,226}]}]}
2022-08-11 10:53:19.199600+00:00 [error] <0.26500.2>
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>   crasher:
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>     initial call: rabbit_mgmt_external_stats:init/1
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>     pid: <0.26500.2>
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>     registered_name: rabbit_mgmt_external_stats
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>     exception error: no match of right hand side value []
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>       in function  rabbit_net:dist_info/4 (rabbit_net.erl, line 354)
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>       in call from rabbit_net:'-dist_info/0-lc$^1/1-1-'/2 (rabbit_net.erl, line 341)
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>       in call from rabbit_mgmt_external_stats:emit_node_node_stats/1 (rabbit_mgmt_external_stats.erl, line 436)
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>       in call from rabbit_mgmt_external_stats:handle_info/2 (rabbit_mgmt_external_stats.erl, line 410)
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>       in call from gen_server:try_dispatch/4 (gen_server.erl, line 695)
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>       in call from gen_server:handle_msg/6 (gen_server.erl, line 771)
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>     ancestors: [rabbit_mgmt_agent_sup,rabbit_mgmt_agent_sup_sup,<0.699.0>]
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>     message_queue_len: 0
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>     messages: []
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>     links: [<0.702.0>]
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>     dictionary: []
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>     trap_exit: false
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>     status: running
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>     heap_size: 28690
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>     stack_size: 28
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>     reductions: 181825725
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>   neighbours:
2022-08-11 10:53:19.200432+00:00 [error] <0.26500.2>
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>     supervisor: {local,rabbit_mgmt_agent_sup}
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>     errorContext: child_terminated
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>     reason: {{badmatch,[]},
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>              [{rabbit_net,dist_info,4,[{file,"rabbit_net.erl"},{line,354}]},
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>               {rabbit_net,'-dist_info/0-lc$^1/1-1-',2,
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>                   [{file,"rabbit_net.erl"},{line,341}]},
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>               {rabbit_mgmt_external_stats,emit_node_node_stats,1,
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>                   [{file,"rabbit_mgmt_external_stats.erl"},{line,436}]},
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>               {rabbit_mgmt_external_stats,handle_info,2,
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>                   [{file,"rabbit_mgmt_external_stats.erl"},{line,410}]},
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>               {gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,695}]},
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>               {gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,771}]},
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>               {proc_lib,init_p_do_apply,3,
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>                   [{file,"proc_lib.erl"},{line,226}]}]}
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>     offender: [{pid,<0.26500.2>},
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>                {id,rabbit_mgmt_external_stats},
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>                {mfargs,{rabbit_mgmt_external_stats,start_link,[]}},
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>                {restart_type,permanent},
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>                {significant,false},
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>                {shutdown,5000},
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>                {child_type,worker}]
2022-08-11 10:53:19.201036+00:00 [error] <0.702.0>

[lukebakken]

The error is happening here -

https://github.com/rabbitmq/rabbitmq-server/blob/master/deps/rabbit_common/src/rabbit_net.erl#L354-L355

Are you using TLS to encrypt distributed Erlang?

In addition, please share your entire set of logs, or at least an hour on either side of these incidents.

Thanks

cc @deadtrickster

[Gama11]

Are you using TLS to encrypt distributed Erlang?

No TLS, and it's a single-node setup.

In addition, please share your entire set of logs, or at least an hour on either side of these incidents.

These errors are actually the only logs in the last few days (log.console.level is left at the default info).

[gomoripeti]

could it be a remote_shell or cli command that temporarily connects to the Rabbit node but is disconnected by the time inet:peername is called?

[lukebakken]

@gomoripeti that's very likely. We just merged in a fix to take this case into account - #5534