Moodle
  1. Moodle
  2. MDL-26416

Intermittent error from the quiz reports on MySQL because of subtracting two unsigned columns

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Critical Critical
    • Resolution: Fixed
    • Affects Version/s: 2.0.1
    • Fix Version/s: 2.0.3
    • Component/s: Quiz
    • Labels:
    • Database:
      MySQL
    • Affected Branches:
      MOODLE_20_STABLE
    • Fixed Branches:
      MOODLE_20_STABLE
    • Rank:
      16116

      Description

      I tested with the following test steps:

      • Connect as admin.
      • Create two essay questions
      • Create a quizz
      • Edit quizz (Navigation: quizz administration) and add two random question (with the two previous essay questions). The quizz should have two page with a random question of each page.
      • Connect as student and answer quizz.
      • As admin I tried to view the attempt (/Moodle_Integration/mod/quiz/report.php?id=5&mode=overview)
        Just after the following text "Showing graded and ungraded attempts for each user. The one attempt for each user that is graded is highlighted. The grading method for this quiz is Highest grade.", I can see this exception:
      Error reading from database
      
      More information about this error
      
      Debug info: BIGINT UNSIGNED value is out of range in '(`moodle_registration`.`qa`.`timefinish` - `moodle_registration`.`qa`.`timestart`)'
      SELECT CONCAT(u.id, '#', COALESCE(qa.attempt, 0)) AS uniqueid, (CASE WHEN qa.sumgrades = (SELECT MAX(qa2.sumgrades) FROM mdl_quiz_attempts qa2 WHERE qa2.quiz = qa.quiz AND qa2.userid = qa.userid) AND qa.timestart = (SELECT MIN(qa3.timestart) FROM mdl_quiz_attempts qa3 WHERE qa3.quiz = qa.quiz AND qa3.userid = qa.userid AND qa3.sumgrades = qa.sumgrades) THEN 1 ELSE 0 END) AS gradedattempt, qa.uniqueid AS attemptuniqueid, qa.id AS attempt, u.id AS userid, u.idnumber, u.firstname, u.lastname, u.picture, u.imagealt, u.email, qa.sumgrades, qa.timefinish, qa.timestart, qa.timefinish - qa.timestart AS duration , COALESCE((SELECT MAX(qqr.regraded) FROM mdl_quiz_question_regrade qqr WHERE qqr.attemptid = qa.uniqueid),-1) AS regraded FROM mdl_user u LEFT JOIN mdl_quiz_attempts qa ON qa.userid = u.id AND qa.quiz = ? WHERE qa.id IS NOT NULL AND qa.preview = 0 ORDER BY uniqueid ASC LIMIT 0, 30
      [array (
      0 => '1',
      )]
      Stack trace:
      line 391 of /lib/dml/moodle_database.php: dml_read_exception thrown
      line 790 of /lib/dml/mysqli_native_moodle_database.php: call to moodle_database->query_end()
      line 1354 of /lib/tablelib.php: call to mysqli_native_moodle_database->get_records_sql()
      line 323 of /mod/quiz/report/overview/overview_table.php: call to table_sql->query_db()
      line 1375 of /lib/tablelib.php: call to quiz_report_overview_table->query_db()
      line 391 of /mod/quiz/report/overview/report.php: call to table_sql->out()
      line 90 of /mod/quiz/report.php: call to quiz_overview_report->display()
      

        Issue Links

          Activity

          Hide
          Travis Wilhelm added a comment -

          I've got the same problem. Appears to be that in the mdl_quiz_attempts table, the query breaks when the 'timefinish' field is 0.

          See thread here: http://moodle.org/mod/forum/discuss.php?d=167616#p741516

          Show
          Travis Wilhelm added a comment - I've got the same problem. Appears to be that in the mdl_quiz_attempts table, the query breaks when the 'timefinish' field is 0. See thread here: http://moodle.org/mod/forum/discuss.php?d=167616#p741516
          Hide
          Tim Hunt added a comment -

          Quiz bug, so -> me.

          The problem is with computing qa.timefinish - qa.timestart AS duration in the select. In MySQL these are unsigned values, and so it does not like it when timefinish < timestart. Except that it does not always happen. For example, for an open attempt, timefinish is 0, but that does not seem to cause problems. At least not on my test MySQL system.

          This value has to be computed in SQL, because it must be possible to sort on that column.

          Presumably, this is fixable with appropriate use of casts, but I would like to know more about the edge-cases for MySQL unsiged int subtraction before doing the fix.

          If anyone can explain a safe way to do the subtraction, or can give examples of pairs of values timestart and timefinish that either do or don't give errors, that would be helpful. Thanks.

          Show
          Tim Hunt added a comment - Quiz bug, so -> me. The problem is with computing qa.timefinish - qa.timestart AS duration in the select. In MySQL these are unsigned values, and so it does not like it when timefinish < timestart. Except that it does not always happen. For example, for an open attempt, timefinish is 0, but that does not seem to cause problems. At least not on my test MySQL system. This value has to be computed in SQL, because it must be possible to sort on that column. Presumably, this is fixable with appropriate use of casts, but I would like to know more about the edge-cases for MySQL unsiged int subtraction before doing the fix. If anyone can explain a safe way to do the subtraction, or can give examples of pairs of values timestart and timefinish that either do or don't give errors, that would be helpful. Thanks.
          Hide
          Travis Wilhelm added a comment -

          OK, I'm currently working on a specific quiz.

          Here's an entry with timefinish that isn't working:
          4733 4733 268 1165 1 0.00000 1297672957 0 1297672957 3187,3188,3192,0 0

          So I will now run a query to update 'timefinish' to a standard sort of timestamp (only for that specific quiz currently giving the error):
          UPDATE `mdl_quiz_attempts` set timefinish=1297994073 WHERE `quiz` = 268 and `timefinish`=0
          (affected 6 rows - others with timefinish=0 from the same quiz).

          And now the quiz works: (mod/quiz/report.php?id=6086&mode=overview) shows up (including 6 non-finished as above).

          Other information about my mysql (my.ini):
          I tried adding sql_mode='NO_UNSIGNED_SUBTRACTION' to the [mysqld] section. I have decommented it also and it still doesn't affect the error.

          Show
          Travis Wilhelm added a comment - OK, I'm currently working on a specific quiz. Here's an entry with timefinish that isn't working: 4733 4733 268 1165 1 0.00000 1297672957 0 1297672957 3187,3188,3192,0 0 So I will now run a query to update 'timefinish' to a standard sort of timestamp (only for that specific quiz currently giving the error): UPDATE `mdl_quiz_attempts` set timefinish=1297994073 WHERE `quiz` = 268 and `timefinish`=0 (affected 6 rows - others with timefinish=0 from the same quiz). And now the quiz works: (mod/quiz/report.php?id=6086&mode=overview) shows up (including 6 non-finished as above). Other information about my mysql (my.ini): I tried adding sql_mode='NO_UNSIGNED_SUBTRACTION' to the [mysqld] section. I have decommented it also and it still doesn't affect the error.
          Hide
          Tim Hunt added a comment - - edited

          Thanks for the extra information, that is really helpful.

          Just two more things I would like to know. Which version of MySQL? and are you using MyISAM or InnoDB tables?

          Aha! the old Google the error message techniqued has worked. Have a read of http://dev.mysql.com/doc/refman/5.5/en/out-of-range-and-overflow.html

          That explains why I can't reproduce this. I still seem to be on MySQL 5.1.x on this test computer. I assume you are on 5.5.5 or later.

          Can you try changing strict mode on your system, and see if it makes a difference? (I am not proposing turning off strict mode as a long-term solution, I just want to make sure we have fully understood the problem before I try to fix the Moodle code.)

          By the way, for testing I made a simple test table

          CREATE TABLE qa (
            id bigint(10) unsigned NOT NULL AUTO_INCREMENT,
            timestart bigint(10) unsigned NOT NULL DEFAULT '0',
            timefinish bigint(10) unsigned NOT NULL DEFAULT '0',
            PRIMARY KEY (id)
          ) DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci AUTO_INCREMENT=5 ;
          INSERT INTO qa (id, timestart, timefinish) VALUES(1, 1297672957, 0);
          INSERT INTO qa (id, timestart, timefinish) VALUES(2, 1297672957, 1297672957);
          INSERT INTO qa (id, timestart, timefinish) VALUES(3, 1297672957, 1297672956);
          INSERT INTO qa (id, timestart, timefinish) VALUES(4, 1297672957, 1297672958);
          

          and was running the test query

          SELECT id, timestart, timefinish, timefinish - timestart
          FROM qa
          ORDER BY id
          

          I think that this covers all the cases that we need to get working in order to fix the Moodle code.

          Show
          Tim Hunt added a comment - - edited Thanks for the extra information, that is really helpful. Just two more things I would like to know. Which version of MySQL? and are you using MyISAM or InnoDB tables? Aha! the old Google the error message techniqued has worked. Have a read of http://dev.mysql.com/doc/refman/5.5/en/out-of-range-and-overflow.html That explains why I can't reproduce this. I still seem to be on MySQL 5.1.x on this test computer. I assume you are on 5.5.5 or later. Can you try changing strict mode on your system, and see if it makes a difference? (I am not proposing turning off strict mode as a long-term solution, I just want to make sure we have fully understood the problem before I try to fix the Moodle code.) By the way, for testing I made a simple test table CREATE TABLE qa ( id bigint(10) unsigned NOT NULL AUTO_INCREMENT, timestart bigint(10) unsigned NOT NULL DEFAULT '0', timefinish bigint(10) unsigned NOT NULL DEFAULT '0', PRIMARY KEY (id) ) DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci AUTO_INCREMENT=5 ; INSERT INTO qa (id, timestart, timefinish) VALUES(1, 1297672957, 0); INSERT INTO qa (id, timestart, timefinish) VALUES(2, 1297672957, 1297672957); INSERT INTO qa (id, timestart, timefinish) VALUES(3, 1297672957, 1297672956); INSERT INTO qa (id, timestart, timefinish) VALUES(4, 1297672957, 1297672958); and was running the test query SELECT id, timestart, timefinish, timefinish - timestart FROM qa ORDER BY id I think that this covers all the cases that we need to get working in order to fix the Moodle code.
          Hide
          Tim Hunt added a comment -

          Right, installing MySQL 5.5.9, and I can reproduce this.

          Show
          Tim Hunt added a comment - Right, installing MySQL 5.5.9, and I can reproduce this.
          Hide
          Tim Hunt added a comment -

          I think I have a fix. See https://github.com/timhunt/moodle/compare/master...MDL-26416.

          Note that there are two commits there. One just cleans up the code a bit, the second one actually makes the relevant change.

          It would be really helpful if someone could test this fix, and confirm that it works, before I do a pull request. Thanks.

          Show
          Tim Hunt added a comment - I think I have a fix. See https://github.com/timhunt/moodle/compare/master...MDL-26416 . Note that there are two commits there. One just cleans up the code a bit, the second one actually makes the relevant change. It would be really helpful if someone could test this fix, and confirm that it works, before I do a pull request. Thanks.
          Hide
          Travis Wilhelm added a comment -

          Perfect Tim - that fixes it and now shows some attempts as 'Open'. As you've probably worked out, I'm using the latest version of mysql (5.5.x - not sure exactly which).

          Thanks for your help Tim! It is much appreciated!

          What's the process from here? When you do a pull request, does the change go into the next daily build?

          Show
          Travis Wilhelm added a comment - Perfect Tim - that fixes it and now shows some attempts as 'Open'. As you've probably worked out, I'm using the latest version of mysql (5.5.x - not sure exactly which). Thanks for your help Tim! It is much appreciated! What's the process from here? When you do a pull request, does the change go into the next daily build?
          Hide
          Tim Hunt added a comment -

          The way it works is described on http://docs.moodle.org/en/Development:Process

          But to summarise: There are not daily builds, there are now weekly builds.

          All the pull requests from the previous week are reviewed on Monday, and combined at http://git.moodle.org/gw?p=integration.git;a=summary

          Then on Tuesday, that new version is tested, and if all is OK, then on Wednesday it becomes that week's weekly build.

          Except that this week and next week are a bit difference because they are about to release Moodle 2.0.2 which involves extra testing.

          Anyway, thanks for testing this, I will do the pull request now. You will know when this becomes part of a weekly build, because the status of the bug will be changed to closed.

          Show
          Tim Hunt added a comment - The way it works is described on http://docs.moodle.org/en/Development:Process But to summarise: There are not daily builds, there are now weekly builds. All the pull requests from the previous week are reviewed on Monday, and combined at http://git.moodle.org/gw?p=integration.git;a=summary Then on Tuesday, that new version is tested, and if all is OK, then on Wednesday it becomes that week's weekly build. Except that this week and next week are a bit difference because they are about to release Moodle 2.0.2 which involves extra testing. Anyway, thanks for testing this, I will do the pull request now. You will know when this becomes part of a weekly build, because the status of the bug will be changed to closed.
          Hide
          Helen Foster added a comment -

          This issue is fixed in the latest 2.0.2+ weekly. Thanks everyone.

          Show
          Helen Foster added a comment - This issue is fixed in the latest 2.0.2+ weekly. Thanks everyone.
          Hide
          omer added a comment -

          hi,
          just installed build 20110303, problam is still not fixed..
          i get the same error.

          in order for the teacher to be able to view the data, i've manually changed the values of finishtime from 0 to the starttime of the same line..

          Show
          omer added a comment - hi, just installed build 20110303, problam is still not fixed.. i get the same error. in order for the teacher to be able to view the data, i've manually changed the values of finishtime from 0 to the starttime of the same line..
          Hide
          Tim Hunt added a comment -

          omer, please set debugging (http://docs.moodle.org/en/Debugging) to developer level, and copy and paste the full error message here. Thanks.

          Show
          Tim Hunt added a comment - omer, please set debugging ( http://docs.moodle.org/en/Debugging ) to developer level, and copy and paste the full error message here. Thanks.
          Hide
          omer added a comment -

          It is exactly the same as the one on the first post..
          From some reason, when the finishtime=0 it fails

          Show
          omer added a comment - It is exactly the same as the one on the first post.. From some reason, when the finishtime=0 it fails
          Hide
          Tim Hunt added a comment -

          What I want to see is the stack trace in the error message. Also, please confirm if this is Moodle 2.x or 1.9.x.

          Show
          Tim Hunt added a comment - What I want to see is the stack trace in the error message. Also, please confirm if this is Moodle 2.x or 1.9.x.
          Hide
          omer added a comment -

          Im using the last weekly build from 10 hours ago..
          2.0.2+.
          Will post stack trace later today

          Show
          omer added a comment - Im using the last weekly build from 10 hours ago.. 2.0.2+. Will post stack trace later today
          Hide
          omer added a comment -

          hi,
          here is everything:

          Debug info: BIGINT UNSIGNED value is out of range in '(`XXXXXXXXX`.`qa`.`timefinish` - `XXXXXXXX`.`qa`.`timestart`)'
          SELECT CONCAT(u.id, '#', COALESCE(qa.attempt, 0)) AS uniqueid, (CASE WHEN qa.sumgrades = (SELECT MAX(qa2.sumgrades) FROM mdl_quiz_attempts qa2 WHERE qa2.quiz = qa.quiz AND qa2.userid = qa.userid) AND qa.timestart = (SELECT MIN(qa3.timestart) FROM mdl_quiz_attempts qa3 WHERE qa3.quiz = qa.quiz AND qa3.userid = qa.userid AND qa3.sumgrades = qa.sumgrades) THEN 1 ELSE 0 END) AS gradedattempt, qa.uniqueid AS attemptuniqueid, qa.id AS attempt, u.id AS userid, u.idnumber, u.firstname, u.lastname, u.picture, u.imagealt, u.email, qa.sumgrades, qa.timefinish, qa.timestart, qa.timefinish - qa.timestart AS duration , COALESCE((SELECT MAX(qqr.regraded) FROM mdl_quiz_question_regrade qqr WHERE qqr.attemptid = qa.uniqueid),-1) AS regraded FROM mdl_user u LEFT JOIN mdl_quiz_attempts qa ON qa.userid = u.id AND qa.quiz = ? WHERE qa.id IS NOT NULL AND qa.preview = 0 ORDER BY uniqueid ASC LIMIT 0, 30
          [array (
          0 => '2',
          )]
          Stack trace:
          line 391 of \lib\dml\moodle_database.php: dml_read_exception thrown
          line 790 of \lib\dml\mysqli_native_moodle_database.php: call to moodle_database->query_end()
          line 1354 of \lib\tablelib.php: call to mysqli_native_moodle_database->get_records_sql()
          line 323 of \mod\quiz\report\overview\overview_table.php: call to table_sql->query_db()
          line 1375 of \lib\tablelib.php: call to quiz_report_overview_table->query_db()
          line 391 of \mod\quiz\report\overview\report.php: call to table_sql->out()
          line 90 of \mod\quiz\report.php: call to quiz_overview_report->display

          thanks for your help.!

          Show
          omer added a comment - hi, here is everything: Debug info: BIGINT UNSIGNED value is out of range in '(`XXXXXXXXX`.`qa`.`timefinish` - `XXXXXXXX`.`qa`.`timestart`)' SELECT CONCAT(u.id, '#', COALESCE(qa.attempt, 0)) AS uniqueid, (CASE WHEN qa.sumgrades = (SELECT MAX(qa2.sumgrades) FROM mdl_quiz_attempts qa2 WHERE qa2.quiz = qa.quiz AND qa2.userid = qa.userid) AND qa.timestart = (SELECT MIN(qa3.timestart) FROM mdl_quiz_attempts qa3 WHERE qa3.quiz = qa.quiz AND qa3.userid = qa.userid AND qa3.sumgrades = qa.sumgrades) THEN 1 ELSE 0 END) AS gradedattempt, qa.uniqueid AS attemptuniqueid, qa.id AS attempt, u.id AS userid, u.idnumber, u.firstname, u.lastname, u.picture, u.imagealt, u.email, qa.sumgrades, qa.timefinish, qa.timestart, qa.timefinish - qa.timestart AS duration , COALESCE((SELECT MAX(qqr.regraded) FROM mdl_quiz_question_regrade qqr WHERE qqr.attemptid = qa.uniqueid),-1) AS regraded FROM mdl_user u LEFT JOIN mdl_quiz_attempts qa ON qa.userid = u.id AND qa.quiz = ? WHERE qa.id IS NOT NULL AND qa.preview = 0 ORDER BY uniqueid ASC LIMIT 0, 30 [array ( 0 => '2', )] Stack trace: line 391 of \lib\dml\moodle_database.php: dml_read_exception thrown line 790 of \lib\dml\mysqli_native_moodle_database.php: call to moodle_database->query_end() line 1354 of \lib\tablelib.php: call to mysqli_native_moodle_database->get_records_sql() line 323 of \mod\quiz\report\overview\overview_table.php: call to table_sql->query_db() line 1375 of \lib\tablelib.php: call to quiz_report_overview_table->query_db() line 391 of \mod\quiz\report\overview\report.php: call to table_sql->out() line 90 of \mod\quiz\report.php: call to quiz_overview_report->display thanks for your help.!
          Hide
          Tim Hunt added a comment -

          Right, well then you are clearly not running the latest Moodle release, because the latest version of Moodle does not execute that database query.

          Look at mod/quiz/report/overview/report.php in your version, and compare it to https://github.com/moodle/moodle/blob/master/mod/quiz/report/overview/report.php#L210

          Show
          Tim Hunt added a comment - Right, well then you are clearly not running the latest Moodle release, because the latest version of Moodle does not execute that database query. Look at mod/quiz/report/overview/report.php in your version, and compare it to https://github.com/moodle/moodle/blob/master/mod/quiz/report/overview/report.php#L210
          Hide
          omer added a comment -

          damn..
          upgraded - but left "MOD" and "THEME" out...

          Show
          omer added a comment - damn.. upgraded - but left "MOD" and "THEME" out...
          Hide
          Christian Gutierrez added a comment -

          Hi, i have the same problem, but Moodle runs with PostgreSQL, i have the latest build (20110303).

          Show
          Christian Gutierrez added a comment - Hi, i have the same problem, but Moodle runs with PostgreSQL, i have the latest build (20110303).
          Hide
          Tim Hunt added a comment -

          If you use Postgres, then you can't possibly have exactly the same error. The text of the error message is MySQL-specific. Please copy and paste exactly the error message you get (with debugging set to developer level) here.

          Show
          Tim Hunt added a comment - If you use Postgres, then you can't possibly have exactly the same error. The text of the error message is MySQL-specific. Please copy and paste exactly the error message you get (with debugging set to developer level) here.
          Hide
          Christian Gutierrez added a comment -

          Hi Tum, you right, my error is:

          PHP Fatal error: Call to undefined method quiz_attempt::get_attempt_state() in /data/web/moodle/mod/quiz/review.php on line 43

          Show
          Christian Gutierrez added a comment - Hi Tum, you right, my error is: PHP Fatal error: Call to undefined method quiz_attempt::get_attempt_state() in /data/web/moodle/mod/quiz/review.php on line 43
          Hide
          Tim Hunt added a comment -

          OK, that is a completely separate issue. Please could you create a new bug report for it. Thanks.

          Show
          Tim Hunt added a comment - OK, that is a completely separate issue. Please could you create a new bug report for it. Thanks.
          Hide
          Christian Gutierrez added a comment -

          Thanks Tim, i create the bug report. http://tracker.moodle.org/browse/MDL-26734

          Show
          Christian Gutierrez added a comment - Thanks Tim, i create the bug report. http://tracker.moodle.org/browse/MDL-26734
          Hide
          Travis Wilhelm added a comment -

          I should have checked this earlier, but the same error occurs when selecting the "responses" portion of the Quiz.

          Below is the debug. I've updated to the latest weekly build of the quiz module.

          Debug info: BIGINT UNSIGNED value is out of range in '(`ecoli2`.`qa`.`timefinish` - `ecoli2`.`qa`.`timestart`)'
          SELECT CONCAT(u.id, '#', COALESCE(qa.attempt, 0)) AS concattedid, qa.uniqueid, qa.id AS attempt, u.id AS userid, u.idnumber, u.firstname, u.lastname, u.institution, u.department, u.email, u.picture, u.imagealt, qa.sumgrades, qa.timefinish, qa.timestart, qa.timefinish - qa.timestart AS duration, qa.layout FROM mdl_user u LEFT JOIN mdl_quiz_attempts qa ON qa.userid = u.id AND qa.quiz = ? WHERE qa.id IS NOT NULL AND qa.preview = 0 ORDER BY concattedid ASC LIMIT 0, 30
          [array (
          0 => '334',
          )]

          Show
          Travis Wilhelm added a comment - I should have checked this earlier, but the same error occurs when selecting the "responses" portion of the Quiz. Below is the debug. I've updated to the latest weekly build of the quiz module. Debug info: BIGINT UNSIGNED value is out of range in '(`ecoli2`.`qa`.`timefinish` - `ecoli2`.`qa`.`timestart`)' SELECT CONCAT(u.id, '#', COALESCE(qa.attempt, 0)) AS concattedid, qa.uniqueid, qa.id AS attempt, u.id AS userid, u.idnumber, u.firstname, u.lastname, u.institution, u.department, u.email, u.picture, u.imagealt, qa.sumgrades, qa.timefinish, qa.timestart, qa.timefinish - qa.timestart AS duration, qa.layout FROM mdl_user u LEFT JOIN mdl_quiz_attempts qa ON qa.userid = u.id AND qa.quiz = ? WHERE qa.id IS NOT NULL AND qa.preview = 0 ORDER BY concattedid ASC LIMIT 0, 30 [array ( 0 => '334', )]
          Hide
          Tim Hunt added a comment -

          Doh! How did I forget to check that myself?

          Since this particular bug about the overview report is already fixed please could you create a new issue for the responses report problem. Thanks.

          Show
          Tim Hunt added a comment - Doh! How did I forget to check that myself? Since this particular bug about the overview report is already fixed please could you create a new issue for the responses report problem. Thanks.
          Hide
          Paul Nijbakker added a comment -

          This problem also affects Moodle 1.9

          Show
          Paul Nijbakker added a comment - This problem also affects Moodle 1.9
          Hide
          Tim Hunt added a comment -

          MDL-26937 is for tracking the same bug, as it affects Moodle 1.9.x

          Show
          Tim Hunt added a comment - MDL-26937 is for tracking the same bug, as it affects Moodle 1.9.x

            People

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

              Dates

              • Created:
                Updated:
                Resolved: