21 May 2018, 21:30

Hello,

After upgrade, i have a very erratic error in my Apache logs, just on some users profiles:

[Mon May 21 10:20:35.945241 2018] [:error] [pid 127749] [client xxx.xxx.xxx..xx:55552] PHP Fatal error:  Call to a member function StartTrans() on null in /var/www/mahara1804/lib/dml.php on line 1607, referer: <website>/user/view.php?id=59034

This error seem not have any effect on the user's profile affected, but i don't find why this error append.

if necessary, i can export an profile.

Thanks,

Thomas.

22 May 2018, 9:02

Hi Thomas,

That is a strange error to get as the error stems from the line:

$db->StartTrans();

So it would be odd for the $db object to be null as that would mean no connection to the database.

What type of database are you using? MySQL, Postgres?

Was there any other trace/debug info after the error?

Cheers

Robert

22 May 2018, 10:41

Hi Robert,

It's a Mysql database.

I tried to have more informations with ""error_reporting(E_ALL);"" insered in the top of /var/www/mahara1804/lib/dml.php, but nothing interesting.

There are an internal debug system in mahara ?

This problem affect may be ten percent of the users. Generally the users with a detailled profiles.

I suspect that one function used in this type of profiles generate this error.

I will try to delete a profile, small block per small block.

Thomas.

22 May 2018, 21:03

Hello Thomas,

If you set "productionmode" to "false" in the config file (see http://manual.mahara.org/en/18.04/administration/config_php.html#productionmode-enable-or-disable-production-mode on how to do that), error messages / warnings etc. are printed directly to the screen. It would be good to know more when the issue arises.

Cheers

Kristina

22 May 2018, 21:35

Hi Kristina,

My configuration :

$cfg->productionmode = false;
$cfg->developermode = true;
$cfg->log_backtrace_levels = LOG_LEVEL_WARN;
$cfg->error_reporting = E_ALL;

I have some WARN in every pages, but nothing about  ""PHP Fatal error:  Call to a member function StartTrans()""

---------------------------------

---------------------------------

Thomas.

23 May 2018, 2:05

I started to log every request on mysql server and compare the dates between the SQL query and PHP error.
Systematically, this error happen just after this update but not on every profiles:

------------------------------------------
[Tue May 22 14:44:20.267967 2018] [:error] [pid 4479] [client 193.60.133.195:38834] PHP Fatal error:  Call to a member function StartTrans() on null in /var/www/mahara1804/lib/dml.php on line 1607, referer: https://***********ac.uk/user/view.php?id=46036
2018-05-22T13:44:20.258651Z      1343 Query     UPDATE "mah_view" SET atime = '2018-05-22 14:44:20' WHERE id = '82381'
------------------------------------------
[Tue May 22 14:45:02.650426 2018] [:error] [pid 4503] [client 193.60.133.195:55182] PHP Fatal error:  Call to a member function StartTrans() on null in /var/www/mahara1804/lib/dml.php on line 1607, referer: https://***********ac.uk/user/view.php?id=49436
2018-05-22T13:45:02.641649Z      1358 Query     UPDATE "mah_view" SET atime = '2018-05-22 14:45:02' WHERE id = '82391'
------------------------------------------
[Tue May 22 14:46:58.258711 2018] [:error] [pid 4491] [client 193.60.133.195:34968] PHP Fatal error:  Call to a member function StartTrans() on null in /var/www/mahara1804/lib/dml.php on line 1607, referer: https://***********c.uk/user/view.php?id=45541
2018-05-22T13:46:58.248158Z      1394 Query     UPDATE "mah_view" SET atime = '2018-05-22 14:46:58' WHERE id = '79906'
------------------------------------------
[Tue May 22 14:48:48.530481 2018] [:error] [pid 4495] [client 193.60.133.195:53980] PHP Fatal error:  Call to a member function StartTrans() on null in /var/www/mahara1804/lib/dml.php on line 1607, referer: https://***********.ac.uk/user/view.php?id=57359
2018-05-22T13:48:48.519147Z      1470 Query     UPDATE "mah_view" SET atime = '2018-05-22 14:48:48' WHERE id = '119573'
-------------------------------------------

---------- Large block
2018-05-22T13:48:48.466389Z      1470 Query     SHOW COLUMNS FROM `mah_institution`
2018-05-22T13:48:48.467860Z      1470 Query     SELECT "logoxs" FROM "mah_institution"  WHERE "name" = 'mahara'
2018-05-22T13:48:48.474414Z      1470 Query     SELECT * FROM "mah_artefact_installed" ORDER BY name
2018-05-22T13:48:48.476055Z      1470 Query     SELECT * FROM "mah_interaction_installed" ORDER BY name
2018-05-22T13:48:48.477718Z      1470 Query     SELECT enabled, restrictedusers, tokenusers FROM "mah_external_services"  WHERE "shortname" = 'maharamobile'  AND "component" = 'module/mobileapi'  LIMIT 2
2018-05-22T13:48:48.479071Z      1470 Query     SELECT "active" FROM "mah_module_installed"  WHERE "name" = 'multirecipientnotification'
2018-05-22T13:48:48.502365Z      1470 Query     SELECT ui.usr, i.displayname, ui.staff, ui.admin, i.name
        FROM "mah_usr_institution" ui JOIN "mah_institution" i ON ui.institution = i.name
        WHERE ui.usr IN (57361)
2018-05-22T13:48:48.503036Z      1470 Query     SELECT * FROM "mah_usr"  WHERE "id" = '108765'  LIMIT 2
2018-05-22T13:48:48.503708Z      1470 Query     SELECT * FROM "mah_usr_account_preference"  WHERE "usr" = 57361  AND "field" = 'messages'  LIMIT 2
2018-05-22T13:48:48.504259Z      1470 Query     SELECT * FROM "mah_usr_friend" WHERE (usr1 = '108765' AND usr2 = 57361) OR (usr2 = '108765' AND usr1 = 57361) LIMIT 1
2018-05-22T13:48:48.505497Z      1470 Query     SELECT "active" FROM "mah_module_installed"  WHERE "name" = 'multirecipientnotification'
2018-05-22T13:48:48.519147Z      1470 Query     UPDATE "mah_view" SET atime = '2018-05-22 14:48:48' WHERE id = '119573'
2018-05-22T13:48:48.529470Z      1470 Quit
2018-05-22T13:48:48.582639Z      1471 Connect   *********** on *********** using TCP/IP
2018-05-22T13:48:48.583002Z      1471 Query     SET NAMES utf8
2018-05-22T13:48:48.586963Z      1471 Init DB   ***********

23 May 2018, 2:52

I tested the function who generate this update in "./user/view.php"

-------------

//mahara_touch_record('view', $viewid); // Update record 'atime'
mahara_log('views', "$viewid"); // Log view visits

function mahara_touch_record($table, $id) {
    execute_sql("UPDATE " . db_table_name($table) . " SET atime = ? WHERE id = ?", array(db_format_timestamp(time()), $id));
}

-------------

This error is still present, with this function(mahara_touch_record) disable

Can I conclude it's during the next reconnection:

2018-05-22T15:39:52.446871-00:00          110 Query     SELECT * FROM "mah_interaction_installed" ORDER BY name
2018-05-22T15:39:52.448510-00:00          110 Query     SELECT enabled, restrictedusers, tokenusers FROM "mah_external_services"  WHERE "shortname" = 'maharamobile'  AND "component" = 'module/mobileapi'  LIMIT 2
2018-05-22T15:39:52.449722-00:00          110 Query     SELECT "active" FROM "mah_module_installed"  WHERE "name" = 'multirecipientnotification'
2018-05-22T15:39:52.471793-00:00          110 Query     SELECT ui.usr, i.displayname, ui.staff, ui.admin, i.name
        FROM "mah_usr_institution" ui JOIN "mah_institution" i ON ui.institution = i.name
        WHERE ui.usr IN (56218)
2018-05-22T15:39:52.472413-00:00          110 Query     SELECT * FROM "mah_usr"  WHERE "id" = '108765'  LIMIT 2
2018-05-22T15:39:52.473052-00:00          110 Query     SELECT * FROM "mah_usr_account_preference"  WHERE "usr" = 56218  AND "field" = 'messages'  LIMIT 2
2018-05-22T15:39:52.473531-00:00          110 Query     SELECT * FROM "mah_usr_friend" WHERE (usr1 = '108765' AND usr2 = 56218) OR (usr2 = '108765' AND usr1 = 56218) LIMIT 1
2018-05-22T15:39:52.474648-00:00          110 Query     SELECT "active" FROM "mah_module_installed"  WHERE "name" = 'multirecipientnotification'

UPDATE SHOULD BE HERE
2018-05-22T15:39:52.491727-00:00          110 Quit
2018-05-22T15:39:52.551325-00:00          111 Connect   ******************* on portfolio using TCP/IP
2018-05-22T15:39:52.551504-00:00          111 Query     SET NAMES utf8
2018-05-22T15:39:52.551652-00:00          111 Init DB   portfolio
2018-05-22T15:39:52.551881-00:00          111 Query     select version()
2018-05-22T15:39:52.552255-00:00          111 Query     SET NAMES 'utf8'
2018-05-22T15:39:52.552527-00:00          111 Query     SET SQL_MODE='POSTGRESQL'
2018-05-22T15:39:52.552802-00:00          111 Query     SET CHARACTER SET utf8mb4
2018-05-22T15:39:52.553056-00:00          111 Query     SET SQL_BIG_SELECTS=1
2018-05-22T15:39:52.553309-00:00          111 Query     SET SESSION TRANSACTION ISOLATION LEVEL READ COMMITTED
2018-05-22T15:39:52.553695-00:00          111 Query     SELECT field, value FROM "mah_config"
2018-05-22T15:39:52.566239-00:00          112 Connect   ******************* on portfolio using TCP/IP
2018-05-22T15:39:52.566365-00:00          112 Query     SET NAMES utf8
2018-05-22T15:39:52.566479-00:00          112 Init DB   portfolio
2018-05-22T15:39:52.566728-00:00          112 Query     select version()
2018-05-22T15:39:52.567113-00:00          112 Query     SET NAMES 'utf8'
2018-05-22T15:39:52.567362-00:00          112 Query     SET SQL_MODE='POSTGRESQL'
2018-05-22T15:39:52.567632-00:00          112 Query     SET CHARACTER SET utf8mb4
2018-05-22T15:39:52.567830-00:00          112 Query     SET SQL_BIG_SELECTS=1
2018-05-22T15:39:52.568035-00:00          112 Query     SET SESSION TRANSACTION ISOLATION LEVEL READ COMMITTED

23 May 2018, 12:44

Hi Thomas,

Ok, there are two errors happening here - the

• error(2048, "Non-static method PluginBlocktypeMyviews::render_i...", "/var/www/mahara1804/blocktype/myviews/lib.php", 109, array(size 8)) at /var/www/mahara1804/blocktype/myviews/lib.php:10

is due to a mistake in htdocs/blocktype/myviews/lib.php on line 44 where

public function render_items(&$items, $template, $options, $pagination) {

should be

public static function render_items(&$items, $template, $options, $pagination) {

I'll make a bug report for that.

The other problems is related to the $db->startTrans(); line. According to the code in htdocs/lib/dml.php

    if (is_mysql()) {
        return;
    }

    $GLOBALS['_TRANSACTION_LEVEL']++;
    $db->StartTrans();

It checks if the site is using mysql and if so skips that call.

What version on mysql are using? and what flavour (MySql vs Mariadb vs  something else)?

Also what value do you have set in config.php file for $cfg->dbtype ?

Cheers

Robert

23 May 2018, 21:11

Hi,

Running version:

mysql-server-5.7                    5.7.20-0ubuntu0.16.04.1                    amd64        MySQL database server binaries and system database setup

Configuration:

$cfg->dbtype   = 'mysql';

Thomas.

24 May 2018, 8:04

Hi Thomas,

In htdocs/lib/dml.php there is a function db_begin() on about line 1600, can you put in line 1602 the following

 log_debug('Am I mysql: ' . is_mysql());

And then do something like upgrade or save a comment to a page. You should end up with the DBG output:

 Am I mysql: 1

If you see:

 Am I mysql:

Then the system doesn't think you are using mysql so check the is_mysql() function on 1561 to see why it may be failing

Cheers

Robert