28 January 2020, 2:03

Mahara version : 19.04.1
Php version : 7.2.26
Apache Server
Mysql version : 10.3.21-MariaDB

Hello, I've been searching in vain for a solution to my problem in the forum.

Almost every time the cron auth_remove_old_session_files starts it ends up crashing. Same thing for cron_site_data_daily.
To get back to a normal display in Mahara's administration, I have to remove two fields from the config table of the database :
_cron_lock_core_remove_old_session_files and _cron_lock_core_cron_site_data_daily and manually restart the CRON, sometimes twice. At the first one I sometimes get this message "A nonrecoverable error occurred. This probably means you have encountered a bug in the system A nonrecoverable error occurred. This probably means you have encountered a bug in the system" and I have to delete the record in the config table again and restart the cron a second time.

In the php error logs I have this :

[23-Jan-2020 20:30:02 Europe/Paris] [INF] 32 (lib/cron.php:176) Running core cron auth_remove_old_session_files
[23-Jan-2020 20:31:09 Europe/Paris] [WAR] 32 (lib/errors.php:858) Failed to get a recordset: mysqli error: [2006: MySQL server has gone away] in EXECUTE("DELETE FROM "usr_session" WHERE mtime < '2020-01-22 20:25:02'")Command was: DELETE FROM "usr_session" WHERE mtime < ? and values was (0:2020-01-2220:25:02)
[23-Jan-2020 20:31:09 Europe/Paris] Call stack (most recent first):
[23-Jan-2020 20:31:09 Europe/Paris] * log_message(string(size 243), integer, true, true) at /home/lyceem2/public_html/mahara/lib/errors.php:95
[23-Jan-2020 20:31:09 Europe/Paris] * log_warn(string(size 243)) at /home/lyceem2/public_html/mahara/lib/errors.php:858
[23-Jan-2020 20:31:09 Europe/Paris] * SQLException->__construct(string(size 243)) at /home/lyceem2/public_html/mahara/lib/dml.php:1025
[23-Jan-2020 20:31:09 Europe/Paris] * delete_records_sql(string(size 41), array(size 1)) at /home/lyceem2/public_html/mahara/lib/dml.php:1002
[23-Jan-2020 20:31:09 Europe/Paris] * delete_records_select(string(size 11), string(size 15), array(size 1)) at /home/lyceem2/public_html/mahara/auth/lib.php:2239
[23-Jan-2020 20:31:09 Europe/Paris] * auth_remove_old_session_files() at /home/lyceem2/public_html/mahara/lib/cron.php:186
[23-Jan-2020 20:31:09 Europe/Paris]
[23-Jan-2020 20:31:09 Europe/Paris] [WAR] 32 (lib/dml.php:1025) Failed to get a recordset: mysqli error: [2006: MySQL server has gone away] in EXECUTE("DELETE FROM "usr_session" WHERE mtime < '2020-01-22 20:25:02'")Command was: DELETE FROM "usr_session" WHERE mtime < ? and values was (0:2020-01-2220:25:02)
[23-Jan-2020 20:31:09 Europe/Paris] Call stack (most recent first):
[23-Jan-2020 20:31:09 Europe/Paris] * delete_records_sql(string(size 41), array(size 1)) at /home/lyceem2/public_html/mahara/lib/dml.php:1002
[23-Jan-2020 20:31:09 Europe/Paris] * delete_records_select(string(size 11), string(size 15), array(size 1)) at /home/lyceem2/public_html/mahara/auth/lib.php:2239
[23-Jan-2020 20:31:09 Europe/Paris] * auth_remove_old_session_files() at /home/lyceem2/public_html/mahara/lib/cron.php:186
[23-Jan-2020 20:31:09 Europe/Paris]
[23-Jan-2020 20:31:09 Europe/Paris] [WAR] 32 (lib/errors.php:858) Failed to get a recordset: mysqli error: [2006: MySQL server has gone away] in EXECUTE("UPDATE "cron" SET "nextrun" = '2020-01-24 20:30:00' WHERE "id" = '7' ")Command was: UPDATE "cron" SET "nextrun" = ? WHERE "id" = ? and values was (0:2020-01-2420:30:00,1:7)
[23-Jan-2020 20:31:09 Europe/Paris] Call stack (most recent first):
[23-Jan-2020 20:31:09 Europe/Paris] * log_message(string(size 263), integer, true, true) at /home/lyceem2/public_html/mahara/lib/errors.php:95
[23-Jan-2020 20:31:09 Europe/Paris] * log_warn(string(size 263)) at /home/lyceem2/public_html/mahara/lib/errors.php:858
[23-Jan-2020 20:31:09 Europe/Paris] * SQLException->__construct(string(size 263)) at /home/lyceem2/public_html/mahara/lib/dml.php:949
[23-Jan-2020 20:31:09 Europe/Paris] * set_field_select(string(size 4), string(size 7), string(size 19), string(size 16), array(size 2)) at /home/lyceem2/public_html/mahara/lib/dml.php:929
[23-Jan-2020 20:31:09 Europe/Paris] * set_field(string(size 4), string(size 7), string(size 19), string(size 2), string(size 1)) at /home/lyceem2/public_html/mahara/lib/cron.php:202
[23-Jan-2020 20:31:09 Europe/Paris]
[23-Jan-2020 20:31:09 Europe/Paris] [WAR] 32 (lib/dml.php:949) Failed to get a recordset: mysqli error: [2006: MySQL server has gone away] in EXECUTE("UPDATE "cron" SET "nextrun" = '2020-01-24 20:30:00' WHERE "id" = '7' ")Command was: UPDATE "cron" SET "nextrun" = ? WHERE "id" = ? and values was (0:2020-01-2420:30:00,1:7)
[23-Jan-2020 20:31:09 Europe/Paris] Call stack (most recent first):
[23-Jan-2020 20:31:09 Europe/Paris] * set_field_select(string(size 4), string(size 7), string(size 19), string(size 16), array(size 2)) at /home/lyceem2/public_html/mahara/lib/dml.php:929
[23-Jan-2020 20:31:09 Europe/Paris] * set_field(string(size 4), string(size 7), string(size 19), string(size 2), string(size 1)) at /home/lyceem2/public_html/mahara/lib/cron.php:202
[23-Jan-2020 20:31:09 Europe/Paris]

I've been talking to my webhost about this and it can't be explained the mysqli error: [2006: MySQL server has gone away] because our web space isn't saturated at the times indicated in the log.
After many tries, php version change, change to memcached for the session management... nothing works !

I am open to all your suggestions to find the reason of my concern about CRON.

Thanx, Anthony.

05 February 2020, 18:26

Hi Anthony,

I don't think we've seen that error before. First it would be good to know if you installed, uninstalled anything from the server or upgraded Mahara version before this problem started, or if you are working with a new Mahara instance.

You said you also tried changing the php version, can you tell us which ones you used?

By looking at the error logs, I can't see there could be an error in Mahara code. But if the site is having problems with this line in auth/lib.php file:

delete_records_select('usr_session', 'mtime < ?', array(db_format_timestamp($mintime - get_config('accesstimeupdatefrequency'))));

you could comment it out and monitor for a day to see if that specific line is breaking the cron function. If it's something more general, then it could happen again in another part of the code.

Cecilia

05 February 2020, 22:00

Hi Cecilia

First of all, thank you for your answer!

I think the problem started when I made the upgrade from 18.04 to 19.04.

I've tried php 7.1, 7.2 and 7.3 and it didn't change anything to my issue with the cron.

I just commented on the suggested line in lib.php and see if that solves the case.

Anthony.

08 February 2020, 1:43

Hello Cecilia
I still have the problem despite the commented line in lib.php (see erro-log below).
I don't understand why the cron launches at 20:30 and then again at 20:32 as I set it every 10 minutes in the CRON task.

Thanks for your help !

Anthony.

[06-Feb-2020 20:30:02 Europe/Paris] [INF] f2 (lib/cron.php:52) ---------- cron running Thu, 06 Feb 2020 20:30:02 +0100 ----------
[06-Feb-2020 20:30:02 Europe/Paris] [INF] f2 (lib/cron.php:105) Running PluginAuthSaml::auth_saml_refresh_cron
[06-Feb-2020 20:30:02 Europe/Paris] [INF] f2 (lib/cron.php:105) Running PluginSearchElasticsearch::cron
[06-Feb-2020 20:30:02 Europe/Paris] [INF] f2 (lib/cron.php:176) Running core cron activity_process_queue
[06-Feb-2020 20:30:02 Europe/Paris] [INF] f2 (lib/cron.php:176) Running core cron auth_remove_old_session_files
[06-Feb-2020 20:32:43 Europe/Paris] [INF] 92 (lib/cron.php:52) ---------- cron running Thu, 06 Feb 2020 20:32:43 +0100 ----------
[06-Feb-2020 20:32:43 Europe/Paris] [INF] 92 (lib/cron.php:549) Skipping long-running cron job core_auth_remove_old_session_files (Thu, 06 Feb 2020 20:30:02 +0100).
[06-Feb-2020 20:32:43 Europe/Paris] [INF] 92 (lib/cron.php:176) Running core cron import_process_queue
[06-Feb-2020 20:32:43 Europe/Paris] [INF] 92 (lib/cron.php:176) Running core cron user_login_tries_to_zero
[06-Feb-2020 20:32:43 Europe/Paris] [INF] 92 (lib/cron.php:176) Running core cron check_imap_for_bounces
[06-Feb-2020 20:32:43 Europe/Paris] [INF] 92 (lib/cron.php:176) Running core cron watchlist_process_notifications
[06-Feb-2020 20:32:43 Europe/Paris] [INF] 92 (lib/cron.php:176) Running core cron export_process_queue
[06-Feb-2020 20:32:43 Europe/Paris] [INF] 92 (lib/cron.php:216) ---------- cron finished Thu, 06 Feb 2020 20:32:43 +0100 ----------

13 February 2020, 9:39

Hi Anthony,

sorry I can't see in the logs you pasted if you still have the 'MySQL server has gone away' problem. Is this still the issue? In which other cron function does it fail?

14 February 2020, 4:04

Hi Cecilia

when the line is commented in lib.php, the log does not display an error but the task still fails.

When I uncomment it, the error is always there and appears in the error log...

is it normal for cron auth_remove_old_session_files to take 1:41 minutes to complete the task (in the error log : 20:30:02 to 20:31:43 ) ?

Thanx again for your help.

The error_log :

[12-Feb-2020 20:30:02 Europe/Paris] [INF] c2 (lib/cron.php:52) ---------- cron running Wed, 12 Feb 2020 20:30:02 +0100 ----------
[12-Feb-2020 20:30:02 Europe/Paris] [INF] c2 (lib/cron.php:105) Running PluginAuthSaml::auth_saml_refresh_cron
[12-Feb-2020 20:30:02 Europe/Paris] [INF] c2 (lib/cron.php:105) Running PluginSearchElasticsearch::cron
[12-Feb-2020 20:30:02 Europe/Paris] [INF] c2 (lib/cron.php:176) Running core cron activity_process_queue
[12-Feb-2020 20:30:02 Europe/Paris] [INF] c2 (lib/cron.php:176) Running core cron auth_remove_old_session_files
[12-Feb-2020 20:31:43 Europe/Paris] [WAR] c2 (lib/errors.php:858) Failed to get a recordset: mysqli error: [2006: MySQL server has gone away] in EXECUTE("DELETE FROM "usr_session" WHERE mtime < '2020-02-11 20:25:02'")Command was: DELETE FROM "usr_session" WHERE mtime < ? and values was (0:2020-02-1120:25:02)
[12-Feb-2020 20:31:43 Europe/Paris] Call stack (most recent first):
[12-Feb-2020 20:31:43 Europe/Paris] * log_message(string(size 243), integer, true, true) at /home/lyceem2/public_html/mahara/lib/errors.php:95
[12-Feb-2020 20:31:43 Europe/Paris] * log_warn(string(size 243)) at /home/lyceem2/public_html/mahara/lib/errors.php:858
[12-Feb-2020 20:31:43 Europe/Paris] * SQLException->__construct(string(size 243)) at /home/lyceem2/public_html/mahara/lib/dml.php:1025
[12-Feb-2020 20:31:43 Europe/Paris] * delete_records_sql(string(size 41), array(size 1)) at /home/lyceem2/public_html/mahara/lib/dml.php:1002
[12-Feb-2020 20:31:43 Europe/Paris] * delete_records_select(string(size 11), string(size 15), array(size 1)) at /home/lyceem2/public_html/mahara/auth/lib.php:2239
[12-Feb-2020 20:31:43 Europe/Paris] * auth_remove_old_session_files() at /home/lyceem2/public_html/mahara/lib/cron.php:186
[12-Feb-2020 20:31:43 Europe/Paris]
[12-Feb-2020 20:31:43 Europe/Paris] [WAR] c2 (lib/dml.php:1025) Failed to get a recordset: mysqli error: [2006: MySQL server has gone away] in EXECUTE("DELETE FROM "usr_session" WHERE mtime < '2020-02-11 20:25:02'")Command was: DELETE FROM "usr_session" WHERE mtime < ? and values was (0:2020-02-1120:25:02)
[12-Feb-2020 20:31:43 Europe/Paris] Call stack (most recent first):
[12-Feb-2020 20:31:43 Europe/Paris] * delete_records_sql(string(size 41), array(size 1)) at /home/lyceem2/public_html/mahara/lib/dml.php:1002
[12-Feb-2020 20:31:43 Europe/Paris] * delete_records_select(string(size 11), string(size 15), array(size 1)) at /home/lyceem2/public_html/mahara/auth/lib.php:2239
[12-Feb-2020 20:31:43 Europe/Paris] * auth_remove_old_session_files() at /home/lyceem2/public_html/mahara/lib/cron.php:186
[12-Feb-2020 20:31:43 Europe/Paris]
[12-Feb-2020 20:31:43 Europe/Paris] [WAR] c2 (lib/errors.php:858) Failed to get a recordset: mysqli error: [2006: MySQL server has gone away] in EXECUTE("UPDATE "cron" SET "nextrun" = '2020-02-13 20:30:00' WHERE "id" = '7' ")Command was: UPDATE "cron" SET "nextrun" = ? WHERE "id" = ? and values was (0:2020-02-1320:30:00,1:7)
[12-Feb-2020 20:31:43 Europe/Paris] Call stack (most recent first):
[12-Feb-2020 20:31:43 Europe/Paris] * log_message(string(size 263), integer, true, true) at /home/lyceem2/public_html/mahara/lib/errors.php:95
[12-Feb-2020 20:31:43 Europe/Paris] * log_warn(string(size 263)) at /home/lyceem2/public_html/mahara/lib/errors.php:858
[12-Feb-2020 20:31:43 Europe/Paris] * SQLException->__construct(string(size 263)) at /home/lyceem2/public_html/mahara/lib/dml.php:949
[12-Feb-2020 20:31:43 Europe/Paris] * set_field_select(string(size 4), string(size 7), string(size 19), string(size 16), array(size 2)) at /home/lyceem2/public_html/mahara/lib/dml.php:929
[12-Feb-2020 20:31:43 Europe/Paris] * set_field(string(size 4), string(size 7), string(size 19), string(size 2), string(size 1)) at /home/lyceem2/public_html/mahara/lib/cron.php:202
[12-Feb-2020 20:31:43 Europe/Paris]
[12-Feb-2020 20:31:43 Europe/Paris] [WAR] c2 (lib/dml.php:949) Failed to get a recordset: mysqli error: [2006: MySQL server has gone away] in EXECUTE("UPDATE "cron" SET "nextrun" = '2020-02-13 20:30:00' WHERE "id" = '7' ")Command was: UPDATE "cron" SET "nextrun" = ? WHERE "id" = ? and values was (0:2020-02-1320:30:00,1:7)
[12-Feb-2020 20:31:43 Europe/Paris] Call stack (most recent first):
[12-Feb-2020 20:31:43 Europe/Paris] * set_field_select(string(size 4), string(size 7), string(size 19), string(size 16), array(size 2)) at /home/lyceem2/public_html/mahara/lib/dml.php:929
[12-Feb-2020 20:31:43 Europe/Paris] * set_field(string(size 4), string(size 7), string(size 19), string(size 2), string(size 1)) at /home/lyceem2/public_html/mahara/lib/cron.php:202
[12-Feb-2020 20:31:43 Europe/Paris]

24 February 2020, 7:52

Hi Anthony

The MySQL server has gone away (error 2006) can be related to the following issues:

1) Server timed out and closed the connection. To fix, check that wait_timeout mysql variable in your my.cnf configuration file is large enough. You may also need to increase the innodb_log_file_size mysql variable in your my.cnf configuration to for example 128MB or higher.
2) Server dropped an incorrect or too large packet. If mysqld gets a packet that is too large or incorrect, it assumes that something has gone wrong with the client and closes the connection. To fix, you can increase the maximal packet size limit max_allowed_packet in my.cnf file, eg. set max_allowed_packet = 128M, then restart your MySQL server

Let us know if any of those setting needed changing or not and if they did - did it fix the problem?

Cheers

Robert

04 March 2020, 23:05

Hi Robert

I just sent a message to our host. I'll get back to you as soon as I have those informations.

Cheers.

Anthony.

04 March 2020, 23:48

Here are the values on the server :

wait_timeout = 360
innodb_log_file_size = 512M
max_allowed_packet = 512M

And we still have our cron problem.

05 March 2020, 9:59

Hi Anthony,

From the error logs you posted it looks like this query is timing out:

DELETE FROM "usr_session" WHERE mtime < '2020-02-11 20:25:02'

Are you able to check that directly on the database server to see how many lines it will involve? eg:

SELECT COUNT(*) FROM "usr_session" WHERE mtime < '2020-02-11 20:25:02';

And / or see if you can run the command direct on the database

DELETE FROM "usr_session" WHERE mtime < '2020-02-11 20:25:02';

To see if that sorts your problem

Cheers

Robert