Event log error during upgrade from 16.10 to 17.10

Bug #1735072 reported by Ghada El-Zoghbi on 2017-11-29
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Mahara
High
Ghada El-Zoghbi
17.10
High
Ghada El-Zoghbi
18.04
High
Ghada El-Zoghbi

Bug Description

Mahara: 17.10.0 (during upgrade from 16.10)
OS: Linux 14.04
DB: Postgres
Browser: N/A - running upgrade through CLI

During the upgrade from a Mahara 16.10.6 to Mahara 17.10, we get the following error:

[WAR] 42 (lib/adodb/adodb-exceptions.inc.php:45) Array to string conversion
Call stack (most recent first):
  * log_message("Array to string conversion", 8, true, true, "/var/www/mahara/htdocs/lib/adodb/adodb...", 45) at /var/www/mahara/htdocs/lib/errors.php:521
  * error(8, "Array to string conversion", "/var/www/mahara/htdocs/lib/adodb/adodb...", 45, array(size 7)) at /var/www/mahara/htdocs/lib/adodb/adodb-exceptions.inc.php:45
  * ADODB_Exception->__construct("postgres8", "adodb_throw", -1, "ERROR: null value in column "time" violates not-n...", "INSERT INTO "event_log" ("usr", "realusr", "event"...", array(size 4), object(ADODB_postgres8)) at /var/www/mahara/htdocs/lib/adodb/adodb-exceptions.inc.php:80
  * adodb_throw("postgres8", "adodb_throw", -1, "ERROR: null value in column "time" violates not-n...", "INSERT INTO "event_log" ("usr", "realusr", "event"...", array(size 4), object(ADODB_postgres8)) at /var/www/mahara/htdocs/lib/adodb/adodb.inc.php:313
  * ADODB_TransMonitor("postgres8", "EXECUTE", -1, "ERROR: null value in column "time" violates not-n...", "INSERT INTO "event_log" ("usr", "realusr", "event"...", array(size 4), object(ADODB_postgres8)) at /var/www/mahara/htdocs/lib/adodb/adodb.inc.php:1264
  * ADOConnection->_Execute("INSERT INTO "event_log" ("usr", "realusr", "event"...", array(size 4)) at /var/www/mahara/htdocs/lib/adodb/adodb.inc.php:1224
  * ADOConnection->Execute("INSERT INTO "event_log" ("usr", "realusr", "event"...", array(size 4)) at /var/www/mahara/htdocs/lib/dml.php:1102
  * insert_record("event_log", object(stdClass)) at /var/www/mahara/htdocs/lib/mahara.php:2008
  * handle_event("saveartefact", object(ArtefactTypeStudentid)) at /var/www/mahara/htdocs/artefact/lib.php:658
  * ArtefactType->commit() at /var/www/mahara/htdocs/artefact/internal/lib.php:774
  * ArtefactTypeCachedProfileField->commit() at /var/www/mahara/htdocs/lib/user.php:577
  * set_profile_field("56999", "studentid", "u3547155", true) at /var/www/mahara/htdocs/lib/db/upgrade.php:4731
  * xmldb_core_upgrade("2016090230") at /var/www/mahara/htdocs/lib/upgrade.php:347
  * upgrade_core(object(stdClass)) at /var/www/mahara/htdocs/lib/mahara.php:268
  * upgrade_mahara(array(size 1)) at /var/www/mahara/htdocs/admin/cli/upgrade.php:53

[WAR] 42 (lib/errors.php:859) Failed to get a recordset: postgres8 error: [-1: ERROR: null value in column "time" violates not-null constraint
[WAR] 42 (lib/errors.php:859) DETAIL: Failing row contains (0, 0, null, saveartefact, {"owner":"56999","ctime":1511926716,"mtime":1511926716,"atime":1...).] in adodb_throw(INSERT INTO "event_log" ("usr", "realusr", "event", "data") VALUES (?, ?, ?, ?), Array)Command was: INSERT INTO "event_log" ("usr", "realusr", "event", "data") VALUES (?, ?, ?, ?) and values was (usr:0,realusr:0,event:saveartefact,data:{"owner":"56999","ctime":1511926716,"mtime":1511926716,"atime":1511926716,"title":"u3547155","author":"56999","path":"\/314601"})
Call stack (most recent first):
  * log_message("Failed to get a recordset: postgres8 error: [-1: E...", 8, true, true) at /var/www/mahara/htdocs/lib/errors.php:95
  * log_warn("Failed to get a recordset: postgres8 error: [-1: E...") at /var/www/mahara/htdocs/lib/errors.php:859
  * SQLException->__construct("Failed to get a recordset: postgres8 error: [-1: E...") at /var/www/mahara/htdocs/lib/dml.php:1105
  * insert_record("event_log", object(stdClass)) at /var/www/mahara/htdocs/lib/mahara.php:2008
  * handle_event("saveartefact", object(ArtefactTypeStudentid)) at /var/www/mahara/htdocs/artefact/lib.php:658
  * ArtefactType->commit() at /var/www/mahara/htdocs/artefact/internal/lib.php:774
  * ArtefactTypeCachedProfileField->commit() at /var/www/mahara/htdocs/lib/user.php:577
  * set_profile_field("56999", "studentid", "u3547155", true) at /var/www/mahara/htdocs/lib/db/upgrade.php:4731
  * xmldb_core_upgrade("2016090230") at /var/www/mahara/htdocs/lib/upgrade.php:347
  * upgrade_core(object(stdClass)) at /var/www/mahara/htdocs/lib/mahara.php:268
  * upgrade_mahara(array(size 1)) at /var/www/mahara/htdocs/admin/cli/upgrade.php:53

[WAR] 42 (lib/dml.php:1105) Failed to get a recordset: postgres8 error: [-1: ERROR: null value in column "time" violates not-null constraint
[WAR] 42 (lib/dml.php:1105) DETAIL: Failing row contains (0, 0, null, saveartefact, {"owner":"56999","ctime":1511926716,"mtime":1511926716,"atime":1...).] in adodb_throw(INSERT INTO "event_log" ("usr", "realusr", "event", "data") VALUES (?, ?, ?, ?), Array)Command was: INSERT INTO "event_log" ("usr", "realusr", "event", "data") VALUES (?, ?, ?, ?) and values was (usr:0,realusr:0,event:saveartefact,data:{"owner":"56999","ctime":1511926716,"mtime":1511926716,"atime":1511926716,"title":"u3547155","author":"56999","path":"\/314601"})
Call stack (most recent first):
  * insert_record("event_log", object(stdClass)) at /var/www/mahara/htdocs/lib/mahara.php:2008
  * handle_event("saveartefact", object(ArtefactTypeStudentid)) at /var/www/mahara/htdocs/artefact/lib.php:658
  * ArtefactType->commit() at /var/www/mahara/htdocs/artefact/internal/lib.php:774
  * ArtefactTypeCachedProfileField->commit() at /var/www/mahara/htdocs/lib/user.php:577
  * set_profile_field("56999", "studentid", "u3547155", true) at /var/www/mahara/htdocs/lib/db/upgrade.php:4731
  * xmldb_core_upgrade("2016090230") at /var/www/mahara/htdocs/lib/upgrade.php:347
  * upgrade_core(object(stdClass)) at /var/www/mahara/htdocs/lib/mahara.php:268
  * upgrade_mahara(array(size 1)) at /var/www/mahara/htdocs/admin/cli/upgrade.php:53

The issue is that there are changes to the table event_log which is not catered for in this part of the script.

Ghada El-Zoghbi (ghada-z) wrote :

Also getting this error further down the upgrade:

[WAR] f3 (lib/db/upgrade.php:5228) Undefined property: stdClass::$id
Call stack (most recent first):
  * log_message("Undefined property: stdClass::$id", 8, true, true, "/var/www/mahara/htdocs/lib/db/upgrade....", 5228) at /var/www/mahara/htdocs/lib/errors.php:521
  * error(8, "Undefined property: stdClass::$id", "/var/www/mahara/htdocs/lib/db/upgrade....", 5228, array(size 37)) at /var/www/mahara/htdocs/lib/db/upgrade.php:5228
  * xmldb_core_upgrade("2016090230") at /var/www/mahara/htdocs/lib/upgrade.php:347
  * upgrade_core(object(stdClass)) at /var/www/mahara/htdocs/lib/mahara.php:268
  * upgrade_mahara(array(size 1)) at /var/www/mahara/htdocs/admin/cli/upgrade.php:53

[WAR] f3 (lib/db/upgrade.php:5229) Undefined property: stdClass::$artefacttype
Call stack (most recent first):
  * log_message("Undefined property: stdClass::$artefacttype", 8, true, true, "/var/www/mahara/htdocs/lib/db/upgrade....", 5229) at /var/www/mahara/htdocs/lib/errors.php:521
  * error(8, "Undefined property: stdClass::$artefacttype", "/var/www/mahara/htdocs/lib/db/upgrade....", 5229, array(size 37)) at /var/www/mahara/htdocs/lib/db/upgrade.php:5229
  * xmldb_core_upgrade("2016090230") at /var/www/mahara/htdocs/lib/upgrade.php:347
  * upgrade_core(object(stdClass)) at /var/www/mahara/htdocs/lib/mahara.php:268
  * upgrade_mahara(array(size 1)) at /var/www/mahara/htdocs/admin/cli/upgrade.php:53

Related to the event_log table changes.

Changed in mahara:
status: New → Confirmed
importance: Undecided → High
milestone: none → 18.04.0
Robert Lyon (robertl-9) wrote :

The problem for the original error:

ERROR: null value in column "time" violates not-null

is due to needing to run handle_event() calls during upgrade but the handle_event() now sets ctime instead of time

The problem in the comment #1 is due to event 'deleteartefacts' unable to be adjusted for new event_log system as we can't map multiple artefacts to one resourceid

Reviewed: https://reviews.mahara.org/8323
Committed: https://git.mahara.org/mahara/mahara/commit/a7acb6a54c360d5bab86b6664b0fc39c3bd2288d
Submitter: Cecilia Vela Gurovic (<email address hidden>)
Branch: master

commit a7acb6a54c360d5bab86b6664b0fc39c3bd2288d
Author: Ghada El-Zoghbi <email address hidden>
Date: Fri Dec 1 15:02:44 2017 +1100

Bug#1735072: Upgrade error with event_log updated columns

Several issues resolved:
1. The event_log.time column has been removed
and replaced by ctime. The handl_event() call is using
the new column even though the new column has
not been created yet in the upgrade script.
Therefore, include both columns in the event handling.

2. The 'deleteartefacts' event stores multiple
artefact IDs in the one event_log record. Therefore,
there is not a one-to-one relationship when converting the
record to the new format. Ignore the record when setting
the resourceid and resourcetype.

3. In the 'saveartefact' and 'deleteartefact' events,
not all of the event_log records have 'id' and 'artefact'.
Ignore setting the resourceid and resourcetype fields
when the data is not available.

4. For newer versions of Postgres and MySql, utilise
the json dattype to convert the data held in the
event_log.data column. This will speed up the
processing of the table for sites with large data
in the event_log table.

Sponsored by Australian National University

behatnotneeded

Change-Id: If068dac825b9cef6301cd970f0a368124a67b3f1

Mahara Bot (dev-mahara) wrote :

Patch for "master" branch: https://reviews.mahara.org/8328

Mahara Bot (dev-mahara) wrote :

Patch for "17.10_STABLE" branch: https://reviews.mahara.org/8330

Reviewed: https://reviews.mahara.org/8328
Committed: https://git.mahara.org/mahara/mahara/commit/bcc68f968ee45d7ca282bbcd2628e8acbbebb0c4
Submitter: Robert Lyon (<email address hidden>)
Branch: master

commit bcc68f968ee45d7ca282bbcd2628e8acbbebb0c4
Author: Ghada El-Zoghbi <email address hidden>
Date: Thu Dec 7 14:49:08 2017 +1100

Bug#1735072: Fix upgrade error by delimiting event_log table in sql

Forgot to wrap the table name event_log with curly brackets.

Sponsored by Australian National University

behatnotneeded

Change-Id: Ia598632b1f0ae177fe646312ea5c2b38a9e83d51

Mahara Bot (dev-mahara) wrote :

Reviewed: https://reviews.mahara.org/8330
Committed: https://git.mahara.org/mahara/mahara/commit/72f4b27ca530a7b5578e8650a2a187e93e5344a9
Submitter: Robert Lyon (<email address hidden>)
Branch: 17.10_STABLE

commit 72f4b27ca530a7b5578e8650a2a187e93e5344a9
Author: Ghada El-Zoghbi <email address hidden>
Date: Thu Dec 7 14:49:08 2017 +1100

Bug#1735072: Fix upgrade error by delimiting event_log table in sql

Forgot to wrap the table name event_log with curly brackets.

Sponsored by Australian National University

behatnotneeded

Change-Id: Ia598632b1f0ae177fe646312ea5c2b38a9e83d51

Mahara Bot (dev-mahara) wrote :

Reviewed: https://reviews.mahara.org/8327
Committed: https://git.mahara.org/mahara/mahara/commit/26886174ca568225f4e58a11c15aebe362555f32
Submitter: Robert Lyon (<email address hidden>)
Branch: 17.10_STABLE

commit 26886174ca568225f4e58a11c15aebe362555f32
Author: Ghada El-Zoghbi <email address hidden>
Date: Fri Dec 1 15:02:44 2017 +1100

Bug#1735072: Upgrade error with event_log updated columns

Several issues resolved:
1. The event_log.time column has been removed
and replaced by ctime. The handl_event() call is using
the new column even though the new column has
not been created yet in the upgrade script.
Therefore, include both columns in the event handling.

2. The 'deleteartefacts' event stores multiple
artefact IDs in the one event_log record. Therefore,
there is not a one-to-one relationship when converting the
record to the new format. Ignore the record when setting
the resourceid and resourcetype.

3. In the 'saveartefact' and 'deleteartefact' events,
not all of the event_log records have 'id' and 'artefact'.
Ignore setting the resourceid and resourcetype fields
when the data is not available.

4. For newer versions of Postgres and MySql, utilise
the json dattype to convert the data held in the
event_log.data column. This will speed up the
processing of the table for sites with large data
in the event_log table.

Sponsored by Australian National University

behatnotneeded

Change-Id: If068dac825b9cef6301cd970f0a368124a67b3f1
(cherry picked from commit a7acb6a54c360d5bab86b6664b0fc39c3bd2288d)

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers