Unstoppable automated backups in 3.5

Unstoppable automated backups in 3.5

by Mike Kelly -
Number of replies: 5

I'm running into a weird issue on two older Moodle 3.5 installs (I know - upgrades are pending), wherein the moodledata/temp/backups folder grows abnormally large very quickly (hundreds of gigs overnight), and Moodle doesn't appear to be cleaning up after itself. Cron appears to be running normally on each server.

The backups were originally configured as automated - however after this problem started happening, I switched them to manual so I could capture a log of what was happening during the backup process. But here's the weird part: despite the backups being configured as manual (and not configured to run via the OS cron until tomorrow), a full restart of both the webserver and PHP backends, *and* me disabling the automated backups task in scheduled tasks ... Moodle still appears to be running the scheduled backup task. Now.

Has anyone seen anything like this before? I'm thinking that there's an outstanding backup job still scheduled that Moodle is trying to complete. Any thoughts as to where I could look in the database to confirm and/or disable this?

The mdl_task_scheduled table does show the automated backup task as disabled:

+----+------------------------------+------------------------------------------------------+-------------+-------------+----------+--------+------+-----+-------+-----------+-----------+------------+----------+

| id | component                    | classname                                            | lastruntime | nextruntime | blocking | minute | hour | day | month | dayofweek | faildelay | customised | disabled |

+----+------------------------------+------------------------------------------------------+-------------+-------------+----------+--------+------+-----+-------+-----------+-----------+------------+----------+

| 24 | moodle                       | \core\task\automated_backup_task                     |  1601034679 |  1601038200 |        0 | 50     | *    | *   | *     | *         |         0 |          1 |        1 |

Average of ratings: -
In reply to Mike Kelly

Re: Unstoppable automated backups in 3.5

by Ken Task -
Picture of Particularly helpful Moodlers

Check what's in moodledata/temp/backup/ and also in trashdir

Then ... what happens if ...

cd code//admin/tool/task/cli/

Create a bash shell script called 'cleanup' which contains

php schedule_task.php --execute="\core\task\backup_cleanup_task";
php schedule_task.php --execute="\core\task\file_temp_cleanup_task";
php schedule_task.php --execute="\tool_recyclebin\task\cleanup_category_bin";
php schedule_task.php --execute="\tool_recyclebin\task\cleanup_course_bin";

then check moodledata/temp/backup/ and moodledata/trashdir/

Above won't fix ... more exploring what's there and might lead to other discoveries! smile

'SoS', Ken

Average of ratings: -
In reply to Ken Task

Re: Unstoppable automated backups in 3.5

by Mike Kelly -
Hi Ken,

Definitely some discoveries. I love the "MySQL server has gone away" phrasing wink The db server is still there and responding to requests, but obviously something's not right with its responses, as far as Moodle is concerned.

After running the tasks, the temp/backups dir is still quite large - there were 260 gigs in there before and 259 afterwards. The trashdir also don't show much in the way of change.

I'll test it on the 2nd affected machine later this afternoon, but I expect I'll probably see similar results.

Execute scheduled task: Clean backup tables and logs (core\task\backup_cleanup_task)
... used 2 dbqueries
... used 10.85179400444 seconds
Scheduled task complete: Clean backup tables and logs (core\task\backup_cleanup_task)
Execute scheduled task: Delete stale temp files (core\task\file_temp_cleanup_task)
... used 0 dbqueries
... used 33.5936460495 seconds
Scheduled task complete: Delete stale temp files (core\task\file_temp_cleanup_task)
... used 1 dbqueries
... used 33.594274997711 seconds
Scheduled task failed: Delete stale temp files (core\task\file_temp_cleanup_task),Error reading from database
Debug info:
MySQL server has gone away
SELECT * FROM mdl_task_scheduled WHERE classname = ?
[array (
0 => '\\core\\task\\file_temp_cleanup_task',
)]
Backtrace:
* 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 674 of /lib/classes/task/manager.php: call to moodle_database->get_record()
* line 162 of /admin/tool/task/cli/schedule_task.php: call to core\task\manager::scheduled_task_complete()

!!! Error reading from database !!!

Debug info: MySQL server has gone away
SELECT * FROM mdl_task_scheduled WHERE classname = ?
[array (
0 => '\\core\\task\\file_temp_cleanup_task',
)]
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 637 of /lib/classes/task/manager.php: call to moodle_database->get_record()
* line 180 of /admin/tool/task/cli/schedule_task.php: call to core\task\manager::scheduled_task_failed()
Execute scheduled task: Cleanup category recycle bin (tool_recyclebin\task\cleanup_category_bin)
... used 1 dbqueries
... used 0.015813827514648 seconds
Scheduled task complete: Cleanup category recycle bin (tool_recyclebin\task\cleanup_category_bin)
Execute scheduled task: Cleanup course recycle bin (tool_recyclebin\task\cleanup_course_bin)
... used 1 dbqueries
... used 0.01140308380127 seconds
Scheduled task complete: Cleanup course recycle bin (tool_recyclebin\task\cleanup_course_bin)
Average of ratings: -
In reply to Mike Kelly

Re: Unstoppable automated backups in 3.5

by Ken Task -
Picture of Particularly helpful Moodlers

MySQL Server has gone away .... too much data in a chunk.

max_allowed_packet needs to be increased in my.cnf config for DB server.

Query:
mysql> show variables like 'max_allowed_packet';

https://dev.mysql.com/doc/refman/5.7/en/program-variables.html

Think default is 8M (I think) ... wouldn't hurt for your server to set to 16M - higher if you continue to get 'gone away'.

trashdir ... you can manually remove contents ... no adverse affects

Delete stale temp files (core\task\file_temp_cleanup_task)

Whats in moodledata/temp/backup/

Successful backups leave 0 byte log files.
Any .log file larger than 0 bytes indicates a failed backup for some reason.
Unfortunately, the .log files aren't really that helpful in discovering why
as they show only at what point in the 'plan' (a number) it failed.

** But, if there are a bunch of directories by hash names, those are what moodle was using to build a backup file.

Some could actually have 'backup.mbz' files in them ... which means the backup was success but the process failed at the last step - copying the .mbz file to destination.

Anyhoo ... everything in moodledata/temp/backup/ could be manually removed.

Suggest it's time for you to install and run MySQLTuner.   Will help with DB server config.

https://github.com/major/MySQLTuner-perl

For info about Tuner ...

https://www.linode.com/docs/databases/mysql/how-to-optimize-mysql-performance-using-mysqltuner/

There are also some command line only scripts in moodlecode/admin/cli/ that help with DB for Moodle ... all begin with mysql_ and all have 'help' screens as defaults when called via php mysql_scriptname.php

'SoS', Ken

Average of ratings: -
In reply to Ken Task

Re: Unstoppable automated backups in 3.5

by Mike Kelly -
Hi Ken,

Thanks for the tips. max_allowed_packet is already set to 16M. Will try bumping it up higher. I've run MySQLTuner in the past but it's been awhile so we'll give it another shot.

Lots of log files in moodledata/temp/backup/ that are > 0 bytes. As you said, they don't really give me much info (see below).

Also a fair number of hashed directories in there, with backup.mbz and the standard selection of .xml files that backups are composed of.

[Sat 26 Sep 2020 13:39:43 PDT] [info] instantiating backup controller e0570c3e9c69c1a57999cf843b7018a3
[Sat 26 Sep 2020 13:39:43 PDT] [debug] setting controller status to 100
[Sat 26 Sep 2020 13:39:43 PDT] [debug] loading controller plan
[Sat 26 Sep 2020 13:39:43 PDT] [debug] setting controller status to 300
[Sat 26 Sep 2020 13:39:43 PDT] [debug] applying plan defaults
[Sat 26 Sep 2020 13:39:43 PDT] [debug] setting controller status to 400
[Sat 26 Sep 2020 13:39:43 PDT] [debug] setting file inclusion to 1
[Sat 26 Sep 2020 13:39:43 PDT] [info] checking plan security
[Sat 26 Sep 2020 13:39:43 PDT] [debug] setting controller status to 700
[Sat 26 Sep 2020 13:39:43 PDT] [debug] saving controller to db
[Sat 26 Sep 2020 13:39:43 PDT] [debug] calculating controller checksum 02f716732c1c02c6456f0b5b3a5a82bc
[Sat 26 Sep 2020 13:39:43 PDT] [debug] loading controller from db
[Sat 26 Sep 2020 13:39:43 PDT] [debug] setting controller status to 800

I'll start with a re-run of Tuner and a bump of the max_allowed_packet, and will see where that gets me. Thanks for the tip re: the scripts in admin/cli/.

For the short term, I've set up a cron job to run tmpreaper (super-handy!) against the moodledata/temp/backups directory and prune anything out that's older than 3 hours, while not breaking backups-in-progress - that should keep the directory size under control while I sort this out.

Regards,
-- Mike K
Average of ratings: -
In reply to Mike Kelly

Re: Unstoppable automated backups in 3.5

by Ken Task -
Picture of Particularly helpful Moodlers

I run Tuner on a regular basis.   Tweaks have been needed from time to time ... and always upwards on sites that are used.

In the hashed directories that have backup.mbz files ... change into one and

head -n 40 moodle_backup.xml

That will show course name and ID.   Go visit the course via Web.

Also what is destination for autobackups?  Back info moodledata/filedir/ is default.   I prefer those go to a designated directory manually created where I can count 'em and see 'em without having to mess with a DB query to see where they are in the maze or filedir.

If you have a designated directory ... is that an SSD device or a mount point to NFS or what?   Could be a bottleneck.

No science to this issue ... just a lot of investigation ... scratching head ... trying something ... sad

'SoS', Ken

Average of ratings: -