Moodle
  1. Moodle
  2. MDL-34251

Cron task never finishes. Gets to line 'Looking for quiz overdue quiz attempts between Wednesday, 31 December 1969, 6:00 PM...' then never advances

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 2.3.1
    • Fix Version/s: 2.2.5, 2.3.2
    • Component/s: Quiz
    • Labels:
    • Testing Instructions:
      Hide

      1. Running the unit tests should be sufficient.

      2. You could also do a basic test of attempting a quiz, and regrading, say, just to make sure there are no regressions caused by these changes.

      Show
      1. Running the unit tests should be sufficient. 2. You could also do a basic test of attempting a quiz, and regrading, say, just to make sure there are no regressions caused by these changes.
    • Affected Branches:
      MOODLE_23_STABLE
    • Fixed Branches:
      MOODLE_22_STABLE, MOODLE_23_STABLE
    • Pull from Repository:
    • Pull Master Branch:

      Description

      Related to http://tracker.moodle.org/browse/MDL-34109

      Cron script runs, but gets stuck at 'Looking for quiz overdue quiz attempts'. Checking SQL server, the cron is executing the following statements in an endless loop:

      SELECT q.*, qc.contextid
      FROM moodle.mdl_question q
      JOIN moodle.mdl_question_categories qc ON q.category = qc.id
      WHERE q.id = '4549'
      (1 row returned)

      SELECT * FROM moodle.mdl_question_hints WHERE questionid = '4549' ORDER BY id ASC
      (0 rows returned)

      SELECT * FROM moodle.mdl_question_multichoice WHERE question = '4549'.
      (1 row returned)

      SELECT * FROM moodle.mdl_question_answers WHERE question = '4549' ORDER BY id ASC
      (4 rows returned)

      Running https://github.com/moodle/moodle/blob/master/mod/quiz/cronlib.php#L91 by hand yields 140 records, so this isn't a huge database

        Gliffy Diagrams

        1. mdl19-attempts.csv
          343 kB
          Brian King
        2. mdl19-quiz-detail.csv
          1 kB
          Brian King
        3. quba-59800.csv
          1 kB
          Brian King
        1. question_attempt-load_from_records-object_values.jpg
          235 kB

          Issue Links

            Activity

            Hide
            Tim Hunt added a comment -

            Are you using a version of Moodle that includes the fix for MDL-34109?

            When you say the results repeat those 4 queries in an infinite loop, are you sure the loop is infinite, or is it just going through that loop 140 times?

            And, when you say it is the same query in the infinite loop, is it the same questionid every time?

            I would actually expect it to do those queries once for each question in each attempt - so more than 140 times.

            Show
            Tim Hunt added a comment - Are you using a version of Moodle that includes the fix for MDL-34109 ? When you say the results repeat those 4 queries in an infinite loop, are you sure the loop is infinite, or is it just going through that loop 140 times? And, when you say it is the same query in the infinite loop, is it the same questionid every time? I would actually expect it to do those queries once for each question in each attempt - so more than 140 times.
            Hide
            Ben Steeples added a comment -

            Running Moodle 2.3.1 (Build: 20120706)

            I ran the cron for nearly 4 hours this morning, and it's looping through the same 4 queries and question id (4549).

            I also did a bit of debugging, it seems to reach https://github.com/moodle/moodle/blob/master/mod/quiz/cronlib.php#L78 in cronlib, then start the infinite loop. I didn't investigate what "new quiz_attempt($attempt, $quizforuser, $cm, $course);" actually does.

            Show
            Ben Steeples added a comment - Running Moodle 2.3.1 (Build: 20120706) I ran the cron for nearly 4 hours this morning, and it's looping through the same 4 queries and question id (4549). I also did a bit of debugging, it seems to reach https://github.com/moodle/moodle/blob/master/mod/quiz/cronlib.php#L78 in cronlib, then start the infinite loop. I didn't investigate what "new quiz_attempt($attempt, $quizforuser, $cm, $course);" actually does.
            Hide
            Tim Hunt added a comment -

            new quiz_attempt($attempt, $quizforuser, $cm, $course); is loading the all the quiz attempt data, so that it can be processed. This is exactly what the quiz does when you go to mod/quiz/review.php.

            Are you able to find the attemptid for the attempt where cron gets stuck? For example you could add

            mtrace('    Processing attempt ' . $attempt->id);
            

            just after the line

            foreach ($attemptstoprocess as $attempt) {
            

            which will give you more information about what is going on.

            If you can do that, then go to

            http://.../mod/quiz/review.php?attemptid=...

            and see if that page loads.

            Show
            Tim Hunt added a comment - new quiz_attempt($attempt, $quizforuser, $cm, $course); is loading the all the quiz attempt data, so that it can be processed. This is exactly what the quiz does when you go to mod/quiz/review.php. Are you able to find the attemptid for the attempt where cron gets stuck? For example you could add mtrace(' Processing attempt ' . $attempt->id); just after the line foreach ($attemptstoprocess as $attempt) { which will give you more information about what is going on. If you can do that, then go to http://.../mod/quiz/review.php?attemptid= ... and see if that page loads.
            Hide
            Ben Steeples added a comment -

            Ok, cron gets to:

            Processing attempt 13949
            

            The, loading http://.../mod/quiz/review.php?attemptid=13949 shows:

            Debug info:
            Error code: missingparam
            Stack trace:
             
                line 467 of /lib/setuplib.php: moodle_exception thrown
                line 508 of /lib/moodlelib.php: call to print_error()
                line 33 of /mod/quiz/review.php: call to required_param()
            

            I checked another attempt and review.php loaded correctly.

            Show
            Ben Steeples added a comment - Ok, cron gets to: Processing attempt 13949 The, loading http://.../mod/quiz/review.php?attemptid=13949 shows: Debug info: Error code: missingparam Stack trace:   line 467 of /lib/setuplib.php: moodle_exception thrown line 508 of /lib/moodlelib.php: call to print_error() line 33 of /mod/quiz/review.php: call to required_param() I checked another attempt and review.php loaded correctly.
            Hide
            Tim Hunt added a comment -

            Sorry, I got that wrong, the review URL needs to be

            http://.../mod/quiz/review.php?attempt=13949

            (no id).

            Please can you try again.

            Show
            Tim Hunt added a comment - Sorry, I got that wrong, the review URL needs to be http://.../mod/quiz/review.php?attempt=13949 (no id). Please can you try again.
            Hide
            Ben Steeples added a comment -

            No problem.

            Loading that page causes the browser to go into an indefinite 'connecting/loading page' state. ie. nothing is returned to the browser, but the server isn't terminating the connection either.

            Show
            Ben Steeples added a comment - No problem. Loading that page causes the browser to go into an indefinite 'connecting/loading page' state. ie. nothing is returned to the browser, but the server isn't terminating the connection either.
            Hide
            Tõnis Tartes added a comment -

            Tim, could you please help?
            After upgrade to 2.3.1+ i have got the same problem that my cron never finishes.

            Log:
            Processing module function quiz_cron ...
            Looking for quiz overdue quiz attempts between neljapäev, 1. jaanuar 1970, 02:00 and esmaspäev, 16. juuli 2012, 11:20...
            !!! Vigane valemi süntaks algusega '0.1*(((8.0)(2*(0.09)))*2) ((2.6)(0.09)) !!!
            !!
            Error code: illegalformulasyntax !!
            !! Stack trace: * line 356 of /question/type/calculated/question.php: moodle_exception thrown

            • line 344 of /question/type/calculated/question.php: call to qtype_calculated_variable_substituter->calculate_raw()
            • line 70 of /question/type/calculated/question.php: call to qtype_calculated_variable_substituter->calculate()
            • line 150 of /question/type/calculated/question.php: call to qtype_calculated_question->calculate_all_expressions()
            • line 59 of /question/type/calculated/question.php: call to qtype_calculated_question_helper::apply_attempt_state()
            • line 1220 of /question/engine/questionattempt.php: call to qtype_calculated_question->apply_attempt_state()
            • line 721 of /question/engine/questionusage.php: call to question_attempt::load_from_records()
            • line 344 of /question/engine/datalib.php: call to question_usage_by_activity::load_from_records()
            • line 78 of /question/engine/lib.php: call to question_engine_data_mapper->load_questions_usage_by_activity()
            • line 468 of /mod/quiz/attemptlib.php: call to question_engine::load_questions_usage_by_activity()
            • line 78 of /mod/quiz/cronlib.php: call to quiz_attempt->__construct()
            • line 469 of /mod/quiz/lib.php: call to mod_quiz_overdue_attempt_updater->update_overdue_attempts()
            • line 259 of /lib/cronlib.php: call to quiz_cron()
            • line 88 of /admin/cron.php: call to cron_run()
              !!

            For what i understand, it has wrong formula syntax, but could you give me any suggestions, what is wrong with the syntax and how to fix it?

            Show
            Tõnis Tartes added a comment - Tim, could you please help? After upgrade to 2.3.1+ i have got the same problem that my cron never finishes. Log: Processing module function quiz_cron ... Looking for quiz overdue quiz attempts between neljapäev, 1. jaanuar 1970, 02:00 and esmaspäev, 16. juuli 2012, 11:20... !!! Vigane valemi süntaks algusega '0.1*(((8.0) (2*(0.09)))* 2) ((2.6) (0.09)) !!! !! Error code: illegalformulasyntax !! !! Stack trace: * line 356 of /question/type/calculated/question.php: moodle_exception thrown line 344 of /question/type/calculated/question.php: call to qtype_calculated_variable_substituter->calculate_raw() line 70 of /question/type/calculated/question.php: call to qtype_calculated_variable_substituter->calculate() line 150 of /question/type/calculated/question.php: call to qtype_calculated_question->calculate_all_expressions() line 59 of /question/type/calculated/question.php: call to qtype_calculated_question_helper::apply_attempt_state() line 1220 of /question/engine/questionattempt.php: call to qtype_calculated_question->apply_attempt_state() line 721 of /question/engine/questionusage.php: call to question_attempt::load_from_records() line 344 of /question/engine/datalib.php: call to question_usage_by_activity::load_from_records() line 78 of /question/engine/lib.php: call to question_engine_data_mapper->load_questions_usage_by_activity() line 468 of /mod/quiz/attemptlib.php: call to question_engine::load_questions_usage_by_activity() line 78 of /mod/quiz/cronlib.php: call to quiz_attempt->__construct() line 469 of /mod/quiz/lib.php: call to mod_quiz_overdue_attempt_updater->update_overdue_attempts() line 259 of /lib/cronlib.php: call to quiz_cron() line 88 of /admin/cron.php: call to cron_run() !! For what i understand, it has wrong formula syntax, but could you give me any suggestions, what is wrong with the syntax and how to fix it?
            Hide
            Tim Hunt added a comment -

            Ben, that is progress of a sort. It is much easier to debug a problem that occurs when you visit on URL in your web browser, compared to a problem that can only be triggered in the middle of cron.

            It looks like we are getting the same infinite loop in both cases, but I cannot understand how that might be happening. Do you feel like tracing what happens when you go to the review.php URL. Basically go through review.php and add

            echo 'Got to line X';
            

            statements throughout the code, to try to work out exactly where the problem is.

            Tonis, your problem has a different cause, so I have created a separate issue, MDL-34351, to track it.

            Show
            Tim Hunt added a comment - Ben, that is progress of a sort. It is much easier to debug a problem that occurs when you visit on URL in your web browser, compared to a problem that can only be triggered in the middle of cron. It looks like we are getting the same infinite loop in both cases, but I cannot understand how that might be happening. Do you feel like tracing what happens when you go to the review.php URL. Basically go through review.php and add echo 'Got to line X'; statements throughout the code, to try to work out exactly where the problem is. Tonis, your problem has a different cause, so I have created a separate issue, MDL-34351 , to track it.
            Hide
            Brian King added a comment - - edited

            I'm seeing this too on a Moodle upgraded to 2.3.1. Cron keeps running forever, the last sign of action is "Looking for quiz overdue quiz attempts between Thursday, 1. January 1970, 01:00 and Monday, 16. July 2012, 16:55...". Well, it's keeping apache and postgresql busy.

            I'll try to pinpoint where it's getting lost. For the momement, in my case, it's not coming back after it calls

            $attemptobj = quiz_attempt::create($attemptid);
            

            when i try to review one of these quiz attempts.

            Will follow up later ... but it might be a day or two before I can get back to it.

            Show
            Brian King added a comment - - edited I'm seeing this too on a Moodle upgraded to 2.3.1. Cron keeps running forever, the last sign of action is "Looking for quiz overdue quiz attempts between Thursday, 1. January 1970, 01:00 and Monday, 16. July 2012, 16:55...". Well, it's keeping apache and postgresql busy. I'll try to pinpoint where it's getting lost. For the momement, in my case, it's not coming back after it calls $attemptobj = quiz_attempt::create($attemptid); when i try to review one of these quiz attempts. Will follow up later ... but it might be a day or two before I can get back to it.
            Hide
            Darko Grabar added a comment - - edited

            Same problem here, Moodle 2.3.1., postgresql database. Moodle was upgraded from 1.9.18 -> 2.2 ->2.3.

            Looking for quiz overdue quiz attempts between Thursday, 1 January 1970, 2:00 AM and Monday, 16 July 2012, 5:25 PM...

            Show
            Darko Grabar added a comment - - edited Same problem here, Moodle 2.3.1., postgresql database. Moodle was upgraded from 1.9.18 -> 2.2 ->2.3. Looking for quiz overdue quiz attempts between Thursday, 1 January 1970, 2:00 AM and Monday, 16 July 2012, 5:25 PM...
            Hide
            Brian King added a comment -

            Tim, this bit of code never advances, does it? Shouldn't it be calling $records->next() instead or $records->current()?

            lines 717 - 727 of question/engine/questionusage.php

                    while ($record && $record->qubaid == $qubaid && !is_null($record->slot)) {
                        $quba->questionattempts[$record->slot] =
                                question_attempt::load_from_records($records,
                                $record->questionattemptid, $quba->observer,
                                $quba->get_preferred_behaviour());
                        if ($records->valid()) {
                            $record = $records->current();
                        } else {
                            $record = false;
                        }
                    }
            

            This is where it seems to be getting stuck by me.

            Show
            Brian King added a comment - Tim, this bit of code never advances, does it? Shouldn't it be calling $records->next() instead or $records->current()? lines 717 - 727 of question/engine/questionusage.php while ($record && $record->qubaid == $qubaid && !is_null($record->slot)) { $quba->questionattempts[$record->slot] = question_attempt::load_from_records($records, $record->questionattemptid, $quba->observer, $quba->get_preferred_behaviour()); if ($records->valid()) { $record = $records->current(); } else { $record = false; } } This is where it seems to be getting stuck by me.
            Hide
            Tim Hunt added a comment -

            I am pretty sure question_attempt::load_from_records should always advance at least one record (because question_attempt_step::load_from_records always advances at least one record).

            Show
            Tim Hunt added a comment - I am pretty sure question_attempt::load_from_records should always advance at least one record (because question_attempt_step::load_from_records always advances at least one record).
            Hide
            Brian King added a comment - - edited

            Tim, in this case $records is not getting advanced in question_attempt::load_from_records. The attached screenshot question_attempt-load_from_records-object_values shows a set of object values in question_attempt::load_from_records that result in $records not getting advanced.

            question_engine_data_mapper->load_questions_usage_by_activity(), which is called earlier, returns 6 records, all of which have questionid = 0.

            Looking in the database, I see that 3412 out of 1270247 records in mdl_question_attempts that have questionid = 0.

            Another piece of information, in case it's helpful: all of the questions in this quiz are of type 'random'.

            Show
            Brian King added a comment - - edited Tim, in this case $records is not getting advanced in question_attempt::load_from_records. The attached screenshot question_attempt-load_from_records-object_values shows a set of object values in question_attempt::load_from_records that result in $records not getting advanced. question_engine_data_mapper->load_questions_usage_by_activity(), which is called earlier, returns 6 records, all of which have questionid = 0. Looking in the database, I see that 3412 out of 1270247 records in mdl_question_attempts that have questionid = 0. Another piece of information, in case it's helpful: all of the questions in this quiz are of type 'random'.
            Hide
            Tim Hunt added a comment -

            Obviously, questionid = 0 should never happen. The fact it relates to random questions suggests to me that these are old attempts upgraded from Moodle <= 2.0, and the data was bad before the upgrade.

            The screen-grab is not really the information I need. What would be most useful is:

            Take the SQL query from question_engine_data_mapper->load_questions_usage_by_activity (with one of the usage ids that causes the problem) and save the data that it outputs as a .csv file, then attach that here.

            Show
            Tim Hunt added a comment - Obviously, questionid = 0 should never happen. The fact it relates to random questions suggests to me that these are old attempts upgraded from Moodle <= 2.0, and the data was bad before the upgrade. The screen-grab is not really the information I need. What would be most useful is: Take the SQL query from question_engine_data_mapper->load_questions_usage_by_activity (with one of the usage ids that causes the problem) and save the data that it outputs as a .csv file, then attach that here.
            Hide
            Brian King added a comment -

            OK, quba-59800.csv is attached.

            Show
            Brian King added a comment - OK, quba-59800.csv is attached.
            Hide
            Ben Steeples added a comment -

            Tim,

            re: http://.../mod/quiz/review.php?attempt=13949

            Tried to add some debug comments, but the page isn't sending any output to the browser, so it's tricky to debug where it's reaching. Any ideas?

            Thanks,
            Ben

            Show
            Ben Steeples added a comment - Tim, re: http://.../mod/quiz/review.php?attempt=13949 Tried to add some debug comments, but the page isn't sending any output to the browser, so it's tricky to debug where it's reaching. Any ideas? Thanks, Ben
            Hide
            Tim Hunt added a comment -

            That is seriously screwed up data! It seems that you have question_attempts with no question_attempt_steps, and that really should never happen.

            OK, so since we have found that this happens in practice, I need to make the code robust so that this does not cause an infinite loop.

            Meanwhile, you probably need to clean up the mess in your database manually. One thing you could do is to go to Home ► Site administration ► Development ► XMLDB editor and use the [Check foreign keys] option. It seems you know a bit about databases, and will understand what you are doing.

            That is a general check. To investigate your specific problem, try a query like:

            SELECT
                qa.questionusageid,
                qa.id AS question_attemtp_id,
                quiza.id AS quiz_attempt_id
             
            FROM q_question_attempts qa
            LEFT JOIN q_question_attempt_steps qas ON qas.questionattemptid = qa.id
            LEFT JOIN q_quiz_attempts quiza ON quiza.uniqueid = qa.questionusageid
             
            WHERE qas.id IS NULL
             
            ORDER BY quiza.quiz
            

            That will find all the question_usages, and associated quiz_attempts, where there are question_attempts that don't have any steps. So, on a healthy Moodle site, that query should return 0 rows.

            You need to have a look at the rows that it does return on your site and decide if there is any useful data there. Hopefully all the data that is there is real garbage, and you can just delete it. If so, that is simple. Have a look at delete_questions_usage_by_activities in question/engine/datalib.php to see what needs to be deleted, and then delete the corresponding quiz_attempts rows.

            If the data that remains in those garbled attempts is important, then you have a bigger problem.

            Show
            Tim Hunt added a comment - That is seriously screwed up data! It seems that you have question_attempts with no question_attempt_steps, and that really should never happen. OK, so since we have found that this happens in practice, I need to make the code robust so that this does not cause an infinite loop. Meanwhile, you probably need to clean up the mess in your database manually. One thing you could do is to go to Home ► Site administration ► Development ► XMLDB editor and use the [Check foreign keys] option. It seems you know a bit about databases, and will understand what you are doing. That is a general check. To investigate your specific problem, try a query like: SELECT qa.questionusageid, qa.id AS question_attemtp_id, quiza.id AS quiz_attempt_id   FROM q_question_attempts qa LEFT JOIN q_question_attempt_steps qas ON qas.questionattemptid = qa.id LEFT JOIN q_quiz_attempts quiza ON quiza.uniqueid = qa.questionusageid   WHERE qas.id IS NULL   ORDER BY quiza.quiz That will find all the question_usages, and associated quiz_attempts, where there are question_attempts that don't have any steps. So, on a healthy Moodle site, that query should return 0 rows. You need to have a look at the rows that it does return on your site and decide if there is any useful data there. Hopefully all the data that is there is real garbage, and you can just delete it. If so, that is simple. Have a look at delete_questions_usage_by_activities in question/engine/datalib.php to see what needs to be deleted, and then delete the corresponding quiz_attempts rows. If the data that remains in those garbled attempts is important, then you have a bigger problem.
            Hide
            Tim Hunt added a comment -

            Debug messages not showing up probably means that your site is configured to use gzip compression or output buffering, or something like that.

            Show
            Tim Hunt added a comment - Debug messages not showing up probably means that your site is configured to use gzip compression or output buffering, or something like that.
            Hide
            Tim Hunt added a comment -

            Right, I think this should fix it. With luck it will be integrated into next week's weekly build.

            Ben, Brian, or anyone else who has this problem: if you can try applying the patch this week, and confirm that it solves the problem, then that would be really helpful.

            Show
            Tim Hunt added a comment - Right, I think this should fix it. With luck it will be integrated into next week's weekly build. Ben, Brian, or anyone else who has this problem: if you can try applying the patch this week, and confirm that it solves the problem, then that would be really helpful.
            Hide
            Brian King added a comment - - edited

            I can confirm that it lets cron complete for my case.

            In my case, the problem is restricted to just two courses and six quizzes, so probably not the end of the world. The problem seems to exist for all attempts of these six quizzes. This is a Moodle that started life at 1.6, and was most recently upgraded from 1.9.12 to 1.9.latest -> 2.2.latest -> 2.3.1.

            Interestingly, reviewing these troublesome attempts in the still-running Moodle 1.9.12 works fine. It seems something went wrong during the upgrade. The data got borked somehow, and now reviewing one of these attempts with the borked data and Tim's patch shows an error "Coding error detected, it must be fixed by a programmer: Unexpected question state."

            Reviewing attempts in 1.9.12 for one of the six problem quizzes shows "The number of random questions required is more than are still available in the category!" for one of the questions. Reviewing attempts for the other five quizzes doesn't reveal anything weird. All of these six quizzes are composed exclusively of questions of type "random". The most recent problematic attempts happened when the Moodle was already running 1.9.12.

            Show
            Brian King added a comment - - edited I can confirm that it lets cron complete for my case. In my case, the problem is restricted to just two courses and six quizzes, so probably not the end of the world. The problem seems to exist for all attempts of these six quizzes. This is a Moodle that started life at 1.6, and was most recently upgraded from 1.9.12 to 1.9.latest -> 2.2.latest -> 2.3.1. Interestingly, reviewing these troublesome attempts in the still-running Moodle 1.9.12 works fine. It seems something went wrong during the upgrade. The data got borked somehow, and now reviewing one of these attempts with the borked data and Tim's patch shows an error "Coding error detected, it must be fixed by a programmer: Unexpected question state." Reviewing attempts in 1.9.12 for one of the six problem quizzes shows "The number of random questions required is more than are still available in the category!" for one of the questions. Reviewing attempts for the other five quizzes doesn't reveal anything weird. All of these six quizzes are composed exclusively of questions of type "random". The most recent problematic attempts happened when the Moodle was already running 1.9.12.
            Hide
            Tim Hunt added a comment -

            Odd. I suppose this means you have found an upgrade bug. Could you run this query: http://docs.moodle.org/dev/Question_database_structure#Following_what_happens_when_questions_are_attempted on the Moodle 1.9 database, for these attemts, and attach the CVS file. I guess it would also be good to have the corresponding quiz settings and question definitions, if possible, but with random questions, working out what are the corresponding question definitions can be tricky.

            Show
            Tim Hunt added a comment - Odd. I suppose this means you have found an upgrade bug. Could you run this query: http://docs.moodle.org/dev/Question_database_structure#Following_what_happens_when_questions_are_attempted on the Moodle 1.9 database, for these attemts, and attach the CVS file. I guess it would also be good to have the corresponding quiz settings and question definitions, if possible, but with random questions, working out what are the corresponding question definitions can be tricky.
            Hide
            Brian King added a comment -

            Attached mdl19-attempts.csv with the attempt data, and mdl19-quiz-detail.csv with the quiz details (with courseid, name, intro anonymized).

            What sort of question detail would you want for the used questions? I see things like 'random94527-...' in mdl19-attempts.csv, which I take to mean that it used the "real" question 94527. Do you want details just from the mdl_question table, or also from the specific question type tables?

            Show
            Brian King added a comment - Attached mdl19-attempts.csv with the attempt data, and mdl19-quiz-detail.csv with the quiz details (with courseid, name, intro anonymized). What sort of question detail would you want for the used questions? I see things like 'random94527-...' in mdl19-attempts.csv, which I take to mean that it used the "real" question 94527. Do you want details just from the mdl_question table, or also from the specific question type tables?
            Hide
            Tim Hunt added a comment -

            Hmm, that all looks quite like how one would expect.

            I don't really need to see the details of the questions. I think we just need to know that the questions exist, and I think we should check that both questions exist, the random question that will be pointed to by question_states.question, and the real question used, which is the id from 'random94527-...' as you correctly guessed.

            Show
            Tim Hunt added a comment - Hmm, that all looks quite like how one would expect. I don't really need to see the details of the questions. I think we just need to know that the questions exist, and I think we should check that both questions exist, the random question that will be pointed to by question_states.question, and the real question used, which is the id from 'random94527-...' as you correctly guessed.
            Hide
            Darko Grabar added a comment -

            Hi, I can also confirm that your patch resolves the problem.
            Thanks

            Show
            Darko Grabar added a comment - Hi, I can also confirm that your patch resolves the problem. Thanks
            Hide
            Dan Poltawski added a comment -

            The main moodle.git repository has just been updated with latest weekly modifications. You may wish to rebase your PULL branches to simplify history and avoid any possible merge conflicts. This would also make integrator's life easier next week.

            TIA and ciao

            Show
            Dan Poltawski added a comment - The main moodle.git repository has just been updated with latest weekly modifications. You may wish to rebase your PULL branches to simplify history and avoid any possible merge conflicts. This would also make integrator's life easier next week. TIA and ciao
            Hide
            Brian King added a comment -

            Tim, for the data related to mdl19-attempts.csv, I found that all of the used random questions exist. There was one real question missing. This is the case for the quiz with id 3039 (this is the quiz that shows "The number of random questions required is more than are still available in the category!" when reviewing attempts in Moodle 1.9). The data in mdl19-attempts.csv is actually only for this one quiz.

            I noticed for 6 of the 7 problem quizzes, http://docs.moodle.org/dev/Question_database_structure#Following_what_happens_when_questions_are_attempted returns no rows when run against the Moodle 1.9 database (my where clause is "WHERE quiza.quiz in (1465,1466,1467,1468,1469,1470,3039)") It is however possible to review these attempts in the browser. These 6 quizzes and their attempts all date from 2009.

            Here's some data from one of the attempts that shows why no data is returned; the questionids do not match:

            > select * from mdl_question_states where attempt=59823;
            +---------+---------+----------+------------------+------------+-------------------------------------------------------+------------+-------+-------+-----------+---------+
            | id      | attempt | question | originalquestion | seq_number | answer                                                | timestamp  | event | grade | raw_grade | penalty |
            +---------+---------+----------+------------------+------------+-------------------------------------------------------+------------+-------+-------+-----------+---------+
            | 1958150 |   59823 |    36273 |                0 |          1 | random36273-143163                                    | 1254516546 |     6 |     1 |         1 |       1 | 
            | 1958149 |   59823 |    36274 |                0 |          1 | random36274-143165                                    | 1254516546 |     6 |     1 |         1 |       1 | 
            | 1958148 |   59823 |    36246 |                0 |          1 | random36246-143093                                    | 1254516546 |     6 |     1 |         1 |       1 | 
            | 1958147 |   59823 |    36253 |                0 |          1 | random36253-143106                                    | 1254516546 |     6 |     1 |         1 |       1 | 
            | 1958146 |   59823 |    36235 |                0 |          1 | random36235-143060,143061,143059,143058:143060        | 1254516546 |     6 |     1 |         1 |     0.1 | 
            | 1958145 |   59823 |    36240 |                0 |          1 | random36240-143082,143080,143083,143079,143081:143083 | 1254516546 |     6 |     1 |         1 |     0.1 | 
            | 1958144 |   59823 |    36235 |                0 |          0 | random36235-143060,143061,143059,143058:              | 1254515660 |     0 |     0 |         0 |       0 | 
            | 1958143 |   59823 |    36253 |                0 |          0 | random36253-                                          | 1254515660 |     0 |     0 |         0 |       0 | 
            | 1958142 |   59823 |    36240 |                0 |          0 | random36240-143082,143080,143083,143079,143081:       | 1254515660 |     0 |     0 |         0 |       0 | 
            | 1958141 |   59823 |    36274 |                0 |          0 | random36274-                                          | 1254515660 |     0 |     0 |         0 |       0 | 
            | 1958140 |   59823 |    36246 |                0 |          0 | random36246-                                          | 1254515660 |     0 |     0 |         0 |       0 | 
            | 1958139 |   59823 |    36273 |                0 |          0 | random36273-                                          | 1254515660 |     0 |     0 |         0 |       0 | 
            +---------+---------+----------+------------------+------------+-------------------------------------------------------+------------+-------+-------+-----------+---------+
             
            > select * from mdl_question_sessions where attemptid=59823;
            +--------+-----------+------------+---------+-----------+------------+---------------+
            | id     | attemptid | questionid | newest  | newgraded | sumpenalty | manualcomment |
            +--------+-----------+------------+---------+-----------+------------+---------------+
            | 742034 |     59823 |      36255 | 1958150 |   1958150 |          1 |               | 
            | 742035 |     59823 |      36256 | 1958148 |   1958148 |          1 |               | 
            | 742036 |     59823 |      36257 | 1958149 |   1958149 |          1 |               | 
            | 742037 |     59823 |      36258 | 1958145 |   1958145 |        0.1 |               | 
            | 742038 |     59823 |      36259 | 1958147 |   1958147 |          1 |               | 
            | 742039 |     59823 |      36260 | 1958146 |   1958146 |        0.1 |               | 
            +--------+-----------+------------+---------+-----------+------------+---------------+
            

            Show
            Brian King added a comment - Tim, for the data related to mdl19-attempts.csv, I found that all of the used random questions exist. There was one real question missing. This is the case for the quiz with id 3039 (this is the quiz that shows "The number of random questions required is more than are still available in the category!" when reviewing attempts in Moodle 1.9). The data in mdl19-attempts.csv is actually only for this one quiz. I noticed for 6 of the 7 problem quizzes, http://docs.moodle.org/dev/Question_database_structure#Following_what_happens_when_questions_are_attempted returns no rows when run against the Moodle 1.9 database (my where clause is "WHERE quiza.quiz in (1465,1466,1467,1468,1469,1470,3039)") It is however possible to review these attempts in the browser. These 6 quizzes and their attempts all date from 2009. Here's some data from one of the attempts that shows why no data is returned; the questionids do not match: > select * from mdl_question_states where attempt=59823; +---------+---------+----------+------------------+------------+-------------------------------------------------------+------------+-------+-------+-----------+---------+ | id | attempt | question | originalquestion | seq_number | answer | timestamp | event | grade | raw_grade | penalty | +---------+---------+----------+------------------+------------+-------------------------------------------------------+------------+-------+-------+-----------+---------+ | 1958150 | 59823 | 36273 | 0 | 1 | random36273-143163 | 1254516546 | 6 | 1 | 1 | 1 | | 1958149 | 59823 | 36274 | 0 | 1 | random36274-143165 | 1254516546 | 6 | 1 | 1 | 1 | | 1958148 | 59823 | 36246 | 0 | 1 | random36246-143093 | 1254516546 | 6 | 1 | 1 | 1 | | 1958147 | 59823 | 36253 | 0 | 1 | random36253-143106 | 1254516546 | 6 | 1 | 1 | 1 | | 1958146 | 59823 | 36235 | 0 | 1 | random36235-143060,143061,143059,143058:143060 | 1254516546 | 6 | 1 | 1 | 0.1 | | 1958145 | 59823 | 36240 | 0 | 1 | random36240-143082,143080,143083,143079,143081:143083 | 1254516546 | 6 | 1 | 1 | 0.1 | | 1958144 | 59823 | 36235 | 0 | 0 | random36235-143060,143061,143059,143058: | 1254515660 | 0 | 0 | 0 | 0 | | 1958143 | 59823 | 36253 | 0 | 0 | random36253- | 1254515660 | 0 | 0 | 0 | 0 | | 1958142 | 59823 | 36240 | 0 | 0 | random36240-143082,143080,143083,143079,143081: | 1254515660 | 0 | 0 | 0 | 0 | | 1958141 | 59823 | 36274 | 0 | 0 | random36274- | 1254515660 | 0 | 0 | 0 | 0 | | 1958140 | 59823 | 36246 | 0 | 0 | random36246- | 1254515660 | 0 | 0 | 0 | 0 | | 1958139 | 59823 | 36273 | 0 | 0 | random36273- | 1254515660 | 0 | 0 | 0 | 0 | +---------+---------+----------+------------------+------------+-------------------------------------------------------+------------+-------+-------+-----------+---------+   > select * from mdl_question_sessions where attemptid=59823; +--------+-----------+------------+---------+-----------+------------+---------------+ | id | attemptid | questionid | newest | newgraded | sumpenalty | manualcomment | +--------+-----------+------------+---------+-----------+------------+---------------+ | 742034 | 59823 | 36255 | 1958150 | 1958150 | 1 | | | 742035 | 59823 | 36256 | 1958148 | 1958148 | 1 | | | 742036 | 59823 | 36257 | 1958149 | 1958149 | 1 | | | 742037 | 59823 | 36258 | 1958145 | 1958145 | 0.1 | | | 742038 | 59823 | 36259 | 1958147 | 1958147 | 1 | | | 742039 | 59823 | 36260 | 1958146 | 1958146 | 0.1 | | +--------+-----------+------------+---------+-----------+------------+---------------+
            Hide
            Tim Hunt added a comment -

            Oh yes, if you look, question_states.question is the same as the random123 bit, not the random question. How odd. That seems sufficiently weird, and I have no idea what would have caused it, so I am not inclined to try to fix upgrade to cope with it.

            But thanks for finding out what was going on.

            Show
            Tim Hunt added a comment - Oh yes, if you look, question_states.question is the same as the random123 bit, not the random question. How odd. That seems sufficiently weird, and I have no idea what would have caused it, so I am not inclined to try to fix upgrade to cope with it. But thanks for finding out what was going on.
            Hide
            Brian King added a comment -

            Yea, OK, I agree, it's probably not worth trying to fix. Thanks for your help!

            Show
            Brian King added a comment - Yea, OK, I agree, it's probably not worth trying to fix. Thanks for your help!
            Hide
            Dan Poltawski added a comment -

            Thanks Tim, i've integrated this now.

            Thanks also to everyone on this bug who has confirmed the issue has been fixed with this patch, it really helps us integrate things more confidently

            Show
            Dan Poltawski added a comment - Thanks Tim, i've integrated this now. Thanks also to everyone on this bug who has confirmed the issue has been fixed with this patch, it really helps us integrate things more confidently
            Hide
            Dan Poltawski added a comment -

            Passing. I could regrade successfully without error.

            Note there is another issue discovered this week MDL-34251, which I have no reason to believe is related to this, but thought would mention anyway.

            Show
            Dan Poltawski added a comment - Passing. I could regrade successfully without error. Note there is another issue discovered this week MDL-34251 , which I have no reason to believe is related to this, but thought would mention anyway.
            Hide
            Dan Poltawski added a comment -

            Grr, I meant MDL-34532

            Show
            Dan Poltawski added a comment - Grr, I meant MDL-34532
            Hide
            Aparup Banerjee added a comment -

            yay, it works!

            This issue has been put through rigorous processes and finally swam upstream along with some 65 others this week.

            Thank you all for taking the time to get us here.

            cheers!

            Show
            Aparup Banerjee added a comment - yay, it works! This issue has been put through rigorous processes and finally swam upstream along with some 65 others this week. Thank you all for taking the time to get us here. cheers!

              People

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

                Dates

                • Created:
                  Updated:
                  Resolved: