Uploaded image for project: 'Moodle'
  1. Moodle
  2. MDL-74183

Course completion race condition/insert error in daily task

    XMLWordPrintable

Details

    • Bug
    • Status: Closed
    • Minor
    • Resolution: Fixed
    • 3.9.12, 3.10.9, 3.11.5
    • 3.11.7
    • Course completion, Tasks
    • MOODLE_310_STABLE, MOODLE_311_STABLE, MOODLE_39_STABLE
    • MOODLE_311_STABLE
    • MDL-74183-311
    • MDL-74183-master
    • Hide

      Setup

      • Debugging enabled and Debug messages set to DEVELOPER.
      • Disable cron from running on the test site (that means, it shouldn't run periodically).

      Testing instructions

      1. Setup a course with course completion enable and a few users newly enrolled as students (annotate the id of this course because you'll need it later).
      2. Setup Course completion to allow the teacher to manually mark the user as complete within the course (Manual completion by others)
      3. Navigate to the course completion report as the teacher
      4. In lib/classes/task/completion_daily_task.php, insert a sleep(30); line after the get_recordset_sql() around line 87

                    $rs = $DB->get_recordset_sql($sql, [CONTEXT_COURSE, $now, $now]);
                    sleep(30);
                    // Check if result is empty.
                    if (!$rs->valid()) {
        

      5. In a terminal, manually run the daily task:

        php admin/cli/scheduled_task.php --execute=\\core\\task\\completion_daily_task

      6. While it is sleeping, mark Approval for one of the new students in the course completion report (and annotate the id of this user because you'll need it later).
      7. Confirm that when the daily task resumes, you see something along the lines of:
        Exception while marking started user [USERID] in course [COURSEID], retrying
      8. Confirm that the task completes successfully (continuing onto other users if there are more in the system), not in failure
      9. Check in the table mdl_course_completions that the record for the userid-courseid and confirm the record has a valid (non-null, non 0) timeenrolled (you'll need to replace [USERID] and [COURSEID] with the proper values):

        SELECT *
        FROM mdl_course_completions
        WHERE userid=[USERID] AND course=[COURSEID]
        

      Show
      Setup Debugging enabled and Debug messages set to DEVELOPER. Disable cron from running on the test site (that means, it shouldn't run periodically). Testing instructions Setup a course with course completion enable and a few users newly enrolled as students (annotate the id of this course because you'll need it later). Setup Course completion to allow the teacher to manually mark the user as complete within the course (Manual completion by others) Navigate to the course completion report as the teacher In lib/classes/task/completion_daily_task.php , insert a sleep(30) ; line after the get_recordset_sql() around line 87 $rs = $DB->get_recordset_sql($sql, [CONTEXT_COURSE, $now, $now]); sleep(30); // Check if result is empty. if (!$rs->valid()) { In a terminal, manually run the daily task: php admin/cli/scheduled_task.php --execute=\\core\\task\\completion_daily_task While it is sleeping, mark Approval for one of the new students in the course completion report (and annotate the id of this user because you'll need it later). Confirm that when the daily task resumes, you see something along the lines of: Exception while marking started user [USERID] in course [COURSEID] , retrying Confirm that the task completes successfully (continuing onto other users if there are more in the system), not in failure Check in the table mdl_course_completions that the record for the userid-courseid and confirm the record has a valid (non-null, non 0) timeenrolled (you'll need to replace [USERID] and [COURSEID] with the proper values): SELECT * FROM mdl_course_completions WHERE userid=[USERID] AND course=[COURSEID]

    Description

      On large sites with high levels of activity, you can run into a situation where the completion_daily_task task fetches the list of completions it needs to create, and while it is working, some other activity in the system has caused the completion to be created, leading to a write error due to duplicate entry:

      Execute scheduled task: Completion mark as started (core\task\completion_daily_task)
      ... started 10:55:42. Current memory use 15MB.
      Marking users as started
      Marked started user 123 in course 2
      ...
      Marked started user 234 in course 4
      ... used 54 dbqueries
      ... used 175.30935502052 seconds
      Scheduled task failed: Completion mark as started (core\task\completion_daily_task),Error writing to database (Duplicate entry '345-6' for key 'mdl_courcomp_usecou_uix'
      INSERT INTO mdl_course_completions (userid,course,timeenrolled,timestarted,timecompleted,reaggregate) VALUES(?,?,?,?,?,?)
      [array (
        0 => '345',
        1 => '6',
        2 => '1647012239',
        3 => 0,
        4 => NULL,
        5 => 1647014317,
      )])
      Debug info:
      Duplicate entry '345-6' for key 'mdl_courcomp_usecou_uix'
      INSERT INTO mdl_course_completions (userid,course,timeenrolled,timestarted,timecompleted,reaggregate) VALUES(?,?,?,?,?,?)
      [array (
        0 => '345',
        1 => '6',
        2 => '1647012239',
        3 => 0,
        4 => NULL,
        5 => 1647014317,
      )]
      Backtrace:
      * line 1357 of /lib/dml/mysqli_native_moodle_database.php: call to moodle_database->query_end()
      * line 1403 of /lib/dml/mysqli_native_moodle_database.php: call to mysqli_native_moodle_database->insert_record_raw()
      * line 334 of /completion/data_object.php: call to mysqli_native_moodle_database->insert_record()
      * line 236 of /completion/completion_completion.php: call to data_object->insert()
      * line 117 of /completion/completion_completion.php: call to completion_completion->_save()
      * line 124 of /lib/classes/task/completion_daily_task.php: call to completion_completion->mark_enrolled()
      * line 253 of /lib/cronlib.php: call to core\task\completion_daily_task->execute()
      * line 167 of /admin/cli/scheduled_task.php: call to cron_run_inner_scheduled_task()
      

      Attachments

        1. MDL-74183_master_1.png
          MDL-74183_master_1.png
          54 kB
        2. MDL-74183_master_2.png
          MDL-74183_master_2.png
          36 kB
        3. MDL-74183_v311_1.png
          MDL-74183_v311_1.png
          55 kB
        4. MDL-74183_v311_2.png
          MDL-74183_v311_2.png
          35 kB

        Activity

          People

            emerrill Eric Merrill
            emerrill Eric Merrill
            Amaia Anabitarte Amaia Anabitarte
            Sara Arjona (@sarjona) Sara Arjona (@sarjona)
            Angelia Dela Cruz Angelia Dela Cruz
            Amaia Anabitarte, Carlos Escobedo, Ferran Recio, Ilya Tregubov, Laurent David, Raquel Ortega, Sara Arjona (@sarjona), Amaia Anabitarte, Carlos Escobedo, Ferran Recio, Ilya Tregubov, Laurent David, Raquel Ortega, Sara Arjona (@sarjona)
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:
              9/May/22

              Time Tracking

                Estimated:
                Original Estimate - Not Specified
                Not Specified
                Remaining:
                Remaining Estimate - 0 minutes
                0m
                Logged:
                Time Spent - 1 hour, 25 minutes
                1h 25m