Moodle

admin/cron.php infinite loop in backup_log_info caused when old logs are deleted

Details

  • Type: Bug Bug
  • Status: Open Open
  • Priority: Major Major
  • Resolution: Unresolved
  • Affects Version/s: 1.6
  • Fix Version/s: None
  • Component/s: Backup, Libraries, Other
  • Labels:
    None
  • Database:
    Any
  • Affected Branches:
    MOODLE_16_STABLE

Description

It is possible for backup_log_info() (called from cron.php) to get into a (potentially) infinite loop when iterating over the logs. This can happen when one or more old log entries are deleted by another invocation of cron.php between the time when the current number of logs is determined by this line:

$count_logs = count_records("log","course",$preferences->backup_course);

and when the test to terminate the loop ("while ($counter < $count_logs)") is made and which should cause termination. If some logs have been deleted, the final call to get_records() may not return enough logs for the counter to equal $count_logs.

I first identified and described this problem (without knowing the cause) here: http://moodle.org/mod/forum/discuss.php?d=50467#238903

The following patch should fix the problem, but recognising that if get_records() doesn't return anything, then it's time to stop.

      • backuplib.php.orig Mon Jan 15 13:13:38 2007
      • backuplib.php Thu Apr 5 16:40:03 2007
        ***************
      • 1308,1313 ****
      • 1308,1317 ----
        backup_flush(300);
        }
        }
        + } else { + //No logs -- old ones were deleted by a different cron.php + //execution; break to avoid potentially infinite loop + break; }
        }
        //End logs tag

I haven't yet had a chance to verify that this fix works. As this problem does not occur every single time backup_log_info(), a test case would need to be created.

Activity

Hide
Bruce Webster added a comment -

Looks like this is what happened to us. Backups started at midnight and I caught this query still running over and over this morning (at 10am). It was seriously affecting performance of the server. I killed the cron job.

SELECT * FROM mdl_log WHERE course = '331' ORDER BY time LIMIT 108276,1000;

We're on Moodle 1.9.5.

We need a database-based check that there is no cron job running before a new cron starts.

Show
Bruce Webster added a comment - Looks like this is what happened to us. Backups started at midnight and I caught this query still running over and over this morning (at 10am). It was seriously affecting performance of the server. I killed the cron job. SELECT * FROM mdl_log WHERE course = '331' ORDER BY time LIMIT 108276,1000; We're on Moodle 1.9.5. We need a database-based check that there is no cron job running before a new cron starts.
Hide
Bruce Webster added a comment -

To prevent backup errors caused by extra crons running during backup, I bunged this at the top of cron.php (after require config.php)

// HACK – avoid running cron while backups are running.
$brunning = get_field_sql("SELECT value FROM {$CFG->prefix}backup_config WHERE name='backup_sche_running'");
if(!empty($brunning)) {echo "Skipping cron as backups are running.\n";exit;}
// END HACK

Show
Bruce Webster added a comment - To prevent backup errors caused by extra crons running during backup, I bunged this at the top of cron.php (after require config.php) // HACK – avoid running cron while backups are running. $brunning = get_field_sql("SELECT value FROM {$CFG->prefix}backup_config WHERE name='backup_sche_running'"); if(!empty($brunning)) {echo "Skipping cron as backups are running.\n";exit;} // END HACK
Hide
Martin Dougiamas added a comment -

Passing to Eloy for looking at.

The last patch though, is not the answer. Cron does other things too, we don't want to stop it all just because backup is running. And I'm pretty sure Backup already detects itself running and will wait. But perhaps there's another issue.

Thanks Eloy!

Show
Martin Dougiamas added a comment - Passing to Eloy for looking at. The last patch though, is not the answer. Cron does other things too, we don't want to stop it all just because backup is running. And I'm pretty sure Backup already detects itself running and will wait. But perhaps there's another issue. Thanks Eloy!
Hide
Geoff Crompton added a comment -

This issue is still present in 1.9.11. Which was released over 4 years after this bug was reported, and the simple patch provided by the original requestor (which is well explained in the bug report) has not yet been applied.

Whats going on here? Is there something wrong with the patch? The problem has been also identified by Bruce, so it is a problem (though rarely triggered, as is often the case with race conditions).

Show
Geoff Crompton added a comment - This issue is still present in 1.9.11. Which was released over 4 years after this bug was reported, and the simple patch provided by the original requestor (which is well explained in the bug report) has not yet been applied. Whats going on here? Is there something wrong with the patch? The problem has been also identified by Bruce, so it is a problem (though rarely triggered, as is often the case with race conditions).

People

Dates

  • Created:
    Updated: