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

Quiz cron not rolling back on exception in process_finish

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: 2.4.9, 2.6.2, 2.7
    • Fix Version/s: 2.5.7, 2.6.4, 2.7.1
    • Component/s: Libraries, Quiz
    • Labels:
    • Testing Instructions:
      Hide
      1. Run through MDLQA-1466 to ensure that in the normal case, cron works.
      2. Do MDLQA-1466 again, but between steps 2. and 3. go into the database and delete the row from mdl_questions for one of the questions used in the quiz. This should ensure an exception is thrown during cron. Verify that you get an error mess in the quiz cron output, but other later parts of cron still work, and don't get rolled back.
      Show
      Run through MDLQA-1466 to ensure that in the normal case, cron works. Do MDLQA-1466 again, but between steps 2. and 3. go into the database and delete the row from mdl_questions for one of the questions used in the quiz. This should ensure an exception is thrown during cron. Verify that you get an error mess in the quiz cron output, but other later parts of cron still work, and don't get rolled back.
    • Affected Branches:
      MOODLE_24_STABLE, MOODLE_26_STABLE, MOODLE_27_STABLE
    • Fixed Branches:
      MOODLE_25_STABLE, MOODLE_26_STABLE, MOODLE_27_STABLE
    • Pull from Repository:
    • Pull Master Branch:

      Description

      If process_finish (mod/quiz/attemptlib.php) is called in the context of a quiz_cron execution, the delegated transaction should be explicitly rolled back on exception. Instead the transaction stays open as the cron moves on to totally unrelated processing. This resulted in a major disruption to users when the process_finish threw exceptions related to bad data in an mdl_question_attempt_step_data row. The major disruption was due to database locking extending over a long period of time.

      Here is mysql status on a typical transaction in this scenario:

      ---TRANSACTION A1589AED2, ACTIVE 2273 sec
      24273 lock struct(s), heap size 2570680, 104688 row lock(s), undo log entries 113642
      MySQL thread id 182178041, OS thread handle 0x7ebacedb7700, query id 10722878600 oit-moodle-prd-web01.oit.umn.edu 134.84.192.50 moodleay13 Sending data
      SELECT f.id AS id, f.contenthash, f.pathnamehash, f.contextid, f.component, f.filearea, f.itemid, f.filepath, f.filename, f.userid, f.filesize, f.mimetype, f.status, f.source, f.author, f.license, f.timecreated, f.timemodified, f.sortorder,
      f.referencefileid, r.repositoryid AS repositoryid, r.reference AS reference, r.lastsync AS referencelastsync, r.lifetime AS referencelifetime
      FROM mdl_files f
      JOIN mdl_files_reference r ON f.referencefileid = r.id
      JOIN mdl_repository_instances ri ON r.repositoryid = ri.id
      WHERE r.referen
      Trx read view will not see trx with id >= A15E6D19E, sees < A15E64997
      TABLE LOCK table `moodleay13`.`mdl_question_attempt_steps` trx id A1589AED2 lock mode IX
      TABLE LOCK table `moodleay13`.`mdl_question_attempt_step_data` trx id A1589AED2 lock mode IX
      TABLE LOCK table `moodleay13`.`mdl_question_attempts` trx id A1589AED2 lock mode IX
      RECORD LOCKS space id 805207 page no 779708 n bits 88 index `PRIMARY` of table `moodleay13`.`mdl_question_attempts` trx id A1589AED2 lock_mode X locks rec but not gap
      RECORD LOCKS space id 805207 page no 784133 n bits 104 index `PRIMARY` of table `moodleay13`.`mdl_question_attempts` trx id A1589AED2 lock_mode X locks rec but not gap
      TABLE LOCK table `moodleay13`.`mdl_quiz_attempts` trx id A1589AED2 lock mode IX
      RECORD LOCKS space id 805404 page no 35873 n bits 192 index `PRIMARY` of table `moodleay13`.`mdl_quiz_attempts` trx id A1589AED2 lock_mode X locks rec but not gap
      TABLE LOCK table `moodleay13`.`mdl_quiz_grades` trx id A1589AED2 lock mode IX
      TABLE LOCK table `moodleay13`.`mdl_grade_grades` trx id A1589AED2 lock mode IX

      Note that the transaction has been active for 2273 seconds, lots of database locks are in place on questions, quizzes, and grades, and the cron has moved on to cleaning up old files.

      I investigated this problem in 2.4 and determined by code inspection that this likely applies to 2.6. We are running both.

        Attachments

          Issue Links

            Activity

              People

              • Votes:
                3 Vote for this issue
                Watchers:
                10 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:
                  Fix Release Date:
                  14/Jul/14