bpges_queued_items ballooning + admin-ajax timout

Hi Vivek,

Sorry for the trouble, and thanks for the report.

I assume that the ‘timeout’ error is connected to the missing digests. Digests are sent in asynchronous batches. At the designated time each day (or week), the batch process is triggered with a admin-ajax.php call like the one you’ve described. The process runs until the time limit or memory limit is close to being exceeded, at which point it triggers a new “batch” of digests. The plugin uses the following logic to determine memory or time limits:

– time https://github.com/boonebgorges/buddypress-group-email-subscription/blob/4092b3c3f39353527dcf4fef4ba2768dd678b792/classes/class-bpges-async-request-send-queue.php#L244
– memory https://github.com/boonebgorges/buddypress-group-email-subscription/blob/4092b3c3f39353527dcf4fef4ba2768dd678b792/classes/class-bpges-async-request-send-queue.php#L195

The fact that you’re seeing a timeout suggests (obviously!) that the time_exceeded() logic is not working correctly. Hopefully you can see in the time_exceeded() method that there are a couple of places where things might be going astray. First, it could be that we’re not correctly determining the max_execution_time on your server (and this could be something that changed recently on your server, like maybe a PHP upgrade or something). Or it could be that $this->start_time is being set too late in the bootstrap process, so that the calculated $finish time is longer than the actual max_execution_time on the server.

We could experiment with this by manually modifying the time_exceeded() logic so that we can ensure that we don’t get timeouts. For example, you could insert a line here https://github.com/boonebgorges/buddypress-group-email-subscription/blob/4092b3c3f39353527dcf4fef4ba2768dd678b792/classes/class-bpges-async-request-send-queue.php#L263 that says $max_execution_time = '10'; – in other words, we are telling BPGES that it should stop execution around 10 seconds, keeping far away from the server’s timeout setting. If this works, it will narrow down the problem a bit.

Items in the bpges_queued_items table should be deleted after they’ve been sent, so it’s likely that these items represent failures. Are all/most of the unsent items linked to a digest (‘daily’ or ‘weekly’) or are some of them ‘immediate’ as well?

One issue here is that there are timeouts, and we’re trying to identify the root cause above. There’s a second issue, which is that BPGES should be better at identifying failures, and triggering a re-send. For that, there’s an existing GitHub ticket, and in that ticket I’ve got a small script that, if placed in an mu-plugins file, will run a periodic check for unsent ‘immediate’ items. See https://github.com/boonebgorges/buddypress-group-email-subscription/issues/163

Thanks very much for the detailed response, Boone- really appreciate that. Below is some more info on the issue. Please bear with me as i am not a developer.

1. I have only daily digests (most) or weekly (few). there are no individual mails being sent.

2. Analysed the bpges_queued_items, and the items in it are only for typically 4-5 days in a month (avg), and on those days the count of mails (user_id count) is about the same as the number of subscribers – so pretty much all the mails that should have gone.

3. However, comparing the count of mails in queue, with mails in my sent mail (sendgrid) log, i cannot find a definite pattern, as on several days whose mails are in the queue table, also show similar count of mails sent. Also, some days when mails are not sent / very few mails sent, those days are not in the queue.

4. I checked my PHP limits and max_execution_time is set for 120, and Memory limit is set to 768M ( i am not on shared hosting, but on Siteground cloud – despite little traffic, i have a lot of plugins)

5. Last 4-5 days as mentioned, only about 10% of mails are being sent, and there are entries in the queue for each day for most of the list ( i could also see some entries in the queued list, which were in the sent list for the next day)

Does any of this help to identify the issue? What do you suggest i should try to do?

Also, can i delete all the items in the bpges queue? if so, how?

thanks,
Vivek

Hi Boone, Just a quick update, for the last 2 days, I am not getting the Timeout error on admin-ajax.php, perhaps after i increased the cron frequency from 30 mins to 10 mins (no idea if that is related, though)

However, even now only very few mails (< 10% are being sent), though there is no error in the logs.

Any suggestions, along with the previous observations sent, will be very useful.

thanks,
Vivek

In the next few days, I’ll find time to try putting together some of the clues you’ve given here.

In the meantime, I forgot to ask previously: did you enable bpges-debug.log, as described at https://github.com/boonebgorges/buddypress-group-email-subscription/wiki/How-to-troubleshoot-missing-emails? This might help explain whether we’re getting just a single batch (my hunch) or whether something else is happening.

Thanks, Boone.

The debug log has these entries (now about 6 hours after the digest should have run, at 1:00 on Sept 15). So it seems the batch is beginning but not finishing. And there is no timeout error in the error log either.

[14-Sep-2020 17:27:39] Beginning batch of immediate notifications for 17025.
[14-Sep-2020 17:27:39] Finished sending immediate notifications for 17025. A total of 0 notifications were sent over all batches.
[14-Sep-2020 18:07:20] Beginning batch of immediate notifications for 17026.
[14-Sep-2020 18:07:20] Finished sending immediate notifications for 17026. A total of 0 notifications were sent over all batches.
[15-Sep-2020 01:10:15] Beginning digest batch of type dig for timestamp 2020-09-15 01:10:03.

I had also deleted the plugin and reinstalled, as well as deleted the queue entries prior to 7 days in the db. After that, the last couple of days intead of the expected ~ 2700 digests, which were down to ~ 250-300 when i wrote last, it is now only ~ 30 being sent.

thanks, Vivek

Also, in case this is relevant, i have this in my bp-custom.php , as i am using the Sendgrid plugin to send mails. While this is probably downstream (as mails are not even shown as sent in the email log), I am just mentoning as i have reaad about some issue with PHPmailer with BP 6.0 etc.

add_filter(‘bp_email_use_wp_mail’, ‘__return_true’);

Thanks for the additional details, Vivek.

A few things about bpges-debug make me suspicious. First, it’s strange that the ‘immediate’ notification rows are showing ‘0 notifications’. Is this actually true? If notifications actually are being sent, but the log says that ‘0 notifications’ have gone out, then it could be related to your use of bp_email_use_wp_email, since wp_mail() may not return the values that BPGES needs to create the debug log. If it’s true that immediate notifications are not being sent, then it could be part of the same problem we’re seeing with digests.

With regard to bpges-debug and digests, it’s suspicious that the batch is starting (“Beginning digest batch…”) but that you’re not seeing a notice of the batch ending. You should see an entry in the log when the batch finishes. If the batch process fails unexpectedly, it might result in the entry not being written into bpges-debug.log, and it would also explain why the next batch is not being launched. So why would a batch fail early? Either because of a timeout or memory failure, or because of a fatal error. You’ve said that the timeouts are no longer appearing. Are you seeing any fatal errors in your Apache log? Do you have the log level turned up high enough so that such errors would appear there?

Hi Boone

Thank you so much for this plugin!

We’re facing same kind of problem.

There are 143 subscribers with our one group and all are using Daily digest for the group.

When the daily digest send the email, only 92 users receive it. I’ve checked our email that we’re using with SMTP.

As in the previous comments, I did this step to check the logs –
in config.php define( ‘BPGES_DEBUG’, true );

Here’s the log for last digest:

[22-Oct-2020 05:00:56] Beginning digest batch of type sum for timestamp 2020-10-22 05:00:55.
[22-Oct-2020 05:00:56] Finished digest run of type sum for timestamp 2020-10-22 05:00:55. Digests were sent to a total of 0 users.
[22-Oct-2020 05:00:57] Beginning digest batch of type dig for timestamp 2020-10-22 05:00:56.
[22-Oct-2020 05:03:09] Finished digest run of type dig for timestamp 2020-10-22 05:00:56. Digests were sent to a total of 143 users.

According to this, there’s no error and email is sent to 143 users but I’ve crosschecked with the users even, they haven’t received the daily digest.

Please help!
Thanks & Regards,
-Mohit

Hi @hotmaddycool – Sorry to hear you’re having problems.

The log doesn’t really give any details here, unfortunately. The internal BPGES log tools don’t currently collect more fine-grained information, which makes it harder to dig into what’s going on here. I’ll work on improved logging for a future release.

Are you able to check the outgoing SMTP logs/outbox to confirm that only 92 emails are sent out?

Hi @boonebgorges

Thank you so much for the response.

Are you able to check the outgoing SMTP logs/outbox to confirm that only 92 emails are sent out? =>
We’re using one of our G Suite account for SMTP. We saw sent emails in the same email account. And from the reports even it is showing 92 emails only.

Is there a way by which we can send the emails of daily digest in BCC rather than individual emails??