[v5.1.0] Database error when upgrading from v4.5.0 to v5.1.0

[danowar2k]

This came up during an upgrade:

Debug-Info:  FEHLER: NULL-Wert in Spalte »questionid« von Relation »m_studentquiz_state_history« verletzt Not-Null-Constraint
DETAIL: Fehlgeschlagene Zeile enthält (1, null, 18182, 2, 1569395230).
INSERT INTO m_studentquiz_state_history (userid,state,timecreated) VALUES($1,$2,$3) RETURNING id
[array (
'userid' => 18182,
'state' => 2,
'timecreated' => 1569395230,
)]
Error code: dmlwriteexception×Diese Systemnachricht ablehnen
Stack trace: 
line 497 of /lib/dml/moodle_database.php: dml_write_exception thrown
line 293 of /lib/dml/moodle_read_slave_trait.php: call to moodle_database->query_end()
line 341 of /lib/dml/pgsql_native_moodle_database.php: call to pgsql_native_moodle_database->read_slave_query_end()
line 1132 of /lib/dml/pgsql_native_moodle_database.php: call to pgsql_native_moodle_database->query_end()
line 1180 of /lib/dml/pgsql_native_moodle_database.php: call to pgsql_native_moodle_database->insert_record_raw()
line 595 of /mod/studentquiz/classes/utils.php: call to pgsql_native_moodle_database->insert_record()
line 923 of /mod/studentquiz/db/upgrade.php: call to mod_studentquiz\utils::question_save_action()
line 934 of /lib/upgradelib.php: call to xmldb_studentquiz_upgrade()
line 677 of /lib/upgradelib.php: call to upgrade_plugins_modules()
line 1953 of /lib/upgradelib.php: call to upgrade_plugins()
line 721 of /admin/index.php: call to upgrade_noncore()

Reloading the upgrade page led to studentquiz finishing the upgrade, which surprised us. I thought we would get the same error again, because of rollbacked transactions (we're using Postgres).

The underlying Moodle instance had previously been upgraded from 3.11.11 to 4.1.1, but mod_studentquiz had been left at v4.5.0 until we separately updated the plugin.

The cause looks to be around here: https://github.com/studentquiz/moodle-mod_studentquiz/blob/main/db/upgrade.php#L887-L938.

A questionid from studentquiz_question is NULL ? That's strange, shouldn't happen...?

[timhunt]

The fact that a reaload works surprises me too. ...

Ah! the code that gave the error was inside an if (!$dbman->table_exists($table)) { and when you reload, the table will exist, so it will skip that bit of hte upgrade, which will leave your system in a bad state.

Was this a test server? Can you restore your backup and try the upgrade again? (perhaps after adding some debugging output, to work out how that column could be null. That still seems impossible to me.)

(The checks under System administration > Development > XMLDB editor, do any of those check that the column NOT NULL in your database, acutally match what it is supposed to be? Or, could you manually check the structure of the studentquiz_question matches what it should be?)

[danowar2k]

Sadly, the system was both a test server with "uncritical data" and I didn't do a backup beforehand because it didn't matter to us very much. But I can try and check with our database admins, they should be able to produce a database backup from the last 24 hours...

[danowar2k]

So the creation of tables is done atomically and in a transaction? Well, shouldn't the "creating table" code not be separate from the "massage old data to new way of thinking" stuff?

[timhunt]

Postgres can do DML statements (like create table) in transactnios, but most other DB can't.

Yes, the upgrade blocks should be separate.

[danowar2k]

I added a PR which doesn't fix the NULL problem, but should at least prevent further resulting data inconsistencies.

[danowar2k]

Aside: js files seem to be stale...

[danowar2k]

We've restored the database via WAL log and just didn't update the plugin for now.

Looking at the contents of studentquiz_question, I can't seem to find a NULL entry. Strange...

EDIT: At least I found the record that possibly was referenced avobe:

questionid;state;createdby;timecreated
"987";"1";"18182";"1569395230"

[danowar2k]

Debugged it. The cause is:

• https://github.com/studentquiz/moodle-mod_studentquiz/blob/main/classes/utils.php#L590 and the current schema at https://github.com/studentquiz/moodle-mod_studentquiz/blob/main/db/install.xml#L169 say the column name is "studentquizquestionid"
• when the table is first created, the column name is "questionid", see https://github.com/studentquiz/moodle-mod_studentquiz/blob/main/db/upgrade.php#L892

That field is only added here: https://github.com/studentquiz/moodle-mod_studentquiz/blob/main/db/upgrade.php#L1118
and populated with the content of questionid here:

moodle-mod_studentquiz/db/upgrade.php

Lines 1414 to 1418 in a07f09a

	$DB->execute("UPDATE {studentquiz_state_history}
	SET studentquizquestionid = (
	SELECT id
	FROM {studentquiz_question}
	WHERE questionid = {studentquiz_state_history}.questionid

and the old field is finally dropped here: https://github.com/studentquiz/moodle-mod_studentquiz/blob/main/db/upgrade.php#L1620

But of course, if one uses the constantly evolving code in the upgrade procedure, this was bound to happen sometime. I gotta remember that for my plugins: "Do not use 'normal' API in plugin updates"...

EDIT: I'll do a PR for this, too...will replace the utils function with creating "at the time correct" data objects...

[danowar2k]

Here's a workaround for anyone looking to update in the meantime.
The v4.5.0 tag officially is 2021071300.
The change is done at 2021102502. The next tag that includes that change is v4.6.0 .

So one can update from v4.5.0 to v4.6.0 (the API is still consistent there), and then update from v4.6.0 to v5.1.0.

[danowar2k]

Okay, I just updated the existing PR with a second commit that doesn't use the utils method anymore.

[timhunt]

Sorry that I am ingoring your! This turned into a very busy week, and I just have not had time. Thank you for continuing to work on this, and I hope I will have time to look next week.

[danowar2k]

No worries. I think I'm done, though.

[danowar2k]

Any progress here?

[eligorio]

In order to be able to upgrade to version 2022122200 i did the below image edits. It is not optimal. Is there other workaround?

I did this because of message.

!!! Erro ao gravar na base de dados !!!
!! Subquery returns more than 1 row
UPDATE mdl_studentquiz_rate
SET studentquizquestionid = (
SELECT id
FROM mdl_studentquiz_question
WHERE questionid = mdl_studentquiz_rate.questionid
)

[array (
)]
Error code: dmlwriteexception !!

[sennewood]

This error also occurs with plugin version v4.7.1 (2022052401).

[danowar2k]

Ran into this problem again when upgrading another instance of ours. @timhunt Can't you at least merge the code that splits table creation from data migration to make the error reproducible and the database inconsistency a smaller problem?

[timhunt]

Merge it into which branch?

[danowar2k]

By the way, applying the fix above to a non-upgraded Moodle removed the error when upgrading.

Merge it into which branch?

Um, I'd gather "main"? The commits don't introduce new features but slightly alter the upgrade procedure to split the studentquiz_state_history table creation and data migration to it, so that could IMHO just be merged to at least prevent data inconsistencies.

The second commit replaces the utils::question_save_action calls with what was at that point in time the function body. This way the upgrade flow is maintained and nothing in this flow has been functionally changed.

Do you need me to do further tests to be able to determine whether this PR can be used?