ERROR: "Bitte benutzen Sie nicht den Zurück-Button", obwohl Zurückbutton nicht genutzt wurde.

ralferlebach commented 2 weeks ago

IMG_20240827_114824333

Wir sehen diesen Fehler sporadisch immer wieder in unseren Error-Logs, heute aber beim Einsatz haben wir den Fehler auch gesehen, obwohl die Personen, die diesen "produzierten", weder vorwärts, noch rückwärts navigierten und auch nicht die Seite neu luden.

ralferlebach commented 2 weeks ago

Es ist derselbe Fehler, der uns auch gestern während der Präsentation von ALiSe unterlief:

error.log

davidszkiba commented 2 weeks ago

@ralferlebach Ich hab den Fehler so reproduzieren können, wie es Tim Hunt hier beschreibt:

1. Open question in one tab.
2. Open question in a second tab.
3. In the first tab, input a response and Click check.
4. Now the first tab is showing the question with feedback, and a try again button.
5. Switch to the second tab, where the question is still shown in the initial state, with Tries remaining: 3 - which is not up-to-date.
6. If the student now tries to input a response and check, this is when the out-of-sequence error should be triggered.

Dann müssten da aber mehrere user die gleiche session verwenden - kann das sein?

Diese Fehlermeldung wird angezeigt, wenn die "sequencenumber" die mit dem HTML Formular mitgeschickt wird, nicht mit der Sequencenumber in der Datenbank für den momentanen Question Attempt übereinstimmt. Der Question Attempt wird über die slot Nummer geholt:

    public function validate_sequence_number($slot, $postdata = null) {
        $qa = $this->get_question_attempt($slot);
        $sequencecheck = $qa->get_submitted_var(
                $qa->get_control_field_name('sequencecheck'), PARAM_INT, $postdata);
        if (is_null($sequencecheck)) {
            return false;
        } else if ($sequencecheck != $qa->get_sequence_check_count()) {
            throw new question_out_of_sequence_exception($this->id, $slot, $postdata);
        } else {
            return true;
        }
    }

Es gibt eine Stelle in local_catquiz, in der mit dem slot gearbeitet wird: das passiert, wenn eine Frage beim Neuladen der Browserseite als falsch gewertet wird und stattdessen eine neue Frage angezeigt wird:

    public static function mark_last_question_failed(int $usageid) {
        global $DB;
        $quba = question_engine::load_questions_usage_by_activity($usageid);
        $slot = max($quba->get_slots());

        // Choose another valid but incorrect response.
        $correctresponse = $quba->get_correct_response($slot)['answer'];
        if ($correctresponse >= 1) {
            $response = $correctresponse - 1;
        } else {
            $response = $correctresponse + 1;
        }

        $qa = $quba->get_question_attempt($slot);
        $qa->process_action(['answer' => $response]);
        $qa->finish();
        $quba->finish_question($slot);
        question_engine::save_questions_usage_by_activity($quba);

Aber da dieser Fehler anscheinend bei ganz normaler Testnutzung ohne Neuladen der Seite auftritt, denke ich, dass es nicht daran liegen wird.

Eine weitere Idee wäre, dass es irgendwie mit der auto-save Funktion zusammenhängt, ich versuche das zu testen.

davidszkiba commented 2 weeks ago

@ralferlebach gibt es bei euch in der Datenbank negative slot Nummern?

ralferlebach commented 2 weeks ago

Errormeldung mit

question id
question usage id
(CATquiz) attempt id (wenn möglich)
user
timestamp
sequence-key für den check (welche aus dem Antwort-Request)

Wo werden die sequence-keys gespeichert?

davidszkiba commented 2 weeks ago

Wie besprochen, sind jetzt in unserem adaptivequiz fork mehr Infos zu dem Fehler: https://github.com/Wunderbyte-GmbH/moodle-mod_adaptivequiz/pull/9 Abgesehen von dem pull request, hab ich die gleichen Änderungen auch direkt in den alise_adaptivequiz branch committed.

ralferlebach commented 1 week ago

Wir haben eine erste Fehlermeldung:

Debug-Info: Array ( [debuginfo] => QUBAid: 865, slot: 3, post data: stdClass Object ( [q865:3_:sequencecheck] => 1 [q865:3_sub1_answer] => 2040,20 [submitanswer] => Antwort einreichen [cmid] => 9021 [sesskey] => 85XvMaO1st [slots] => 3 )

[questionusageid] => 865 [userid] => 4 [catquizattemptid] => 815 [currenttime] => 1725219362 [currenttime_readable] => 1. September 2024, 21:36 [attemptedquestions] => Array ( [0] => Array ( [slot] => 1 [sequencecheckcount] => 3 [question] => Array ( [qtype] => qtype_multianswer [id] => 4603 [idnumber] => MA.v1.C09-10 [last_step_modified] => 1725219264 [last_step_modified_readable] => 1. September 2024, 21:34 )

[autosavedstep] => false )

[1] => Array ( [slot] => 2 [sequencecheckcount] => 3 [question] => Array ( [qtype] => qtype_multianswer [id] => 4526 [idnumber] => MA.v1.C04-02 [last_step_modified] => 1725219327 [last_step_modified_readable] => 1. September 2024, 21:35 )

[autosavedstep] => false )

[2] => Array ( [slot] => 3 [sequencecheckcount] => 3 [question] => Array ( [qtype] => qtype_multianswer [id] => 4411 [idnumber] => MA.v1.A10-06 [last_step_modified] => 1725219358 [last_step_modified_readable] => 1. September 2024, 21:35 )

[autosavedstep] => false )

[3] => Array ( [slot] => 4 [sequencecheckcount] => 1 [question] => Array ( [qtype] => qtype_gapselect [id] => 4380 [idnumber] => MA.v1.A07-13 [last_step_modified] => 1725219362 [last_step_modified_readable] => 1. September 2024, 21:36 )

[autosavedstep] => false )

)

Error code: submissionoutofsequence

ralferlebach commented 1 week ago

Wenn ich ds richtig sehen, sollten nur drei Slots vorliegen, es sind aber 4;

Sequence-Check von Slot 3 ist 3, von Slot 4 ist 1. 1 wurde zurückgegeben, aber Slot 3 erwartet.

ralferlebach commented 1 week ago

Es scheinen sich die Hinweise darauf zu verdichten, dass etwas mit der Frage-Auswahl nicht stimmt. Es wurde immer offenbar in den Fällen, in denen der Fehler auftritt, bereits eine weitere Frage ausgewählt.

Ich habe bereits begonnen, die Error-Logs zu sichten und zu bereinigen, aber das ist angesichts der Masse an Fehlermeldungen ein schier hoffnungsloses Unterfangen: error.log

Zusätzlich erscheinen (seltener) folgende Fehler, die auch mit fehlerhafter Item-Auswahl zusammenhängen:

[Mon Sep 02 13:30:52.476882 2024] [php:notice] [pid 689370] [client 79.237.8.127:59095] Default exception handler: Fehler in der Kodierung gefunden, den nur Programmierer/innen korrigieren k\xc3\xb6nnen: There is no question_attempt number 8 in this attempt. Debug: \nError code: codingerror\n line 287 of /question/engine/questionusage.php: coding_exception thrown\n line 301 of /question/engine/questionusage.php: call to question_usage_by_activity->check_slot()\n line 793 of /question/engine/questionusage.php: call to question_usage_by_activity->get_question_attempt()\n line 639 of /question/engine/questionusage.php: call to question_usage_by_activity->validate_sequence_number()\n line 91 of /mod/adaptivequiz/classes/local/adaptive_quiz_session.php: call to question_usage_by_activity->process_all_actions()\n line 136 of /mod/adaptivequiz/attempt.php: call to mod_adaptivequiz\local\adaptive_quiz_session->process_item_result()\n, referer: https://lti.alise.uni-wuppertal.de/mod/adaptivequiz/attempt.php?cmid=9021

davidszkiba commented 6 days ago

Ich hab es nicht beheben können - hier mal eine Zusammenfassung

Was genau wird verglichen, wenn der Error ausgelöst wird?

Wichtig: der Vergleich findet nur bei POST requests statt - also wenn eine neue Antwort submitted worden ist. Grob gesagt werden versteckte Felder, die per POST gesendet worden sind, mit den Datenbank-Werten der question_usage_by_activity (quba) verglichen.

Daten aus der Datenbank: Es wird eine $quba mit question_engine::load_questions_usage_by_activity($qubaid); ausgelesen. Diese Werte kommen direkt aus der Datenbank (werden mit question_engine_data_mapper->load_questions_usage_by_activity($id) gelesen). Das $quba Objekt enthält dann eine $questionattempts property - ein array mit $slot als Index und $questionattempt als Wert.

Daten vom POST request: Der slot wird aus dem hidden HTML field slot ausgelesen. Für alle slots (ist bei uns immer nur einer), werden dann die sequencecheck Nummern verglichen. Genauer gesagt, wird das hidden HTML Field sequencecheck mit der Anzahl an attemptsteps aus dem questionattempt in slot $slot verglichen.

Wenn der Vergleich in Ordnung ist, wird die Antwort aus den POST Daten verwertet. Danach wird ein redirect auf attempt.php getriggert.

Wie werden die Werte für die hidden HTML Felder berechnet?

Das passiert im GET request

Es wird eine neue Frage ausgewählt und als questionattempt zur $quba hinzugefügt. Die neue Frage hat den nächst höheren slot (also praktisch count($quba->questionattempts)).
- slot: Die slot Nummer kommt aus der $quba - das ist die Nummer von der Frage, die gerade hinzugefügt worden ist.
sequencecheck: Kommt auch vom $quba Objekt. Hole attempt von slot $slot und zähle die Anzahl an steps - normalerweise ist das 1, weil die Frage ja gerade erst hinzugefügt worden ist, und state todo hat.

Ursache für den Fehler

Da die Daten (slots etc) von der $quba direkt aus der Datenbank geholt werden, ist für mich die einzige Erklärung für den submissionoutofsequence Error, dass eine neue Frage zur $quba hinzugefügt wird, bevor der user das HTML Formular abschickt. Es gibt eine verdächtige Stelle in local catquiz: https://github.com/Wunderbyte-GmbH/moodle-local_catquiz/blob/main/classes/catquiz.php#L2149 ... aber laut event logs ist das nicht der Auslöser.

davidszkiba commented 6 days ago

Es ist bei anderen auch schon aufgetreten, allerdings ist das schon länger her: https://moodle.org/mod/forum/discuss.php?d=311999

Vielleicht würde es helfen, sich die fehlerhaften attempts hiermit genauer anzusehen: https://docs.moodle.org/dev/Overview_of_the_Moodle_question_engine#Detailed_data_about_an_attempt

ralferlebach commented 5 days ago

Hier einmal Fehlermeldung sowie zugehörige Event- und Questionbank-Einträge:

[Tue Sep 10 02:03:07.197393 2024] [php:notice] [pid 864866] [client 104.28.54.63:56127] Default exception handler: Benutzen Sie nicht den Zur\xc3\xbcck-Button, wenn Sie Fragen bearbeiten. Debug: Array\n(\n [debuginfo] => QUBAid: 2311, slot: 8, post data: stdClass Object\n(\n [q2311:8_:sequencecheck] => 1\n [q2311:8_answer] => 2\n [submitanswer] => Antwort einreichen\n [cmid] => 10504\n [sesskey] => 0YDGuGvWWR\n [slots] => 8\n)\n\n [questionusageid] => 2311\n [userid] => 4417\n [catquizattemptid] => 2252\n [currenttime] => 1725926587\n [currenttime_readable] => 10. September 2024, 02:03\n [attemptedquestions] => Array\n (\n [0] => Array\n (\n [slot] => 1\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4647\n [idnumber] => MA.v1.D01-19\n [last_step_modified] => 1725926351\n [last_step_modified_readable] => 10. September 2024, 01:59\n )\n\n [autosavedstep] => false\n )\n\n [1] => Array\n (\n [slot] => 2\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_truefalse\n [id] => 4700\n [idnumber] => MA.v1.D06-03\n [last_step_modified] => 1725926365\n [last_step_modified_readable] => 10. September 2024, 01:59\n )\n\n [autosavedstep] => false\n )\n\n [2] => Array\n (\n [slot] => 3\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_gapselect\n [id] => 4346\n [idnumber] => MA.v1.A05-04\n [last_step_modified] => 1725926428\n [last_step_modified_readable] => 10. September 2024, 02:00\n )\n\n [autosavedstep] => false\n )\n\n [3] => Array\n (\n [slot] => 4\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4318\n [idnumber] => MA.v1.A03-13\n [last_step_modified] => 1725926465\n [last_step_modified_readable] => 10. September 2024, 02:01\n )\n\n [autosavedstep] => false\n )\n\n [4] => Array\n (\n [slot] => 5\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4696\n [idnumber] => MA.v1.D06-02\n [last_step_modified] => 1725926496\n [last_step_modified_readable] => 10. September 2024, 02:01\n )\n\n [autosavedstep] => false\n )\n\n [5] => Array\n (\n [slot] => 6\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_gapselect\n [id] => 4380\n [idnumber] => MA.v1.A07-13\n [last_step_modified] => 1725926559\n [last_step_modified_readable] => 10. September 2024, 02:02\n )\n\n [autosavedstep] => false\n )\n\n [6] => Array\n (\n [slot] => 7\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_truefalse\n [id] => 4321\n [idnumber] => MA.v1.A03-10\n [last_step_modified] => 1725926570\n [last_step_modified_readable] => 10. September 2024, 02:02\n )\n\n [autosavedstep] => false\n )\n\n [7] => Array\n (\n [slot] => 8\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_multichoice\n [id] => 4628\n [idnumber] => MA.v1.D01-05\n [last_step_modified] => 1725926584\n [last_step_modified_readable] => 10. September 2024, 02:03\n )\n\n [autosavedstep] => false\n )\n\n [8] => Array\n (\n [slot] => 9\n [sequencecheckcount] => 1\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4349\n [idnumber] => MA.v1.A05-06\n [last_step_modified] => 1725926587\n [last_step_modified_readable] => 10. September 2024, 02:03\n )\n\n [autosavedstep] => false\n )\n\n )\n\n)\n\nError code: submissionoutofsequence\n line 125 of /mod/adaptivequiz/classes/local/adaptive_quiz_session.php: moodle_exception thrown\n line 136 of /mod/adaptivequiz/attempt.php: call to mod_adaptivequiz\local\adaptive_quiz_session->process_item_result()\n, referer: https://lti.alise.uni-wuppertal.de/mod/adaptivequiz/attempt.php?cmid=10504

[Tue Sep 10 09:04:53.091800 2024] [php:notice] [pid 873303] [client 93.132.13.104:51955] Default exception handler: Benutzen Sie nicht den Zur\xc3\xbcck-Button, wenn Sie Fragen bearbeiten. Debug: Array\n(\n [debuginfo] => QUBAid: 2313, slot: 5, post data: stdClass Object\n(\n [q2313:5_:sequencecheck] => 1\n [q2313:5_sub1_answer] => 0\n [q2313:5_sub2_answer] => -5\n [submitanswer] => Antwort einreichen\n [cmid] => 10504\n [sesskey] => Vs7mhjL466\n [slots] => 5\n)\n\n [questionusageid] => 2313\n [userid] => 4262\n [catquizattemptid] => 2254\n [currenttime] => 1725951893\n [currenttime_readable] => 10. September 2024, 09:04\n [attemptedquestions] => Array\n (\n [0] => Array\n (\n [slot] => 1\n [sequencecheckcount] => 2\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4546\n [idnumber] => MA.v1.C04-10\n [last_step_modified] => 1725951141\n [last_step_modified_readable] => 10. September 2024, 08:52\n )\n\n [autosavedstep] => false\n )\n\n [1] => Array\n (\n [slot] => 2\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_truefalse\n [id] => 4700\n [idnumber] => MA.v1.D06-03\n [last_step_modified] => 1725951180\n [last_step_modified_readable] => 10. September 2024, 08:53\n )\n\n [autosavedstep] => false\n )\n\n [2] => Array\n (\n [slot] => 3\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4736\n [idnumber] => MA.v1.D08-07\n [last_step_modified] => 1725951255\n [last_step_modified_readable] => 10. September 2024, 08:54\n )\n\n [autosavedstep] => false\n )\n\n [3] => Array\n (\n [slot] => 4\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4526\n [idnumber] => MA.v1.C04-02\n [last_step_modified] => 1725951589\n [last_step_modified_readable] => 10. September 2024, 08:59\n )\n\n [autosavedstep] => false\n )\n\n [4] => Array\n (\n [slot] => 5\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4740\n [idnumber] => MA.v1.D08-09\n [last_step_modified] => 1725951868\n [last_step_modified_readable] => 10. September 2024, 09:04\n )\n\n [autosavedstep] => false\n )\n\n [5] => Array\n (\n [slot] => 6\n [sequencecheckcount] => 1\n [question] => Array\n (\n [qtype] => qtype_multichoice\n [id] => 4491\n [idnumber] => MA.v1.C01-02\n [last_step_modified] => 1725951871\n [last_step_modified_readable] => 10. September 2024, 09:04\n )\n\n [autosavedstep] => false\n )\n\n )\n\n)\n\nError code: submissionoutofsequence\n line 125 of /mod/adaptivequiz/classes/local/adaptive_quiz_session.php: moodle_exception thrown\n line 136 of /mod/adaptivequiz/attempt.php: call to mod_adaptivequiz\local\adaptive_quiz_session->process_item_result()\n, referer: https://lti.alise.uni-wuppertal.de/mod/adaptivequiz/attempt.php?cmid=10504

[Tue Sep 10 09:05:01.135487 2024] [php:notice] [pid 873304] [client 93.132.13.104:51956] Default exception handler: Benutzen Sie nicht den Zur\xc3\xbcck-Button, wenn Sie Fragen bearbeiten. Debug: Array\n(\n [debuginfo] => QUBAid: 2313, slot: 5, post data: stdClass Object\n(\n [q2313:5_:sequencecheck] => 1\n [q2313:5_sub1_answer] => 0\n [q2313:5_sub2_answer] => -5\n [submitanswer] => Antwort einreichen\n [cmid] => 10504\n [sesskey] => Vs7mhjL466\n [slots] => 5\n)\n\n [questionusageid] => 2313\n [userid] => 4262\n [catquizattemptid] => 2254\n [currenttime] => 1725951901\n [currenttime_readable] => 10. September 2024, 09:05\n [attemptedquestions] => Array\n (\n [0] => Array\n (\n [slot] => 1\n [sequencecheckcount] => 2\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4546\n [idnumber] => MA.v1.C04-10\n [last_step_modified] => 1725951141\n [last_step_modified_readable] => 10. September 2024, 08:52\n )\n\n [autosavedstep] => false\n )\n\n [1] => Array\n (\n [slot] => 2\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_truefalse\n [id] => 4700\n [idnumber] => MA.v1.D06-03\n [last_step_modified] => 1725951180\n [last_step_modified_readable] => 10. September 2024, 08:53\n )\n\n [autosavedstep] => false\n )\n\n [2] => Array\n (\n [slot] => 3\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4736\n [idnumber] => MA.v1.D08-07\n [last_step_modified] => 1725951255\n [last_step_modified_readable] => 10. September 2024, 08:54\n )\n\n [autosavedstep] => false\n )\n\n [3] => Array\n (\n [slot] => 4\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4526\n [idnumber] => MA.v1.C04-02\n [last_step_modified] => 1725951589\n [last_step_modified_readable] => 10. September 2024, 08:59\n )\n\n [autosavedstep] => false\n )\n\n [4] => Array\n (\n [slot] => 5\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4740\n [idnumber] => MA.v1.D08-09\n [last_step_modified] => 1725951868\n [last_step_modified_readable] => 10. September 2024, 09:04\n )\n\n [autosavedstep] => false\n )\n\n [5] => Array\n (\n [slot] => 6\n [sequencecheckcount] => 1\n [question] => Array\n (\n [qtype] => qtype_multichoice\n [id] => 4491\n [idnumber] => MA.v1.C01-02\n [last_step_modified] => 1725951871\n [last_step_modified_readable] => 10. September 2024, 09:04\n )\n\n [autosavedstep] => false\n )\n\n )\n\n)\n\nError code: submissionoutofsequence\n line 125 of /mod/adaptivequiz/classes/local/adaptive_quiz_session.php: moodle_exception thrown\n line 136 of /mod/adaptivequiz/attempt.php: call to mod_adaptivequiz\local\adaptive_quiz_session->process_item_result()\n, referer: https://lti.alise.uni-wuppertal.de/mod/adaptivequiz/attempt.php?cmid=10504

[Tue Sep 10 09:26:39.706167 2024] [php:notice] [pid 874057] [client 109.42.179.112:6804] Default exception handler: Benutzen Sie nicht den Zur\xc3\xbcck-Button, wenn Sie Fragen bearbeiten. Debug: Array\n(\n [debuginfo] => QUBAid: 2324, slot: 3, post data: stdClass Object\n(\n [q2324:3_:sequencecheck] => 1\n [q2324:3_sub1_answer] => 6\n [q2324:3_sub2_answer] => 3\n [q2324:3_sub3_answer] => 9\n [submitanswer] => Antwort einreichen\n [cmid] => 10560\n [sesskey] => TB8yznEHHf\n [slots] => 3\n)\n\n [questionusageid] => 2324\n [userid] => 3342\n [catquizattemptid] => 2265\n [currenttime] => 1725953199\n [currenttime_readable] => 10. September 2024, 09:26\n [attemptedquestions] => Array\n (\n [0] => Array\n (\n [slot] => 1\n [sequencecheckcount] => 2\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4546\n [idnumber] => MA.v1.C04-10\n [last_step_modified] => 1725953197\n [last_step_modified_readable] => 10. September 2024, 09:26\n )\n\n [autosavedstep] => false\n )\n\n [1] => Array\n (\n [slot] => 2\n [sequencecheckcount] => 2\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4546\n [idnumber] => MA.v1.C04-10\n [last_step_modified] => 1725953197\n [last_step_modified_readable] => 10. September 2024, 09:26\n )\n\n [autosavedstep] => false\n )\n\n [2] => Array\n (\n [slot] => 3\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4546\n [idnumber] => MA.v1.C04-10\n [last_step_modified] => 1725953197\n [last_step_modified_readable] => 10. September 2024, 09:26\n )\n\n [autosavedstep] => false\n )\n\n [3] => Array\n (\n [slot] => 4\n [sequencecheckcount] => 1\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4526\n [idnumber] => MA.v1.C04-02\n [last_step_modified] => 1725953199\n [last_step_modified_readable] => 10. September 2024, 09:26\n )\n\n [autosavedstep] => false\n )\n\n )\n\n)\n\nError code: submissionoutofsequence\n line 125 of /mod/adaptivequiz/classes/local/adaptive_quiz_session.php: moodle_exception thrown\n line 136 of /mod/adaptivequiz/attempt.php: call to mod_adaptivequiz\local\adaptive_quiz_session->process_item_result()\n, referer: https://lti.alise.uni-wuppertal.de/mod/adaptivequiz/attempt.php

[Tue Sep 10 09:26:40.127838 2024] [php:notice] [pid 874016] [client 109.42.179.112:11879] Default exception handler: Benutzen Sie nicht den Zur\xc3\xbcck-Button, wenn Sie Fragen bearbeiten. Debug: Array\n(\n [debuginfo] => QUBAid: 2324, slot: 3, post data: stdClass Object\n(\n [q2324:3_:sequencecheck] => 1\n [q2324:3_sub1_answer] => 6\n [q2324:3_sub2_answer] => 3\n [q2324:3_sub3_answer] => 9\n [submitanswer] => Antwort einreichen\n [cmid] => 10560\n [sesskey] => TB8yznEHHf\n [slots] => 3\n)\n\n [questionusageid] => 2324\n [userid] => 3342\n [catquizattemptid] => 2265\n [currenttime] => 1725953200\n [currenttime_readable] => 10. September 2024, 09:26\n [attemptedquestions] => Array\n (\n [0] => Array\n (\n [slot] => 1\n [sequencecheckcount] => 2\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4546\n [idnumber] => MA.v1.C04-10\n [last_step_modified] => 1725953197\n [last_step_modified_readable] => 10. September 2024, 09:26\n )\n\n [autosavedstep] => false\n )\n\n [1] => Array\n (\n [slot] => 2\n [sequencecheckcount] => 2\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4546\n [idnumber] => MA.v1.C04-10\n [last_step_modified] => 1725953197\n [last_step_modified_readable] => 10. September 2024, 09:26\n )\n\n [autosavedstep] => false\n )\n\n [2] => Array\n (\n [slot] => 3\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4546\n [idnumber] => MA.v1.C04-10\n [last_step_modified] => 1725953197\n [last_step_modified_readable] => 10. September 2024, 09:26\n )\n\n [autosavedstep] => false\n )\n\n [3] => Array\n (\n [slot] => 4\n [sequencecheckcount] => 1\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4526\n [idnumber] => MA.v1.C04-02\n [last_step_modified] => 1725953199\n [last_step_modified_readable] => 10. September 2024, 09:26\n )\n\n [autosavedstep] => false\n )\n\n )\n\n)\n\nError code: submissionoutofsequence\n line 125 of /mod/adaptivequiz/classes/local/adaptive_quiz_session.php: moodle_exception thrown\n line 136 of /mod/adaptivequiz/attempt.php: call to mod_adaptivequiz\local\adaptive_quiz_session->process_item_result()\n, referer: https://lti.alise.uni-wuppertal.de/mod/adaptivequiz/attempt.php

[Tue Sep 10 09:26:55.901728 2024] [php:notice] [pid 874057] [client 132.195.49.186:58271] Default exception handler: Benutzen Sie nicht den Zur\xc3\xbcck-Button, wenn Sie Fragen bearbeiten. Debug: Array\n(\n [debuginfo] => QUBAid: 2328, slot: 1, post data: stdClass Object\n(\n [q2328:1_:sequencecheck] => 1\n [q2328:1_sub1_answer] => 3\n [q2328:1_sub2_answer] => 2\n [q2328:1_sub3_answer] => 1\n [submitanswer] => Antwort einreichen\n [cmid] => 10560\n [sesskey] => Ti1gf7kTyw\n [slots] => 1\n)\n\n [questionusageid] => 2328\n [userid] => 3437\n [catquizattemptid] => 2269\n [currenttime] => 1725953215\n [currenttime_readable] => 10. September 2024, 09:26\n [attemptedquestions] => Array\n (\n [0] => Array\n (\n [slot] => 1\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4546\n [idnumber] => MA.v1.C04-10\n [last_step_modified] => 1725953213\n [last_step_modified_readable] => 10. September 2024, 09:26\n )\n\n [autosavedstep] => false\n )\n\n [1] => Array\n (\n [slot] => 2\n [sequencecheckcount] => 1\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4526\n [idnumber] => MA.v1.C04-02\n [last_step_modified] => 1725953215\n [last_step_modified_readable] => 10. September 2024, 09:26\n )\n\n [autosavedstep] => false\n )\n\n )\n\n)\n\nError code: submissionoutofsequence\n line 125 of /mod/adaptivequiz/classes/local/adaptive_quiz_session.php: moodle_exception thrown\n line 136 of /mod/adaptivequiz/attempt.php: call to mod_adaptivequiz\local\adaptive_quiz_session->process_item_result()\n, referer: https://lti.alise.uni-wuppertal.de/mod/adaptivequiz/attempt.php

[Tue Sep 10 09:27:07.930205 2024] [php:notice] [pid 874059] [client 109.42.179.112:8764] Default exception handler: Benutzen Sie nicht den Zur\xc3\xbcck-Button, wenn Sie Fragen bearbeiten. Debug: Array\n(\n [debuginfo] => QUBAid: 2324, slot: 3, post data: stdClass Object\n(\n [q2324:3_:sequencecheck] => 1\n [q2324:3_sub1_answer] => 6\n [q2324:3_sub2_answer] => 3\n [q2324:3_sub3_answer] => 9\n [submitanswer] => Antwort einreichen\n [cmid] => 10560\n [sesskey] => TB8yznEHHf\n [slots] => 3\n)\n\n [questionusageid] => 2324\n [userid] => 3342\n [catquizattemptid] => 2265\n [currenttime] => 1725953227\n [currenttime_readable] => 10. September 2024, 09:27\n [attemptedquestions] => Array\n (\n [0] => Array\n (\n [slot] => 1\n [sequencecheckcount] => 2\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4546\n [idnumber] => MA.v1.C04-10\n [last_step_modified] => 1725953197\n [last_step_modified_readable] => 10. September 2024, 09:26\n )\n\n [autosavedstep] => false\n )\n\n [1] => Array\n (\n [slot] => 2\n [sequencecheckcount] => 2\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4546\n [idnumber] => MA.v1.C04-10\n [last_step_modified] => 1725953197\n [last_step_modified_readable] => 10. September 2024, 09:26\n )\n\n [autosavedstep] => false\n )\n\n [2] => Array\n (\n [slot] => 3\n [sequencecheckcount] => 3\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4546\n [idnumber] => MA.v1.C04-10\n [last_step_modified] => 1725953197\n [last_step_modified_readable] => 10. September 2024, 09:26\n )\n\n [autosavedstep] => false\n )\n\n [3] => Array\n (\n [slot] => 4\n [sequencecheckcount] => 1\n [question] => Array\n (\n [qtype] => qtype_multianswer\n [id] => 4526\n [idnumber] => MA.v1.C04-02\n [last_step_modified] => 1725953199\n [last_step_modified_readable] => 10. September 2024, 09:26\n )\n\n [autosavedstep] => false\n )\n\n )\n\n)\n\nError code: submissionoutofsequence\n line 125 of /mod/adaptivequiz/classes/local/adaptive_quiz_session.php: moodle_exception thrown\n line 136 of /mod/adaptivequiz/attempt.php: call to mod_adaptivequiz\local\adaptive_quiz_session->process_item_result()\n, referer: https://lti.alise.uni-wuppertal.de/mod/adaptivequiz/attempt.php

error.log

ralferlebach commented 5 days ago

Zum reproduzieren hier noch die SQL-Abfrage:

Event und Questionbank-Abfrage OutOfSequenceError.sql.txt

ralferlebach commented 4 days ago

VOR der Ausgabe des HTML-Forms ist NACH der Ausgabe des HTML-Forms isr VOR der Überprüfung des Ergebnisses ist WÄHREND des Fehlers?

Um den Fehler endlich einzugrenzen, habe ich Warnings in die Error-Logs schreiben lassen, und zwar an folgenden Stellen in der attempt.php VOR und NACH der Überprüfung der Ergebnisse VOR und NACH der Ausgabe des HTML-Formulars fürs Ergebnis (Zeile 136 ff)

stellt sich heraus, dass GLEICHZEITIG eine Überprüfung des Ergebnisses (plus Fehlermeldung) als auch ein Rendern des HTML-Forms stattzufinden scheint...

ralferlebach commented 4 days ago

Im Quelltext der attempt.php finden eine ganze Reihe an HTTP-Redirects statt, ohne dass das Skript explizit danach abgebrochen wird. Meine Vermutung ist, dass bei längeren Request-Zeiten Teile im Skript (weiter) abgearbeitet werden, die nicht abgearbeitet werden sollten.

Ich habe mal hinter jedem redirect ein exit-Statement gepackt. Es scheint noch alles zu laufen, mal sehen, ob dies den erratischen Fehler nun (endlich) beseitigt.

ralferlebach commented 3 days ago

Fehlerursache: Nach dem Ausstellen des HTML-Formulars wurde vom User versehentlich ein weiterer Request noch mit den alten Formulardaten eingereicht, vermutlich da dieser aus Ungeduld mehrfach auf den Absende-Button klickte.

Lösung:

Abgleich der eingelieferten slot-Angabe aus dem HTML-Form gegen die Datenbank in attempt.php. Wenn die Angaben aus dem Form nicht der letzten Slot entsprechen, werden diese verworfen und eine neue Frage ausgespielt (ggf. dies noch anpassen und diesselbe, letzte Frage ausspielen lassen!)
JavaSkript im HTML-Form verhindert nun ein doppeltes Betätigen des Absendebuttons, indem dieser beim Absenden deaktiviert und ausgegraut wird.

Seit 8:30 keine Fehler mehr in den Error-Logs

Wunderbyte-GmbH / moodle-local_catquiz