Backups stall at restart after xxx seconds

  • I use BackWPup on several charity sites I look after. On just one of them I see messages like ‘Restart after xxx seconds’ and then nothing happens unless I do something at the site in which case the backup continues to run until the next ‘Restart after xxx seconds’. The problem is that when we run the backups at 1am, there is no site activity so backups stop running.

    You will see from our site details…

    WordPress version: 4.9.8
    BackWPup version: 3.6.6
    PHP version: 7.0.32 (64bit)
    MySQL version: 10.1.27-MariaDB
    cURL version: 7.19.7
    cURL SSL version: NSS/3.27.1
    WP-Cron url: https://www.cyclehayling.org.uk/wp-cron.php
    Server self connect: Not expected HTTP response: cURL error 56: Failure when receiving data from the peer
    Document root: ********
    Temp folder: ********
    Log folder: ********
    Server: Apache/2.4.34 (Unix)
    Operating System: Linux
    PHP SAPI: cgi-fcgi
    Current PHP user: cyclehayling.org.uk
    Maximum execution time: 300 seconds
    BackWPup maximum script execution time: 120 seconds
    Alternative WP Cron: On
    Disabled WP Cron: Off
    CHMOD Dir: 0755
    Server Time: 17:11
    Blog Time: 17:11
    Blog Timezone:
    Blog Time offset: 0 hours
    Blog language: en-GB
    MySQL Client encoding: utf8
    PHP Memory limit: 512M
    WP memory limit: 256M
    WP maximum memory limit: 512M
    Memory in use: 36.00 MB
    Loaded PHP Extensions:: Core, PDO, PDO_ODBC, Phar, Reflection, SPL, SimpleXML, Zend OPcache, bcmath, bz2, calendar, cgi-fcgi, ctype, curl, date, dba, dom, enchant, exif, fileinfo, filter, ftp, gd, gettext, gmp, hash, iconv, imap, intl, ionCube Loader, json, ldap, libxml, mbstring, mcrypt, mysqli, mysqlnd, odbc, openssl, pcntl, pcre, pdo_dblib, pdo_mysql, pdo_pgsql, pdo_sqlite, pgsql, posix, pspell, readline, recode, session, shmop, soap, sockets, sqlite3, standard, sysvmsg, sysvsem, sysvshm, tidy, tokenizer, wddx, xml, xmlreader, xmlrpc, xmlwriter, xsl, zip, zlib

    … that there is an issue with wp-cron. We start backups through a URL generated by an external server. With the alternate wp-cron option there is no problem starting backups. They just don’t finish.

    We did have ‘Reduce server load’ activated and I thought it might have been the source of the ‘Restart after xxx seconds’ messages, but I disabled the option and the messages still appear.

    Here’s a sample log…

    [INFO] BackWPup 3.6.6; A project of Inpsyde GmbH
    [INFO] WordPress 4.9.8 on https://www.cyclehayling.org.uk/
    [INFO] Log Level: Debug
    [INFO] BackWPup job: Daily; DBDUMP+FILE
    [INFO] Runs with user: Andy (2)
    [INFO] BackWPup job start with link is active
    [INFO] BackWPup job started from external url
    [INFO] PHP ver.: 7.0.32 (64bit); cgi-fcgi; Linux
    [INFO] Maximum PHP script execution time is 300 seconds
    [INFO] Script restart time is configured to 120 seconds
    [INFO] MySQL ver.: 10.1.27-MariaDB
    [INFO] Web Server: Apache/2.4.34 (Unix)
    [INFO] curl ver.: 7.19.7; NSS/3.27.1
    [INFO] Temp folder is: /home/sites/cyclehayling.org.uk/public_html/wp-content/uploads/backwpup-f1d081-temp/
    [INFO] Logfile is: *************
    [INFO] Backup file is: ******************
    [12-Dec-2018 14:10:17] 1. Try to backup database …
    [12-Dec-2018 14:10:17] Connected to database *********** on localhost
    [12-Dec-2018 14:10:17] Backup database table “*********” with “~318” records
    Repeats for each table
    [12-Dec-2018 14:10:18] Added database dump “**********.sql” with 8.15 MB to backup file list
    [12-Dec-2018 14:10:18] Database backup done!
    [12-Dec-2018 14:10:18] 1. Trying to make a list of folders to back up …
    [12-Dec-2018 14:10:21] Added “wp-config.php” to backup file list
    [12-Dec-2018 14:10:21] 287 folders to backup.
    [12-Dec-2018 14:10:21] Restart after 5 seconds.
    [12-Dec-2018 14:30:31] 1. Trying to generate a manifest file …
    [12-Dec-2018 14:30:31] Added manifest.json file with 7.25 KB to backup file list.
    [12-Dec-2018 14:30:31] 1. Trying to create backup archive …
    [12-Dec-2018 14:30:31] Compressing files as ZipArchive. Please be patient, this may take a moment.
    [12-Dec-2018 14:30:31] Adding Extra files to Archive
    [12-Dec-2018 14:30:31] Archiving Folder: *************
    Repeats for each folder until…
    [12-Dec-2018 14:31:20] Archive size is 165.93 MB.
    [12-Dec-2018 14:31:20] 1916 Files with 192.17 MB in Archive.
    [12-Dec-2018 14:31:20] Restart after 49 seconds.
    [12-Dec-2018 14:32:01] 1. Try to send backup file to Dropbox …
    [12-Dec-2018 14:32:01] Call to users/get_current_account
    [12-Dec-2018 14:32:03] Authenticated with Dropbox of user: *********
    [12-Dec-2018 14:32:03] Call to users/get_space_usage
    [12-Dec-2018 14:32:04] 2.00 GB available on your Dropbox
    [12-Dec-2018 14:32:04] Uploading to Dropbox …
    [12-Dec-2018 14:32:04] Beginning new file upload session
    [12-Dec-2018 14:32:04] Call to files/upload_session/start
    [12-Dec-2018 14:32:05] Uploading 4 MB of data
    [12-Dec-2018 14:32:05] Call to files/upload_session/append_v2, with 4 MB of data, with parameters: {“cursor”:{“session_id”:”***********”,”offset”:0}}
    Repeats several times until
    [12-Dec-2018 14:34:00] Restart after 119 seconds.
    [12-Dec-2018 14:38:06] Uploading 4 MB of data
    More diagnostic messages until…
    [12-Dec-2018 14:40:04] Restart after 119 seconds.
    [12-Dec-2018 14:40:51] Uploading 4 MB of data
    More diagnostic messages until…
    [12-Dec-2018 14:42:51] Restart after 120 seconds.
    [12-Dec-2018 14:42:53] Uploading 4 MB of data
    More diagnostic messages until…
    [12-Dec-2018 14:44:50] Restart after 118 seconds.
    [12-Dec-2018 14:45:12] Uploading 4 MB of data
    More diagnostic messages until…
    [12-Dec-2018 14:50:20] Finishing upload session with a total of 166 MB uploaded
    [12-Dec-2018 14:50:20] Call to files/upload_session/finish, with parameters: {“cursor”:{“session_id”:”**********”,”offset”:173993827},”commit”:{“path”:”\/CH\/2018-12-12_14-10-17_**********.zip”,”mode”:”overwrite”}}
    [12-Dec-2018 14:50:22] Backup transferred to /CH/2018-12-12_14-10-17_***********.zip
    [12-Dec-2018 14:50:22] Call to files/list_folder, with parameters: {“path”:”\/CH\/”}
    [12-Dec-2018 14:50:23] Job done in 2406 seconds.

    Note the 20 minute delay at 14:10:21 which was only supposed to be 5 seconds. The other delays varied depending on what was happening on the site.

    I think that the backup will work fine if we can eliminate the restarts. Is that possible?

    I don’t think it is significant, but we also see this warning message in our logs…

    [10-Dec-2018 00:23:06 UTC] PHP Warning: sprintf(): Too few arguments in /********/plugins/backwpup/inc/class-page-settings.php on line 88

    Andy Henderson

Viewing 8 replies - 1 through 8 (of 8 total)
  • Thread Starter AndyHenderson

    (@andyhenderson)

    I’ve found that when in the ‘Restarting after xxx seconds’ situation, there is no restart job in wp_cron. Plugin WP Crontrol shows only backwpup_check_cleanup and inpsyde_phone-home_checkin as BackWPup jobs.

    My attempts to force a restart by executing wp-cron.php, running wp_cron() and opening pages on the site were therefore all doomed to failure.

    This moring, the backup had stalled for over 7 hours. While I was investigating, something kicked it off again and it finished without any errors or warnings in the log! Is there some code in the wp-admin BackWPup jobs display that can do that?

    I tried re-running and, when it stalled again, I tried calling:
    do_action( ‘backwpup_cron’, array( ‘id’ => ‘restart’ ) );
    to simulate the restart firing from wp_cron, but that had no effect.

    I’ve answered my original question by looking through the code. Setting ‘Maximum script execution time’ to zero eliminates the ‘Restart after xxx seconds’ situations. After just one test, the backup worked without stopping.

    I regard that as a work-around, however, not a resolution because introducing delays to long-running programs is good practice and I run the risk that my ISP will intervene.

    I’m happy to help with investigating further,

    Andy

    Plugin Support happyAnt

    (@duongcuong96)

    Hi @andyhenderson
    Please try the following:
    – go to BackWPup > Settings > Jobs, try to set Maximum Script Execution Time setting to about 25 seconds.
    – After that, Go to BackWPUp -> Settings -> Job tab -> Reduce server load and choose medium
    Then try run the job again, is that help?

    Thread Starter AndyHenderson

    (@andyhenderson)

    Thanks for getting back.

    From memory, that’s how it was set up in the first place. I just tried those settings and it stalled on my first attempt. As I write this, the backup has been stalled on ‘Restart after 27 seconds’ for over 20 minutes and WP Crontrol shows there are no relevant wp_cron entries.

    Andy

    Plugin Support happyAnt

    (@duongcuong96)

    Hi @andyhenderson

    WP Crontrol shows there are no relevant wp_cron entries.

    yes, no cron event will be scheduled during the backup progress.
    Hmm, could you please again try the following:
    – At first, change max execution time to 0 secs, but set reduce server load to max
    – If not works, change max execution time to 20 secs then select backup job to create Tar archive instead of Zip.
    If not work, I maybe I would need to ask our devs about your case :/
    Thanks!

    Thread Starter AndyHenderson

    (@andyhenderson)

    I’ll give those a try tomorrow afternoon.

    I’m surprised, though, that you think no cron events are created during backup. Looking at the code, I can find just one reference to the ‘Restart after xxx seconds’ message. It occurs in inc/class-job.php at line 1253 immediately before these statements at line 1265…

    wp_clear_scheduled_hook( 'backwpup_cron', array( 'id' => 'restart' ) );
    wp_schedule_single_event( time() + 5, 'backwpup_cron', array( 'id' => 'restart' ) );

    Which I believe generate wp_cron events. I know that’s not the same as cron events, but it’s wp_cron that the WP Crontrol plugin looks at. Having said that, I don’t see wp_cron events, so maybe I’m missing something. Note, however, there is no check on the response returned by either statement.

    Andy

    Thread Starter AndyHenderson

    (@andyhenderson)

    Also, the settings page makes explicit mention of wp_cron in relation to ‘Maximum script execution time’.

    I just tracked down the code that ‘Reduce server load’ controls. That introduces delays of 30, 60 or 90 milliseconds during the process using ‘usleep’ not wp_cron. That leads me to believe your first suggestion will work. I’m going to let the backup run with that option tonight.

    I don’t believe your second suggestion will work, however, because I’ve seen the backup stall during the ‘send to Dropbox’ phase.

    Andy

    Thread Starter AndyHenderson

    (@andyhenderson)

    As expected, after setting ‘Maximum execution time’ to 0 and ‘Reduce server load’ to maximum last night’s backup ran all the way through to the end.

    Lousy weather this morning, so instead of cycling I did some more detective work…

    The wp_cron jobs are being created successfully in ‘Restart after xxx’ situations. I didn’t see them before because they last only for 5 seconds and the act of looking with WP Crontrol forced them to fire and WP deleted them before I got a chance to see them.

    The problem is that when the wp_cron event executes, firing action backwpup_cron doesn’t do anything.

    The hook is created in backwpup.php at around line 94:
    add_action( 'backwpup_cron', array( 'BackWPup_Cron', 'run' ) );
    but that code is never executed in my setup. By inserting error_log commands I can see that the code starting:
    if ( defined( 'DOING_CRON' ) && DOING_CRON ) {
    runs frequently, occasionally the if statement is true, but it always results in:
    add_action( 'wp_loaded', array( 'BackWPup_Cron', 'cron_active' ), PHP_INT_MAX );

    I’ve left an error_log just before the backup_cron hook and it is never executed. As a result, the wp_cron job is ignored and the backwpup job waits for something that is not going to happen!

    I’m guessing that the backwpup jobs page does some ajax stuff, so going to that page or refreshing it, does get things going again but – obviously – there’s no-one around to do that at 1am in the morning.

    So, I can now run backup jobs and be reasonably sociable at the same time.

    However, in a more restrictive environment, for example an ISP decides to impose restrictions on run time, there is still a problem.

    Happy to do some more digging if that helps,

    Andy

    Plugin Support happyAnt

    (@duongcuong96)

    Hi @andyhenderson
    Thank you for the really detailed report!
    I forwarded all you report to our devs, they will back and respond to you when we have found something new!
    Thank you again!!!

Viewing 8 replies - 1 through 8 (of 8 total)
  • The topic ‘Backups stall at restart after xxx seconds’ is closed to new replies.