Port operation in rabbit_mgmt_external_stats failed with a badarg

[wuweapon]

2020-12-01 17:41:31 =ERROR REPORT====
** Generic server rabbit_mgmt_external_stats terminating 
** Last message in was emit_update
** When Server state == {state,8192,[{{io_file_handle_open_attempt,count},9},{{io_file_handle_open_attempt,time},93000},{{io_read,bytes},1},{{io_read,count},1},{{io_read,time},0},{{io_reopen,count},0},{{io_seek,count},0},{{io_seek,time},0},{{io_sync,count},0},{{io_sync,time},0},{{io_write,bytes},0},{{io_write,count},0},{{io_write,time},0},{{mnesia_disk_tx,count},0},{{mnesia_ram_tx,count},941},{{msg_store_read,count},0},{{msg_store_write,count},0},{{queue_index_journal_write,count},0},{{queue_index_read,count},0},{{queue_index_write,count},0}],{set,0,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]}}},undefined,5000}
** Reason for termination == 
** {badarg,[{erlang,port_command,[#Port<0.10213>,[]],[{file,"erlang.erl"},{line,3141}]},{os,cmd,2,[{file,"os.erl"},{line,278}]},{rabbit_mgmt_external_stats,get_used_fd,1,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,137}]},{rabbit_mgmt_external_stats,get_used_fd,0,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,65}]},{rabbit_mgmt_external_stats,'-infos/2-lc$^0/1-0-',2,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,181}]},{rabbit_mgmt_external_stats,emit_update,1,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,370}]},{rabbit_mgmt_external_stats,handle_info,2,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,357}]},{gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,637}]}]}
2020-12-01 17:41:31 =CRASH REPORT====
  crasher:
    initial call: rabbit_mgmt_external_stats:init/1
    pid: <0.4031.0>
    registered_name: rabbit_mgmt_external_stats
    exception error: bad argument: [{erlang,port_command,[#Port<0.10213>,[]],[{file,"erlang.erl"},{line,3141}]},{os,cmd,2,[{file,"os.erl"},{line,278}]},{rabbit_mgmt_external_stats,get_used_fd,1,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,137}]},{rabbit_mgmt_external_stats,get_used_fd,0,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,65}]},{rabbit_mgmt_external_stats,'-infos/2-lc$^0/1-0-',2,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,181}]},{rabbit_mgmt_external_stats,emit_update,1,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,370}]},{rabbit_mgmt_external_stats,handle_info,2,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,357}]},{gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,637}]}]
    ancestors: [rabbit_mgmt_agent_sup,rabbit_mgmt_agent_sup_sup,<0.425.0>]
    message_queue_len: 1
    messages: [{'DOWN',#Ref<0.3536825852.53215233.168424>,port,#Port<0.10213>,noproc}]
    links: [<0.427.0>]
    dictionary: [{logged_used_fd_error,true}]
    trap_exit: false
    status: running
    heap_size: 6772
    stack_size: 27
    reductions: 5530866
  neighbours:
2020-12-01 17:41:31 =SUPERVISOR REPORT====
     Supervisor: {local,rabbit_mgmt_agent_sup}
     Context:    child_terminated
     Reason:     {badarg,[{erlang,port_command,[#Port<0.10213>,[]],[{file,"erlang.erl"},{line,3141}]},{os,cmd,2,[{file,"os.erl"},{line,278}]},{rabbit_mgmt_external_stats,get_used_fd,1,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,137}]},{rabbit_mgmt_external_stats,get_used_fd,0,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,65}]},{rabbit_mgmt_external_stats,'-infos/2-lc$^0/1-0-',2,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,181}]},{rabbit_mgmt_external_stats,emit_update,1,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,370}]},{rabbit_mgmt_external_stats,handle_info,2,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,357}]},{gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,637}]}]}
     Offender:   [{pid,<0.4031.0>},{id,rabbit_mgmt_external_stats},{mfargs,{rabbit_mgmt_external_stats,start_link,[]}},{restart_type,permanent},{shutdown,5000},{child_type,worker}]

Status of node rabbit@XXXXX ...
[{pid,6668},
 {running_applications,
     [{rabbitmq_management,"RabbitMQ Management Console","3.7.14"},
      {rabbitmq_management_agent,"RabbitMQ Management Agent","3.7.14"},
      {rabbitmq_web_dispatch,"RabbitMQ Web Dispatcher","3.7.14"},
      {rabbit,"RabbitMQ","3.7.14"},
      {amqp_client,"RabbitMQ AMQP Client","3.7.14"},
      {rabbit_common,
          "Modules shared by rabbitmq-server and rabbitmq-erlang-client",
          "3.7.14"},
      {cowboy,"Small, fast, modern HTTP server.","2.6.1"},
      {ranch,"Socket acceptor pool for TCP protocols.","1.7.1"},
      {ssl,"Erlang/OTP SSL application","9.2"},
      {public_key,"Public key infrastructure","1.6.5"},
      {asn1,"The Erlang ASN1 compiler version 5.0.8","5.0.8"},
      {recon,"Diagnostic tools for production use","2.4.0"},
      {mnesia,"MNESIA  CXC 138 12","4.15.6"},
      {os_mon,"CPO  CXC 138 46","2.4.7"},
      {sysmon_handler,"Rate-limiting system_monitor event handler","1.1.0"},
      {xmerl,"XML parser","1.3.19"},
      {inets,"INETS  CXC 138 49","7.0.6"},
      {cowlib,"Support library for manipulating Web protocols.","2.7.0"},
      {crypto,"CRYPTO","4.4.1"},
      {jsx,"a streaming, evented json parsing toolkit","2.9.0"},
      {lager,"Erlang logging framework","3.6.9"},
      {goldrush,"Erlang event stream processor","0.1.9"},
      {compiler,"ERTS  CXC 138 10","7.3.2"},
      {syntax_tools,"Syntax tools","2.1.7"},
      {sasl,"SASL  CXC 138 11","3.3"},
      {stdlib,"ERTS  CXC 138 10","3.8"},
      {kernel,"ERTS  CXC 138 10","6.3"}]},
 {os,{win32,nt}},
 {erlang_version,
     "Erlang/OTP 21 [erts-10.3] [64-bit] [smp:4:4] [ds:4:4:10] [async-threads:64
]\n"},
 {memory,
     [{connection_readers,0},
      {connection_writers,0},
      {connection_channels,0},
      {connection_other,2732},
      {queue_procs,0},
      {queue_slave_procs,0},
      {plugins,422356},
      {other_proc,32842596},
      {metrics,205668},
      {mgmt_db,139256},
      {mnesia,77792},
      {other_ets,3077464},
      {binary,252592},
      {msg_index,30080},
      {code,27690369},
      {atom,1172689},
      {other_system,10982998},
      {allocated_unused,16098992},
      {reserved_unallocated,0},
      {strategy,rss},
      {total,[{erlang,76896592},{rss,92995584},{allocated,92995584}]}]},
 {alarms,[]},
 {listeners,
     [{clustering,25672,"::"},
      {amqp,5672,"::"},
      {amqp,5672,"0.0.0.0"},
      {http,15672,"::"},
      {http,15672,"0.0.0.0"}]},
 {vm_memory_calculation_strategy,rss},
 {vm_memory_high_watermark,0.4},
 {vm_memory_limit,6848130252},
 {disk_free_limit,50000000},
 {disk_free,14760919040},
 {file_descriptors,
     [{total_limit,8092},
      {total_used,2},
      {sockets_limit,7280},
      {sockets_used,0}]},
 {processes,[{limit,1048576},{used,405}]},
 {run_queue,1},
 {uptime,10},
 {kernel,{net_ticktime,60}}]

[michaelklishin]

Thank you for your time.

Team RabbitMQ uses GitHub issues for specific actionable items engineers can work on. This assumes that we have a certain amount of information to work with.

Getting all the details necessary to reproduce an issue, make a conclusion or even form a hypothesis about what's happening can take a fair amount of time. Our team is multiple orders of magnitude smaller than the RabbitMQ community. Please help others help you by providing a way to reproduce the behavior you're
observing and sharing as much relevant information as possible on the list:

• Server, client library and plugin (if applicable) versions used
• Server logs
• A code example or terminal transcript that can be used to reproduce
• Full exception stack traces (not a single line message)
• rabbitmqctl status (and, if possible, rabbitmqctl environment output)
• Other relevant things about the environment and workload, e.g. OS/systemd logs, a traffic capture, deployment tool logs, etc

Feel free to edit out hostnames and other potentially sensitive information.

When/if we have a complete enough understanding of what's going on, a recommendation will be provided or a new issues with more context will be filed.

Thank you.

[wuweapon]

rabbitMQ_crash_log.zip
Server OS : Windows 2016 Server
The Server has enough resousrce.
memory: 16GB free, disk: 100GB free.
attachment rabbitmq log and crash log and erl_crash.dump.

Thank you.

[michaelklishin]

This does not reveal a whole lot more. The node tries to compute how many file handles it has and the subprocess fails repeatedly:

2020-12-01 13:48:46.740 [error] <0.436.0> ** Generic server rabbit_mgmt_external_stats terminating 
** Last message in was emit_update
** When Server state == {state,8192,[{{io_file_handle_open_attempt,count},9},{{io_file_handle_open_attempt,time},93000},{{io_read,bytes},1},{{io_read,count},1},{{io_read,time},0},{{io_reopen,count},0},{{io_seek,count},0},{{io_seek,time},0},{{io_sync,count},0},{{io_sync,time},0},{{io_write,bytes},0},{{io_write,count},0},{{io_write,time},0},{{mnesia_disk_tx,count},0},{{mnesia_ram_tx,count},475},{{msg_store_read,count},0},{{msg_store_write,count},0},{{queue_index_journal_write,count},0},{{queue_index_read,count},0},{{queue_index_write,count},0}],{set,0,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]}}},undefined,5000}
** Reason for termination == 
** {badarg,[{erlang,port_command,[#Port<0.5099>,[]],[{file,"erlang.erl"},{line,3141}]},{os,cmd,2,[{file,"os.erl"},{line,278}]},{rabbit_mgmt_external_stats,get_used_fd,1,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,137}]},{rabbit_mgmt_external_stats,get_used_fd,0,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,65}]},{rabbit_mgmt_external_stats,'-infos/2-lc$^0/1-0-',2,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,181}]},{rabbit_mgmt_external_stats,emit_update,1,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,370}]},{rabbit_mgmt_external_stats,handle_info,2,[{file,"src/rabbit_mgmt_external_stats.erl"},{line,357}]},{gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,637}]}]}
2020-12-01 13:48:46.740 [error] <0.436.0> CRASH REPORT Process rabbit_mgmt_external_stats with 0 neighbours crashed with reason: bad argument in call to erlang:port_command(#Port<0.5099>, []) line 3141 in os:cmd/2 line 278
2020-12-01 13:48:46.741 [error] <0.427.0> Supervisor rabbit_mgmt_agent_sup had child rabbit_mgmt_external_stats started with rabbit_mgmt_external_stats:start_link() at <0.436.0> exit with reason bad argument in call to erlang:port_command(#Port<0.5099>, []) line 3141 in os:cmd/2 line 278 in context child_terminated

There is also a pretty clear and actionable warning about handle.exe missing on the host:

2020-12-01 13:48:46.773 [warning] <0.2860.0> Could not find handle.exe, please install from sysinternals

And evidence of constantly used short lived connections:

2020-12-01 13:49:43.858 [info] <0.2864.0> accepting AMQP connection <0.2864.0> (10.66.37.100:65096 -> 10.66.37.100:5672)
2020-12-01 13:49:43.861 [info] <0.2864.0> connection <0.2864.0> (10.66.37.100:65096 -> 10.66.37.100:5672): user 'admin' authenticated and granted access to vhost '/'
2020-12-01 13:49:43.861 [info] <0.2864.0> closing AMQP connection <0.2864.0> (10.66.37.100:65096 -> 10.66.37.100:5672, vhost: '/', user: 'admin')
2020-12-01 13:50:43.849 [info] <0.2873.0> accepting AMQP connection <0.2873.0> (10.66.37.100:65153 -> 10.66.37.100:5672)
2020-12-01 13:50:43.853 [info] <0.2873.0> connection <0.2873.0> (10.66.37.100:65153 -> 10.66.37.100:5672): user 'admin' authenticated and granted access to vhost '/'
2020-12-01 13:50:43.854 [info] <0.2873.0> closing AMQP connection <0.2873.0> (10.66.37.100:65153 -> 10.66.37.100:5672, vhost: '/', user: 'admin')
2020-12-01 13:51:43.856 [info] <0.2884.0> accepting AMQP connection <0.2884.0> (10.66.37.100:65220 -> 10.66.37.100:5672)

[michaelklishin]

The exception tells us that the node tried to run an OS subprocess to get some external stats (e.g. how much disk space is left on its data directory partition) and that failed. The node may be out of file descriptors, for example. Unfortunately there aren't any more details available here.

There are existing threads. It mentions a more defensive version of this stats collector function in rabbitmq/rabbitmq-management-agent#87, which was committed in Nov 2019 and shipped in RabbitMQ 3.7.22.

FYI, RabbitMQ 3.7 is has reached end of life.