CUNY Academic Commons

Thanks for the detailed report.

The discrepancy between Profile > My Settings > Notifications and My Groups > Memberships is a red herring. The former (Notifications) was not working properly (and will be fixed when #13442 is deployed as part of the next release) but this bug is unrelated to the user's not receiving digest emails.

There does seem to be something strange happening with the specific user, as I see that even some of the user's immediate notifications ("All Email") are unsent in the queue. I'll see if I can figure it out.

I just checked Cavalcade and it appears that the hook for daily digests (ass_digest_event) was not running or queued up. Not sure how the hook got unscheduled or removed.

I've just queued the daily digest for tomorrow at 05:30 GMT.

Boone, I ran two queries before the daily digest fired:

1. select count(id) from wp_bpges_queued_items where type = 'dig' and date_recorded < '2020-10-08 05:30:00' - 65526
2. select count(distinct user_id) from wp_bpges_queued_items where type = 'dig' and date_recorded < '2020-10-08 05:30:00' - 627

About an hour after the daily digest fired, I ran the same queries:

1. select count(id) from wp_bpges_queued_items where type = 'dig' and date_recorded < '2020-10-08 05:30:00' - 65420
2. select count(distinct user_id) from wp_bpges_queued_items where type = 'dig' and date_recorded < '2020-10-08 05:30:00' - 627

This means that the daily digest queue stalled and only processed 106 queued items out of 65526. The user count also didn't change so it looks like the digest for that one user did not complete either.

Next, I checked the GES debug log:

[08-Oct-2020 05:30:08] Beginning digest batch of type dig for timestamp 2020-10-08 05:30:05.

And the Cavalcade log:

$ wp cavalcade log --hook=ass_digest_event
+--------+------------------+---------------------+-----------+
| job    | hook             | timestamp           | status    |
+--------+------------------+---------------------+-----------+
| 625212 | ass_digest_event | 2020-10-08 05:30:16 | completed |
+--------+------------------+---------------------+-----------+

It appears that the digest blast ran for only 11 seconds.

Based on this, I started looking at the queue process code and have the following observations / suggestions:

1. BPGES_Async_Request_Send_Queue::time_exceeded() always returns true when run from CLI. Meaning after the first loop, the queue bails and doesn't run again. I've posted some thoughts here. Perhaps we can also add set_time_limit( 0 ) when the queue starts being processed around here if we're running from WP-CLI.

2. We should remove all items in wp_bpges_queued_items older than October 2020. This is to prevent the queued digest query from becoming too big and having too many older entries that are not applicable.

3. To prevent the queued digest query from becoming too big again, for BPGES_Queued_Item_Query::get_results() and BPGES_Queued_Item_Query::get_users_with_pending_digest(), we should do what you recommended here. Basically, setting a prior limit for daily digests and weekly summaries. You mention three days for daily digests and three weeks for weekly summaries. Perhaps set it to two days for daily digests and 1.5 weeks for weekly summaries?

Thanks for helping to debug this mess, Ray.

1. BPGES_Async_Request_Send_Queue::time_exceeded() always returns true when run from CLI. Meaning after the first loop, the queue bails and doesn't run again. I've posted some thoughts here. Perhaps we can also add set_time_limit( 0 ) when the queue starts being processed around here if we're running from WP-CLI.

Agreed. I've made the change in BPGES and pushed the latest to the production site. https://github.com/cuny-academic-commons/cac/commit/f638a18e04596adf8e2a176aa8126ec711391caa

2. We should remove all items in wp_bpges_queued_items older than October 2020. This is to prevent the queued digest query from becoming too big and having too many older entries that are not applicable.

Agreed. I've done this.

3. To prevent the queued digest query from becoming too big again, for BPGES_Queued_Item_Query::get_results() and BPGES_Queued_Item_Query::get_users_with_pending_digest(), we should do what you recommended here. Basically, setting a prior limit for daily digests and weekly summaries. You mention three days for daily digests and three weeks for weekly summaries. Perhaps set it to two days for daily digests and 1.5 weeks for weekly summaries?

Let's hold off on this for a moment while we see what happens with changes we've already put in place.

Marilyn, please let the user know that we're looking into digest issues across the system.

Will do, thanks!

The user (a very nice DH student) writes "I only tested the daily digests and all mail options. I hope they are
also testing to learn if weekly digests have been disabled."

Thanks for the update. Weekly digests work based on the same logic as daily digests, so what fixes one should fix the other.

Thanks for making those changes, Boone.

I'll check in on the daily digest after it runs in the early morning and report back.

Fantastic and thank you both! Please update when you can and I'll pass it on.

Just checked the GES log.

[09-Oct-2020 05:30:06] Beginning digest batch of type dig for timestamp 2020-10-09 05:30:04.
[09-Oct-2020 05:30:24] Sent dig digests to 176 users as part of this batch. Launching another batch....
[09-Oct-2020 05:30:25] Beginning digest batch of type dig for timestamp 2020-10-09 05:30:04.
[09-Oct-2020 05:30:32] Finished digest run of type dig for timestamp 2020-10-09 05:30:04. Digests were sent to a total of 250 users.

Looks like we're good!

However, when I run the select count(id) from wp_bpges_queued_items where type = 'dig' and date_recorded < '2020-10-09 05:30:00' query, there are still a lot of entries. Before the digest ran, there were 6962 rows; after the digest completed, there were 4660 rows. The date_recorded rows for the remaining entries are from October 1 to 6 though, however I don't see where we are enforcing a prior limit in BPGES. Any ideas, Boone?

However, when I run the select count(id) from wp_bpges_queued_items where type = 'dig' and date_recorded < '2020-10-09 05:30:00' query, there are still a lot of entries. Before the digest ran, there were 6962 rows; after the digest completed, there were 4660 rows. The date_recorded rows for the remaining entries are from October 1 to 6 though, however I don't see where we are enforcing a prior limit in BPGES. Any ideas, Boone?

BPGES filters out "invalid" entries when assembling the digest. See https://github.com/boonebgorges/buddypress-group-email-subscription/blob/4.0.x/bp-activity-subscription-digest.php#L181. One of these validity checks is for staleness, which uses the logic we discussed earlier in this thread, but which I forgot already existed :) So these items will never be added to any future digests, and it should be safe to delete them. Does that seem right to you too?

Fantastic and thank you both! Please update when you can and I'll pass it on.

Marilyn, can you ask Lisa if she received a daily digest over the past few days?

One of these validity checks is for staleness, which uses the logic we discussed earlier in this thread, but which I forgot already existed :) So these items will never be added to any future digests, and it should be safe to delete them. Does that seem right to you too?

I missed the bp_ges_activity_is_valid_for_digest() function, Boone! Should be safe to delete the stale items.

Is there a reason for having the stale check in that function rather than in BPGES_Queued_Item_Query::get_results() and BPGES_Queued_Item_Query::get_users_with_pending_digest()? Is it for individual activity filtering?

I asked yesterday, no reply yet but am checking.

I got a digest for a site I'd forgotten I signed up for, so I guess it's working!

Marilyn Weber wrote:

I got a digest for a site I'd forgotten I signed up for, so I guess it's working!

Same here!