search

wpsharks / comment-mail

A WordPress plugin enabling email subscriptions for comments.
http://comment-mail.com
GNU General Public License v3.0
8 stars 3 forks source link

Queued (Pending) Notifications are never sent #192

Closed raamdev closed 8 years ago

raamdev commented 8 years ago

I was testing Comment Mail Lite v151224 after importing StCR subscriptions when I tried posting two new replies to existing comments with subscriptions (i.e., I posted new replies to comments that had StCR subscriptions, which were imported into Comment Mail). The new Comment Mail subscriptions were created fine, and were connected to the appropriate imported StCR subscription, however the notifications for those new replies were never sent.

Looking at the Mail Queue, I noticed the two notifications were sitting there, unsent:

2015-12-26_09-37-26

Notice the time on them... it had been ~45 minutes since the notifications were created and they still have not been sent. Here's what I tried to get the email queue to be processed:

None of these things helped. The queued notifications remained queued and were not sent out.

Also, my PHP error log did not report any errors during this time.

raamdev commented 8 years ago

Note: I don't believe this is related to https://github.com/websharks/comment-mail/issues/194 (_Cron event disappears in some scenarios: _cron_comment_mail_queue_processor_) because as noted above the notifications in the queue would not send even when I was able to manually run the _cron_comment_mail_queue_processor event.

jaswrks commented 8 years ago

None of these things helped. The queued notifications remained queued and were not sent out.

Also try looking at the Queue Event Log to see if anything turns up there after you run the queue processor. If they were not processed that should show up in the log as having been invalidated for some reason. Also be sure to look over the available Screen Options in the Queue Event Log, because there is a lot of information available there if you tell WordPress to expose it.

Also referencing: https://github.com/websharks/comment-mail-pro/blob/151224/comment-mail-pro/includes/classes/queue-processor.php#L503

raamdev commented 8 years ago

@jaswsinc The Queue Event Log shows nothing:

2015-12-29_12-29-17

raamdev commented 8 years ago

@kristineds @renzms @Reedyseth I could use some help attempting to reproduce the issue described above. :smile:

renzms commented 8 years ago

@raamdev

Under my Events list it says notified, but I may need to replicate it exactly as you did by using a fresh install of Comment Mail Lite v151224 right after using StCR subscribe and to import users.

I imported users from StCR a week ago, and the Comment Mail subscriptions were working as normal.

raamdev commented 8 years ago

@renzms Any more progress on testing this one?

renzms commented 8 years ago

@raamdev

screen shot 2016-01-15 at 3 46 23 pm

@kristineds @Reedyseth Could you guys please try as well and see if you can replicate what Raam has noted?

kristineds commented 8 years ago

@raamdev: Tested this but wasn't able to reproduce the issue you pointed out.

Comment Mail Queue Event Log

Queued (Pending) Notifications

raamdev commented 8 years ago

@renzms @kristineds Thanks so much for testing this some more. I'm going to close this as cannot reproduce for now. I was seeing this on my personal raam.org site where there are several other plugins running, so it sounds like what I was seeing might be related to a plugin conflict.

I'll come back and reopen this if I'm able to reproduce it. :smile:

raamdev commented 8 years ago

Reopening. Also reported here: https://wordpress.org/support/topic/why-are-some-emails-awaiting-processing?replies=1

lucashall commented 8 years ago

Hi @raamdev,

Thanks for trying to help.

I'm seeing this same issue. Some comments are getting through, others are getting stuck in processing.

The site is https://landlordology.com

The odd thing is that some emails are getting stuck, while others are getting through. Here's the Pending Queue vs the Log.

screenshot 2016-02-14 13 06 59

screenshot 2016-02-14 13 05 25

Here's the configuration:

I followed the instructions on importing users from StCR.

Here are the active plugins:

lucashall commented 8 years ago

Hi @raamdev

Just wanted to circle back to this. I've finding that the emails that get stuck as "awaiting processing" are getting sent roughly 19 days later. What can I do to help with this issue?

raamdev commented 8 years ago

the emails that get stuck as "awaiting processing" are getting sent roughly 19 days later.

@lucashall That's really interesting. @jaswsinc any thoughts on what might be causing this?

raamdev commented 8 years ago

@jaswsinc Ping. ↑

raamdev commented 8 years ago

Also reported here: https://wordpress.org/support/topic/sparkpost-and-asynchronous-mail?replies=7#post-8466772

jaswrks commented 8 years ago

Nothing jumping right out at me yet, sorry. I'm going to do some digging as I outline some of the logic behind the software for others in a video soon, and I'll keep this in mind so that we can get to the bottom of it by running diagnostics on sub-routines in the queue processor.

It may also help if we implement some debug logging routines in the queue processor whenever WP_DEBUG mode is enabled so that a site owner reporting problems like this will be able to copy/paste something for us privately that might shed more light.

bobinoz commented 8 years ago

Hi everyone

Continuing the conversation on from the WordPress support page via the link you have already just posted raamdev, here is an up-to-date list of my active plug-ins:

Akismet Anti-spam BackupBuddy Better WordPress Minify Cron Gui Easy Digital Downloads Google Analytics Dashboard for WP Google XML Site Map for Videos Jetpack by WordPress.com Jetpack lite Maintenance Mode MaxBlogPress Ping Optimizer neuvoo jobroll No Self Pings Ozh' Admin Drop-Down Menu P3 Plug-In Performance Profiler Post Plug-In Library Redirection Reenable Shortlink Item In Admin Toolbar Related Posts Thumbnails Remember Me Controls Revision Cleaner S3FlowShield SEO Friendly Images Simple Social Icons Social Share Bar (Digg Digg Alternative) SparkPost Tako Movable Comments Ultimate Category Excluder What Would Seth Godin Do WordPress Popular Posts WordPress PopUp WordPress.com Popular Posts WP Missed Schedule WPtouch Mobile Plugin Youtube Not Found

As you can see, I only have Akismet and Jetpack by WordPress.com in common with lucashall's plug-in list, for what it's worth though I also have Broken Link Checker installed but deactivated. What I do seem to have in common with lucashall's website though is large numbers of comments, the test I ran which produced this error was posting a reply on a page with around 1500 comments and about 100 subscribers.

My website is http://www.bobinoz.com/ running WordPress version 4.5.2 and Thesis theme 2.2.

Thanks, Bob

raamdev commented 8 years ago

So far the only active plugins that are common to the three people experiencing this (myself, @lucashall, and @bobinoz) are Akismet and JetPack for WordPress.com.

That makes me wonder if this issue is related to a specific JetPack module.

Here's my list of active JetPack modules:

@lucashall @bobinoz Would you mind listing your active JetPack modules? (See JetPack → Settings.)

bobinoz commented 8 years ago

Well, I think I might be able to make this bit of the process easier, I only have two of their modules active.

As you can see from my list, I also use Jetpack Lite which I think I installed to prevent Jetpack from automatically loading up more modules.

I assume from your response that you have completely discounted the number of comments/subscribers as being the issue?

raamdev commented 8 years ago

@bobinoz writes...

I assume from your response that you have completely discounted the number of comments/subscribers as being the issue?

No, certainly not. That's a definite possibility. On my personal site I have over 1,000 StCR subscriptions that I imported into Comment Mail and when I tried posting new replies to comments associated with an imported StCR subscription, that's when I saw the issue with "Awaiting processing".

How many StCR subscriptions did you import?

@lucashall If you could tell us how many StCR subscriptions you imported, that would be helpful as well.

bobinoz commented 8 years ago

Well, for me it was just over 4000 subscriptions that I imported from StCR and I think lucashall had quite a big database, because he had 3000 stuck in the "awaiting processing" queue and he said it was a large blog. That's why I was thinking maybe it is the numbers.

lucashall commented 8 years ago

Hi All,

If this is helpful, I have approx 4300 subscriptions on landlordology.com

Best, Lucas Hall

Head of Industry Relations, Cozy | cozy.co | @CozyCo https://twitter.com/CozyCo Founder of Landlordology | landlordology.com http://www.landlordology.com/ | @Landlordology https://twitter.com/Landlordology

On Thu, Jun 2, 2016 at 10:46 AM, bobinoz notifications@github.com wrote:

Well, for me it was just over 4000 subscriptions that I imported from StCR and I think lucashall had quite a big database, because he had 3000 stuck in the "awaiting processing" queue and he said it was a large blog. That's why I was thinking maybe it is the numbers.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/websharks/comment-mail/issues/192#issuecomment-223314652, or mute the thread https://github.com/notifications/unsubscribe/AGCiN5M-o210129EfFu2FoRHkLudZGV3ks5qHuzMgaJpZM4G7dcU .

raamdev commented 8 years ago

@bobinoz @lucashall Thank you. 4,000+ and 3,000+ StCR subscriptions. Coupling that with my (measly!) 1,000 subscriptions, I'd say there's a good chance the bug here is related to the large number of StCR subscriptions being imported.

@kristineds @renzms I could use some help here.

The next step is to start attempting to reproduce this bug on a test site with a large (2,000+) number of existing StCR subscriptions and then see if Comment Mail has a problem sending notifications after an import. (See my first post in this issue for a description of the problem.

@jaswsinc Any new thoughts come to mind about this issue given the new information above?

jaswrks commented 8 years ago

@raamdev Here's a video I did that might help you debug this: Comment Mail; How to Debug 192

raamdev commented 8 years ago

@jaswsinc While testing v160611-RC, I was able to reproduce this issue again on my personal site, where I'm currently using StCR. To recap, here's what I did:

  1. Before installing Comment Mail, I posted a couple of comments on an existing post with various configurations (i.e., replies only, all replies, no subscription) and confirmed the StCR created the subscriptions properly and that StCR was sending the notifications to subsequent replies as expected.
  2. I then installed and activated Comment Mail Lite v160611-RC.
  3. I deactivated the StCR plugin.
  4. I enabled Comment Mail.
  5. I ran the StCR importer and confirmed that all of my test subscriptions were imported as expected (they were).

  6. To test that Comment Mail would now send notifications to those imported StCR subscriptions, I left a few more replies to those existing comments. When I took a look at the Mail Queue, I saw exactly what I reported at the top of this GitHub issue:

    2016-06-14_15-55-53

  7. I then took a look at the wp_comment_mail_queue table in the database as you suggested in your video; the hold_until_time shows a 0 value for both rows:

    2016-06-14_15-50-46

  8. I installed WP Crontrol and confirmed that the _cron_comment_mail_queue_processor cron event was present. I also waited two entire 5-minute cycles, pressing refresh over and over on the Mail Queue page. The notifications in the queue were never sent.

    2016-06-14_15-58-25

  9. I confirmed that the Mail Queue Processor and Comment Mail were enabled all this time:

    2016-06-14_15-58-04

Any ideas for what to try next? 😄

raamdev commented 8 years ago

Since I'm running Akismet and JetPack for WordPress.com, the two plugins in common with @bobinoz and @lucashall as noted above, I tried disabling both of those on my personal site to see if that might get the Mail Queue Processor to run and pick up those two stuck notifications: No such luck.

jaswrks commented 8 years ago

@raamdev Thank you. If you still have that available can you post a screenshot of the database rows for sub_id 966 and 967 for me? i.e., those that match the queue entries in your screenshot above.

raamdev commented 8 years ago

@jaswsinc writes...

can you post a screenshot of the database rows for sub_id 966 and 967 for me?

Here you go:

2016-06-15_22-46-47

jaswrks commented 8 years ago

This just looks like the CRON is not actually running for some reason. I'll take a wild guess and blame this on WP Crontrol for now, but I'm going to run some tests of my own shortly to see why/how WP Crontrol seems to not work when it comes to Comment Mail.

raamdev commented 8 years ago

@jaswsinc writes...

I'll take a wild guess and blame this on WP Crontrol for now,

But, why? I'm not using WP Crontrol to run the cron event... and if I deactivate WP Crontrol, I still have the same issue...

jaswrks commented 8 years ago

At the moment, the only explanation I can come up with for this is that the queue processor is simply not running. All of my tests indicate that if it was, this simply would not be the case; i.e., they shouldn't just sit in the queue if the queue processor is running, because the point of it running is to clear these out of the queue. The hold_until_time is 0 indicating that these entries have never been processed.

So in order to narrow it down and try to prove that theory, we need to make absolutely sure the queue processor is in fact running via CRON as it's supposed to. The only way to force this to occur at the moment is via WP Crontrol. If that's failing also, then this is becoming a more difficult mystery to solve.

If these are still just sitting in the queue you can try to attach a custom log routine of your own so that you can prove that it's running and failing, or find out if it's simply not running at all.

After this line try something like this and monitor the log file.

file_put_contents(WP_CONTENT_DIR.'/cm-queue-debug.log', print_r($_REQUEST, true)."\n\n", FILE_APPEND);
raamdev commented 8 years ago

@jaswsinc After watching the _cron_comment_mail_queue_processor cron event (from inside WP Crontrol) count down and run on schedule, I find the following in the log file:

$ cat cm-queue-debug.log
Array
(
    [doing_wp_cron] => 1466046615.4939270019531250000000
)

The stuck items are still in the Mail Queue.

raamdev commented 8 years ago

@jaswsinc I've narrowed down the issue to a problem with entryMessage(). Something is happening on this line that is causing a silent failure.

I'm suspecting this might have something to do with the fact that I'm seeing stuff related to RVE (Replies via Email) in the entryMessage() method, and I'm testing this on Comment Mail Lite, which doesn't have that feature. However, the src/includes/classes/UtilsRve.php file does currently exist in the Lite version of v160611-RC (it probably shouldn't...right?)

raamdev commented 8 years ago

I'm seeing stuff related to RVE

Scratch that. I see that we're specifically checking if ($this->plugin->options['replies_via_email_enable']).

Now looking more closely at parse().

jaswrks commented 8 years ago

After watching the _cron_comment_mail_queue_processor cron event (from inside WP Crontrol) count down and run on schedule, I find the following in the log file:

So it is running then. Hmm. The plot thickens.

Now looking more closely at parse().

Cool. Really curious to know how this happens.

raamdev commented 8 years ago

@jaswsinc Something is going on in this evaluate() method... any debugging suggestions for that? 😁

raamdev commented 8 years ago

I've confirmed there's nothing wrong with if ($this->isPossible('eval')), i.e., eval IS possible, so it's not that... my only thought is that this has something to do with the output buffering that is being used there.

jaswrks commented 8 years ago

Something is going on in this evaluate() method...

What indication do you have there is a problem? Just curious to know what the symptom is so I can help debug.

raamdev commented 8 years ago

@jaswsinc Since this is on my live site where I don't have xdebug (and since I can't seem to reproduce this in a separate test install), I'm just adding logging routines (like the one you gave me above) to follow the code and try to figure out at what point things "fail".

In the parse() method, I changed this line to the following:

        file_put_contents(WP_CONTENT_DIR.'/cm-queue-debug.log', "INSIDE parse() BEFORE passing evaluate()\n\n", FILE_APPEND);
        $var = trim($this->plugin->utils_php->evaluate($this->file_contents, $vars));
        file_put_contents(WP_CONTENT_DIR.'/cm-queue-debug.log', "INSIDE parse() AFTER passing evaluate()\n\n", FILE_APPEND);
        return $var;

I would expect that every time I pass something to evaluate() I will see a BEFORE and an AFTER log entry, however the log always ends with a BEFORE entry and no AFTER entry, indicating to me that something went wrong in there...

(The first entryMessage() passing to parse() entry is where I added a logging routine to this line in entryMessage().)

entryMessage() passing to parse()

INSIDE parse() BEFORE passing evaluate()

INSIDE parse() AFTER passing evaluate()

INSIDE parse() BEFORE passing evaluate()

INSIDE parse() AFTER passing evaluate()

INSIDE parse() BEFORE passing evaluate()

INSIDE parse() AFTER passing evaluate()

INSIDE parse() BEFORE passing evaluate()

INSIDE parse() AFTER passing evaluate()

INSIDE parse() BEFORE passing evaluate()

INSIDE parse() AFTER passing evaluate()

INSIDE parse() BEFORE passing evaluate()

INSIDE parse() AFTER passing evaluate()

INSIDE parse() BEFORE passing evaluate()
raamdev commented 8 years ago

The PHP it's choking on is somewhere in here: src/includes/templates/type-s/email/comment-notification/message.php

raamdev commented 8 years ago

This issue is making me wonder how difficult it would be a for a site owner to debug their own modified templates if they find something isn't working as expected...

raamdev commented 8 years ago

@jaswsinc Well, it looks like what I was suspecting with Template processing and evaluate() above may have been a false alarm. I wasn't able to reproduce it consistently and on subsequent cron runs the logs ended with INSIDE parse() AFTER passing evaluate(), as would be expected.

I'm taking a break from this for now, but I wanted to leave some notes with where I left off:

I'm currently focused on processEntry(), where I've added the following debugging routines:

    protected function processEntry(\stdClass $entry)
    {
        if ($entry->dby_queue_id || $entry->logged) {
            return true; // Already processed this.
        }
        if (!($entry_props = $this->validatedEntryProps($entry))) {
            return true; // Bypass; unable to validate entry props.
        }
        if ($this->checkEntryHoldUntilTime($entry_props)) {
            return false; // Holding (for now).
        }
        $this->checkCompileEntryDigestableEntries($entry_props);

        file_put_contents(WP_CONTENT_DIR.'/cm-queue-debug.log', "AFTER checkCompile...()\n\n", FILE_APPEND);

        if (!($entry_headers = $this->entryHeaders($entry_props))) {
            $entry_props->event     = 'invalidated'; // Invalidate.
            $entry_props->note_code = 'comment_notification_headers_empty';

            $this->logEntry($entry_props); // Log invalidation.
            return true; // Not possible; headers are empty.
        }

        file_put_contents(WP_CONTENT_DIR.'/cm-queue-debug.log', "AFTER entryHeaders()\n\n", FILE_APPEND);

        if (!($entry_subject = $this->entrySubject($entry_props))) {
            $entry_props->event     = 'invalidated'; // Invalidate.
            $entry_props->note_code = 'comment_notification_subject_empty';

            $this->logEntry($entry_props); // Log invalidation.
            return true; // Not possible; subject line is empty.
        }

        file_put_contents(WP_CONTENT_DIR.'/cm-queue-debug.log', "AFTER entrySubject()\n\n", FILE_APPEND);

        if (!($entry_message = $this->entryMessage($entry_props))) {
            $entry_props->event     = 'invalidated'; // Invalidate.
            $entry_props->note_code = 'comment_notification_message_empty';
            file_put_contents(WP_CONTENT_DIR.'/cm-queue-debug.log', "BEFORE logEntry() AFTER entrySubject()\n\n", FILE_APPEND);

            $this->logEntry($entry_props); // Log invalidation.
            return true; // Not possible; message body is empty.
        }

        file_put_contents(WP_CONTENT_DIR.'/cm-queue-debug.log', "AFTER entryMessage()\n\n", FILE_APPEND);

        $entry_props->event     = 'notified'; // Notifying now.
        $entry_props->note_code = 'comment_notification_sent_successfully';

        file_put_contents(WP_CONTENT_DIR.'/cm-queue-debug.log', "REACHED NEAR END Of processEntry()\n\n", FILE_APPEND);

        $this->logEntry($entry_props); // Log successful processing.
        $this->plugin->utils_mail->send($entry_props->sub->email, $entry_subject, $entry_message, $entry_headers);
        return true; // Notified; OK to delete this entry now.
    }

With that in place (along with the original logging routine @jaswsinc suggested I add to make sure Cron was running), my log file contains the following:

Array
(
    [doing_wp_cron] => 1466052317.7762129306793212890625
)

AFTER checkCompile...()

AFTER entryHeaders()

AFTER entrySubject()

So as you can see, we never make it past this line:

if (!($entry_message = $this->entryMessage($entry_props))) {

Which tells me that something is going on inside entryMessage().

Here's a copy of $entry_props being passed into the entryMessage() method itself:

stdClass Object
(
    [event] =>
    [note_code] =>
    [entry] => stdClass Object
        (
            [ID] => 1
            [sub_id] => 966
            [user_id] => 0
            [post_id] => 16860
            [comment_parent_id] => 11853
            [comment_id] => 11858
            [insertion_time] => 1465933066
            [last_update_time] => 1465933066
            [hold_until_time] => 0
            [dby_queue_id] => 0
            [logged] =>
        )

    [sub] => stdClass Object
        (
            [ID] => 966
            [key] => kevv9yco8s0zlf36fx6
            [user_id] => 0
            [post_id] => 16860
            [comment_id] => 0
            [deliver] => asap
            [fname] => Raam+test2allreplies
            [lname] =>
            [email] => raam+test2allreplies@raamdev.com
            [insertion_ip] =>
            [insertion_region] =>
            [insertion_country] =>
            [last_ip] =>
            [last_region] =>
            [last_country] =>
            [status] => subscribed
            [insertion_time] => 1465903656
            [last_update_time] => 1465932801
        )

    [sub_post] => WP_Post Object
        (
            [ID] => 16860
            [post_author] => 1
            [post_date] => 2015-08-06 12:57:46
            [post_date_gmt] => 2015-08-06 16:57:46
            [post_content] => Self-sufficiency fosters empathy.
            [post_title] => Empathy
            [post_excerpt] =>
            [post_status] => publish
            [comment_status] => open
            [ping_status] => open
            [post_password] =>
            [post_name] => empathy
            [to_ping] =>
            [pinged] =>
            [post_modified] => 2015-08-06 12:57:46
            [post_modified_gmt] => 2015-08-06 16:57:46
            [post_content_filtered] =>
            [post_parent] => 0
            [guid] => https://raam.org/?p=16860
            [menu_order] => 0
            [post_type] => post
            [post_mime_type] =>
            [comment_count] => 6
            [filter] => raw
        )

    [sub_comment] =>
    [post] => WP_Post Object
        (
            [ID] => 16860
            [post_author] => 1
            [post_date] => 2015-08-06 12:57:46
            [post_date_gmt] => 2015-08-06 16:57:46
            [post_content] => Self-sufficiency fosters empathy.
            [post_title] => Empathy
            [post_excerpt] =>
            [post_status] => publish
            [comment_status] => open
            [ping_status] => open
            [post_password] =>
            [post_name] => empathy
            [to_ping] =>
            [pinged] =>
            [post_modified] => 2015-08-06 12:57:46
            [post_modified_gmt] => 2015-08-06 16:57:46
            [post_content_filtered] =>
            [post_parent] => 0
            [guid] => https://raam.org/?p=16860
            [menu_order] => 0
            [post_type] => post
            [post_mime_type] =>
            [comment_count] => 6
            [filter] => raw
        )

    [comment] => WP_Comment Object
        (
            [comment_ID] => 11858
            [comment_post_ID] => 16860
            [comment_author] => secondreplytotest1
            [comment_author_email] => raam+secondreplytotest1@websharks-inc.com
            [comment_author_url] =>
            [comment_author_IP] => 97.101.220.142
            [comment_date] => 2016-06-14 15:37:18
            [comment_date_gmt] => 2016-06-14 19:37:18
            [comment_content] => 2nd Reply to Test 1
            [comment_karma] => 0
            [comment_approved] => 1
            [comment_agent] => Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.79 Safari/537.36
            [comment_type] =>
            [comment_parent] => 11853
            [user_id] => 0
            [children:protected] =>
            [populated_children:protected] =>
            [post_fields:protected] => Array
                (
                    [0] => post_author
                    [1] => post_date
                    [2] => post_date_gmt
                    [3] => post_content
                    [4] => post_title
                    [5] => post_excerpt
                    [6] => post_status
                    [7] => comment_status
                    [8] => ping_status
                    [9] => post_name
                    [10] => to_ping
                    [11] => pinged
                    [12] => post_modified
                    [13] => post_modified_gmt
                    [14] => post_content_filtered
                    [15] => post_parent
                    [16] => guid
                    [17] => menu_order
                    [18] => post_type
                    [19] => post_mime_type
                    [20] => comment_count
                )

        )

    [props] => Array
        (
            [1] => stdClass Object
 *RECURSION*
        )

    [comments] => Array
        (
            [11858] => WP_Comment Object
                (
                    [comment_ID] => 11858
                    [comment_post_ID] => 16860
                    [comment_author] => secondreplytotest1
                    [comment_author_email] => raam+secondreplytotest1@websharks-inc.com
                    [comment_author_url] =>
                    [comment_author_IP] => 97.101.220.142
                    [comment_date] => 2016-06-14 15:37:18
                    [comment_date_gmt] => 2016-06-14 19:37:18
                    [comment_content] => 2nd Reply to Test 1
                    [comment_karma] => 0
                    [comment_approved] => 1
                    [comment_agent] => Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.79 Safari/537.36
                    [comment_type] =>
                    [comment_parent] => 11853
                    [user_id] => 0
                    [children:protected] =>
                    [populated_children:protected] =>
                    [post_fields:protected] => Array
                        (
                            [0] => post_author
                            [1] => post_date
                            [2] => post_date_gmt
                            [3] => post_content
                            [4] => post_title
                            [5] => post_excerpt
                            [6] => post_status
                            [7] => comment_status
                            [8] => ping_status
                            [9] => post_name
                            [10] => to_ping
                            [11] => pinged
                            [12] => post_modified
                            [13] => post_modified_gmt
                            [14] => post_content_filtered
                            [15] => post_parent
                            [16] => guid
                            [17] => menu_order
                            [18] => post_type
                            [19] => post_mime_type
                            [20] => comment_count
                        )

                )

        )

    [held] =>
    [dby_queue_id] => 0
    [logged] =>
)

My brain is fried for now. Maybe you can see something I didn't, @jaswsinc. 😄

jaswrks commented 8 years ago

@raamdev writes...

So as you can see, we never make it past this line: if (!($entry_message = $this->entryMessage($entry_props))) {

Copy that. Awesome work in debugging this so far. So it looks to me like there is a fatal error in that file. That should leave behind something in your PHP error log. Although, it might not show you very much, since that code is being eval'd. Still, it should help you confirm that a fatal error is in fact taking place in eval'd code. Do you find anything in your PHP error log?

The next step I would take is to do the same thing you've been doing thus far with the debugging lines, but this time put them into the template file that is causing the problem and see if you can get closer to determining which line of code in the template is choking.

Referencing: https://github.com/websharks/comment-mail-pro/blob/000000-dev/src/includes/templates/type-s/email/comment-notification/message.php

Since this doesn't seem to impact everyone at all times, it could have something to do with a certain condition being met in that template file; e.g., the comment having a parent maybe.

raamdev commented 8 years ago

@jaswsinc writes...

Do you find anything in your PHP error log?

No, no errors in the error log.

The next step I would take is to do the same thing you've been doing thus far with the debugging lines, but this time put them into the template file that is causing the problem and see if you can get closer to determining which line of code in the template is choking.

Referencing: https://github.com/websharks/comment-mail-pro/blob/000000-dev/src/includes/templates/type-s/email/comment-notification/message.php

Done. It appears that things go wrong on this line in message.php, basically as soon as $sub or $sub_post are used. (I tried logging the value of those vars and that logging line never showed up in the log file at all...). Maybe those are being referenced wrong??

raamdev commented 8 years ago

I did print_r(get_defined_vars(), true) in message.php and it seems that $sub and $sub_post are accounted for...

[...]
   [___vars] => Array
        (
            [event] =>
            [note_code] =>
            [entry] => stdClass Object
                (
                    [ID] => 3
                    [sub_id] => 966
                    [user_id] => 0
                    [post_id] => 16860
                    [comment_parent_id] => 11853
                    [comment_id] => 11862
                    [insertion_time] => 1466199965
                    [last_update_time] => 1466199965
                    [hold_until_time] => 0
                    [dby_queue_id] => 0
                    [logged] =>
                )

            [sub] => stdClass Object
                (
                    [ID] => 966
                    [key] => kevv9yco8s0zlf36fx6
                    [user_id] => 0
                    [post_id] => 16860
                    [comment_id] => 0
                    [deliver] => asap
                    [fname] => Raam+test2allreplies
                    [lname] =>
                    [email] => raam+test2allreplies@raamdev.com
                    [insertion_ip] =>
                    [insertion_region] =>
                    [insertion_country] =>
                    [last_ip] =>
                    [last_region] =>
                    [last_country] =>
                    [status] => subscribed
                    [insertion_time] => 1465903656
                    [last_update_time] => 1465932801
                )

            [sub_post] => WP_Post Object
                (
                    [ID] => 16860
                    [post_author] => 1
                    [post_date] => 2015-08-06 12:57:46
                    [post_date_gmt] => 2015-08-06 16:57:46
                    [post_content] => Self-sufficiency fosters empathy.
                    [post_title] => Empathy
                    [post_excerpt] =>
                    [post_status] => publish
                    [comment_status] => open
                    [ping_status] => open
                    [post_password] =>
                    [post_name] => empathy
                    [to_ping] =>
                    [pinged] =>
                    [post_modified] => 2015-08-06 12:57:46
                    [post_modified_gmt] => 2015-08-06 16:57:46
                    [post_content_filtered] =>
                    [post_parent] => 0
                    [guid] => https://raam.org/?p=16860
                    [menu_order] => 0
                    [post_type] => post
                    [post_mime_type] =>
                    [comment_count] => 7
                    [filter] => raw
                )

            [sub_comment] =>
            [post] => WP_Post Object
                (
                    [ID] => 16860
                    [post_author] => 1
                    [post_date] => 2015-08-06 12:57:46
                    [post_date_gmt] => 2015-08-06 16:57:46
                    [post_content] => Self-sufficiency fosters empathy.
                    [post_title] => Empathy
                    [post_excerpt] =>
                    [post_status] => publish
                    [comment_status] => open
                    [ping_status] => open
                    [post_password] =>
                    [post_name] => empathy
                    [to_ping] =>
                    [pinged] =>
                    [post_modified] => 2015-08-06 12:57:46
                    [post_modified_gmt] => 2015-08-06 16:57:46
                    [post_content_filtered] =>
                    [post_parent] => 0
                    [guid] => https://raam.org/?p=16860
                    [menu_order] => 0
                    [post_type] => post
                    [post_mime_type] =>
                    [comment_count] => 7
                    [filter] => raw
                )
[...]
raamdev commented 8 years ago

As I noted in Slack, what's really odd is that those two notifications that were stuck in the queue for a few days while I was initially testing this suddenly disappeared from the queue at some point over the last ~35 hours (the timestamp on when they were actually sent is wrong—i.e., it looks like they were processed correctly from the start, when they most certainly were not).

I posted another comment a few hours ago on the post that I'm using for testing and that generated two more notifications, which got stuck once again.

raamdev commented 8 years ago

One thing I did notice looking at the output of print_r(get_defined_vars(), true) in message.php was that the very first array key is [___string] that contains what looks like a full copy of the contents of message.php. I did some research and I haven't been able to find anything about what [___string] signifies. I even tried digging into the PHP source. 

Array
(
    [___string] => <?php
namespace WebSharks\CommentMail;

/*
 * @var Plugin           $plugin       Plugin class.
 * @var Template         $template     Template class.
 *
 * Other variables made available in this template file:
 *
 * @var string           $email_header Parsed email header template.
 * @var string           $email_footer Parsed email footer template.
 *
 * @var \stdClass        $sub          Subscription object data.
 *
 * @var \WP_Post         $sub_post     Post they're subscribed to.
 *
 * @var \WP_Comment|null $sub_comment  Comment they're subcribed to; if applicable.
 *
 * @var \WP_Comment[]    $comments     An array of all WP comment objects we are notifying about.
 *
 * -------------------------------------------------------------------
 * @note In addition to plugin-specific variables & functionality,
 *    you may also use any WordPress functions that you like.
 */
?>
<?php // Sets document <title> tag via `%%title%%` replacement code in header.
echo str_replace('%%title%%', __('Comment Notification(s)', 'comment-mail'), $email_header); ?>

<?php
file_put_contents(WP_CONTENT_DIR.'/cm-queue-debug.log', "message.php:30\n\n".print_r(get_defined_vars(), true), FILE_APPEND);
/*
 * Here we define a few more variables of our own.
 * All based on what the template makes available to us;
 * ~ as documented at the top of this file.
 */
// URL to comments on the post they're subscribed to.
$sub_post_comments_url = get_comments_link($sub_post->ID);
file_put_contents(WP_CONTENT_DIR.'/cm-queue-debug.log', "message.php:38\n\n", FILE_APPEND);
[...]

Something tells me that the way the PHP templates are being parsed/evaluated is causing the odd behavior I'm seeing, but I can't put my finger on why...

raamdev commented 8 years ago

9 hours 39 minutes after arriving in the Mail Queue, one of the "stuck" notifications went through. However, the other stuck notification, which was generated at the same time as the one that went through, is still sitting the Mail Queue.

I'm adding a few more things to my logging routines to hopefully get more information the next time one goes through.

jaswrks commented 8 years ago

Copy that. Thank you for the updates. The ___string comes from this function. It might be worth us changing the way templates are parsed; i.e., moving from eval() to just include() in the future.

Referencing: https://github.com/websharks/comment-mail-pro/blob/160618/src/includes/classes/UtilsPhp.php#L71

raamdev commented 8 years ago

@jaswsinc The other two pending notifications in the queue eventually went through, but I mistakenly updated Comment Mail to the latest version and overwrote all the logging lines I had added to the codebase, so I wasn't able to catch any extra information.

Do you have any thoughts on why they would eventually go through? That seems like a clue to me. If they go through at all, then it must not be a parsing issue (otherwise they would never go through) but instead something related to time...