Report long tasks #4430

arcusfelis · 2024-12-11T12:52:37Z

This PR addresses "MIM-2351 Better logging when something takes too long".

Proposed changes include:

Use mongoose_task:run_tracked/2 to report slow progress in ejabberd_app and ejabberd_sup.

Question:

We could move cets_long into some repo like long_task. Do we want to do so though? The only issues I see: cets_long would be reported as a part of a stacktrace - possible confusion. cets_long behaviour could be changed someday - we control cets though.

New found bugs:

Bug 1 -- pep_SUITE:pep_tests:h_ok_after_notify_test
CI task 1

PEP could fail: report log

EODBC timeout, not much we can do there (could be a deadlock, an issue with mssql or an issue with eodbc. could be CI machine):

callback failed:\
3233 ** Tab: caps_features\
3234 ** Owner: <0.16661.0>\
3235 ** Operation: insert\
3236 ** Args: [{<<\"http://www.chatopus.com\">>,<<\"fsTdKpAlqJVSSyAsVkE/LZjsQps=\">>},\
3237           1734085334]\
3238 ** Reason: {timeout,\
3239                {gen_server,call,\
3240                    ['wpool_pool-mongoose_wpool$rdbms$global$default-2',\
3241                     {sql_cmd,\
3242                         {sql_execute,caps_upsert,\
3243                             [<<\"http://www.chatopus.com\">>,\
3244                              <<\"fsTdKpAlqJVSSyAsVkE/LZjsQps=\">>,\
3245                              <<\"http://www.chatopus.com\">>,\
3246                              <<\"fsTdKpAlqJVSSyAsVkE/LZjsQps=\">>,\
3247                              <<\"1734085334\">>,<<\"1734085334\">>]},\
3248                         -576459923992},\
3249                     60000]}}\

Bug 2 -- graphql_server_SUITE:admin_cli:clustering_tests:remove_dead_from_cluster (ldap_mnesia preset usually)

CI tasks 1 2 3 4

mongoose_start_node_id could stuck in init in erpc forever.
This RPC call does persistent term insert and a gen_server cast - so, it should not block in theory.

first time

623 when=2024-12-11T13:03:58.475773+00:00 level=warning what=long_task_progress pid=<0.49836.0> at=cets_long:monitor_loop/5:116 child_module=mongoose_start_node_id time_ms=90017 caller_pid=<0.49835.0> task=start_linked_child 
current_stacktrace="[{proc_lib,sync_start,2,[{file,\"proc_lib.erl\"},{line,309}]},{cets_long,run_tracked,2,[{file,\"/home/circleci/project/_build/default/lib/cets/src/cets_long.erl\"},{line,61}]},{supervisor,do_start_child_i,3,[{file,\"supervisor.erl\"},{line,420}]},{supervisor,do_start_child,2,[{file,\"supervisor.erl\"},{line,406}]},{supervisor,'-start_children/2-fun-0-',3,[{file,\"supervisor.erl\"},{line,390}]},{supervisor,children_map,4,[{file,\"supervisor.erl\"},{line,1275}]},{supervisor,init_children,2,[{file,\"supervisor.erl\"},{line,350}]},{gen_server,init_it,2,[{file,\"gen_server.erl\"},{line,980}]}]" 

624 when=2024-12-11T13:04:03.107750+00:00 level=warning what=long_task_progress pid=<0.49755.0> at=cets_long:monitor_loop/5:116 time_ms=95018 caller_pid=<0.49754.0> task=start_mongooseim current_stacktrace="[{proc_lib,sync_start,2,[{file,\"proc_lib.erl\"},{line,309}]},
{ejabberd_app,do_start,0,[{file,\"/home/circleci/project/src/ejabberd_app.erl\"},{line,68}]},{cets_long,run_tracked,2,[{file,\"/home/circleci/project/_build/default/lib/cets/src/cets_long.erl\"},{line,61}]},{ejabberd_app,start,2,[{file,\"/home/circleci/project/src/ejabberd_app.erl\"},{line,46}]},{application_master,start_it_old,4,[{file,\"application_master.erl\"},{line,293}]}]" 

625 when=2024-12-11T13:04:03.476973+00:00 level=warning what=long_task_progress pid=<0.49836.0> at=cets_long:monitor_loop/5:116 child_module=mongoose_start_node_id time_ms=95018 caller_pid=<0.49835.0> task=start_linked_child 
current_stacktrace="[{proc_lib,sync_start,2,[{file,\"proc_lib.erl\"},{line,309}]},{cets_long,run_tracked,2,[{file,\"/home/circleci/project/_build/default/lib/cets/src/cets_long.erl\"},{line,61}]},{supervisor,do_start_child_i,3,[{file,\"supervisor.erl\"},{line,420}]},{supervisor,do_start_child,2,[{file,\"supervisor.erl\"},{line,406}]},
{supervisor,'-start_children/2-fun-0-',3,[{file,\"supervisor.erl\"},{line,390}]},{supervisor,children_map,4,[{file,\"supervisor.erl\"},{line,1275}]},{supervisor,init_children,2,[{file,\"supervisor.erl\"},{line,350}]},{gen_server,init_it,2,[{file,\"gen_server.erl\"},{line,980}]}]" 

626 when=2024-12-11T13:04:08.108731+00:00 level=warning what=long_task_progress pid=<0.49755.0> at=cets_long:monitor_loop/5:116 time_ms=100019 caller_pid=<0.49754.0> task=start_mongooseim current_stacktrace="[{proc_lib,sync_start,2,[{file,\"proc_lib.erl\"},{line,309}]},
{ejabberd_app,do_start,0,[{file,\"/home/circleci/project/src/ejabberd_app.erl\"},{line,68}]},{cets_long,run_tracked,2,[{file,\"/home/circleci/project/_build/default/lib/cets/src/cets_long.erl\"},{line,61}]},
{ejabberd_app,start,2,[{file,\"/home/circleci/project/src/ejabberd_app.erl\"},{line,46}]},{application_master,start_it_old,4,[{file,\"application_master.erl\"},{line,293}]}]"

After adding extra code with the 10 seconds timeout for RPC and extra cets_long:run_tracked call, we are getting timeout after 10 seconds what=node_id_register_on_remote_node_failed reason={badrpc,timeout} which is still bad, but at least it is not "Never finish starting MongooseIM application bad" log:


768 when=2024-12-12T18:43:16.119002+00:00 level=warning what=long_task_progress pid=<0.53066.0> at=cets_long:monitor_loop/5:116 time_ms=5001 caller_pid=<0.53065.0> task=start_mongooseim current_stacktrace="[{proc_lib,sync_start,2,[{file,\"proc_lib.erl\"},{line,309}]},{ejabberd_app,do_start,0,[{file,\"/home/circleci/project/src/ejabberd_app.erl\"},{line,68}]},{cets_long,run_tracked,2,[{file,\"/home/circleci/project/_build/default/lib/cets/src/cets_long.erl\"},{line,61}]},{ejabberd_app,start,2,[{file,\"/home/circleci/project/src/ejabberd_app.erl\"},{line,46}]},{application_master,start_it_old,4,[{file,\"application_master.erl\"},{line,293}]}]" 
769 when=2024-12-12T18:43:16.433944+00:00 level=warning what=long_task_progress pid=<0.53150.0> at=cets_long:monitor_loop/5:116 child_module=mongoose_start_node_id time_ms=5000 caller_pid=<0.53146.0> task=start_linked_child current_stacktrace="[{proc_lib,sync_start,2,[{file,\"proc_lib.erl\"},{line,309}]},{cets_long,run_tracked,2,[{file,\"/home/circleci/project/_build/default/lib/cets/src/cets_long.erl\"},{line,61}]},{supervisor,do_start_child_i,3,[{file,\"supervisor.erl\"},{line,420}]},{supervisor,do_start_child,2,[{file,\"supervisor.erl\"},{line,406}]},{supervisor,'-start_children/2-fun-0-',3,[{file,\"supervisor.erl\"},{line,390}]},{supervisor,children_map,4,[{file,\"supervisor.erl\"},{line,1275}]},{supervisor,init_children,2,[{file,\"supervisor.erl\"},{line,350}]},{gen_server,init_it,2,[{file,\"gen_server.erl\"},{line,980}]}]" 
770 when=2024-12-12T18:43:16.433961+00:00 level=warning what=long_task_progress pid=<0.53152.0> at=cets_long:monitor_loop/5:116 time_ms=5000 caller_pid=<0.53151.0> task=mongoose_start_node_id_init current_stacktrace="[{erpc,call,5,[{file,\"erpc.erl\"},{line,146}]},{rpc,call,5,[{file,\"rpc.erl\"},{line,401}]},{mongoose_start_node_id,do_register_on_remote_node,2,[{file,\"/home/circleci/project/src/mongoose_start_node_id.erl\"},{line,106}]},{cets_long,run_tracked,2,[{file,\"/home/circleci/project/_build/default/lib/cets/src/cets_long.erl\"},{line,61}]},{mongoose_start_node_id,'-do_init/0-lc$^0/1-0-',2,[{file,\"/home/circleci/project/src/mongoose_start_node_id.erl\"},{line,50}]},{mongoose_start_node_id,do_init,0,[{file,\"/home/circleci/project/src/mongoose_start_node_id.erl\"},{line,51}]},{cets_long,run_tracked,2,[{file,\"/home/circleci/project/_build/default/lib/cets/src/cets_long.erl\"},{line,61}]},{gen_server,init_it,2,[{file,\"gen_server.erl\"},{line,980}]}]" 
771 when=2024-12-12T18:43:16.435936+00:00 level=warning what=long_task_progress pid=<0.53157.0> at=cets_long:monitor_loop/5:116 start_id=52480a0b94f48ad3 time_ms=5000 caller_pid=<0.53151.0> task=register_on_remote_node remote_node=mongooseim3@localhost current_stacktrace="[{erpc,call,5,[{file,\"erpc.erl\"},{line,146}]},{rpc,call,5,[{file,\"rpc.erl\"},{line,401}]},{mongoose_start_node_id,do_register_on_remote_node,2,[{file,\"/home/circleci/project/src/mongoose_start_node_id.erl\"},{line,106}]},{cets_long,run_tracked,2,[{file,\"/home/circleci/project/_build/default/lib/cets/src/cets_long.erl\"},{line,61}]},{mongoose_start_node_id,'-do_init/0-lc$^0/1-0-',2,[{file,\"/home/circleci/project/src/mongoose_start_node_id.erl\"},{line,50}]},{mongoose_start_node_id,do_init,0,[{file,\"/home/circleci/project/src/mongoose_start_node_id.erl\"},{line,51}]},{cets_long,run_tracked,2,[{file,\"/home/circleci/project/_build/default/lib/cets/src/cets_long.erl\"},{line,61}]},{gen_server,init_it,2,[{file,\"gen_server.erl\"},{line,980}]}]" 
772 when=2024-12-12T18:43:21.119974+00:00 level=warning what=long_task_progress pid=<0.53066.0> at=cets_long:monitor_loop/5:116 time_ms=10002 caller_pid=<0.53065.0> task=start_mongooseim current_stacktrace="[{proc_lib,sync_start,2,[{file,\"proc_lib.erl\"},{line,309}]},{ejabberd_app,do_start,0,[{file,\"/home/circleci/project/src/ejabberd_app.erl\"},{line,68}]},{cets_long,run_tracked,2,[{file,\"/home/circleci/project/_build/default/lib/cets/src/cets_long.erl\"},{line,61}]},{ejabberd_app,start,2,[{file,\"/home/circleci/project/src/ejabberd_app.erl\"},{line,46}]},{application_master,start_it_old,4,[{file,\"application_master.erl\"},{line,293}]}]" 
773 when=2024-12-12T18:43:21.435013+00:00 level=warning what=long_task_progress pid=<0.53150.0> at=cets_long:monitor_loop/5:116 child_module=mongoose_start_node_id time_ms=10001 caller_pid=<0.53146.0> task=start_linked_child current_stacktrace="[{proc_lib,sync_start,2,[{file,\"proc_lib.erl\"},{line,309}]},{cets_long,run_tracked,2,[{file,\"/home/circleci/project/_build/default/lib/cets/src/cets_long.erl\"},{line,61}]},{supervisor,do_start_child_i,3,[{file,\"supervisor.erl\"},{line,420}]},{supervisor,do_start_child,2,[{file,\"supervisor.erl\"},{line,406}]},{supervisor,'-start_children/2-fun-0-',3,[{file,\"supervisor.erl\"},{line,390}]},{supervisor,children_map,4,[{file,\"supervisor.erl\"},{line,1275}]},{supervisor,init_children,2,[{file,\"supervisor.erl\"},{line,350}]},{gen_server,init_it,2,[{file,\"gen_server.erl\"},{line,980}]}]" 
774 when=2024-12-12T18:43:21.434982+00:00 level=warning what=long_task_progress pid=<0.53152.0> at=cets_long:monitor_loop/5:116 time_ms=10001 caller_pid=<0.53151.0> task=mongoose_start_node_id_init current_stacktrace="[{erpc,call,5,[{file,\"erpc.erl\"},{line,146}]},{rpc,call,5,[{file,\"rpc.erl\"},{line,401}]},{mongoose_start_node_id,do_register_on_remote_node,2,[{file,\"/home/circleci/project/src/mongoose_start_node_id.erl\"},{line,106}]},{cets_long,run_tracked,2,[{file,\"/home/circleci/project/_build/default/lib/cets/src/cets_long.erl\"},{line,61}]},{mongoose_start_node_id,'-do_init/0-lc$^0/1-0-',2,[{file,\"/home/circleci/project/src/mongoose_start_node_id.erl\"},{line,50}]},{mongoose_start_node_id,do_init,0,[{file,\"/home/circleci/project/src/mongoose_start_node_id.erl\"},{line,51}]},{cets_long,run_tracked,2,[{file,\"/home/circleci/project/_build/default/lib/cets/src/cets_long.erl\"},{line,61}]},{gen_server,init_it,2,[{file,\"gen_server.erl\"},{line,980}]}]" 
775 when=2024-12-12T18:43:21.436166+00:00 level=error what=node_id_register_on_remote_node_failed reason={badrpc,timeout} pid=<0.53151.0> at=mongoose_start_node_id:do_register_on_remote_node/2:112 remote_node=mongooseim3@localhost

By the way, we cannot do this operation async, otherwise IQ related test would start failing.

Guessing: this should not happen. The caller should receive nodedown on their monitor eventually and stop waiting for a call. Still, it waits for a call.
Nothing particular interesting in logs, sometimes there is MIM-2354 (Avoid noproc error in mongoose_epmd if CETS is not configured) bug in logs.

Could it be related to CETS and mongoose_epmd? Could it be stuck schedulers?
Ideally we need a better logging based on heart to report non-responding nodes into logs. And start/stop times for each node.
We can also have heartbeat for distributed connections to ensure they actually work and if not - log something.

Bug 3 - starting wpool manager times out - default is 5 seconds

CI task 1

Error on MIM side:

{task_failed,{timeout,{gen_server,call,[mongoose_wpool_rdbms_mgr,{start_pool,global,default,[{worke

Error on CT side:

vcard_SUITE:init_per_suite
{fail,[{validate_node_failed,mongooseim_not_running,mongooseim2@localhost}]}

Logs link:

958 when=2024-12-12T15:47:57.547520+00:00 level=error what=task_failed reason="{timeout,{gen_server,call,[mongoose_wpool_rdbms_mgr,{start_pool,global,default,[{workers,5}],#{driver => odbc,settings => \"DSN=mongoose-mssql;UID=sa;PWD=mongooseim_secret+ESL123\",query_timeout => 5000,max_start_interval => 30}}]}}" pid=<0.67166.0> at=cets_long:run_tracked/2:75 stacktrace="gen_server:call/2:1142 mongoose_wpool:start/7:164 mongoose_wpool:'-start_configured_pools/3-lc$^1/1-1-'/1:123 ejabberd_app:do_start/0:72 cets_long:run_tracked/2:61 ejabberd_app:start/2:46 application_master:start_it_old/4:295" long_ref=#Ref<0.687671701.3611295747.178154> caller_pid=<0.67166.0> task=start_mongooseim 
959 when=2024-12-12T15:47:57.547909+00:00 level=critical what=app_failed_to_start reason="{task_failed,{timeout,{gen_server,call,[mongoose_wpool_rdbms_mgr,{start_pool,global,default,[{workers,5}],#{driver => odbc,settings => \"DSN=mongoose-mssql;UID=sa;PWD=mongooseim_secret+ESL123\",query_timeout => 5000,max_start_interval => 30}}]}},#{task => start_mongooseim}}" pid=<0.67166.0> at=ejabberd_app:start/2:50 stacktrace="gen_server:call/2:1142 mongoose_wpool:start/7:164 mongoose_wpool:'-start_configured_pools/3-lc$^1/1-1-'/1:123 ejabberd_app:do_start/0:72 cets_long:run_tracked/2:61 ejabberd_app:start/2:46 application_master:start_it_old/4:295" 
960 when=2024-12-12T15:47:57.550290+00:00 level=error pid=<0.67246.0> at=supervisor:handle_info/2:1165 unstructured_log="Supervisor received unexpected message: {'ETS-TRANSFER',prepared_statements,\
961                                          <0.67166.0>,testing}\
962 "

Solution: increase timeout to 30 seconds.

mongoose-im · 2024-12-11T13:01:18Z

elasticsearch_and_cassandra_27 / elasticsearch_and_cassandra_mnesia / a43fd31
Reports root/ big
OK: 472 / Failed: 0 / User-skipped: 49 / Auto-skipped: 0

small_tests_27 / small_tests / a43fd31
Reports root / small

small_tests_26 / small_tests / a43fd31
Reports root / small

small_tests_27_arm64 / small_tests / a43fd31
Reports root / small

ldap_mnesia_27 / ldap_mnesia / a43fd31
Reports root/ big
OK: 2353 / Failed: 0 / User-skipped: 912 / Auto-skipped: 0

dynamic_domains_mysql_redis_27 / mysql_redis / a43fd31
Reports root/ big
OK: 4726 / Failed: 0 / User-skipped: 154 / Auto-skipped: 0

dynamic_domains_pgsql_mnesia_26 / pgsql_mnesia / a43fd31
Reports root/ big
OK: 4761 / Failed: 0 / User-skipped: 119 / Auto-skipped: 0

dynamic_domains_pgsql_mnesia_27 / pgsql_mnesia / a43fd31
Reports root/ big
OK: 4761 / Failed: 0 / User-skipped: 119 / Auto-skipped: 0

ldap_mnesia_26 / ldap_mnesia / a43fd31
Reports root/ big
OK: 1130 / Failed: 3 / User-skipped: 479 / Auto-skipped: 1653

graphql_server_SUITE:admin_cli:clustering_tests:remove_dead_from_cluster

{failed,
  {graphql_server_SUITE,end_per_testcase,
    {'EXIT',
      {{badrpc,timeout},
       [{distributed_helper,rpc,
          [#{timeout => 30000,node => mongooseim2@localhost},
           mongoose_cluster,leave,[]],
          [{file,
             "/home/circleci/project/big_tests/../test/common/distributed_helper.erl"},
           {line,140}]},
        {distributed_helper,remove_node_from_cluster,2,
          [{file,
             "/home/circleci/project/big_tests/../test/common/distributed_helper.erl"},
           {line,55}]},
        {graphql_server_SUITE,end_per_testcase,2,
          [{file,
             "/home/circleci/project/big_tests/tests/graphql_server_SUITE.erl"},
           {line,120}]},
        {test_server,do_end_per_testcase,4,
          [{file,"test_server.erl"},{line,1637}]},
        {test_server,run_test_case_eval1,6,
          [{file,"test_server.erl"},{line,1345}]},
        {test_server,run_test_case_eval,9,
          [{file,"test_server.erl"},{line,1234}]}]}}}}

Report long tasks #4430

Report long tasks #4430

Conversation

arcusfelis commented Dec 11, 2024 • edited Loading

mongoose-im commented Dec 11, 2024 • edited Loading

codecov bot commented Dec 11, 2024 • edited Loading

Codecov Report

mongoose-im commented Dec 11, 2024 • edited Loading

This comment was marked as outdated.

This comment was marked as outdated.

mongoose-im commented Dec 12, 2024 • edited Loading

mongoose-im commented Dec 12, 2024 • edited Loading

mongoose-im commented Dec 12, 2024 • edited Loading

mongoose-im commented Dec 13, 2024 • edited Loading

chrzaszcz left a comment • edited Loading

Choose a reason for hiding this comment

chrzaszcz left a comment

Choose a reason for hiding this comment

arcusfelis commented Dec 11, 2024 •

edited

Loading

mongoose-im commented Dec 11, 2024 •

edited

Loading

codecov bot commented Dec 11, 2024 •

edited

Loading

mongoose-im commented Dec 11, 2024 •

edited

Loading

mongoose-im commented Dec 12, 2024 •

edited

Loading

mongoose-im commented Dec 12, 2024 •

edited

Loading

mongoose-im commented Dec 12, 2024 •

edited

Loading

mongoose-im commented Dec 13, 2024 •

edited

Loading

chrzaszcz left a comment •

edited

Loading