test failure: nodeos_signal_throw_test

[spoonincode]

https://github.com/AntelopeIO/spring/actions/runs/12996557058/job/36246263466

may or may not be related to #1004 that was closed in last couple months

[heifner]

info  2025-01-27T19:33:37.815 nodeos    test_control_plugin.cp:91     throw_exception      ] throwing controller_emit_signal_exception for signal irreversible_block
warn  2025-01-27T19:33:37.815 nodeos    controller.cpp:950            emit                 ] /__w/spring/spring/libraries/chain/controller.cpp:1589 controller_emit_signal_exception: 3140000 controller_emit_signal_exception: Exceptions that are allowed to bubble out of emit calls in controller

    {}
    nodeos  test_control_plugin.cpp:93 throw_exception

warn  2025-01-27T19:33:37.815 nodeos    controller.cpp:951            emit                 ] Shutting down due to controller_emit_signal_exception
debug 2025-01-27T19:33:37.815 nodeos    chain_plugin.cpp:1128         operator()           ] controller shutdown, quitting...
info  2025-01-27T19:33:37.815 nodeos    main.cpp:193                  operator()           ] appbase quit called
error 2025-01-27T19:33:37.815 nodeos    controller.cpp:1614           operator()           ] Caught exception while logging irreversible: 3140000 controller_emit_signal_exception: Exceptions that are allowed to bubble out of emit calls in controller

    {}
    nodeos  test_control_plugin.cpp:93 throw_exception

    {}
    nodeos  controller.cpp:1611 operator()

warn  2025-01-27T19:33:37.815 nodeos    producer_plugin.cpp:2947      maybe_produce_block  ] 3140000 controller_emit_signal_exception: Exceptions that are allowed to bubble out of emit calls in controller

    {}
    nodeos  test_control_plugin.cpp:93 throw_exception

    {}
    nodeos  controller.cpp:1611 operator()

debug 2025-01-27T19:33:37.815 nodeos    producer_plugin.cpp:2949      maybe_produce_block  ] Aborting block due to produce_block error
debug 2025-01-27T19:33:37.815 nodeos    producer_plugin.cpp:2955      maybe_produce_block  ] Not starting block until 2025-01-27T19:33:38.000
debug 2025-01-27T19:33:37.815 nodeos    producer_plugin.cpp:2923      schedule_delayed_pro ] Scheduling Speculative/Production Change at 2025-01-27T19:33:38.000
debug 2025-01-27T19:33:37.815 nodeos    producer_plugin.cpp:2914      operator()           ] Producing Block #179 returned: false
debug 2025-01-27T19:33:37.815 nodeos    resource_monitor_plugi:117    plugin_shutdown      ] entered shutdown...
debug 2025-01-27T19:33:37.815 trace-mx  trace_api_plugin.cpp:155      operator()           ] Waking up to handle lib: 176
debug 2025-01-27T19:33:37.818 nodeos    resource_monitor_plugi:119    plugin_shutdown      ] exiting shutdown
debug 2025-01-27T19:33:37.818 nodeos    test_control_plugin.cp:287    plugin_shutdown      ] test_control_plugin shutting down
debug 2025-01-27T19:33:37.818 nodeos    trace_api_plugin.cpp:436      plugin_shutdown      ] exit shutdown
debug 2025-01-27T19:33:37.820 nodeos    http_plugin.cpp:516           plugin_shutdown      ] exit shutdown
debug 2025-01-27T19:33:37.820 nodeos    net_plugin.cpp:4636           plugin_shutdown      ] shutdown..
debug 2025-01-27T19:33:37.821 nodeos    net_plugin.cpp:4638           plugin_shutdown      ] exit shutdown
debug 2025-01-27T19:33:37.821 nodeos    producer_plugin.cpp:1673      plugin_shutdown      ] exit shutdown
debug 2025-01-27T19:33:37.821 nodeos    chain_plugin.cpp:1174         plugin_shutdown      ] shutdown
info  2025-01-27T19:33:42.280 nodeos    block_handle.cpp:21           write                ] Writing chain_head block 178 000000b22722d0c809cd4120eb1d82f3e2a0719a2482f4ca981d28147415ac74
info  2025-01-27T19:33:42.280 nodeos    fork_database.cpp:671         close                ] Persisting to fork_database file: /__w/spring/spring/build/TestLogs/nodeos_signal_throw_test8/node_00/blocks/reversible/fork_db.dat
info  2025-01-27T19:33:42.280 nodeos    fork_database.cpp:167         close_impl           ] Writing fork_database 4 blocks with root 175:000000afb22923ca3679c1b745e031448efb2b1621dc407c6ba8b9bcd890445e and head 179:000000b3407bcd9694f404eb0782d670095025ee8de33ea968defd5312cb94fe
info  2025-01-27T19:33:43.325 nodeos    main.cpp:165                  operator()           ] nodeos version v1.1.0-dev v1.1.0-dev-98c980a36c162bdc5be92b08d4cd480437ad8e8d
info  2025-01-27T19:33:43.325 nodeos    main.cpp:69                   log_non_default_opti ] Non-default options: blocks-dir = blocks, p2p-listen-endpoint = 0.0.0.0:9876, p2p-server-address = localhost:9876, p2p-peer-address = localhost:9776, p2p-peer-address = localhost:9877, p2p-peer-address = localhost:9878, plugin = eosio::producer_plugin, signature-provider = EOS8AYX8L56HkFu7toh5235jHGHmQRXpE4dguharRg7oKmPf2NNkh=KEY:***, signature-provider = PUB_BLS_cysqwqefU2tLqHX-OA60xp_Lh2eLlqZtTtY_6I7vSN6VHU7d-JWeylhHDJHtTtUGvelOocPbIDzyRxfAcYxaf3HQ0Jzn1FETiFVzxkHSxLs3dMmroKrp723yc1qJXJQI2qNqtA=KEY:***, producer-name = defproducera, plugin = eosio::net_plugin, plugin = eosio::chain_api_plugin, vote-threads = 4, max-transaction-time = -1, abi-serializer-max-time-ms = 990000, p2p-max-nodes-per-host = 3, max-clients = 25, connection-cleanup-period = 15, contracts-console, plugin = eosio::producer_api_plugin, plugin = eosio::trace_api_plugin, trace-no-abis, plugin = eosio::test_control_api_plugin, http-max-response-time-ms = 990000, enable-stale-production, config-dir = /__w/spring/spring/build/TestLogs/nodeos_signal_throw_test8/node_00, data-dir = /__w/spring/spring/build/TestLogs/nodeos_signal_throw_test8/node_00, http-validate-host = false, http-server-address = localhost:8888
info  2025-01-27T19:33:43.326 nodeos    main.cpp:253                  main                 ] nodeos successfully exiting

The signal was handled correctly, and shutdown was started.

There is a 4.45 second pause between:

debug 2025-01-27T19:33:37.821 nodeos    chain_plugin.cpp:1174         plugin_shutdown      ] shutdown
info  2025-01-27T19:33:42.280 nodeos    block_handle.cpp:21           write                ] Writing chain_head block 178 000000b22722d0c809cd4120eb1d82f3e2a0719a2482f4ca981d28147415ac74

It is unclear why there is this long of a pause, maybe ci/cd was just really busy during that time.

The node did correctly shutdown before the integration test killed it at:

2025-01-27T19:33:43.768769    Killing node: ['/__w/spring/spring/build/bin/nodeos', '--blocks-dir', 'blocks', '--p2p-listen-endpoint', '0.0.0.0:9876', '--p2p-server-address', 'localhost:9876', '--p2p-peer-address', 'localhost:9776', '--p2p-peer-address', 'localhost:9877', '--p2p-peer-address', 'localhost:9878', '--plugin', 'eosio::producer_plugin', '--signature-provider', 'EOS8AYX8L56HkFu7toh5235jHGHmQRXpE4dguharRg7oKmPf2NNkh=KEY:5KDvgibAvbE4rpCpx6jKmFrAQkPVBQiuhkb3e551j6LtReZgmZQ', '--signature-provider', 'PUB_BLS_cysqwqefU2tLqHX-OA60xp_Lh2eLlqZtTtY_6I7vSN6VHU7d-JWeylhHDJHtTtUGvelOocPbIDzyRxfAcYxaf3HQ0Jzn1FETiFVzxkHSxLs3dMmroKrp723yc1qJXJQI2qNqtA=KEY:PVT_BLS_s9VeZ03_Z4Yiom_7KH7DVHkQn9JS4erGECCUtK8fClzfI6qT', '--producer-name', 'defproducera', '--plugin', 'eosio::net_plugin', '--plugin', 'eosio::chain_api_plugin', '--vote-threads', '4', '--max-transaction-time', '-1', '--abi-serializer-max-time-ms', '990000', '--p2p-max-nodes-per-host', '3', '--max-clients', '25', '--connection-cleanup-period', '15', '--contracts-console', '--plugin', 'eosio::producer_api_plugin', '--plugin', 'eosio::trace_api_plugin', '--trace-no-abis', '--plugin', 'eosio::test_control_api_plugin', '--http-max-response-time-ms', '990000', '--enable-stale-production', '--config-dir', '/__w/spring/spring/build/TestLogs/nodeos_signal_throw_test8/node_00', '--data-dir', '/__w/spring/spring/build/TestLogs/nodeos_signal_throw_test8/node_00', '--http-validate-host', 'false', '--http-server-address', 'localhost:8888']

I believe we just need to increase the timeout for nodeos to shutdown in the test.