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

Moodle 2.1/2.2 upgrade crashes with "Cannot insert duplicate key row in object 'dbo.mdl_question_attempt_steps'" error

    XMLWordPrintable

    Details

    • Affected Branches:
      MOODLE_22_STABLE, MOODLE_25_STABLE

      Description

      I've been struggling for a long time to upgrade a Moodle 2.0.4+ site to Moodle 2.5, via version 2.2. The upgrade to Moodle 2.2 crashes at the point where it tries to migrate the question attempt data from the 'question_states' table to the new 'question_attempt_steps' table. Due to "some old bugs" in older versions of Moodle, bad data - duplicate rows I presume - have been written to the 'question_states' table over time. Modern versions of Moodle now have the 'mdl_quesattestep_queseq_uix' index on the 'mdl_question_attempt_steps' table which prevent this from happening again. However, it seems that the Moodle 2.1/2.2 upgrade code isn't able to handle that existing bad data (duplicates) in the 'question_states' table when it migrates the old question data to 'question_attempt_steps'. Instead it crashes with this message:

      Debug info: SQLState: 23000<br>
      Error Code: 2601<br>
      Message: [Microsoft][SQL Server Native Client 10.0][SQL Server]Cannot insert duplicate key row in object 'dbo.mdl_question_attempt_steps' with unique index 'mdl_quesattestep_queseq_uix'.<br>
      SQLState: 01000<br>
      Error Code: 3621<br>
      Message: [Microsoft][SQL Server Native Client 10.0][SQL Server]The statement has been terminated.<br>
      INSERT INTO mdl_question_attempt_steps (fraction,timecreated,userid,state,sequencenumber,questionattemptid) VALUES(NULL,'1268039088','7472',N'todo','0','1000')
      [array (
      0 => NULL,
      1 => '1268039088',
      2 => '7472',
      3 => 'todo',
      4 => 0,
      5 => 1000,
      )]
      Stack trace:
      ?? line 397 of \lib\dml\moodle_database.php: dml_write_exception thrown
      ?? line 252 of \lib\dml\sqlsrv_native_moodle_database.php: call to moodle_database->query_end()
      ?? line 368 of \lib\dml\sqlsrv_native_moodle_database.php: call to sqlsrv_native_moodle_database->query_end()
      ?? line 881 of \lib\dml\sqlsrv_native_moodle_database.php: call to sqlsrv_native_moodle_database->do_query()
      ?? line 959 of \lib\dml\sqlsrv_native_moodle_database.php: call to sqlsrv_native_moodle_database->insert_record_raw()
      ?? line 299 of \question\engine\upgrade\upgradelib.php: call to sqlsrv_native_moodle_database->insert_record()
      ?? line 258 of \question\engine\upgrade\upgradelib.php: call to question_engine_attempt_upgrader->insert_record()
      ?? line 221 of \question\engine\upgrade\upgradelib.php: call to question_engine_attempt_upgrader->save_usage()
      ?? line 176 of \question\engine\upgrade\upgradelib.php: call to question_engine_attempt_upgrader->convert_quiz_attempt()
      ?? line 131 of \question\engine\upgrade\upgradelib.php: call to question_engine_attempt_upgrader->update_all_attempts_at_quiz()
      ?? line 1112 of \mod\quiz\db\upgrade.php: call to question_engine_attempt_upgrader->convert_all_quiz_attempts()
      ?? line 538 of \lib\upgradelib.php: call to xmldb_quiz_upgrade()
      ?? line 271 of \lib\upgradelib.php: call to upgrade_plugins_modules()
      ?? line 1449 of \lib\upgradelib.php: call to upgrade_plugins()
      ?? line 269 of \admin\index.php: call to upgrade_noncore()

      I origionally asked for help with this on the Using Moodle forum: https://moodle.org/mod/forum/discuss.php?d=196599.

      Another user, Steve Lawrence, reported the same problem on https://moodle.org/mod/forum/discuss.php?d=213578 and I've added details of my problem to that thread. Tim Hunt responded with an explanation that: "during the upgrade to 2.2, Moodle copies data from the 'question_states' table to the new 'question_attempt_steps' table. However, due to old bugs in Moodle, some bits of quiz attempt data in your database are meaningless, and that confuses the upgrade code. In this case, for one particular 'question_attempt' there are two 'start' states. Obviously a given attempt at a question should only be started once."

      So I'm stuck with bad data in the 'question_states' table - and no simple way to clean it up. And the Moodle upgrade code can't handle it either, so I'm at a dead end with this upgrade...

      In https://moodle.org/mod/forum/discuss.php?d=213578#p930650 Tim Hunt explained that the following query shows the duplicate rows:

      SELECT question, attempt, seq_number,
      COUNT (seq_number)AS NumOccurrences
      FROM mdl_question_states
      GROUP BY question, attempt, seq_number
      HAVING (COUNT(seq_number)> 1)

      On a "clean" database that query should return zero rows, but on my database it returns about 6872 rows. There are 8.9 million rows in question_states. The problem with that query though is that it will just return the higher numbered duplicate of each set. If there are any cases where there are three or more duplciated rows, not just two, this will not be enough. Unfortunately, I do have question attempts where there are more than two duplciated rows - I have up to 8! Example: https://moodle.org/mod/forum/discuss.php?d=213578#p1003462.

      So, to try and fix this I run the above "SELECT ... HAVING (COUNT(seq_number)> 1)" query and delete the 6800 rows that it returns. When I run the query again to check for any more duplicates I get another 562 rows!

      I delete those 562 rows and check for the duplicates again - 116 rows.
      I delete those 116 rows and check for the duplicates again - 83 rows.
      I delete those 83 rows and check for the duplicates again - 49 rows...

      I have to check for, and delete, duplicate rows 15 times before I get to a position where that "SELECT ... HAVING (COUNT(seq_number)> 1)" query returns zero rows. I presume zero rows means that there are no more duplicate rows in question_states and, theoretically, I should now be able to successfully complete the upgrade to 2.1 or 2.2.

      So I install the qeupgradehelper from https://github.com/timhunt/moodle-local_qeupgradehelper in \local\qeupgradehelper in the Moodle 2.0.4+ codebase. In the Moodle 2.2.11+ codebase it's already in \admin\tool\qeupgradehelper.

      qeupgradehelper on the 2.0.4+ codebase is:
      $plugin->version = 2011040400;
      $plugin->requires = 2010080300;

      qeupgradehelper on the 2.2.11+ codebase is:
      $plugin->version = 2011092500;
      $plugin->requires = 2011092100;

      My partialupgrade.php file contains just one quiz id, which is the id of a quiz that I have tested and I know will be successfully upgraded (it has only a few attempts):

      function tool_qeupgradehelper_get_quizzes_to_upgrade()

      { return array(1201); }

      I then point my IIS virtual directory to the Moodle 2.2.11 codebase on the test server and start the upgrade:
      FROM: $release = '2.0.4+ (Build: 20110907)';
      TO: $release = '2.2.11 (Build: 20130708)';

      And it completes successfully! My dev site is now on version 2.2.11. That 1201 quiz specified in partialupgrade.php is also successfully upgraded.

      Great. I login to the 2.2.11 site and navigate to the qeupgradehelper "todo list": /admin/tool/qeupgradehelper/listtodo.php
      It lists all quizes still to upgrade. The first quiz on that list is id=1425

      I run this sql to check if that 1425 quiz has any duplicates in question_states:

      SELECT
      mdl_question_states.question,
      mdl_question_states.attempt,
      mdl_question_states.seq_number,
      COUNT(mdl_question_states.seq_number) AS num_occurrences
      FROM
      mdl_question_states
      INNER JOIN mdl_question_sessions ON mdl_question_states.question = mdl_question_sessions.questionid AND mdl_question_states.attempt = mdl_question_sessions.attemptid
      INNER JOIN mdl_quiz_attempts ON mdl_quiz_attempts.uniqueid = mdl_question_sessions.attemptid
      LEFT OUTER JOIN mdl_quiz ON mdl_quiz_attempts.quiz = mdl_quiz.id
      WHERE mdl_quiz.id = 1425
      GROUP BY
      mdl_question_states.question,
      mdl_question_states.attempt,
      mdl_question_states.seq_number
      HAVING
      COUNT(mdl_question_states.seq_number) > 1;

      It returns 0 rows, which I presume means there are no duplicates. Without the "HAVING COUNT(mdl_question_states.seq_number) > 1" clause it returns 15081 rows.

      So I click the "Convert attempts" action next to the 1425 quiz id on the qeupgradehelper screen. It shows:
      Attempts needing conversion: 252
      Question sessions: 5040

      I continue with the conversion of that quiz. Now the question engine upgrade code starts doing funny things...

      After 4 minutes the /admin/tool/qeupgradehelper/convertquiz.php page crashes with the "Cannot insert duplicate key row in object 'dbo.mdl_question_attempt_steps' with unique index 'mdl_quesattestep_queseq_uix'" error below.

      <BEGIN ERROR>
      [17-Jul-2013 07:43:41 UTC] sqlsrv_query: SQLSTATE = 23000
      [17-Jul-2013 07:43:41 UTC] sqlsrv_query: error code = 2601
      [17-Jul-2013 07:43:41 UTC] sqlsrv_query: message = [Microsoft][SQL Server Native Client 10.0][SQL Server]Cannot insert duplicate key row in object 'dbo.mdl_question_attempt_steps' with unique index 'mdl_quesattestep_queseq_uix'.
      [17-Jul-2013 07:43:42 UTC] sqlsrv_query: SQLSTATE = 01000
      [17-Jul-2013 07:43:42 UTC] sqlsrv_query: error code = 3621
      [17-Jul-2013 07:43:42 UTC] sqlsrv_query: message = [Microsoft][SQL Server Native Client 10.0][SQL Server]The statement has been terminated.
      [17-Jul-2013 07:43:42 UTC] Database transaction aborted automatically in C:\Moodle/admin/tool/qeupgradehelper/convertquiz.php
      [17-Jul-2013 07:45:01 UTC] Default exception handler: Error writing to database Debug: SQLState: 23000<br>
      Error Code: 2601<br>
      Message: [Microsoft][SQL Server Native Client 10.0][SQL Server]Cannot insert duplicate key row in object 'dbo.mdl_question_attempt_steps' with unique index 'mdl_quesattestep_queseq_uix'.<br>
      SQLState: 01000<br>
      Error Code: 3621<br>
      Message: [Microsoft][SQL Server Native Client 10.0][SQL Server]The statement has been terminated.<br>

      INSERT INTO mdl_question_attempt_steps (fraction,timecreated,userid,state,sequencenumber,questionattemptid) VALUES(NULL,'1368687945','6035',N'todo','0','0')
      [array (
      0 => NULL,
      1 => '1368687945',
      2 => '6035',
      3 => 'todo',
      4 => 0,
      5 => 0,
      )]

      • line 397 of \lib\dml\moodle_database.php: dml_write_exception thrown
      • line 256 of \lib\dml\sqlsrv_native_moodle_database.php: call to moodle_database->query_end()
      • line 372 of \lib\dml\sqlsrv_native_moodle_database.php: call to sqlsrv_native_moodle_database->query_end()
      • line 885 of \lib\dml\sqlsrv_native_moodle_database.php: call to sqlsrv_native_moodle_database->do_query()
      • line 963 of \lib\dml\sqlsrv_native_moodle_database.php: call to sqlsrv_native_moodle_database->insert_record_raw()
      • line 300 of \question\engine\upgrade\upgradelib.php: call to sqlsrv_native_moodle_database->insert_record()
      • line 259 of \question\engine\upgrade\upgradelib.php: call to question_engine_attempt_upgrader->insert_record()
      • line 222 of \question\engine\upgrade\upgradelib.php: call to question_engine_attempt_upgrader->save_usage()
      • line 52 of \admin\tool\qeupgradehelper\afterupgradelib.php: call to question_engine_attempt_upgrader->convert_quiz_attempt()
      • line 177 of \question\engine\upgrade\upgradelib.php: call to tool_qeupgradehelper_attempt_upgrader->convert_quiz_attempt()
      • line 132 of \question\engine\upgrade\upgradelib.php: call to question_engine_attempt_upgrader->update_all_attempts_at_quiz()
      • line 63 of \admin\tool\qeupgradehelper\convertquiz.php: call to question_engine_attempt_upgrader->convert_all_quiz_attempts()

      [17-Jul-2013 07:45:01 UTC] sqlsrv_free_stmt: SQLSTATE = IMSSP
      [17-Jul-2013 07:45:01 UTC] sqlsrv_free_stmt: error code = -14
      [17-Jul-2013 07:45:01 UTC] sqlsrv_free_stmt: message = An invalid parameter was passed to sqlsrv_free_stmt.
      [17-Jul-2013 07:45:01 UTC] sqlsrv_free_stmt: SQLSTATE = IMSSP
      [17-Jul-2013 07:45:01 UTC] sqlsrv_free_stmt: error code = -14
      [17-Jul-2013 07:45:01 UTC] sqlsrv_free_stmt: message = An invalid parameter was passed to sqlsrv_free_stmt.
      </END ERROR>

      So deleting all those rows from question_states did not solve the problem.

      And notice the values that are passed for the 'sequencenumber' and 'questionattemptid' columns in the "INSERT INTO mdl_question_attempt_steps..." statement. As you can see, sequencenumber and questionattemptid are both passed the value '0'. According to Tim Hunt in https://moodle.org/mod/forum/discuss.php?d=213578#p997993 the questionattemptid should never be 0.

      To check if there are any rows "where questionattemptid = 0" I run this:

      SELECT *
      FROM mdl_question_states
      WHERE attempt = 0

      It returns 0 rows. So where is the qeupgradehelper getting the "questionattemptid = 0" value that it's passing to the INSERT statement from?

      If I try to upgrade that same quiz again it fails with the "Cannot insert duplicate key row in object 'dbo.mdl_question_attempt_steps' with unique index 'mdl_quesattestep_queseq_uix'" error. This time there is a different value in the userid column, but the questionattemptid is still the invalid '0':

      INSERT INTO mdl_question_attempt_steps (fraction,timecreated,userid,state,sequencenumber,questionattemptid) VALUES(NULL,'1368449963','9301',N'todo','0','0')

      So, it seems that the Moodle upgrade code isn't handling the bad/duplicate data properly.

      I need help coming up with a different strategy for cleaning up that question_states table. Running the "SELECT ... FROM mdl_question_states ... HAVING (COUNT(seq_number)> 1)" query multiple times and deleting the rows that it returns each time is clearly not a workable solution.

      Is there a better strategy for cleaning up my question_states table? I'm at a dead end...

      The test environment where the upgrade has been attempted is:

      Windows Server 2008 VM
      IIS 7.5
      Microsoft SQL Server 2008 R2 (RTM) version 10.50.1600.1
      Microsoft Drivers for PHP for SQL Server version 2.0.1802.200
      $CFG->dbtype = 'sqlsrv';
      PHP version 5.3.9 NTS

      php.ini contains:
      [sqlsrv]
      extension=php_sqlsrv.dll
      sqlsrv.LogSubsystems = SQLSRV_LOG_SYSTEM_ALL
      sqlsrv.LogSeverity = SQLSRV_LOG_SEVERITY_ERROR
      sqlsrv.WarningsReturnAsErrors = TRUE

      The production site was origionally launched as a Moodle 1.9 site in Feb 2009, so it's been through a few upgrades up to 2.0.4+. But an upgrade is now way overdue...

      I've also tested the upgrade on a pc with WinXP SP3, IIS 5.1, MSSQL 2008 R2 and have experienced the same problem as above.

      Is there a better strategy for cleaning up my question_states table? Or a patch for the upgrade code that will handle the bad data?

        Attachments

          Activity

            People

            Assignee:
            timhunt Tim Hunt
            Reporter:
            libertymoodle Luis de Vasconcelos
            Participants:
            Component watchers:
            Andrew Lyons, Dongsheng Cai, Huong Nguyen, Jun Pataleta, Michael Hawkins, Shamim Rezaie, Simey Lameze, Matteo Scaramuccia, Andrew Lyons, Dongsheng Cai, Huong Nguyen, Jun Pataleta, Michael Hawkins, Shamim Rezaie, Simey Lameze, Tim Hunt, Andrew Lyons, Dongsheng Cai, Huong Nguyen, Jun Pataleta, Michael Hawkins, Shamim Rezaie, Simey Lameze, Tim Hunt, Andrew Lyons, Dongsheng Cai, Huong Nguyen, Jun Pataleta, Michael Hawkins, Shamim Rezaie, Simey Lameze
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: