CUNY Academic Commons

I just checked the Gmail logs and the email was received at the time you sent it, Matt (Sunday, 4am EDT). It's also interesting to note that Boone's email in #2045 was the next email that followed in the inbox (Sunday, 1pm EDT).

I'm curious to know if there was any type of server maintenance around this time period - Sunday, August 12, 4am EDT. This might have caused some type of parsing error, although at this point I'm purely speculating.

Hi André -- Can you shed any light on Ray's question? Many thanks.

Just FYI, it looks like André is on vacation until 8/16

There was no server maintenance. I'll double-check with the network team to see if there were any network at that time but I highly doubt it.

What's the logical tnread here? How often does the software check for new reply emails? Why would it only kick back into gear on Monday 11am?

I was able to duplicate this problem on cdev.

I've listed my observations here:
http://cdev.gc.cuny.edu/groups/email-test-group/forum/topic/testing-long-posts/?topic_page=1#post-2790

André, can you check to see if any server error messages were posted around 14-Aug-2012 02:30:33 UTC on cdev.gc.cuny.edu? Any issues with server load or anything like that?

I looked into this from multiple angles and can confirm that there were no outages or service interruption during this time-frame. Also I see no errors on cdev either. Here's the log entries for Aug 14:

[Tue Aug 14 00:36:40 2012] [error] [client 146.96.128.210] PHP Fatal error:  Call to undefined method WP_Error::get_item_quantity() in /var/www/html/wp-content/plugins/bp-external-activity/bp-external-activity.php on line 19
[Tue Aug 14 00:39:54 2012] [error] [client 50.98.25.126] ModSecurity: Failed to access DBM file "/etc/httpd/logs//global": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/index.php"] [unique_id "UCnWmJJggNIAABDTMzIAAAAE"]
[Tue Aug 14 00:39:54 2012] [error] [client 50.98.25.126] ModSecurity: Failed to access DBM file "/etc/httpd/logs//ip": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/index.php"] [unique_id "UCnWmJJggNIAABDTMzIAAAAE"]
[Tue Aug 14 00:39:58 2012] [error] [client 50.98.25.126] ModSecurity: Failed to access DBM file "/etc/httpd/logs//global": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/wp-content/plugins/buddypress-group-documents/js/general.js"] [unique_id "UCnWnpJggNIAACb7Zm0AAAAJ"]
[Tue Aug 14 00:39:58 2012] [error] [client 50.98.25.126] ModSecurity: Failed to access DBM file "/etc/httpd/logs//ip": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/wp-content/plugins/buddypress-group-documents/js/general.js"] [unique_id "UCnWnpJggNIAACb7Zm0AAAAJ"]
[Tue Aug 14 00:40:00 2012] [error] [client 50.98.25.126] PHP Fatal error:  Call to undefined method WP_Error::get_item_quantity() in /var/www/html/wp-content/plugins/bp-external-activity/bp-external-activity.php on line 19
[Tue Aug 14 00:40:33 2012] [error] [client 50.98.25.126] PHP Fatal error:  Call to undefined method WP_Error::get_item_quantity() in /var/www/html/wp-content/plugins/bp-external-activity/bp-external-activity.php on line 19
[Tue Aug 14 00:40:37 2012] [error] [client 50.98.25.126] ModSecurity: Failed to access DBM file "/etc/httpd/logs//global": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/wp-content/plugins/post-gallery-widget/js/pgw-slide.js"] [unique_id "UCnWxZJggNIAACb8ZvsAAAAK"]
[Tue Aug 14 00:40:37 2012] [error] [client 50.98.25.126] ModSecurity: Failed to access DBM file "/etc/httpd/logs//ip": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/wp-content/plugins/post-gallery-widget/js/pgw-slide.js"] [unique_id "UCnWxZJggNIAACb8ZvsAAAAK"]
[Tue Aug 14 03:18:46 2012] [error] [client 124.115.6.13] File does not exist: /home/cboxdev/www/robots.txt
[Tue Aug 14 11:42:44 2012] [error] [client 146.96.128.210] PHP Fatal error:  Call to undefined method WP_Error::get_item_quantity() in /var/www/html/wp-content/plugins/bp-external-activity/bp-external-activity.php on line 19
[Tue Aug 14 14:48:54 2012] [error] [client 66.249.71.197] File does not exist: /home/cboxdev/www/robots.txt
[Tue Aug 14 14:58:03 2012] [error] [client 146.96.128.210] PHP Fatal error:  Allowed memory size of 134217728 bytes exhausted (tried to allocate 2097152 bytes) in /var/www/html/wp-includes/cache.php on line 506
[Tue Aug 14 15:03:35 2012] [error] [client 146.96.128.210] PHP Fatal error:  Call to undefined method WP_Error::get_item_quantity() in /var/www/html/wp-content/plugins/bp-external-activity/bp-external-activity.php on line 19
[Tue Aug 14 15:04:19 2012] [error] [client 50.98.25.126] ModSecurity: Failed to access DBM file "/etc/httpd/logs//global": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/wp-admin/js/plugin-install.js"] [unique_id "UCqhM5JggNIAABDTM14AAAAE"]
[Tue Aug 14 15:04:19 2012] [error] [client 50.98.25.126] ModSecurity: Failed to access DBM file "/etc/httpd/logs//ip": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/wp-admin/js/plugin-install.js"] [unique_id "UCqhM5JggNIAABDTM14AAAAE"]
[Tue Aug 14 15:04:36 2012] [error] [client 146.96.128.210] PHP Fatal error:  Call to undefined method WP_Error::get_item_quantity() in /var/www/html/wp-content/plugins/bp-external-activity/bp-external-activity.php on line 19
[Tue Aug 14 15:05:51 2012] [error] [client 146.96.128.210] PHP Warning:  Variable passed to each() is not an array or object in /var/www/html/wp-content/plugins/forum-attachments-for-buddypress/forum-attachments-for-buddypress-bp-functions.php on line 464
[Tue Aug 14 15:06:47 2012] [error] [client 50.98.25.126] PHP Fatal error:  Call to undefined method WP_Error::get_item_quantity() in /var/www/html/wp-content/plugins/bp-external-activity/bp-external-activity.php on line 19
[Tue Aug 14 15:07:53 2012] [error] [client 50.98.25.126] ModSecurity: Failed to access DBM file "/etc/httpd/logs//global": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/wp-admin/css/colors-fresh.css"] [unique_id "UCqiCZJggNIAADvbTSoAAAAL"]
[Tue Aug 14 15:07:53 2012] [error] [client 50.98.25.126] ModSecurity: Failed to access DBM file "/etc/httpd/logs//ip": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/wp-admin/css/colors-fresh.css"] [unique_id "UCqiCZJggNIAADvbTSoAAAAL"]
[Tue Aug 14 15:20:50 2012] [error] [client 50.98.25.126] ModSecurity: Failed to access DBM file "/etc/httpd/logs//global": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/wp-content/plugins/buddypress-group-documents/css/style.css"] [unique_id "UCqlEpJggNIAABDVNVIAAAAG"]
[Tue Aug 14 15:20:50 2012] [error] [client 50.98.25.126] ModSecurity: Failed to access DBM file "/etc/httpd/logs//ip": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/wp-content/plugins/buddypress-group-documents/css/style.css"] [unique_id "UCqlEpJggNIAABDVNVIAAAAG"]
[Tue Aug 14 15:20:50 2012] [error] [client 50.98.25.126] ModSecurity: Failed to access DBM file "/etc/httpd/logs//global": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/wp-content/themes/bp-nelo/_inc/js/cac-custom-js.js"] [unique_id "UCqlEpJggNIAACb6ZewAAAAI"]
[Tue Aug 14 15:20:50 2012] [error] [client 50.98.25.126] ModSecurity: Failed to access DBM file "/etc/httpd/logs//ip": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/wp-content/themes/bp-nelo/_inc/js/cac-custom-js.js"] [unique_id "UCqlEpJggNIAACb6ZewAAAAI"]
[Tue Aug 14 15:25:03 2012] [error] [client 146.96.128.210] PHP Fatal error:  Call to undefined method WP_Error::get_item_quantity() in /var/www/html/wp-content/plugins/bp-external-activity/bp-external-activity.php on line 19
[Tue Aug 14 15:25:06 2012] [error] [client 50.98.25.126] PHP Fatal error:  Call to undefined method WP_Error::get_item_quantity() in /var/www/html/wp-content/plugins/bp-external-activity/bp-external-activity.php on line 19
[Tue Aug 14 15:27:00 2012] [error] [client 146.96.128.210] PHP Fatal error:  Call to undefined method WP_Error::get_item_quantity() in /var/www/html/wp-content/plugins/bp-external-activity/bp-external-activity.php on line 19
[Tue Aug 14 15:38:38 2012] [error] [client 146.96.128.210] PHP Fatal error:  Call to undefined method WP_Error::get_item_quantity() in /var/www/html/wp-content/plugins/bp-external-activity/bp-external-activity.php on line 19
[Tue Aug 14 15:38:40 2012] [error] [client 50.98.25.126] PHP Fatal error:  Call to undefined method WP_Error::get_item_quantity() in /var/www/html/wp-content/plugins/bp-external-activity/bp-external-activity.php on line 19
[Tue Aug 14 15:39:50 2012] [error] [client 146.96.128.210] PHP Warning:  Variable passed to each() is not an array or object in /var/www/html/wp-content/plugins/forum-attachments-for-buddypress/forum-attachments-for-buddypress-bp-functions.php on line 464
[Tue Aug 14 15:40:11 2012] [error] [client 50.98.25.126] ModSecurity: Failed to access DBM file "/etc/httpd/logs//global": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/wp-content/themes/bp-nelo/_inc/images/forum_bullet.gif"] [unique_id "UCqpm5JggNIAACb7Zs0AAAAJ"]
[Tue Aug 14 15:40:11 2012] [error] [client 50.98.25.126] ModSecurity: Failed to access DBM file "/etc/httpd/logs//ip": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/wp-content/themes/bp-nelo/_inc/images/forum_bullet.gif"] [unique_id "UCqpm5JggNIAACb7Zs0AAAAJ"]
[Tue Aug 14 15:40:22 2012] [error] [client 50.98.25.126] PHP Fatal error:  Call to undefined method WP_Error::get_item_quantity() in /var/www/html/wp-content/plugins/bp-external-activity/bp-external-activity.php on line 19
[Tue Aug 14 16:19:58 2012] [error] [client 123.125.71.101] ModSecurity: Failed to access DBM file "/etc/httpd/logs//global": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/"] [unique_id "UCqy7pJggNIAACb6ZgEAAAAI"]
[Tue Aug 14 16:19:58 2012] [error] [client 123.125.71.101] ModSecurity: Failed to access DBM file "/etc/httpd/logs//ip": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/"] [unique_id "UCqy7pJggNIAACb6ZgEAAAAI"]
[Tue Aug 14 17:57:55 2012] [error] [client 146.96.128.210] PHP Fatal error:  Call to undefined method WP_Error::get_item_quantity() in /var/www/html/wp-content/plugins/bp-external-activity/bp-external-activity.php on line 19
[Tue Aug 14 17:57:56 2012] [error] [client 50.98.25.126] ModSecurity: Failed to access DBM file "/etc/httpd/logs//global": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/wp-content/plugins/buddypress-group-email-subscription/css/bp-activity-subscription-css.css"] [unique_id "UCrJ5JJggNIAACb8Z1wAAAAK"]
[Tue Aug 14 17:57:56 2012] [error] [client 50.98.25.126] ModSecurity: Failed to access DBM file "/etc/httpd/logs//ip": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/wp-content/plugins/buddypress-group-email-subscription/css/bp-activity-subscription-css.css"] [unique_id "UCrJ5JJggNIAACb8Z1wAAAAK"]
[Tue Aug 14 17:58:42 2012] [error] [client 50.98.25.126] PHP Fatal error:  Call to undefined method WP_Error::get_item_quantity() in /var/www/html/wp-content/plugins/bp-external-activity/bp-external-activity.php on line 19
[Tue Aug 14 17:59:05 2012] [error] [client 146.96.128.210] PHP Fatal error:  Call to undefined method WP_Error::get_item_quantity() in /var/www/html/wp-content/plugins/bp-external-activity/bp-external-activity.php on line 19
[Tue Aug 14 18:52:54 2012] [error] [client 146.96.128.210] PHP Fatal error:  Call to undefined method WP_Error::get_item_quantity() in /var/www/html/wp-content/plugins/bp-external-activity/bp-external-activity.php on line 19
[Tue Aug 14 18:53:46 2012] [error] [client 201.15.121.73] File does not exist: /var/www/status/manager
[Tue Aug 14 21:00:59 2012] [error] [client 146.96.128.210] PHP Fatal error:  Call to undefined method WP_Error::get_item_quantity() in /var/www/html/wp-content/plugins/bp-external-activity/bp-external-activity.php on line 19
[Tue Aug 14 23:33:43 2012] [error] [client 66.249.71.211] ModSecurity: Failed to access DBM file "/etc/httpd/logs//global": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/members/jtalbird/activity/"] [unique_id "UCsYl5JggNIAADvbTVUAAAAL"]
[Tue Aug 14 23:33:43 2012] [error] [client 66.249.71.211] ModSecurity: Failed to access DBM file "/etc/httpd/logs//ip": Permission denied [hostname "cdev.gc.cuny.edu"] [uri "/members/jtalbird/activity/"] [unique_id "UCsYl5JggNIAADvbTVUAAAAL"]

Many thanks, André

Thanks Boone for noting.

Looks like the crux of the problem came after [19-Aug-2012 07:56:02] GMT. The IMAP connection is never disconnected (at least in RBE's eyes), which is causing all the problems.

Can you copy and paste the contents of the error log for August 19th? Just want to do some cross-referencing.

I have an idea about fixing this problem using a __destruct() method or a register_shutdown_function() in the class that will hopefully clean up some DB connection entries during shutdown. Will be hard to duplicate locally though, since it's all time-sensitive! :(

I'll try also to build an admin alert to be sent via email when perhaps three consecutive "--- Cronjob wants to connect - however according to our DB indicator, we already have an active IMAP connection! ---" are posted in a row.

Can you copy and paste the contents of the error log for August 19th?

Which error log? André may have to get that for you.

I'll try also to build an admin alert to be send via email when perhaps three consecutive "--- Cronjob wants to connect - however according to our DB indicator, we already have an active IMAP connection! ---" are posted in a row.

Great idea. This would go a long way toward mitigating the issue.

Thanks so much, Ray!

I've added a failsafe for RBE as part of commit 8ed8a2e.

What this failsafe does is clear RBE's DB markers and scheduled hook when RBE logs three consecutive "--- Cronjob wants to connect - however according to our DB indicator, we already have an active IMAP connection! ---" messages. This will ensure that RBE will reboot on the fourth try.

As for the email functionality I mentioned here, since we no longer need user intervention to deactivate the plugin to reboot RBE, I have extrapolated the email-to-admin feature into a small plugin. I didn't add it into the CAC repo because I wasn't sure if it was still needed.

The failsafe takes some steps in reviving RBE after it fails, but it doesn't really address the original issue of the duplicate, delayed post. Unfortunately, RBE will sometimes fail during the inbox loop. I've found this issue hard to debug because it's hard to duplicate and that no errors are left in the server error log when it does occur.

Boone, if you have any ideas that I'm overlooking, let me know.

FWIW, I did experiment with using a __destruct() method and a register_shutdown_function() hook, but they both didn't fire when the inbox loop failed so I ended up using the log check method above.

Yes -- huge thanks, Ray.