Adhoc task freezes when querying temp table

Adhoc task freezes when querying temp table

by David Ball -
Number of replies: 9
The short version: gradebook items are stuck in the [Deletion in progress] status.  I ran the adhog_task.php manually and saw that the task hangs forever at the following query:

SELECT 'x' FROM #mdl_backup_ids_temp WITH (NOLOCK) WHERE backupid = N'633eea43439d92cf119d09bb687326ff' AND itemname = N'user' AND itemid = '6607' ORDER BY 1 OFFSET 0 ROWS  FETCH NEXT 1 ROWS ONLY
[array (
  0 => '633eea43439d92cf119d09bb687326ff',
  1 => 'user',
  2 => '6607',
)]

If I restart the database service, it crashes the php execution and gives the following error message:

PS C:\Windows\system32> C:\php\php.exe -f C:\inetpub\wwwroot\moodle\admin\cli\adhoc_task.php -- -e -i --showdebugging
Server Time: Thu, 22 Feb 2024 14:18:25 -0600
Execute adhoc task: core_course\task\course_delete_modules
... started 14:18:26. Current memory use 11.9MB.
... used 1270 dbqueries
... used 60191.899248123 seconds
Adhoc task failed: core_course\task\course_delete_modules,Coding error detected, it must be fixed by a programmer: The course module 302186 could not be deleted. #0 C:\inetpub\wwwroot\moodle\lib\dml\sqlsrv_native_moodle_database.php(331): moodle_database->query_end()
#1 C:\inetpub\wwwroot\moodle\lib\dml\sqlsrv_native_moodle_database.php(438): sqlsrv_native_moodle_database->query_end()
#2 C:\inetpub\wwwroot\moodle\lib\dml\sqlsrv_native_moodle_database.php(907): sqlsrv_native_moodle_database->do_query()
#3 C:\inetpub\wwwroot\moodle\lib\dml\moodle_database.php(1955): sqlsrv_native_moodle_database->get_recordset_sql()
#4 C:\inetpub\wwwroot\moodle\lib\dml\moodle_database.php(1940): moodle_database->record_exists_sql()
#5 C:\inetpub\wwwroot\moodle\lib\dml\moodle_database.php(1924): moodle_database->record_exists_select()
#6 C:\inetpub\wwwroot\moodle\backup\util\dbops\backup_structure_dbops.class.php(169): moodle_database->record_exists()
#7 C:\inetpub\wwwroot\moodle\backup\moodle2\backup_stepslib.php(1812): backup_structure_dbops::move_annotations_to_final()
#8 C:\inetpub\wwwroot\moodle\backup\util\plan\backup_execution_step.class.php(34): move_inforef_annotations_to_final->define_execution()
#9 C:\inetpub\wwwroot\moodle\backup\util\plan\base_task.class.php(183): backup_execution_step->execute()
#10 C:\inetpub\wwwroot\moodle\backup\util\plan\base_plan.class.php(193): base_task->execute()
#11 C:\inetpub\wwwroot\moodle\backup\util\plan\backup_plan.class.php(145): base_plan->execute()
#12 C:\inetpub\wwwroot\moodle\backup\controller\backup_controller.class.php(419): backup_plan->execute()
#13 C:\inetpub\wwwroot\moodle\admin\tool\recyclebin\classes\course_bin.php(136): backup_controller->execute_plan()
#14 C:\inetpub\wwwroot\moodle\admin\tool\recyclebin\lib.php(151): tool_recyclebin\course_bin->store_item()
#15 C:\inetpub\wwwroot\moodle\course\lib.php(1046): tool_recyclebin_pre_course_module_delete()
#16 C:\inetpub\wwwroot\moodle\course\classes\task\course_delete_modules.php(66): course_delete_module()
#17 C:\inetpub\wwwroot\moodle\lib\cronlib.php(341): core_course\task\course_delete_modules->execute()
#18 C:\inetpub\wwwroot\moodle\lib\cronlib.php(198): cron_run_inner_adhoc_task()
#19 C:\inetpub\wwwroot\moodle\admin\cli\adhoc_task.php(122): cron_run_adhoc_tasks()
#20 {main}
Backtrace:
* line 341 of \lib\cronlib.php: call to core_course\task\course_delete_modules->execute()
* line 198 of \lib\cronlib.php: call to cron_run_inner_adhoc_task()
* line 122 of \admin\cli\adhoc_task.php: call to cron_run_adhoc_tasks()
!!! Error writing to database !!!
Debug info: SQLState: 08S01<br>
Error Code: -1<br>
Message: [Microsoft][ODBC Driver 17 for SQL Server]Session Provider: Connection has been closed by peer [xFFFFFFFF]. <br>
SQLState: 08S01<br>
Error Code: -1<br>
Message: [Microsoft][ODBC Driver 17 for SQL Server]Communication link failure<br>
UPDATE mdl_task_adhoc SET classname = N'\core_course\task\course_delete_modules',component = N'',blocking = '0',nextruntime = '1708693357',faildelay = '60',customdata = N'{"cms":[{"id":"302186","course":"741","module":"14","instance":"1722","section":"10998","idnumber":"","added":"1704474541","score":"0","indent":"0","visible":"1","visibleoncoursepage":"1","visibleold":"1","groupmode":"0","groupingid":"0","completion":"0","completiongradeitemnumber":null,"completionview":"0","completionexpected":"0","showdescription":"0","availability":null,"deletioninprogress":"1"}],"userid":"1440","realuserid":"1440"}',userid = NULL WHERE id = '1992'
[array (
  0 => '\\core_course\\task\\course_delete_modules',
  1 => '',
  2 => 0,
  3 => 1708693357,
  4 => 60,
  5 => '{"cms":[{"id":"302186","course":"741","module":"14","instance":"1722","section":"10998","idnumber":"","added":"1704474541","score":"0","indent":"0","visible":"1","visibleoncoursepage":"1","visibleold":"1","groupmode":"0","groupingid":"0","completion":"0","completiongradeitemnumber":null,"completionview":"0","completionexpected":"0","showdescription":"0","availability":null,"deletioninprogress":"1"}],"userid":"1440","realuserid":"1440"}',
  6 => NULL,
  7 => '1992',
)]
Error code: dmlwriteexception
Stack trace: * line 489 of \lib\dml\moodle_database.php: dml_write_exception thrown
* line 331 of \lib\dml\sqlsrv_native_moodle_database.php: call to moodle_database->query_end()
* line 438 of \lib\dml\sqlsrv_native_moodle_database.php: call to sqlsrv_native_moodle_database->query_end()
* line 1219 of \lib\dml\sqlsrv_native_moodle_database.php: call to sqlsrv_native_moodle_database->do_query()
* line 1251 of \lib\dml\sqlsrv_native_moodle_database.php: call to sqlsrv_native_moodle_database->update_record_raw()
* line 730 of \lib\classes\task\manager.php: call to sqlsrv_native_moodle_database->update_record()
* line 369 of \lib\cronlib.php: call to core\task\manager::adhoc_task_failed()
* line 198 of \lib\cronlib.php: call to cron_run_inner_adhoc_task()
* line 122 of \admin\cli\adhoc_task.php: call to cron_run_adhoc_tasks()


This happened after migrating to a new web server and new database, so I suspect a database configuration setting is to blame.  I've tried purging the caches, deleting the 

moodledata\lock directory, and restarting the database server with no success.  The database reports that there are no locked transactions.  

Any ideas what could be causing the adhoc tasks to freeze, or how to fix it?


Here are details of my environment:

Moodle version: 3.9.21+ (Build: 20230602)

PHP version: 7.4.33

Web server is Windows Server 2022 Standard, running IIS

Database server is Windows Server 2022 Standard, running Microsoft SQL Server 2019


Average of ratings: -
In reply to David Ball

Re: Adhoc task freezes when querying temp table

by Ken Task -
Picture of Particularly helpful Moodlers
Qualifcations for this response ... none, I no longer run Windows (many years now) ... so in just looking at the debug, a brief explanation and suggestion that might get by this:

Check the setting for Recyclebin and set that to the least amount of time to retain - think that's 1 second.

Why?    Anything deleted from a Moodle now a backup (.mbz file) is made of what's being deleted and that is stored as a backup just in case it needs to be restored.   It's retained for X days and eventually moved to mooldedata/trashdir where one can manually remove contents without any ill affect on Moodle.

So if you are sure about what is being deleted, help moodle get rid of it sooner!

'SoS', Ken

Average of ratings: -
In reply to Ken Task

Re: Adhoc task freezes when querying temp table

by David Ball -
Thanks Ken. I changed the "Clean up trash pool files" setting to 1 second and deleted the contents out of moodledata\trashdir. I re-ran the adhoc tasks and unfortunately have the same problem. The last query output by the script is still trying to read from the mdl_backup_ids_temp table. Nothing new showed up in the trashdir though. I'll keep looking through the source code from the stack trace to see if I can find what php line is the last to run.
Average of ratings: -
In reply to Ken Task

Re: Adhoc task freezes when querying temp table

by David Ball -
I also changed the Recycle Bin settings "Item lifetime" and "Course lifetime" to 1 second and re-ran the adhoc tasks. I still got the issue, sadly.
Average of ratings: -
In reply to David Ball

Re: Adhoc task freezes when querying temp table

by Ken Task -
Picture of Particularly helpful Moodlers
Since your's crashed ... does this table:
mdl_backup_ids_temp
exist?    If so, it shouldn't .... it's a temp table.
https://serverfault.com/questions/1057583/dropped-temporary-table-still-exist-on-the-mysql-db

'SoS', Ken

Average of ratings: -
In reply to Ken Task

Re: Adhoc task freezes when querying temp table

by David Ball -
There are three instances of the mdl_backup_ids_temp table in the tempdb database. I assume these were created by the cron task running the adhoc tasks and never finishing. That's why I tried restarting the database service. That wipes out the temporary tables when the service starts back up. But the issue persists even when running with an empty tempdb.
Average of ratings: -
In reply to David Ball

Re: Adhoc task freezes when querying temp table

by David Ball -
Update:
I discovered that there are locks getting created. It looks like the session is getting blocked by a previous query that locks and never finishes (for unknown reasons). The previous query that holds the lock is:
SELECT * FROM #mdl_backup_ids_temp WITH (NOLOCK) WHERE backupid = N'4f1adc4103ed6b8e26c705facbf921a6' AND itemname = N'user'

That gets granted an exclusive lock, even though the query is using the NOLOCK hint. Later, that blocks the final query I was seeing before:
SELECT 'x' FROM #mdl_backup_ids_temp WITH (NOLOCK) WHERE backupid = N'4f1adc4103ed6b8e26c705facbf921a6' AND itemname = N'userfinal' AND itemid = '3' ORDER BY 1 OFFSET 0 ROWS FETCH NEXT 1 ROWS ONLY

That process is waiting for the exclusive lock on the same object as the first query. Again, it's trying to acquire a lock even when using the NOLOCK hint.

Does anyone have any ideas what fix I can pursue from here? There is something that's preventing the first query from finishing, but I'm not sure how to troubleshoot that. I'm also not sure how to prevent the lock from being granted in the first place. It seems like the NOLOCK hint should do that.
Average of ratings: Useful (1)
In reply to David Ball

Re: Adhoc task freezes when querying temp table

by David Ball -
I managed to fix the issue. I don't understand why the exclusive lock was being granted in the first place, but I was able to edit the moodle\backup\util\dbops\backup_structure_dbops.class.php file to release the lock from the first query before starting the second query. In case anyone finds themselves in the same situation and needs this fix, here's what I changed.  Find this code in moodle\backup\util\dbops\backup_structure_dbops.class.php:

        foreach($rs as $annotation) {
            // If corresponding 'itemfinal' annotation does not exist, update 'item' to 'itemfinal'
            if (! $DB->record_exists('backup_ids_temp', array('backupid' => $backupid,
                                                              'itemname' => $itemname . 'final',
                                                              'itemid' => $annotation->itemid))) {
                $DB->set_field('backup_ids_temp', 'itemname', $itemname . 'final', array('id' => $annotation->id));
            }
            $progress->progress();
        }
        $rs->close();

Replace it with this code:


	$annotations = array();
	foreach($rs as $key => $value) {
		$annotations[$key] = clone $v;
	}
	$rs->close();
		
	foreach($annotations as $annotation) {
            // If corresponding 'itemfinal' annotation does not exist, update 'item' to 'itemfinal'
            if (! $DB->record_exists('backup_ids_temp', array('backupid' => $backupid,
                                                              'itemname' => $itemname . 'final',
                                                              'itemid' => $annotation->itemid))) {
                $DB->set_field('backup_ids_temp', 'itemname', $itemname . 'final', array('id' => $annotation->id));
            }
            $progress->progress();
        }

Average of ratings: -
In reply to David Ball

Re: Adhoc task freezes when querying temp table

by David Ball -
Scratch that previous change. It produces PHP errors and breaks other functionality. For example, I could no longer create a copy of a .pdf file on a course page because of a problem with the #mdl_backup_ids_temp table.

My next goal is to prevent the SELECT queries from placing exclusive locks on the #mdl_backup_ids_temp table in the tempdb database. Nothing I've read so far provides any clues how SELECT is creating those locks, or how to stop it from happening.
Average of ratings: -
In reply to David Ball

Re: Adhoc task freezes when querying temp table

by Ken Task -
Picture of Particularly helpful Moodlers
"It produces PHP errors and breaks other functionality"
What are those? Might provide a clue for others!

Also, is there a lock directory in your moodledata directory?
What does it contain?

No temp tables should remain after moodle gets done with them.
You might consider changing the DB user to superuser and DB pass for that superuser.

Set the path to php-cli then go to:
Site administration
Server
Tasks
Scheduled tasks

There should be 'run now' links under the various task in the 'Last Run' column.
In the task list look task related to annotation ... click the 'run now' links

There are, for example,
Delete stale temp files \core\task\file_temp_cleanup_task
Cleanup of temporary records for file conversions \core_files\task\conversion_cleanup_task
That might be related.

There are lots of Cleanup task
'SoS', Ken

Average of ratings: -