Automated backups - Cannot obtain task lock

Automated backups - Cannot obtain task lock

by António Godinho -
Number of replies: 22
We are running a cluster Moodle.
5 Web nodes, 2 HA NFS nodes, and a custer of 3 DB nodes. Locking has been moved into Redis. 
Only one server is running the crontab job, that same that has the volume for backups mounted.

While everything has working ok, the automated backups failed.
Even running by shell fails:
[root@MoodleWeb1 moodle]# sudo -u apache php admin/tool/task/cli/schedule_task.php --execute=\\core\\task\\automated_backup_task
Execute scheduled task: Cópias de segurança automáticas (core\task\automated_backup_task)
Cannot obtain task lock
[root@MoodleWeb1 moodle]#

Any ideas what can be wrong?
Average of ratings: -
In reply to António Godinho

Re: Automated backups - Cannot obtain task lock

by Matteo Scaramuccia -
Picture of Core developers Picture of Peer reviewers Picture of Plugin developers

Ciao António,
please enable Moodle debug at DEVELOPER level: it would be a mis-configured setting which prevents to connect to your Redis.

Please, share here at least your Moodle version and your config.php file, removing all the sensitive data.
Note: the content of that file should be shared/kept aligned among the whole web cluster.

HTH,
Matteo

Average of ratings: -
In reply to Matteo Scaramuccia

Re: Automated backups - Cannot obtain task lock

by António Godinho -
Here's my config:

I'm going to debug now:

unset($CFG);
global $CFG;
$CFG = new stdClass();

$CFG->dbtype    = 'mariadb';
$CFG->dblibrary = 'native';

$CFG->dbhost    = '10.10.10.1';
$CFG->dbname    = 'dbmoodle';
$CFG->dbuser    = 'root';
$CFG->dbpass    = 'pwdb';

$CFG->prefix    = 'mdl_';
$CFG->dboptions = array(
    'dbpersist' => false,
    'dbsocket'  => false,
    'dbport'    => '',
    'dbhandlesoptions' => false,
    'dbcollation' => 'utf8mb4_unicode_ci',
);
$CFG->wwwroot   = 'https://moodle.isec.pt/moodle';
$CFG->dataroot  = '/moodledata';
$CFG->admin     = 'admin';

//$CFG->directorypermissions = 0777;
$CFG->directorypermissions = 02777;

date_default_timezone_set('Europe/London');
$CFG->usezipbackups = false;

$CFG->session_handler_class = '\core\session\redis';
$CFG->session_redis_host = '10.10.10.2';
$CFG->session_redis_port = 6379;
$CFG->session_redis_database = 0;
$CFG->session_redis_auth = 'pwredis';
$CFG->session_redis_prefix = '';
$CFG->session_redis_acquire_lock_timeout = 120;
$CFG->session_redis_lock_expire = 7200;
$CFG->MR_SHORT_NAME = "MoodleCluster";

$CFG->lock_factory = "\core\lock\db_record_lock_factory";

$CFG->apacheloguser = 1;
$CFG->preventfilelocking = true;

require_once(dirname(__FILE__) . '/lib/setup.php');

// There is no php closing tag in this file,
// it is intentional because it prevents trailing whitespace problems!
Average of ratings: -
In reply to António Godinho

Re: Automated backups - Cannot obtain task lock

by Matteo Scaramuccia -
Picture of Core developers Picture of Peer reviewers Picture of Plugin developers

Hi António,

$CFG->MR_SHORT_NAME = "MoodleCluster";
[...]
$CFG->lock_factory = "\core\lock\db_record_lock_factory";

I'm a bit confused: if you want to use https://github.com/blackboard-open-source/moodle-local_redislock you need to set $CFG->lock_factory to '\\local_redislock\\lock\\redis_lock_factory'.
Please, note the double backslash (escaping the "escape")!

HTH,
Matteo

Average of ratings: -
In reply to Matteo Scaramuccia

Re: Automated backups - Cannot obtain task lock

by António Godinho -
Ok hope that got fixed.
This was added:
$CFG->local_redislock_redis_server = '10.10.10.2';
$CFG->lock_factory = '\\local_redislock\\lock\\redis_lock_factory';

Also removed the password from Redis to simplifly things... Again got stuck outside... Have no idea where the store is defined...
I can enter Moodle, even after restart httpd and php-fpm...

PHP-FPM log:
[03-May-2020 16:23:58 Europe/Lisbon] Cannot obtain session lock for sid: 81epvb4u2rcho63r13qp4ifg36 within 120. It is likely another page has a long session lock, or the session lock was never released.
[03-May-2020 16:23:58 Europe/Lisbon] Default exception handler: error/Unable to obtain session lock Debug:
Error code: Unable to obtain session lock
$a contents:
* line 366 of /lib/classes/session/redis.php: core\session\exception thrown
* line 258 of /lib/classes/session/redis.php: call to core\session\redis->lock_session()
* line ? of unknownfile: call to core\session\redis->handler_read()
* line 42 of /lib/classes/session/handler.php: call to session_start()
* line 124 of /lib/classes/session/redis.php: call to core\session\handler->start()
* line 90 of /lib/classes/session/manager.php: call to core\session\redis->start()
* line 794 of /lib/setup.php: call to core\session\manager::start()
* line 60 of /config.php: call to require_once()
* line 30 of /index.php: call to require_once()
Average of ratings: -
In reply to António Godinho

Re: Automated backups - Cannot obtain task lock

by António Godinho -
Ok it's working, well kinda, it says that automated backup are already running...


[root@MoodleWeb1 moodle]# sudo -u apache php admin/tool/task/cli/schedule_task.php --execute=\\core\\task\\automated_backup_task
Execute scheduled task: Cópias de segurança automáticas (core\task\automated_backup_task)
Redis lock; pid=3713; Waiting to get MoodleCluster_cron_core_cron lock
Redis lock; pid=3713; Obtained MoodleCluster_cron_core_cron lock with value hostname=MoodleWeb1&processid=3713
Redis lock; pid=3713; Waiting to get MoodleCluster_cron_\core\task\automated_backup_task lock
Redis lock; pid=3713; Obtained MoodleCluster_cron_\core\task\automated_backup_task lock with value hostname=MoodleWeb1&processid=3713
Redis lock; pid=3713; Released MoodleCluster_cron_core_cron lock
Checking automated backup status...RUNNING
automated backup are already running. Execution delayed
... used 1 dbqueries
... used 0.097186088562012 seconds
Scheduled task complete: Cópias de segurança automáticas (core\task\automated_backup_task)
Redis lock; pid=3713; Released MoodleCluster_cron_\core\task\automated_backup_task lock
Redis lock; pid=3713; Auto-release called, releasing 0 locks
[root@MoodleWeb1 moodle]#
Average of ratings: -
In reply to António Godinho

Re: Automated backups - Cannot obtain task lock

by Matteo Scaramuccia -
Picture of Core developers Picture of Peer reviewers Picture of Plugin developers

Hi António,

[03-May-2020 16:23:58 Europe/Lisbon] Cannot obtain session lock for sid: 81epvb4u2rcho63r13qp4ifg36 within 120. It is likely another page has a long session lock, or the session lock was never released.
03-May-2020 16:23:58 Europe/Lisbon] Default exception handler: error/Unable to obtain session lock Debug:
Error code: Unable to obtain session lock

that's because of $CFG->session_handler_class = '\core\session\redis'; is missing the doubled \.

Guessing you've already fixed that cool.

HTH,
Matteo

Average of ratings: -
In reply to Matteo Scaramuccia

Re: Automated backups - Cannot obtain task lock

by António Godinho -
I thought that everything was ok, but I've a huge problem now.
I thought I was missing some system package to sent emails, but this is failing because of something else.

The tasks running via cron are giving me this, on this case the \mod_forum\task\cron_task:
Execute scheduled task: Forum mailings and maintenance jobs (mod_forum\task\cron_task)
Redis lock; pid=5991; Waiting to get MoodleCluster_cron_core_cron lock
Redis lock; pid=5991; Obtained MoodleCluster_cron_core_cron lock with value hostname=MoodleWeb1&processid=5991
Redis lock; pid=5991; Waiting to get MoodleCluster_cron_\mod_forum\task\cron_task lock
Redis lock; pid=5991; Lock timeout, did not obtain MoodleCluster_cron_\mod_forum\task\cron_task lock
Redis lock; pid=5991; Released MoodleCluster_cron_core_cron lock
Cannot obtain task lock

And no crons are running:
[root@MoodleWeb1 php-fpm]# ps -edafl | grep cron
4 S root 2767 1 0 80 0 - 61470 hrtime 11:10 ? 00:00:00 /usr/sbin/crond -n
0 S root 7262 5935 0 80 0 - 55475 - 15:03 pts/2 00:00:00 grep --color=auto cron

What I'm missing here?
Average of ratings: -
In reply to António Godinho

Re: Automated backups - Cannot obtain task lock

by Alain Raap -
Picture of Particularly helpful Moodlers

Hi Antonio, just a tip to see what's happening with Redis, start 'redis-cli MONITOR' and you can see what's happening inside Redis.
Another issue I had with the automated backup when it was already running, I got the same error (RUNNING). My solution, I truncated the mdl_backup_controllers table (a tip I saw in the backup forum). 

Have you also checked the cron log of your Linux system? There you can see if your scheduled jobs are running as expected.

Average of ratings: -
In reply to Alain Raap

Re: Automated backups - Cannot obtain task lock

by António Godinho -
You are right!
I also had to clean my readis with:
redis-cli FLUSHDB
redis-cli -n DB_NUMBER FLUSHDB
redis-cli -n DB_NUMBER FLUSHDB ASYNC
redis-cli FLUSHALL
redis-cli FLUSHALL ASYNC

I've change my cron from running every minutes to:

*/30 * * * * /usr/bin/php /var/www/moodle/admin/cli/cron.php >> /var/log/moodle_cron.log
*/5 * * * * /usr/bin/php /var/www/moodle/admin/tool/task/cli/schedule_task.php --execute="\mod_forum\task\cron_task" >> /var/log/moodle_cron.log
Average of ratings: -
In reply to António Godinho

Re: Automated backups - Cannot obtain task lock

by Alain Raap -
Picture of Particularly helpful Moodlers
Is cron running without problems now? And your automated backup task?

I also had the lock problem some time ago and that was because several cron processes
of Moodle hanged (state ‘D’) . After I killed these processes, the problem was solved.
Average of ratings: -
In reply to Matteo Scaramuccia

Re: Automated backups - Cannot obtain task lock

by António Godinho -
Now I'm locked on the outside....

[root@MoodleWeb1 moodle]# redis-cli -h 10.10.10.2 -a "pwredis" ping
Warning: Using a password with '-a' or '-u' option on the command line interface may not be safe.
PONG
[root@MoodleWeb1 moodle]#

But when I try to enter moodle via browser, it takes for ever until it fails with: Gateway Timeout.

php-fpm gives this error:
[03-May-2020 10:40:17 Europe/Lisbon] Cannot obtain session lock for sid: 2vlkgthakdojlonb6t8mcgopvb within 120. It is likely another page has a long session lock, or the session lock was never released.
[03-May-2020 10:40:17 Europe/Lisbon] Default exception handler: error/Unable to obtain session lock Debug:
Error code: Unable to obtain session lock
$a contents:
* line 366 of /lib/classes/session/redis.php: core\session\exception thrown
* line 258 of /lib/classes/session/redis.php: call to core\session\redis->lock_session()
* line ? of unknownfile: call to core\session\redis->handler_read()
* line 42 of /lib/classes/session/handler.php: call to session_start()
* line 124 of /lib/classes/session/redis.php: call to core\session\handler->start()
* line 90 of /lib/classes/session/manager.php: call to core\session\redis->start()
* line 794 of /lib/setup.php: call to core\session\manager::start()
* line 56 of /config.php: call to require_once()
* line 30 of /index.php: call to require_once()

Average of ratings: -
In reply to Matteo Scaramuccia

Re: Automated backups - Cannot obtain task lock

by António Godinho -
And I also can't find with the caching store settings are stored, this happend when I change it over the admin page...
It's stored on the database?
Average of ratings: -
In reply to António Godinho

Re: Automated backups - Cannot obtain task lock

by António Godinho -
I've restarted the redis server, and the httpd, php-fpm.
Also edited the Database to match all settings. SELECT * FROM `mdl_config_plugins` Where plugin Like '%cache%' ORDER BY `mdl_config_plugins`.`plugin` ASC

Everything is working OK. But I'm back to my original problem smile
Average of ratings: -
In reply to António Godinho

Re: Automated backups - Cannot obtain task lock

by Howard Miller -
Picture of Core developers Picture of Documentation writers Picture of Particularly helpful Moodlers Picture of Peer reviewers Picture of Plugin developers
Running on the command line when other cron jobs are running can cause that even if everything is ok. That probably isn't your problem.

Make sure that Cron is stopped and all tasks have completed before you do a test run from the command line.
Average of ratings: -
In reply to Howard Miller

Re: Automated backups - Cannot obtain task lock

by António Godinho -
Cron is stoped.
I've tryed other task and it works.

[root@MoodleWeb1 moodle]# sudo -u apache php admin/tool/task/cli/schedule_task.php --execute=\\core\\task\\task_log_cleanup_task --showdebugging
Execute scheduled task: Limpeza de registos da tarefa (core\task\task_log_cleanup_task)
... used 15 dbqueries
... used 0.048033952713013 seconds
Scheduled task complete: Limpeza de registos da tarefa (core\task\task_log_cleanup_task)
[root@MoodleWeb1 moodle]# sudo -u apache php admin/tool/task/cli/schedule_task.php --execute=\\block_recent_activity\\task\\cleanup --showdebugging
Execute scheduled task: Tarefa de limpeza do bloco Atividade recente (block_recent_activity\task\cleanup)
... used 8 dbqueries
... used 0.048834085464478 seconds
Scheduled task complete: Tarefa de limpeza do bloco Atividade recente (block_recent_activity\task\cleanup)
[root@MoodleWeb1 moodle]# sudo -u apache php admin/tool/task/cli/schedule_task.php --execute=\\core\\task\\automated_backup_task --showdebugging
Execute scheduled task: Cópias de segurança automáticas (core\task\automated_backup_task)
Cannot obtain task lock
[root@MoodleWeb1 moodle]#

Debug doesn't provide any more info... Any more ideas?
Average of ratings: -
In reply to António Godinho

Re: Automated backups - Cannot obtain task lock

by Howard Miller -
Picture of Core developers Picture of Documentation writers Picture of Particularly helpful Moodlers Picture of Peer reviewers Picture of Plugin developers
So you're saying that you confirmed that no other tasks where running after Cron stopped (it's possible that you have some long-running task hanging around)?
Average of ratings: -
In reply to Howard Miller

Re: Automated backups - Cannot obtain task lock

by António Godinho -
I've stoped cron, httpd and php-fpm. I have no httpd or php processes running.
MySQL show processlist, doesn't show anything moodle releated.

Can something be stuck on the database?
Is there anything on moodledata dir that I can clear?
All 5 nodes share /moodledada dir via NFS. Is there something that should be local?

Other thing, this is a new server I've changed the backups dir to the new. I've made a php file to write a file and works. It seams that apache has all the permissions required.
Average of ratings: -
In reply to António Godinho

Re: Automated backups - Cannot obtain task lock

by Howard Miller -
Picture of Core developers Picture of Documentation writers Picture of Particularly helpful Moodlers Picture of Peer reviewers Picture of Plugin developers
You're probably quite right - I've just been down a blind alley myself diagnosing cron problems.
Average of ratings: -
In reply to António Godinho

Re: Automated backups - Cannot obtain task lock

by Alain Raap -
Picture of Particularly helpful Moodlers
Hi Antonio,

I hope this problem is already solved and that your automated backup runs ok now. I've had the same problem with another task in the Moodle cron that didn't work anymore and with debugging I got the same error. This error was caused by some Moodle cron php processes that hadn't finished and were freezed in state 'D'. After I had killed these processes the specific cron task that had failed was running without problem again. You can check your cron processes with 'ps -edafl | grep cron'. Every minute (the usual interval for Moodle cron) you can see the tasks that are running, usually with your user of the apache server. Another way to find problems with the Moodle cron tasks is to (temporary) log the output of your cron process in the Linux crontab to a file. Instead of using '> /dev/null' use '>> /var/log/moodle_cron.log'
Average of ratings: -
In reply to Alain Raap

Re: Automated backups - Cannot obtain task lock

by António Godinho -

There's allways something else...


Backing up Mecânica dos Solos (908921)...
PHP Warning:  mysqli::query(): MySQL server has gone away in /var/www/moodle/lib/dml/mysqli_native_moodle_database.php on line 1246
PHP Warning:  mysqli::query(): Error reading result set's header in /var/www/moodle/lib/dml/mysqli_native_moodle_database.php on line 1246
... used 41974 dbqueries
... used 391.87420105934 seconds
Scheduled task failed: Automated backups (core\task\automated_backup_task),Error reading from database (MySQL server has gone away
SELECT * FROM mdl_backup_courses WHERE courseid = ?
[array (
  0 => '7868',
)])
Debug info:
MySQL server has gone away
SELECT * FROM mdl_backup_courses WHERE courseid = ?
[array (
  0 => '7868',
)]
Backtrace:
* line 1247 of /lib/dml/mysqli_native_moodle_database.php: call to moodle_database->query_end()
* line 1587 of /lib/dml/moodle_database.php: call to mysqli_native_moodle_database->get_records_sql()
* line 1559 of /lib/dml/moodle_database.php: call to moodle_database->get_record_sql()
* line 1538 of /lib/dml/moodle_database.php: call to moodle_database->get_record_select()
* line 132 of /backup/util/helper/backup_cron_helper.class.php: call to moodle_database->get_record()
* line 50 of /lib/classes/task/automated_backup_task.php: call to backup_cron_automated_helper::run_automated_backup()
* line 157 of /admin/tool/task/cli/schedule_task.php: call to core\task\automated_backup_task->execute()
Default exception handler: Table "task_scheduled" does not exist Debug:
Error code: ddltablenotexist
* line 665 of /lib/dml/moodle_database.php: dml_exception thrown
* line 1537 of /lib/dml/moodle_database.php: call to moodle_database->where_clause()
* line 682 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()
!!! Table "task_scheduled" does not exist !!!
Debug info:
Error code: ddltablenotexist
Stack trace: * line 665 of /lib/dml/moodle_database.php: dml_exception thrown
* line 1537 of /lib/dml/moodle_database.php: call to moodle_database->where_clause()
* line 682 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()
Exception ignored in shutdown function Closure::__invoke: Table "task_log" does not exist
Redis lock; pid=6386; Auto-release called, releasing 1 locks
Redis lock; pid=6386; Released MoodleCluster_cron_\core\task\automated_backup_task lock
Exception ignored in shutdown function tool_log\log\manager::dispose: Error reading from database (MySQL server has gone away
SHOW VARIABLES LIKE 'max_allowed_packet'
[NULL])
[root@MoodleWeb1 moodle]#


My Galera right now has:


MariaDB [(none)]> Select @@global.max_allowed_packet;
+-----------------------------+
| @@global.max_allowed_packet |
+-----------------------------+
|                   524288000 |
+-----------------------------+
1 row in set (0.000 sec)
MariaDB [(none)]> select @max_allowed_packet;
+---------------------+
| @max_allowed_packet |
+---------------------+
| NULL                |
+---------------------+
1 row in set (0.000 sec)
MariaDB [(none)]>


Any advice?





Average of ratings: -
In reply to António Godinho

Re: Automated backups - Cannot obtain task lock

by Alain Raap -
Picture of Particularly helpful Moodlers
I see this error in your log "!!! Table "task_scheduled" does not exist !!!", there should be a table mdl_task_scheduled in your Moodle database. Can you check your table list in mysql ('show tables' in your database)? Did the automated backup task work? Were there made any backups?
Average of ratings: -
In reply to Alain Raap

Re: Automated backups - Cannot obtain task lock

by António Godinho -
I think the issue is releated to this: MySQL server has gone away
From what I see I have to increase max_allowed_packet again. Maybe I also need to restart the service, I'll do it later at night.
Average of ratings: -