Excimer complicating the php shutdown handler process

[brendanheywood]

There is a feature in core where you can run a cli script like cron, and then if you press control c then instead of it being hard killed it can detect it and gracefully finish what it is doing and then quit asap and not continue in whatever loop it was doing. Cron in particular has some special handling so that if you press it once then it says it is trying to do a graceful shutdown, but if you press it a second time then it just hard exits.

One of the reasons we want this is because if a container is about to be culled then we send a SIGINT to all the scripts which are running and this tries to finish them prematurely but in a nicer way before we hard SIGKILL them. See:

https://tracker.moodle.org/browse/MDL-59594

But with excimer in the brew, the second hard shutdown doesn't work. I left it running ages and eventually it died with this long error below.

I think we need to detect somehow that php is trying to shut down and just get out of its way. If we can possibly persist a partial profile then great, but if we can't then just stop sampling either way and exit.

== Exiting right NOW == PHP Warning: pg_last_error(): supplied resource is not a valid PostgreSQL link resource in /var/www/moodle.local/lib/dml/pgsql_native_moodle_database.php on line 374 PHP Stack trace: PHP 1. {main}() /var/www/moodle.local/admin/cli/cron.php:0 PHP 2. cron_run() /var/www/moodle.local/admin/cli/cron.php:178 PHP 3. cron_run_scheduled_tasks() /var/www/moodle.local/lib/cronlib.php:73 PHP 4. cron_run_inner_scheduled_task() /var/www/moodle.local/lib/cronlib.php:120 PHP 5. tool_langimport\task\update_langpacks_task->execute() /var/www/moodle.local/lib/cronlib.php:253 PHP 6. tool_langimport\controller->update_all_installed_languages() /var/www/moodle.local/admin/tool/langimport/classes/task/update_langpacks_task.php:57 PHP 7. tool_langimport\controller->install_languagepacks() /var/www/moodle.local/admin/tool/langimport/classes/controller.php:179 PHP 8. lang_installer->run() /var/www/moodle.local/admin/tool/langimport/classes/controller.php:74 PHP 9. lang_installer->install_language_pack() /var/www/moodle.local/lib/componentlib.class.php:665 PHP 10. component_installer->install() /var/www/moodle.local/lib/componentlib.class.php:804 PHP 11. component_installer->need_upgrade() /var/www/moodle.local/lib/componentlib.class.php:285 PHP 12. component_installer->get_component_md5() /var/www/moodle.local/lib/componentlib.class.php:390 PHP 13. component_installer->get_all_components_md5() /var/www/moodle.local/lib/componentlib.class.php:458 PHP 14. download_file_content() /var/www/moodle.local/lib/componentlib.class.php:511 PHP 15. curl->get() /var/www/moodle.local/lib/filelib.php:1610 PHP 16. curl->request() /var/www/moodle.local/lib/filelib.php:3976 PHP 17. curl_exec() /var/www/moodle.local/lib/filelib.php:3742 PHP 18. curl->formatHeader() /var/www/moodle.local/lib/filelib.php:3742 PHP 19. tool_excimer\cron_processor->tool_excimer{closure:/var/www/moodle.local/admin/tool/excimer/classes/cron_processor.php:49-51}() /var/www/moodle.local/lib/filelib.php:3370 PHP 20. tool_excimer\cron_processor->on_interval() /var/www/moodle.local/admin/tool/excimer/classes/cron_processor.php:50 PHP 21. tool_excimer\cron_processor->findtaskname() /var/www/moodle.local/admin/tool/excimer/classes/cron_processor.php:92 PHP 22. core_shutdown_manager::signal_handler() /var/www/moodle.local/admin/tool/excimer/classes/cron_processor.php:120 PHP 23. core\lock\lock->__destruct() /var/www/moodle.local/lib/classes/lock/lock.php:0 PHP 24. core\lock\lock->release() /var/www/moodle.local/lib/classes/lock/lock.php:121 PHP 25. core\lock\postgres_lock_factory->release_lock() /var/www/moodle.local/lib/classes/lock/lock.php:107 PHP 26. pgsql_native_moodle_database->get_record_sql() /var/www/moodle.local/lib/classes/lock/postgres_lock_factory.php:198 PHP 27. pgsql_native_moodle_database->get_records_sql() /var/www/moodle.local/lib/dml/moodle_database.php:1671 PHP 28. pgsql_native_moodle_database->query_end() /var/www/moodle.local/lib/dml/pgsql_native_moodle_database.php:1008 PHP 29. pgsql_native_moodle_database->query_end() /var/www/moodle.local/lib/dml/pgsql_native_moodle_database.php:329 PHP 30. pgsql_native_moodle_database->get_last_error() /var/www/moodle.local/lib/dml/moodle_database.php:479 PHP 31. pg_last_error() /var/www/moodle.local/lib/dml/pgsql_native_moodle_database.php:374

Warning: pg_last_error(): supplied resource is not a valid PostgreSQL link resource in /var/www/moodle.local/lib/dml/pgsql_native_moodle_database.php on line 374

Call Stack: 0.0007 417360 1. {main}() /var/www/moodle.local/admin/cli/cron.php:0 0.1967 18474352 2. cron_run() /var/www/moodle.local/admin/cli/cron.php:178 0.2381 21296576 3. cron_run_scheduled_tasks() /var/www/moodle.local/lib/cronlib.php:73 3.1822 73446864 4. cron_run_inner_scheduled_task() /var/www/moodle.local/lib/cronlib.php:120 3.1844 73482112 5. tool_langimport\task\update_langpacks_task->execute() /var/www/moodle.local/lib/cronlib.php:253 4.8082 73767816 6. tool_langimport\controller->update_all_installed_languages() /var/www/moodle.local/admin/tool/langimport/classes/task/update_langpacks_task.php:57 4.9265 73902400 7. tool_langimport\controller->install_languagepacks() /var/www/moodle.local/admin/tool/langimport/classes/controller.php:179 4.9265 73902400 8. lang_installer->run() /var/www/moodle.local/admin/tool/langimport/classes/controller.php:74 4.9266 73902808 9. lang_installer->install_language_pack() /var/www/moodle.local/lib/componentlib.class.php:665 4.9266 73903160 10. component_installer->install() /var/www/moodle.local/lib/componentlib.class.php:804 4.9266 73903160 11. component_installer->need_upgrade() /var/www/moodle.local/lib/componentlib.class.php:285 4.9267 73903224 12. component_installer->get_component_md5() /var/www/moodle.local/lib/componentlib.class.php:390 4.9267 73903224 13. component_installer->get_all_components_md5() /var/www/moodle.local/lib/componentlib.class.php:458 4.9268 73903336 14. download_file_content() /var/www/moodle.local/lib/componentlib.class.php:511 4.9269 73905048 15. curl->get() /var/www/moodle.local/lib/filelib.php:1610 4.9269 73905424 16. curl->request() /var/www/moodle.local/lib/filelib.php:3976 4.9279 73908256 17. curl_exec() /var/www/moodle.local/lib/filelib.php:3742 105.0319 73916408 18. curl->formatHeader() /var/www/moodle.local/lib/filelib.php:3742 105.0320 73916424 19. tool_excimer\cron_processor->tool_excimer{closure:/var/www/moodle.local/admin/tool/excimer/classes/cron_processor.php:49-51}() /var/www/moodle.local/lib/filelib.php:3370 105.0320 73916424 20. tool_excimer\cron_processor->on_interval() /var/www/moodle.local/admin/tool/excimer/classes/cron_processor.php:50 105.0321 73916872 21. tool_excimer\cron_processor->findtaskname() /var/www/moodle.local/admin/tool/excimer/classes/cron_processor.php:92 105.0322 73924624 22. core_shutdown_manager::signal_handler() /var/www/moodle.local/admin/tool/excimer/classes/cron_processor.php:120 105.1398 74196528 23. core\lock\lock->__destruct() /var/www/moodle.local/lib/classes/lock/lock.php:0 105.1398 74196528 24. core\lock\lock->release() /var/www/moodle.local/lib/classes/lock/lock.php:121 105.1398 74196528 25. core\lock\postgres_lock_factory->release_lock() /var/www/moodle.local/lib/classes/lock/lock.php:107 105.1398 74196904 26. pgsql_native_moodle_database->get_record_sql() /var/www/moodle.local/lib/classes/lock/postgres_lock_factory.php:198 105.1398 74196904 27. pgsql_native_moodle_database->get_records_sql() /var/www/moodle.local/lib/dml/moodle_database.php:1671 105.1400 74197496 28. pgsql_native_moodle_database->query_end() /var/www/moodle.local/lib/dml/pgsql_native_moodle_database.php:1008 105.1400 74197528 29. pgsql_native_moodle_database->query_end() /var/www/moodle.local/lib/dml/pgsql_native_moodle_database.php:329 105.1400 74197528 30. pgsql_native_moodle_database->get_last_error() /var/www/moodle.local/lib/dml/moodle_database.php:479 105.1400 74197528 31. pg_last_error() /var/www/moodle.local/lib/dml/pgsql_native_moodle_database.php:374

PHP Fatal error: Uncaught dml_read_exception: Error reading from database ( SELECT pg_advisory_unlock($1, $2) AS unlocked [array ( 0 => -908881031, 1 => 113801282, )]) in /var/www/moodle.local/lib/dml/moodle_database.php:486 Stack trace:

0 /var/www/moodle.local/lib/dml/pgsql_native_moodle_database.php(329): moodle_database->query_end()

1 /var/www/moodle.local/lib/dml/pgsql_native_moodle_database.php(1008): pgsql_native_moodle_database->query_end()

2 /var/www/moodle.local/lib/dml/moodle_database.php(1671): pgsql_native_moodle_database->get_records_sql()

3 /var/www/moodle.local/lib/classes/lock/postgres_lock_factory.php(198): moodle_database->get_record_sql()

4 /var/www/moodle.local/lib/classes/lock/lock.php(107): core\lock\postgres_lock_factory->release_lock()

5 /var/www/moodle.local/lib/classes/lock/lock.php(121): core\lock\lock->release()

6 [internal function]: core\lock\lock->__destruct()

7 {main}

thrown in /var/www/moodle.local/lib/dml/moodle_database.php on line 486 PHP Stack trace: PHP 1. {main}() /var/www/moodle.local/admin/cli/cron.php:0 PHP 2. cron_run() /var/www/moodle.local/admin/cli/cron.php:178 PHP 3. cron_run_scheduled_tasks() /var/www/moodle.local/lib/cronlib.php:73 PHP 4. cron_run_inner_scheduled_task() /var/www/moodle.local/lib/cronlib.php:120 PHP 5. tool_langimport\task\update_langpacks_task->execute() /var/www/moodle.local/lib/cronlib.php:253 PHP 6. tool_langimport\controller->update_all_installed_languages() /var/www/moodle.local/admin/tool/langimport/classes/task/update_langpacks_task.php:57 PHP 7. tool_langimport\controller->install_languagepacks() /var/www/moodle.local/admin/tool/langimport/classes/controller.php:179 PHP 8. lang_installer->run() /var/www/moodle.local/admin/tool/langimport/classes/controller.php:74 PHP 9. lang_installer->install_language_pack() /var/www/moodle.local/lib/componentlib.class.php:665 PHP 10. component_installer->install() /var/www/moodle.local/lib/componentlib.class.php:804 PHP 11. component_installer->need_upgrade() /var/www/moodle.local/lib/componentlib.class.php:285 PHP 12. component_installer->get_component_md5() /var/www/moodle.local/lib/componentlib.class.php:390 PHP 13. component_installer->get_all_components_md5() /var/www/moodle.local/lib/componentlib.class.php:458 PHP 14. download_file_content() /var/www/moodle.local/lib/componentlib.class.php:511 PHP 15. curl->get() /var/www/moodle.local/lib/filelib.php:1610 PHP 16. curl->request() /var/www/moodle.local/lib/filelib.php:3976 PHP 17. curl_exec() /var/www/moodle.local/lib/filelib.php:3742 PHP 18. curl->formatHeader() /var/www/moodle.local/lib/filelib.php:3742 PHP 19. tool_excimer\cron_processor->tool_excimer{closure:/var/www/moodle.local/admin/tool/excimer/classes/cron_processor.php:49-51}() /var/www/moodle.local/lib/filelib.php:3370 PHP 20. tool_excimer\cron_processor->on_interval() /var/www/moodle.local/admin/tool/excimer/classes/cron_processor.php:50 PHP 21. tool_excimer\cron_processor->findtaskname() /var/www/moodle.local/admin/tool/excimer/classes/cron_processor.php:92 PHP 22. core_shutdown_manager::signal_handler() /var/www/moodle.local/admin/tool/excimer/classes/cron_processor.php:120

[jaypha]

Is it supposed to be putting any kind of stack trace at all? When I test this on a vanilla install, I still get an error in the database code.

[brendanheywood]

Do you mean should the normal code which is running explode with a track trace? If so yes, basically if excimer wasn’t running at all and it explodes with a stack trace then it should behave the same with excimer running.

there might be some loss of samples here, eg if we stop proofing after the first control c, but then cron keeps running for another minute and then gracefully shuts down. In this case I’d prefer to have samples for that extra minute but if it isn’t viable then so be it

[jaypha]

I have examined this using many scenarios, but I have not been able to reproduce this problem. Each time, the code quits cleanly. Can you give details about the environment you used?

[brendanheywood]

I can half reproduce but I think this might be unrelated. It might be happening the same without excimer in the brew and it looks related to the process being blocked on a curl call. Lets down tools and come back to this later

$ php admin/cli/cron.php 
Server Time: Mon, 11 Apr 2022 13:18:19 +1000

Execute scheduled task: Download available H5P content types from h5p.org (core\task\h5p_get_content_types_task)
... started 13:18:20. Current memory use 21.3 MB.
^C
== Exiting gracefully, please wait ... ==
^C^C^C^C^C^C
== Exiting right NOW ==
PHP Warning:  pg_last_error(): supplied resource is not a valid PostgreSQL link resource in /var/www/moodle.local/lib/dml/pgsql_native_moodle_database.php on line 374
PHP Stack trace:
PHP   1. {main}() /var/www/moodle.local/admin/cli/cron.php:0
PHP   2. cron_run() /var/www/moodle.local/admin/cli/cron.php:178
PHP   3. cron_run_scheduled_tasks() /var/www/moodle.local/lib/cronlib.php:73
PHP   4. cron_run_inner_scheduled_task() /var/www/moodle.local/lib/cronlib.php:120
PHP   5. core\task\h5p_get_content_types_task->execute() /var/www/moodle.local/lib/cronlib.php:253
PHP   6. core_h5p\core->fetch_latest_content_types() /var/www/moodle.local/lib/classes/task/h5p_get_content_types_task.php:69
PHP   7. core_h5p\core->fetch_content_type() /var/www/moodle.local/h5p/classes/core.php:215
PHP   8. file_storage->create_file_from_url() /var/www/moodle.local/h5p/classes/core.php:268
PHP   9. download_file_content() /var/www/moodle.local/lib/filestorage/file_storage.php:1242
PHP  10. curl->get() /var/www/moodle.local/lib/filelib.php:1610
PHP  11. curl->request() /var/www/moodle.local/lib/filelib.php:3977
PHP  12. core_shutdown_manager::signal_handler() /var/www/moodle.local/lib/filelib.php:3743
PHP  13. core\lock\lock->__destruct() /var/www/moodle.local/lib/classes/lock/lock.php:0
PHP  14. core\lock\lock->release() /var/www/moodle.local/lib/classes/lock/lock.php:121
PHP  15. core\lock\postgres_lock_factory->release_lock() /var/www/moodle.local/lib/classes/lock/lock.php:107
PHP  16. pgsql_native_moodle_database->get_record_sql() /var/www/moodle.local/lib/classes/lock/postgres_lock_factory.php:198
PHP  17. pgsql_native_moodle_database->get_records_sql() /var/www/moodle.local/lib/dml/moodle_database.php:1671
PHP  18. pgsql_native_moodle_database->query_end() /var/www/moodle.local/lib/dml/pgsql_native_moodle_database.php:1008
PHP  19. pgsql_native_moodle_database->query_end() /var/www/moodle.local/lib/dml/pgsql_native_moodle_database.php:329
PHP  20. pgsql_native_moodle_database->get_last_error() /var/www/moodle.local/lib/dml/moodle_database.php:479
PHP  21. pg_last_error() /var/www/moodle.local/lib/dml/pgsql_native_moodle_database.php:374
PHP Fatal error:  Uncaught dml_read_exception: Error reading from database in /var/www/moodle.local/lib/dml/moodle_database.php:486
Stack trace:
#0 /var/www/moodle.local/lib/dml/pgsql_native_moodle_database.php(329): moodle_database->query_end()
#1 /var/www/moodle.local/lib/dml/pgsql_native_moodle_database.php(1008): pgsql_native_moodle_database->query_end()
#2 /var/www/moodle.local/lib/dml/moodle_database.php(1671): pgsql_native_moodle_database->get_records_sql()
#3 /var/www/moodle.local/lib/classes/lock/postgres_lock_factory.php(198): moodle_database->get_record_sql()
#4 /var/www/moodle.local/lib/classes/lock/lock.php(107): core\lock\postgres_lock_factory->release_lock()
#5 /var/www/moodle.local/lib/classes/lock/lock.php(121): core\lock\lock->release()
#6 [internal function]: core\lock\lock->__destruct()
#7 {main}
  thrown in /var/www/moodle.local/lib/dml/moodle_database.php on line 486
PHP Stack trace:
PHP   1. {main}() /var/www/moodle.local/admin/cli/cron.php:0
PHP   2. cron_run() /var/www/moodle.local/admin/cli/cron.php:178
PHP   3. cron_run_scheduled_tasks() /var/www/moodle.local/lib/cronlib.php:73
PHP   4. cron_run_inner_scheduled_task() /var/www/moodle.local/lib/cronlib.php:120
PHP   5. core\task\h5p_get_content_types_task->execute() /var/www/moodle.local/lib/cronlib.php:253
PHP   6. core_h5p\core->fetch_latest_content_types() /var/www/moodle.local/lib/classes/task/h5p_get_content_types_task.php:69
PHP   7. core_h5p\core->fetch_content_type() /var/www/moodle.local/h5p/classes/core.php:215
PHP   8. file_storage->create_file_from_url() /var/www/moodle.local/h5p/classes/core.php:268
PHP   9. download_file_content() /var/www/moodle.local/lib/filestorage/file_storage.php:1242
PHP  10. curl->get() /var/www/moodle.local/lib/filelib.php:1610
PHP  11. curl->request() /var/www/moodle.local/lib/filelib.php:3977
PHP  12. core_shutdown_manager::signal_handler() /var/www/moodle.local/lib/filelib.php:3743