02 October 2009, 10:26

 I, unfortunately, the cron job in our Mahara version 1.1.6 (2009022617), there seems to be a problem with SQL orders on our mySQL Database:

Can someone tell me, if those errors have been reported or yet better fixed? I know, this is mySQL and not the recommended, but maybe, there is some solution.

Thanks,

Regards,

Arne

[DBG] 69 (lib/cron.php:64) ---------- cron running Fri, 02 Oct 2009 16:04:49 +0200 ----------
[DBG] 69 (lib/cron.php:84) Running PluginInteractionForum::interaction_forum_new_post
[WAR] 69 (lib/errors.php:663) Failed to get a recordset: mysql error: [1064: You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'key, 'topic' AS type
[WAR] 69 (lib/errors.php:663)                 FROM "interaction_forum_subscription_topic"' at line 3] in EXECUTE("SELECT s.subscriber, s.type, s.key, p.id
[WAR] 69 (lib/errors.php:663)             FROM (
[WAR] 69 (lib/errors.php:663)                 SELECT st."user" AS subscriber, st.topic AS topic, st.key AS key, 'topic' AS type
[WAR] 69 (lib/errors.php:663)                 FROM "interaction_forum_subscription_topic" st
[WAR] 69 (lib/errors.php:663)                 UNION SELECT sf."user" AS subscriber, t.id AS topic, sf.key AS key, 'forum' AS type
[WAR] 69 (lib/errors.php:663)                 FROM "interaction_forum_subscription_forum" sf
[WAR] 69 (lib/errors.php:663)                 INNER JOIN "interaction_forum_topic" t ON t.forum = sf.forum
[WAR] 69 (lib/errors.php:663)             ) s
[WAR] 69 (lib/errors.php:663)             INNER JOIN "interaction_forum_topic" t ON (t.deleted != 1 AND t.id = s.topic)
[WAR] 69 (lib/errors.php:663)             INNER JOIN "interaction_forum_post" p ON (p.sent != 1 AND p.ctime < '2009-10-02 15:34:49' AND p.deleted != 1 AND p.topic = t.id)
[WAR] 69 (lib/errors.php:663)             INNER JOIN "interaction_instance" f ON (f.id = t.forum AND f.deleted != 1)
[WAR] 69 (lib/errors.php:663)             INNER JOIN "group" g ON (g.id = f.group AND g.deleted = 0)
[WAR] 69 (lib/errors.php:663)             INNER JOIN "group_member" gm ON (gm.member = s.subscriber AND gm.group = f.group)
[WAR] 69 (lib/errors.php:663)             ORDER BY type, p.id")
[WAR] 69 (lib/errors.php:663) Command was: SELECT s.subscriber, s.type, s.key, p.id
[WAR] 69 (lib/errors.php:663)             FROM (
[WAR] 69 (lib/errors.php:663)                 SELECT st."user" AS subscriber, st.topic AS topic, st.key AS key, 'topic' AS type
[WAR] 69 (lib/errors.php:663)                 FROM "interaction_forum_subscription_topic" st
[WAR] 69 (lib/errors.php:663)                 UNION SELECT sf."user" AS subscriber, t.id AS topic, sf.key AS key, 'forum' AS type
[WAR] 69 (lib/errors.php:663)                 FROM "interaction_forum_subscription_forum" sf
[WAR] 69 (lib/errors.php:663)                 INNER JOIN "interaction_forum_topic" t ON t.forum = sf.forum
[WAR] 69 (lib/errors.php:663)             ) s
[WAR] 69 (lib/errors.php:663)             INNER JOIN "interaction_forum_topic" t ON (t.deleted != 1 AND t.id = s.topic)
[WAR] 69 (lib/errors.php:663)             INNER JOIN "interaction_forum_post" p ON (p.sent != 1 AND p.ctime < ? AND p.deleted != 1 AND p.topic = t.id)
[WAR] 69 (lib/errors.php:663)             INNER JOIN "interaction_instance" f ON (f.id = t.forum AND f.deleted != 1)
[WAR] 69 (lib/errors.php:663)             INNER JOIN "group" g ON (g.id = f.group AND g.deleted = 0)
[WAR] 69 (lib/errors.php:663)             INNER JOIN "group_member" gm ON (gm.member = s.subscriber AND gm.group = f.group)
[WAR] 69 (lib/errors.php:663)             ORDER BY type, p.id and values was (2009-10-02 15:34:49)
Call stack (most recent first):
  * log_message("Failed to get a recordset: mysql error: [1064: You...", 8, true, true) at /srv/mahara_elsa/htdocs/lib/errors.php:90
  * log_warn("Failed to get a recordset: mysql error: [1064: You...") at /srv/mahara_elsa/htdocs/lib/errors.php:663
  * SQLException->__construct("Failed to get a recordset: mysql error: [1064: You...") at /srv/mahara_elsa/htdocs/lib/dml.php:449
  * get_recordset_sql("SELECT s.subscriber, s.type, s.key, p.id
         ...", array(size 1), "", "") at /srv/mahara_elsa/htdocs/lib/dml.php:631
  * get_records_sql_array("SELECT s.subscriber, s.type, s.key, p.id
         ...", array(size 1)) at /srv/mahara_elsa/htdocs/interaction/forum/lib.php:338
  * PluginInteractionForum::interaction_forum_new_post() at Unknown:0
  * call_user_func_array(array(size 2), array(size 0)) at /srv/mahara_elsa/htdocs/lib/mahara.php:986
  * call_static_method("PluginInteractionForum", "interaction_forum_new_post") at /srv/mahara_elsa/htdocs/lib/cron.php:90

04 October 2009, 18:58

Hi, looks like you've run into a bug that we fixed just recently (after 1.1.6 was released though).

The following patch fixes it. It shouldn't be too hard to apply, so give it a go and see if it works 

http://git.mahara.org/?p=mahara.git;a=commitdiff;h=a26322ad711be9978a5210c7c6340dcedc85a462;hp=65733fd58d2e479d771a28a49aeee0409df21293

05 October 2009, 13:14

Hi Nigel,

thanks for your fast help. The error message disappeared, but the problem is not solved, yet. Still no notification messages ....?

Please help, is there any other possibility, I can check?

(We are about to start productively with mahara at the Leibniz University of Hannover, Germany, they tell me, they ll dearly need this function :-) )

Kind Regards,

Arne

05 October 2009, 17:25

06 October 2009, 3:59

Hi Nigel,

yes, the server sends mails, if  a account is created and when you send new passwords. But notifications are not sent. They are set to "e-mail" in the configuration.

30 minutes ago, my colleague produced a notification message. I waited some minutes and then executed the cron.php manually (no error shown by it), but those things didn't help. The mail didn't arrive until 10 mins ago.

06 October 2009, 21:03

Hm. Are you logging the output of your cron job? I guess you are, if you found that SQL error in the first place. It might pay for you to put a bit of code into the code that sends the e-mails, to see what is going on.

In interaction/forum/lib.php, you will see the method interaction_forum_new_post. In there, you can put calls to the log_debug() function to output logging lines to the error log. If you call it passing arrays, it will dump them in a nice format.

You might want to change the job to run every minute instead of every 30 minutes. If you look in the interaction_cron table in the database, you can update the minute record to be *, and also make the nextrun column be a minute or two away. Then the cron job should start running every minute after that.

I guess it's a bit of a long shot, but if you can work through those steps, you might find more information about what is wrong. The only other thing I can think of is to again, re-check all of your email server logs to see if any mails are being sent at all, and if they are, whether they're being delivered.

08 October 2009, 12:26

I do pipe the cron messages in a log file in the crontab file.

But where does log_debug write its messages to? I cannot locate the regular log file, if there is one?

Searching alt least for the output of log_debug.....

08 October 2009, 18:10

If the log_debug calls happen during the cron run, they'll go to the log file you're piping output to. During cron, log_debug messages go to stdout.

However, if you're running the cron job with curl, then it's just a standard HTTP request, so the log_debug lines will all go to the apache error log for your Mahara vhost. So you should check there to see if the lines are in there. 

09 October 2009, 16:20

Hi Nigel,

I am currently on it and tracked the process down.

First of all, it cannot be a problem with the MTA, since messages concerning the creation of new accounts are sent.

I am testing like this: Creation of a new entry in a forum, which I (as user) also do register for notications. E-Mails are turned also on the the settings.

The notification is certainly built some minutes after the creation of the forum post. It looks like:

[DBG] 2e (interaction/forum/lib.php:361) Array
[DBG] 2e (interaction/forum/lib.php:361) (
[DBG] 2e (interaction/forum/lib.php:361)     [0] => stdClass Object
[DBG] 2e (interaction/forum/lib.php:361)         (
[DBG] 2e (interaction/forum/lib.php:361)             [subscriber] => 28
[DBG] 2e (interaction/forum/lib.php:361)             [type] => forum
[DBG] 2e (interaction/forum/lib.php:361)             [key] => 5dfa6929
[DBG] 2e (interaction/forum/lib.php:361)             [id] => 18
[DBG] 2e (interaction/forum/lib.php:361)             [users] => Array
[DBG] 2e (interaction/forum/lib.php:361)                 (
[DBG] 2e (interaction/forum/lib.php:361)                     [0] => 28
[DBG] 2e (interaction/forum/lib.php:361)                     [1] => 1
[DBG] 2e (interaction/forum/lib.php:361)                     [2] => 4
[DBG] 2e (interaction/forum/lib.php:361)                 )
[DBG] 2e (interaction/forum/lib.php:361)
[DBG] 2e (interaction/forum/lib.php:361)             [subscriptions] => Array
[DBG] 2e (interaction/forum/lib.php:361)                 (
[DBG] 2e (interaction/forum/lib.php:361)                     [28] => Array
[DBG] 2e (interaction/forum/lib.php:361)                         (
[DBG] 2e (interaction/forum/lib.php:361)                             [key] => 5dfa6929
[DBG] 2e (interaction/forum/lib.php:361)                             [type] => forum
[DBG] 2e (interaction/forum/lib.php:361)                         )
[DBG] 2e (interaction/forum/lib.php:361)
[DBG] 2e (interaction/forum/lib.php:361)                     [1] => Array
[DBG] 2e (interaction/forum/lib.php:361)                         (
[DBG] 2e (interaction/forum/lib.php:361)                             [key] => 982fc6a
[DBG] 2e (interaction/forum/lib.php:361)                             [type] => forum
[DBG] 2e (interaction/forum/lib.php:361)                         )
[DBG] 2e (interaction/forum/lib.php:361)
[DBG] 2e (interaction/forum/lib.php:361)                     [4] => Array
[DBG] 2e (interaction/forum/lib.php:361)                         (
[DBG] 2e (interaction/forum/lib.php:361)                             [key] => 41f5885f
[DBG] 2e (interaction/forum/lib.php:361)                             [type] => forum
[DBG] 2e (interaction/forum/lib.php:361)                         )
[DBG] 2e (interaction/forum/lib.php:361)
[DBG] 2e (interaction/forum/lib.php:361)                 )
[DBG] 2e (interaction/forum/lib.php:361)
[DBG] 2e (interaction/forum/lib.php:361)         )
[DBG] 2e (interaction/forum/lib.php:361)
[DBG] 2e (interaction/forum/lib.php:361) )

Then, this array is  given from function "interaction_forum_new_post" to function "activity_occured".

This seems to be also ok, since the information is packed as this:

 [DBG] 2e (lib/activity.php:44) stdClass Object
[DBG] 2e (lib/activity.php:44) (
[DBG] 2e (lib/activity.php:44)     [type] => 11
[DBG] 2e (lib/activity.php:44)     [data] => a:3:{s:6:"postid";s:2:"18";s:5:"users";a:3:{i:0;s:2:"28";i:1;s:1:"1";i:2;s:1:"4";}s:13:"subscriptions";a:3:{i:28;a:2:{s:3:"key";s:8:"5dfa6929";s:4:"type";s:5:"forum";}i:1;a:2:{s:3:"key";s:7:"982fc6a";s:4:"type";s:5:"forum";}i:4;a:2:{s:3:"key";s:8:"41f5885f";s:4:"type";s:5:"forum";}}}
[DBG] 2e (lib/activity.php:44)     [ctime] => 2009-10-09 20:48:02
[DBG] 2e (lib/activity.php:44) )
[DBG] 2e (lib/activity.php:44)

in "activity_occured" it is given to insert_record('activity_queue' and put into the table activity_queue in the database. The activity_queue Table is empty, as I checked some time after the events happend. 

That's why I supposed, there has something happened with this entries from the table.

Hoever, I am still searching for the routine, that works down the activity queue, because I did not receive any mails since.

I am currently still in progress, so if you answer, I can incorporate your knowledge directly and I also need it, so please... :-)

Kind Regards,

Arne

09 October 2009, 16:45

ok, got down to the call of the function "notify_users" in function "handle_activity".

I'm close to the solution of this riddle, I can sense it....

However, still waiting for the interaction_forum_newpost function to notice that there are a lot new forum posts. it just doesn't do anything until now (waited at least 20 mins or more, although the cron runs every minute)