Moodle
  1. Moodle
  2. MDL-28116

Backup fails when restoring completion data

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Critical Critical
    • Resolution: Fixed
    • Affects Version/s: 2.1
    • Fix Version/s: 2.1
    • Component/s: Activity completion, Backup
    • Labels:
    • Environment:
      qa.moodle.net
    • Testing Instructions:
      Hide

      To test, you need a sample backup file that used to demonstrate the problem. (I attached one to this bug, but if you have a better one, use that.)

      1. Restore backup leaving all options default

      (there is no step 2)

      If it doesn't get a database error then probably the change worked. (Ideally you would also test that the correct values were restored; I did a bit of testing of this already, it's not possible unless you know what the original tickbox values were supposed to be.)

      Show
      To test, you need a sample backup file that used to demonstrate the problem. (I attached one to this bug, but if you have a better one, use that.) 1. Restore backup leaving all options default (there is no step 2) If it doesn't get a database error then probably the change worked. (Ideally you would also test that the correct values were restored; I did a bit of testing of this already, it's not possible unless you know what the original tickbox values were supposed to be.)
    • Workaround:
      Hide

      Uncheck the option "Include user completion details" at step 3 of the restore process.

      Show
      Uncheck the option "Include user completion details" at step 3 of the restore process.
    • Affected Branches:
      MOODLE_21_STABLE
    • Fixed Branches:
      MOODLE_21_STABLE
    • Pull Master Branch:
      MDL-28116-master
    • Rank:
      18105

      Description

      During a QA test of backup and restore of grade categories and calculated grades, I struck a problem restoring a backup that included completion data.

      During the final restore step the restore fails and the following error is reported.

      Debug info: Duplicate entry '4-69' for key 'mdl_courmoducomp_usecou_uix'
      INSERT INTO mdl_course_modules_completion (userid,completionstate,viewed,timemodified,coursemoduleid) VALUES(?,?,?,?,?)
      [array (
      0 => '4',
      1 => '1',
      2 => '0',
      3 => 1309411185,
      4 => 69,
      )]
      Stack trace:
      line 396 of /lib/dml/moodle_database.php: dml_write_exception thrown
      line 878 of /lib/dml/mysqli_native_moodle_database.php: call to moodle_database->query_end()
      line 920 of /lib/dml/mysqli_native_moodle_database.php: call to mysqli_native_moodle_database->insert_record_raw()
      line 2238 of /backup/moodle2/restore_stepslib.php: call to mysqli_native_moodle_database->insert_record()
      line 131 of /backup/util/plan/restore_structure_step.class.php: call to restore_userscompletion_structure_step->process_completion()
      line 103 of /backup/util/helper/restore_structure_parser_processor.class.php: call to restore_structure_step->process()
      line 125 of /backup/util/xml/parser/processors/grouped_parser_processor.class.php: call to restore_structure_parser_processor->dispatch_chunk()
      line 91 of /backup/util/helper/restore_structure_parser_processor.class.php: call to grouped_parser_processor->postprocess_chunk()
      line 148 of /backup/util/xml/parser/processors/simplified_parser_processor.class.php: call to restore_structure_parser_processor->postprocess_chunk()
      line 92 of /backup/util/xml/parser/processors/progressive_parser_processor.class.php: call to simplified_parser_processor->process_chunk()
      line 169 of /backup/util/xml/parser/progressive_parser.class.php: call to progressive_parser_processor->receive_chunk()
      line 253 of /backup/util/xml/parser/progressive_parser.class.php: call to progressive_parser->publish()
      line ? of unknownfile: call to progressive_parser->end_tag()
      line 158 of /backup/util/xml/parser/progressive_parser.class.php: call to xml_parse()
      line 137 of /backup/util/xml/parser/progressive_parser.class.php: call to progressive_parser->parse()
      line 105 of /backup/util/plan/restore_structure_step.class.php: call to progressive_parser->process()
      line 153 of /backup/util/plan/base_task.class.php: call to restore_structure_step->execute()
      line 179 of /backup/moodle2/restore_activity_task.class.php: call to base_task->execute()
      line 148 of /backup/util/plan/base_plan.class.php: call to restore_activity_task->execute()
      line 157 of /backup/util/plan/restore_plan.class.php: call to base_plan->execute()
      line 302 of /backup/controller/restore_controller.class.php: call to restore_plan->execute()
      line 144 of /backup/util/ui/restore_ui.class.php: call to restore_controller->execute_plan()
      line 45 of /backup/restore.php: call to restore_ui->execute()

      Replication instructions:

      1. Create a backup which includes completion data (or use the attached backup)
      2. On the Settings, expand Course administration and click Restore
      3. Check that setting to restore as a new course and, pick a category and click Next
      4. Proceed through the steps with the default options

      The restore failed at the last step (step 6).

      If, when replicating this on another site (other than qa.moodle.net), the restore succeeds, repeat the restore process a second time. It looks like the conflict comes about with duplicates in the course completion table.

        Issue Links

          Activity

          Hide
          Sam Marshall added a comment -

          Argh! Damn. This problem occurs because of the unique index that was added in MDL-28021 to ensure database integrity.

          Unfortunately, the restore process is not able to update the course-module IDs at the point of restore, because they aren't available. I think the best solution, rather than discarding the index, may be to add a really big number when restoring, and subtract that number again when converting to the 'real' numbers. Maybe. But I'm not too sure. (The other option would be to discard the index again, which is annoying given that I just wrote the update to add it, etc...)

          I'm going to ask some other opinions.

          Show
          Sam Marshall added a comment - Argh! Damn. This problem occurs because of the unique index that was added in MDL-28021 to ensure database integrity. Unfortunately, the restore process is not able to update the course-module IDs at the point of restore, because they aren't available. I think the best solution, rather than discarding the index, may be to add a really big number when restoring, and subtract that number again when converting to the 'real' numbers. Maybe. But I'm not too sure. (The other option would be to discard the index again, which is annoying given that I just wrote the update to add it, etc...) I'm going to ask some other opinions.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          As commented @ HQ chat it seems that current code is 100% perfect, as far as the new cmid is already known at that stage!

          So, for any reason, it's returning one wrong cmid or the information is processed twice or whatever, surely will need some debugging to see what happens, but code seems perfect on its current incarnation.

              protected function process_completion($data) {
                  global $DB;
          
                  $data = (object)$data;
          
                  $data->coursemoduleid = $this->task->get_moduleid();
                  $data->userid = $this->get_mappingid('user', $data->userid);
                  $data->timemodified = $this->apply_date_offset($data->timemodified);
          
                  $DB->insert_record('course_modules_completion', $data);
              }
          
          Show
          Eloy Lafuente (stronk7) added a comment - As commented @ HQ chat it seems that current code is 100% perfect, as far as the new cmid is already known at that stage! So, for any reason, it's returning one wrong cmid or the information is processed twice or whatever, surely will need some debugging to see what happens, but code seems perfect on its current incarnation. protected function process_completion($data) { global $DB; $data = (object)$data; $data->coursemoduleid = $ this ->task->get_moduleid(); $data->userid = $ this ->get_mappingid('user', $data->userid); $data->timemodified = $ this ->apply_date_offset($data->timemodified); $DB->insert_record('course_modules_completion', $data); }
          Hide
          Eloy Lafuente (stronk7) added a comment - - edited

          LOL, just guessing if the dupe problem is on origin, could be a good cause for this. Needs debugging anyway.

          Show
          Eloy Lafuente (stronk7) added a comment - - edited LOL, just guessing if the dupe problem is on origin, could be a good cause for this. Needs debugging anyway.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Which backup file was used to reproduce the error above? I've examined the one available @ MDLQA-1110 and it has not users activity completion at all.

          Show
          Eloy Lafuente (stronk7) added a comment - Which backup file was used to reproduce the error above? I've examined the one available @ MDLQA-1110 and it has not users activity completion at all.
          Hide
          Sam Marshall added a comment -

          Thanks for the assistance Eloy. I've been really struggling today (because I got a new PC and had to install all the software and such) but I've eventually managed to come to the same conclusion - the restore code is basically correct and my initial assumption about the cause of the problem was wrong.

          I think there is still a problem here, but perhaps not a 'critical' one. The problem is, if you take a backup including completion data that was made before MDL-28021 is fixed, then it might include duplicate rows if users on that system had previously encountered the bug that MDL-28021 fixed. If you then restore that backup on a system after MDL-28021, it will cause this error. The solution is to specifically detect duplicate rows, and ignore them, in restore. I will code a patch soon (going to make a test backup file first).

          Show
          Sam Marshall added a comment - Thanks for the assistance Eloy. I've been really struggling today (because I got a new PC and had to install all the software and such) but I've eventually managed to come to the same conclusion - the restore code is basically correct and my initial assumption about the cause of the problem was wrong. I think there is still a problem here, but perhaps not a 'critical' one. The problem is, if you take a backup including completion data that was made before MDL-28021 is fixed, then it might include duplicate rows if users on that system had previously encountered the bug that MDL-28021 fixed. If you then restore that backup on a system after MDL-28021 , it will cause this error. The solution is to specifically detect duplicate rows, and ignore them, in restore. I will code a patch soon (going to make a test backup file first).
          Hide
          Sam Marshall added a comment -

          Here's a test backup that displays the problem.

          Show
          Sam Marshall added a comment - Here's a test backup that displays the problem.
          Hide
          Sam Marshall added a comment -

          Here's my fix, hope this is okay. Some notes:

          1) My compare URL for the 20_STABLE version is based on the 20 branch version of my other bugfix (it isn't integrated into MOODLE_20_STABLE). If the other bugfix is never integrated into 2.0 then there is no need to integrate this one into it either.

          2) I did a fair bit of testing to check whether after_execute is called, definitely seems like it's after each activity (in which case it is safe to clear that array, so as not to use loads of memory on a big course with lots of tickboxes).

          Show
          Sam Marshall added a comment - Here's my fix, hope this is okay. Some notes: 1) My compare URL for the 20_STABLE version is based on the 20 branch version of my other bugfix (it isn't integrated into MOODLE_20_STABLE). If the other bugfix is never integrated into 2.0 then there is no need to integrate this one into it either. 2) I did a fair bit of testing to check whether after_execute is called, definitely seems like it's after each activity (in which case it is safe to clear that array, so as not to use loads of memory on a big course with lots of tickboxes).
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Hi Sam,

          some comments (sorry I didn't see your messages in the HQ chat along the evening):

          1) About MDL-28021. Yes it was for master only, so I guess we won't be applying this to 20_STABLE.
          2) About this. Do you think it's ok to use such a cache? What if one course has, say, 50000 students? Uhm.. aprox 20bytes * 50000 = 1000000 bytes = 1MB.. oki, forget, I think we can survive with that.

          So, integrating (master only). Thanks!

          Show
          Eloy Lafuente (stronk7) added a comment - Hi Sam, some comments (sorry I didn't see your messages in the HQ chat along the evening): 1) About MDL-28021 . Yes it was for master only, so I guess we won't be applying this to 20_STABLE. 2) About this. Do you think it's ok to use such a cache? What if one course has, say, 50000 students? Uhm.. aprox 20bytes * 50000 = 1000000 bytes = 1MB.. oki, forget, I think we can survive with that. So, integrating (master only). Thanks!
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Integrated!

          Show
          Eloy Lafuente (stronk7) added a comment - Integrated!
          Hide
          Tim Hunt added a comment -

          Attached backup file restored twice with no errors (after editing the admin email address so the users matched).

          The completion tickboxes on the restored courses are ticked.

          Passing.

          Show
          Tim Hunt added a comment - Attached backup file restored twice with no errors (after editing the admin email address so the users matched). The completion tickboxes on the restored courses are ticked. Passing.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Yay, this is now part of the just released Moodle 2.1 ! Thanks for all the hard work!

          Show
          Eloy Lafuente (stronk7) added a comment - Yay, this is now part of the just released Moodle 2.1 ! Thanks for all the hard work!
          Hide
          Tony Levi added a comment -

          It looks like MDL-28021 was applied to 20_STABLE, can we apply this on there too?

          Show
          Tony Levi added a comment - It looks like MDL-28021 was applied to 20_STABLE, can we apply this on there too?

            People

            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: