31 May 2022, 19:33

Hello there,

we are struggeling with our mahara cron job about since we upgraded to 21.10 in April this year.

Some mahara users told us, they received e-mail messages, which have been delayed by nearly 2 months (forum post from 08. April was received yesterday, 30. May).

After digging through maharas settings, everything seems to be correctly setup, most emails are being sent in time to our users. 

But Mahara also tells me "cron is not running" while the server command line clearly shows, the cron (no, not really cron, it's systemd's timer) is being called every minute.

"NEXT                         LEFT          LAST                         PASSED       UNIT                         ACTIVATES
Di 2022-05-31 09:14:00 CEST  27s left      Di 2022-05-31 09:12:05 CEST  1min 26s ago mahara-cron.timer            mahara-cron.service"

journalctl too tells me the cron job per se is being executed.

Mai 31 09:14:05 vmurzmaharaapp2.rz.intern.uni-leipzig.de php[12842]: [INF] 3e (lib/cron.php:55) ---------- cron running Tue, 31 May 2022 09:14:05 +0200 ----------
Mai 31 09:14:05 vmurzmaharaapp2.rz.intern.uni-leipzig.de php[12842]: [INF] 3e (lib/cron.php:114) Running PluginSearchElasticsearch::cron
Mai 31 09:14:05 vmurzmaharaapp2.rz.intern.uni-leipzig.de php[12842]: [INF] 3e (lib/cron.php:568) Skipping long-running cron job core_activity_process_queue (Mon, 30 May 2022 12:53:06 +0200).
Mai 31 09:14:05 vmurzmaharaapp2.rz.intern.uni-leipzig.de php[12842]: [INF] 3e (lib/cron.php:193) Running core cron watchlist_process_notifications
Mai 31 09:14:05 vmurzmaharaapp2.rz.intern.uni-leipzig.de php[12842]: [INF] 3e (lib/cron.php:193) Running core cron check_imap_for_bounces
Mai 31 09:14:06 vmurzmaharaapp2.rz.intern.uni-leipzig.de php[12842]: [INF] 3e (lib/cron.php:193) Running core cron portfolio_auto_copy
Mai 31 09:14:06 vmurzmaharaapp2.rz.intern.uni-leipzig.de php[12842]: [INF] 3e (lib/cron.php:235) ---------- cron finished Tue, 31 May 2022 09:14:06 +0200 ----------

What caught my attention is the following line:

Mai 31 09:14:05 vmurzmaharaapp2.rz.intern.uni-leipzig.de php[12842]: [INF] 3e (lib/cron.php:568) Skipping long-running cron job core_activity_process_queue (Mon, 30 May 2022 12:53:06 +0200).

Looking at the mahara code base I found the database table "activity_queue" with the following content:

   id   | type |        ctime        | last_processed_userid
--------+------+---------------------+-----------------------
 456407 |    5 | 2022-04-05 11:12:54 |                 16469
 456410 |    5 | 2022-04-05 11:12:55 |                 16469
 456412 |    5 | 2022-04-05 11:12:58 |                 13318
 456416 |    5 | 2022-04-05 11:14:32 |                 16466
 456415 |    5 | 2022-04-05 11:14:32 |                 16478
 456417 |    5 | 2022-04-05 11:16:01 |                 16466
 456419 |    5 | 2022-04-05 11:16:02 |                 16469
 456418 |    5 | 2022-04-05 11:16:02 |                 16349
 456420 |    5 | 2022-04-05 11:16:05 |                 16478
 456422 |    5 | 2022-04-05 11:16:06 |                 16478
 456428 |   11 | 2022-04-05 13:05:52 |                 15056
 456440 |    5 | 2022-04-05 13:45:29 |                 16345
 456442 |    5 | 2022-04-05 13:45:58 |                 16345
 456465 |    5 | 2022-04-05 14:37:41 |                 15076
 456460 |    5 | 2022-04-05 14:37:41 |                 16509
 456462 |    5 | 2022-04-05 14:37:41 |                 16509 ...

There are almost 2000 entries in this table, which seem to me, what is blocking this cron function.

maharadb=> select type, count(type) from activity_queue group by type;
 type | count
------+-------
   11 |   236
    6 |     3
    1 |    96
   12 |    14
    5 |  1606
(5 Zeilen)

What can we do to either speed up the execution of this cron function or to empty this table? Can we delete the entries from the table or does this lead to strange behaviour? Most the email messages which are delayed do not need to be sent anymore, I think. 

Hoping someone can help us with this strange problem.

Regards Sven

02 June 2022, 7:25

Hi Sven,

Do you have anything in your error log?

Thank you

Kristina

02 June 2022, 20:16

Hi Kristina,

no, there are no further log messages I'm aware of. Maybe i'm looking at the wrong place?

I looked at "$cfg->dataroot/log". The error log was not touched since 2019.

Can I force extended logging?

I posted the problem in our german mahara forum for universities (moodle.hu-berlin.de/mod/forum/view.php?id=692215). One other university ran into the same problem after upgrading mahara. They removed the blocking entries from the database table and everything was fine.

Best regards
Sven

08 June 2022, 12:15

Hi Sven,

Not having any errors in the error log since 2019 does not sound right. Please check with your server admin where they've put it. The error log is typically configured in the Apache configuration. Typically, you'd have an error log and an access log set up.

If the problem happens on a non-production site, you can also output errors to screen, which can help greatly spot issues during testing quickly.

Cheers

Kristina

13 June 2022, 20:40

Hi Kristina,

I'm not that deep into Mahara, but I don't think, the cron job output is logged into apaches error log unless the cron run ist triggered via web. But this isn't the case, we are triggering it via systemds timer. So all messages from maharas cron functions are going to the journal (I posted an excerpt from that in my first message).

The error log I mentioned is located in a directory inside "$cfg->dataroot", it is called "log" and contains an old error log file. Maybe this was used in an earlier version of mahara.

I solved the problem now by deleting all piled up entries from the database table 'activity_queue'. Now that this table is empty, Mahara tells me that the cron job ist running fully correctly.

Best regards

Sven