Project

General

Profile

Actions

Bug #2046

closed

RBE Delayed Post

Added by Matt Gold about 10 years ago. Updated about 10 years ago.

Status:
Resolved
Priority name:
High
Assignee:
Category name:
BuddyPress (misc)
Target version:
Start date:
2012-08-13
Due date:
% Done:

0%

Estimated time:

Description

A message that I sent by RBE a day ago (Sunday 4am) just appeared now (Monday 11am). Screenshots attached and I'll forward the message in question to you, Ray.


Files

reply-sent-by-rbe-sunday-4am.png (166 KB) reply-sent-by-rbe-sunday-4am.png Matt Gold, 2012-08-13 11:36 PM
email-notification-monday-11pm.png (142 KB) email-notification-monday-11pm.png Matt Gold, 2012-08-13 11:36 PM
posting-on-site.png (47.1 KB) posting-on-site.png Matt Gold, 2012-08-13 11:36 PM
Actions #1

Updated by Raymond Hoh about 10 years ago

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.

Actions #2

Updated by Matt Gold about 10 years ago

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

Actions #3

Updated by Matt Gold about 10 years ago

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

Actions #4

Updated by local admin about 10 years ago

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?

Actions #5

Updated by Raymond Hoh about 10 years ago

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?

Actions #6

Updated by local admin about 10 years ago

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"]
Actions #7

Updated by Matt Gold about 10 years ago

Many thanks, André

Actions #8

Updated by Boone Gorges about 10 years ago

  • Severity changed from High impact to Critical

Hey Ray - Just want to note that the system hung again. Here's the last successful post before the hang in the log (this should help you find the point):

[18-Aug-2012 12:59:12] Message #1: this is a private message reply
[18-Aug-2012 12:59:12] Message #1: PM reply successfully posted!

I noticed today that replies weren't posting successfully (after I sent one myself), so I deactivated and reactivated RBE. The 10 messages in the queue came through once the IMAP connection was reestablished.

Just another data point. Hope that's helpful in debugging.

I'm going to bump the severity on this one, because as we get closer to the school year, it gets more likely that this will affect real use. Thanks, Ray.

Actions #9

Updated by Raymond Hoh about 10 years ago

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.

Actions #10

Updated by Boone Gorges about 10 years ago

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!

Actions #11

Updated by Raymond Hoh about 10 years ago

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.

Actions #12

Updated by Boone Gorges about 10 years ago

  • Status changed from Assigned to Resolved

Thanks for this, Ray.

The failsafe looks good for now. I know the frustration of building a band-aid for something without being able to identify the undelying cause of the problem, but for now this is sufficient for our purposes.

That said, if you have any ideas about ways that André could help to debug the root cause, please don't hesitate to pipe up. I don't understand what's happening well enough to make any concrete suggestions - maybe a higher level of error logging?

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.

Let's run without this additional plugin for now. If the system can kickstart itself, there's no reason why I should suffer the stress of a failure email :)

Marking this issue Resolved. If we see more issues after the 1.4.3 release, let's revisit. Thanks again for your work debugging an eely issue, Ray.

Actions #13

Updated by Matt Gold about 10 years ago

Yes -- huge thanks, Ray.

Actions

Also available in: Atom PDF