Moodle in English: One scheduled task successfully completing but closing/unlocking failing

One scheduled task successfully completing but closing/unlocking failing

by Steve Howes - Thursday, November 7, 2019, 7:39 PM

So apologies if it is the wrong place.

We have a Scheduled tasks that was running up to about this time last week. We have been able to run it successfully from the command line and it completes but we are seeing errors related to not being to unlock the task. Any thoughts on where to start diagnosing the exact problem and resolving it.

We are on Moodle 3.7.1+ (Build: 20190725)

error output from task

used 1399254 dbqueries
... used 3693.0848801136 seconds
Scheduled task complete: assessmentgrades (local_assessmentgrades\\task\\assessmentgrades)
',
)]
Backtrace:
* line 1329 of /lib/dml/mysqli_native_moodle_database.php: call to moodle_database->query_end()
* line 1375 of /lib/dml/mysqli_native_moodle_database.php: call to mysqli_native_moodle_database->insert_record_raw()
* line 84 of /lib/classes/task/database_logger.php: call to mysqli_native_moodle_database->insert_record()
* line 299 of /lib/classes/task/logmanager.php: call to core\task\database_logger::store_log_for_task()
* line 718 of /lib/classes/task/manager.php: call to core\task\logmanager::finalise_log()
* line 163 of /admin/tool/task/cli/schedule_task.php: call to core\task\manager::scheduled_task_complete()

Default exception handler: Error reading from database Debug: MySQL server has gone away
SELECT * FROM mdl_task_scheduled WHERE classname = ?
[array (
0 => '\\local_assessmentgrades\\task\\assessmentgrades',
)]

Re: One scheduled task successfully completing but closing/unlocking failing

by Ken Task - Thursday, November 7, 2019, 8:32 PM

"MySQL server has gone away"

https://dev.mysql.com/doc/refman/5.7/en/gone-away.html
Increase max_allowed_packet variable in config of MySQL

Default for 5.7 is 16M. Set to 32M.
Restart mysqld (db service).

'SoS', Ken

Average of ratings:Useful (1)

Re: One scheduled task successfully completing but closing/unlocking failing

by Steve Howes - Saturday, November 9, 2019, 12:33 AM

Thank you Ken for your quick reply unfortunately that didn't work. The fully errors after completing are

used 888385 dbqueries
... used 2496.9658410549 seconds
Scheduled task complete: assessmentgrades (local_assessmentgrades\\task\\assessmentgrades)
',
)]
Backtrace:
* line 1329 of /lib/dml/mysqli_native_moodle_database.php: call to moodle_database->query_end()
* line 1375 of /lib/dml/mysqli_native_moodle_database.php: call to mysqli_native_moodle_database->insert_record_raw()
* line 84 of /lib/classes/task/database_logger.php: call to mysqli_native_moodle_database->insert_record()
* line 299 of /lib/classes/task/logmanager.php: call to core\task\database_logger::store_log_for_task()
* line 718 of /lib/classes/task/manager.php: call to core\task\logmanager::finalise_log()
* line 163 of /admin/tool/task/cli/schedule_task.php: call to core\task\manager::scheduled_task_complete()

Default exception handler: Error reading from database Debug: MySQL server has gone away
SELECT * FROM mdl_task_scheduled WHERE classname = ?
[array (
  0 => '\\local_assessmentgrades\\task\\assessmentgrades',
)]
Error code: dmlreadexception
* line 486 of /lib/dml/moodle_database.php: dml_read_exception thrown
* line 1245 of /lib/dml/mysqli_native_moodle_database.php: call to moodle_database->query_end()
* line 1571 of /lib/dml/moodle_database.php: call to mysqli_native_moodle_database->get_records_sql()
* line 1543 of /lib/dml/moodle_database.php: call to moodle_database->get_record_sql()
* line 1522 of /lib/dml/moodle_database.php: call to moodle_database->get_record_select()
* line 678 of /lib/classes/task/manager.php: call to moodle_database->get_record()
* line 181 of /admin/tool/task/cli/schedule_task.php: call to core\task\manager::scheduled_task_failed()

!!! Error reading from database !!!

Debug info: MySQL server has gone away
SELECT * FROM mdl_task_scheduled WHERE classname = ?
[array (
  0 => '\\local_assessmentgrades\\task\\assessmentgrades',
)]
Error code: dmlreadexception
Stack trace: * line 486 of /lib/dml/moodle_database.php: dml_read_exception thrown
* line 1245 of /lib/dml/mysqli_native_moodle_database.php: call to moodle_database->query_end()
* line 1571 of /lib/dml/moodle_database.php: call to mysqli_native_moodle_database->get_records_sql()
* line 1543 of /lib/dml/moodle_database.php: call to moodle_database->get_record_sql()
* line 1522 of /lib/dml/moodle_database.php: call to moodle_database->get_record_select()
* line 678 of /lib/classes/task/manager.php: call to moodle_database->get_record()
* line 181 of /admin/tool/task/cli/schedule_task.php: call to core\task\manager::scheduled_task_failed()
PHP Fatal error:  Uncaught coding_exception: Coding error detected, it must be fixed by a programmer: A lock was created but not released at:
/var/www/html/moodle/admin/tool/task/cli/schedule_task.php on line 142

 Code should look like:

 $factory = \core\lock\lock_config::get_lock_factory('type');
 $lock = $factory->get_lock(Resource id #656);
 $lock->release();  // Locks must ALWAYS be released like this.

 in /var/www/html/moodle/lib/classes/lock/lock.php:117
Stack trace:
#0 [internal function]: core\lock\lock->__destruct()
#1 {main}
  thrown in /var/www/html/moodle/lib/classes/lock/lock.php on line 117

Also we are running this task from the command-line but if we try to run it from within the browser (Scheduled Task -> Run Now) it is not completing and just fails/stops mid process so we never get to see a log.

As far as we are aware this has been ruining successfully with no errors for months, only i the last week has it failed.

Any help/thoughts, from anyone, would be very appreciated.

Thanks.

Average of ratings: -

Re: One scheduled task successfully completing but closing/unlocking failing

by Ken Task - Saturday, November 9, 2019, 1:31 AM

"A lock was created but not released at:
/var/www/html/moodle/admin/tool/task/cli/schedule_task.php on line 142"

Locks prevent other processes from running on same stuff if there is a process working with something.

Look in moodledata/lock/

owerships/permissions on all/any you see in there.

Safe to manually remove.

'SoS', Ken

Average of ratings:Useful (1)

Re: One scheduled task successfully completing but closing/unlocking failing

by David Mudrák - Saturday, November 9, 2019, 2:13 PM

I would recommend to focus on the "MySQL server has gone away" issue - that is the problem here. Although this particular one can have many possible reasons, if I remember correctly.

I believe the message about the locks ("A lock was created but not released") is just a consequence of this unexpected MySQL connection termination.

Average of ratings:Useful (1)

Re: One scheduled task successfully completing but closing/unlocking failing

by Ken Task - Saturday, November 9, 2019, 9:38 PM

Agree with David ... but a question ...

Do you have a custom local plugin ... local_assessmentgrades?

mysql> select classname from mdl_task_scheduled where classname like '%local%';

'SoS', Ken

Average of ratings:Useful (1)

Re: One scheduled task successfully completing but closing/unlocking failing

by Richard Oelmann - Monday, November 11, 2019, 4:45 PM

Hi Ken,
Yes, there is a custom local scheduled task local_assessmentgrades, which was running fine until this happened (and has been for over a year). It's part of a group of scheduled tasks which work to integrate Moodle and the university's data-warehouse and Student Record system.

Unfortunately the fault happened 10 days or so after I have left the university, so while I'm trying to help Steve over text, I'm no longer there to look at it directly

@Steve, I'd recommend enlisting some help to look at the settings on both the web-server and database server to see what may have changed in any summer server upgrade (eg php/mysql being upgraded) and whether all the settings were properly migrated (e.g. do a side by side comparison of the my.cnf).

This may have run smoothly up until the end of October and only hit a problem with the quantity of data following the early set of assessments hitting the 20 working days mark and so being processed by the task and then the quantity of data causing a time out in accessing the database and hence the 'gone away' message, if some of those php/mysql settings were not properly transferred.

https://stackoverflow.com/questions/7942154/mysql-error-2006-mysql-server-has-gone-away

Average of ratings: -

Re: One scheduled task successfully completing but closing/unlocking failing

by Steve Howes - Tuesday, December 3, 2019, 10:54 PM

Thanks to everyone who replied, it turned out that this was the resolution; it was initially hidden by the fact we had increased debugging output to try and track down the exact point of failure but in doing so had only increased again the needed packet size. Once we removed the extra outputs the task ran and completed successfully with cleanup and removing the lock.

Thanks.

Average of ratings: -

General developer forum

One scheduled task successfully completing but closing/unlocking failing