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

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.

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.

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.

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.

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.

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.

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?

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.

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.

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...

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.

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).

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'.

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.

OK, quba-59800.csv is attached.

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

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.

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

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.

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.

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.

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?

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.

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

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

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 |               | 
+--------+-----------+------------+---------+-----------+------------+---------------+

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.

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

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

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.

Grr, I meant MDL-34532

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!