Campaign finished too early (after 200, 300 or 400 emails out of 2498)

bernard.fruga · June 10, 2017, 10:31pm

Hi,
I’m on the version 3.3.1. and all has been OK since March.
Then in May the nasty problem started.
After processing two, three or four batches of 100 emails the system reports the campaign finished.
Then I manually requeue the campaign. And again, and again.
(There are 2499 subscribers on the list in batches of 100 emails, cron job every 10 minutes and define(“MAILQUEUE_BATCH_PERIOD”,150). )

I’ve already put define (“VERBOSE”,1); and just got:
The following events occured while processing the message queue:
[Sun 11 Jun 2017 00:20] [CL] Started
[Sun 11 Jun 2017 00:20] [CL] Sending in batches of 100 emails
[Sun 11 Jun 2017 00:20] [CL] select id from pl_message where status not in
(“draft”, “sent”, “prepared”, “suspended”) and embargo

I’ve search in the discussions for similar issues and noticed someone had a problem with the old version of phpList (not my case as I’m on 3.3.1) and someone else got the issue on the old PHP (not my case: PHP Version 5.6.30).

What else would you suggest to check.
I’m considering to disable the cron job and go with manually process queue.
Would you consider it worth trying?
Thanks in advance!
Cheers, Bernard

duncanc · June 11, 2017, 5:30am

Can you show the part of the event log where phplist says that the campaign has finished?

bernard.fruga · June 12, 2017, 7:35pm

Hi @duncanc !
One of the stops happened at 2am. So that should be that part of the log:

duncanc · June 12, 2017, 8:28pm

Can you show the complete event log for that particular run of process queue?

bernard.fruga · June 12, 2017, 8:52pm

I’ve just sent you privately as some details were not allowed for the public posting. I hope you’ve got my message.

duncanc · June 12, 2017, 9:22pm

116405 12 June 2017 02:00:02 Not sending xxx@xxxx
PAGE: PROCESSQUEUE

Do you have a plugin installed that is filtering the subscribers to be sent to?
Is there some other reason why those subscribers are not being sent to?

You appear to have setup some sort of hourly repetition of campaigns. Please explain more clearly what you are doing.

danwaterloo · June 13, 2017, 1:22am

As a follow-up on @duncanc 's comment, if you are sending ‘as text’, only the subscribers that prefer text will get the email. Or, if you send ‘as html’, it won’t go to people that prefer text…

bernard.fruga · June 13, 2017, 5:49pm

Let me explaining the situation in details, using the campaigns’ numbers:

The campaign 378 was the one causing problems. It was entered 2017-06-10 22:22:42, and to be sent to the list of 2499 subscribers of the list named 1-xxxxxx. No special setting, no repetition defined. And at Sat, 10 Jun 2017 23:10:09 +0200 the “Campaign finished” mail was generated, and the status of the campaign in List of Campaigns was “Sent”, but “Total” showed just 400 (or 300 don’t remember exactly). So I clicked “Requeue”. The campaign started again and at Sun, 11 Jun 2017 00:00:09 +0200 stopped again with “Campaign finished” and with Total of 700 sent out. I clicked “Requeue” again. And at Sun, 11 Jun 2017 01:00:07 +0200 it stopped again, and then again at Sun, 11 Jun 2017 02:00:03 +0200 and finally at Sun, 11 Jun 2017 02:15:03 +0200 it finished for good as all 2499 subscribers were served. The same time on my phpList some other campaigns were active:
The campaign 372 (entered at 2017-05-23 08:47:34) is requeueing every hour until 2018-05-23 08:00:00 Segment conditions: Subscribers match all of the following: Entered date is after 2017-05-22 and of the list: E-bookxxxxxxxxxxxxxxxxxx
The campaign 305 is requeueing every hour until 2020-01-09 11:00:00 to the list: Naxxxxxxxxxxxxxxxxxxxxx
The campaign 288 is requeueing every hour until 2017-11-21 18:00:00 to the list Audiobookxxxxxxxxx

Therefore the log record 116405 mentioned in your post was most probably referring to the campaign 372, as that subscriber was on two lists:1-xxxxxx and E-bookxxxxxxxxxxxxxxxxxx , (and as seen in the picture below, the campaign 378 was sent to her at 11 Jun 2017 01:45:07)

The bottom line is: there was the problem with the campaign 378 stopping too early (and the same problem I had a week earlier with another campaign). So the problem is a systematic problem on my end.
And, as the repetitive campaign 372 was launched in May, so maybe it is causing the problem in breaking down the delivery of other campaigns?
This week, when sending a new campaign to the list 1-xxxxxx I might pause the campaign 372 to see it that would help. Then I could share my findings here.
Does it make any sense to you?

bernard.fruga · June 13, 2017, 5:51pm

Thanks. But no issue in that, as all my subscribers are set for html and all my campaigns are html.

duncanc · June 13, 2017, 7:18pm

@bernard.fruga The event log that you sent to me did not include campaign 378. From what you have explained you don’t think that there are any problems with the other three campaigns - 288, 305 and 372. Please can you show the event log for the campaign that you think is not working properly.

bernard.fruga · June 13, 2017, 7:33pm

Sorry, but I have no idea which campaign is in the Event Log as there is just the list of events with no reference to the campaign number. I took it from the Log of Events (see below). Is there any other place where I could find the log?

duncanc · June 13, 2017, 7:38pm

@bernard.fruga Look for the entry like this but for campaign 378. There will be a group of entries for that campaign, but in reverse chronological order.

116340 12 June 2017 02:00:02 Processing message 288

bernard.fruga · June 13, 2017, 8:18pm

@duncanc thanks! I’ve found the relevant part of the log, see below.
I’m sharing the part from 22:40 (when I started) till 23:30 (well after the second attempt to sent out the 378)
If you’ve wish to see more, I’d be glad to share.

100171 10 June 2017 23:30:02 Processing message 378
PAGE: PROCESSQUEUE
Del
100170 10 June 2017 23:30:02 One campaign to process.
PAGE: PROCESSQUEUE
Del
100169 10 June 2017 23:30:02 Processing has started,
PAGE: PROCESSQUEUE
Del
100168 10 June 2017 23:20:07 Finished this run
PAGE: PROCESSQUEUE
Del
100167 10 June 2017 23:20:07 9 failed (will retry later)
PAGE: PROCESSQUEUE
Del
100166 10 June 2017 23:20:07 100 messages sent in 5.74 seconds (62768 msgs/hr)
PAGE: PROCESSQUEUE
Del
100165 10 June 2017 23:20:07 batch limit reached: 100 (100)
PAGE: PROCESSQUEUE
Del
100164 10 June 2017 23:20:02 Found them: 2298 to process
PAGE: PROCESSQUEUE
Del
100163 10 June 2017 23:20:02 Looking for subscribers
PAGE: PROCESSQUEUE
Del
100162 10 June 2017 23:20:02 Processing message 378
PAGE: PROCESSQUEUE
Del
100161 10 June 2017 23:20:02 One campaign to process.
PAGE: PROCESSQUEUE
Del
100160 10 June 2017 23:20:02 Processing has started,
PAGE: PROCESSQUEUE
Del
100159 10 June 2017 23:10:09 Warning: script never reached stage 5 This may be caused by a too slow or too busy server
PAGE: PROCESSQUEUE
Del
100158 10 June 2017 23:10:09 Finished this run
PAGE: PROCESSQUEUE
Del
100157 10 June 2017 23:10:09 It took 30 minutes 07 seconds to send this message
PAGE: PROCESSQUEUE
Del
100156 10 June 2017 23:10:09 Processed 2298 out of 2298 subscribers
PAGE: PROCESSQUEUE
Del
100155 10 June 2017 23:10:01 Found them: 2298 to process
PAGE: PROCESSQUEUE
Del
100154 10 June 2017 23:10:01 Looking for subscribers
PAGE: PROCESSQUEUE
Del
100153 10 June 2017 23:10:01 Processing message 378
PAGE: PROCESSQUEUE
Del
100152 10 June 2017 23:10:01 It took very little time to send this message
PAGE: PROCESSQUEUE
Del
100151 10 June 2017 23:10:01 Processed 44 out of 44 subscribers
PAGE: PROCESSQUEUE
Del
100150 10 June 2017 23:10:01 Found them: 44 to process
PAGE: PROCESSQUEUE
Del
100149 10 June 2017 23:10:01 Looking for subscribers
PAGE: PROCESSQUEUE
Del
100148 10 June 2017 23:10:01 Processing message 372
PAGE: PROCESSQUEUE
Del
100147 10 June 2017 23:10:01 2 campaigns to process.
PAGE: PROCESSQUEUE
Del
100146 10 June 2017 23:10:01 Processing has started,
PAGE: PROCESSQUEUE
Del
100145 10 June 2017 23:00:02 Finished this run
PAGE: PROCESSQUEUE
Del
100144 10 June 2017 23:00:02 No subscribers apply for attributes
PAGE: PROCESSQUEUE
Del
100143 10 June 2017 23:00:02 Looking for subscribers
PAGE: PROCESSQUEUE
Del
100142 10 June 2017 23:00:02 Processing message 356
PAGE: PROCESSQUEUE
Del
100141 10 June 2017 23:00:02 It took very little time to send this message
PAGE: PROCESSQUEUE
Del
100140 10 June 2017 23:00:02 Hmmm, No subscribers found to send to
PAGE: PROCESSQUEUE
Del
100139 10 June 2017 23:00:02 Processed 0 out of 0 subscribers
PAGE: PROCESSQUEUE
Del
100138 10 June 2017 23:00:02 Found them: 0 to process
PAGE: PROCESSQUEUE
Del
100137 10 June 2017 23:00:02 Looking for subscribers
PAGE: PROCESSQUEUE
Del
100136 10 June 2017 23:00:02 Processing message 305
PAGE: PROCESSQUEUE
Del
100135 10 June 2017 23:00:02 It took very little time to send this message
PAGE: PROCESSQUEUE
Del
100134 10 June 2017 23:00:02 Hmmm, No subscribers found to send to
PAGE: PROCESSQUEUE
Del
100133 10 June 2017 23:00:02 Processed 0 out of 0 subscribers
PAGE: PROCESSQUEUE
Del
100132 10 June 2017 23:00:02 Found them: 0 to process
PAGE: PROCESSQUEUE
Del
100131 10 June 2017 23:00:02 Looking for subscribers
PAGE: PROCESSQUEUE
Del
100130 10 June 2017 23:00:02 Processing message 288
PAGE: PROCESSQUEUE
Del
100129 10 June 2017 23:00:02 5 campaigns to process.
PAGE: PROCESSQUEUE
Del
100128 10 June 2017 23:00:02 Processing has started,
PAGE: PROCESSQUEUE
Del
100127 10 June 2017 22:50:07 Finished this run
PAGE: PROCESSQUEUE
Del
100126 10 June 2017 22:50:07 100 messages sent in 5.88 seconds (61249 msgs/hr)
PAGE: PROCESSQUEUE
Del
100125 10 June 2017 22:50:07 batch limit reached: 100 (100)
PAGE: PROCESSQUEUE
Del
100124 10 June 2017 22:50:01 Found them: 2398 to process
PAGE: PROCESSQUEUE
Del
100123 10 June 2017 22:50:01 Looking for subscribers
PAGE: PROCESSQUEUE
Del
100122 10 June 2017 22:50:01 Processing message 378
PAGE: PROCESSQUEUE

EVENTS
DATE
MESSAGE
100121 10 June 2017 22:50:01 One campaign to process.
PAGE: PROCESSQUEUE
Del
100120 10 June 2017 22:50:01 Processing has started,
PAGE: PROCESSQUEUE
Del
100119 10 June 2017 22:40:08 Finished this run
PAGE: PROCESSQUEUE
Del
100118 10 June 2017 22:40:08 100 messages sent in 6.49 seconds (55484 msgs/hr)
PAGE: PROCESSQUEUE
Del
100117 10 June 2017 22:40:08 batch limit reached: 100 (100)
PAGE: PROCESSQUEUE
Del
100116 10 June 2017 22:40:02 Found them: 2498 to process
PAGE: PROCESSQUEUE
Del
100115 10 June 2017 22:40:02 Looking for subscribers
PAGE: PROCESSQUEUE
Del
100114 10 June 2017 22:40:02 Processing message 378
PAGE: PROCESSQUEUE
Del
100113 10 June 2017 22:40:02 One campaign to process.
PAGE: PROCESSQUEUE
Del
100112 10 June 2017 22:40:02 Processing has started,

duncanc · June 13, 2017, 10:07pm

This message in the event log does not usually appear. What is different about campaign 356?

bernard.fruga · June 14, 2017, 5:38am

356 is for the list E-bookxxxxxxxxxxxxx, and is related to the Autoresponder 8:
Campaign 356 | Autoresponder email will be sent 1 day after subscription to "E-bookxxxxxxxxxxxxxxxxxxxxxx"
After sending, add subscriber to 1-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx

and here are the settings of 356:
Stop sending after 2017-11-28 10:00:00
Requeueing every day until 2018-05-29 23:00:00
Autoresponder Autoresponder 8

duncanc · June 14, 2017, 6:17am

@bernard.fruga The last set of event log entries almost looks ok for campaign 378.
22:40 sent 100
22:50 sent 100
23:00 did not appear to send anything
23:10 an odd message about having processed all 2298 subscribers
23:20 sent 100

I still do not see your original problem of phplist reporting the campaign to be finished.
The event at 23:00 is a phplist bug caused by using the autoresponder plugin (not in the plugin itself). The event at 23:10 might be a consequence of that, but I don’t really know.

bernard.fruga · June 14, 2017, 7:07am

I suggest we treat 372 as a potential suspect of the problem. I will temporarily stop 372 when sending out a new newsletter this week (on Saturday). And then we will see.
As putting together all the pieces I see time coincidence of the problem and the launch of 372 in May.
If that would solve the issue we’d look deeper into the 372 details. Otherwise I’d keep searching.

bernard.fruga · June 17, 2017, 8:23pm

@duncanc The 372 campaign was the one causing the problem of stopping other campaigns every hour. I know it as I’ve completed the test today. I paused the 372 and sent out a new campaign (379 to the list 1-xxxxxx of 2493 subscribers).
In my understanding the problem was correlated with the usage of the plugin SegmentPlugin (filtering subscribers by Segment conditions).
The settings of the campaign 372 were the following:
(entered at 2017-05-23 08:47:34) is requeueing every hour until 2018-05-23 08:00:00 Segment conditions: Subscribers match all of the following: Entered date is after 2017-05-22 and of the list: E-bookxxxxxxxxxxxxxxxxxx
Do you want me to perform any more tests on SegmentPlugin to confirm or reject the hypothesis of the bug sitting there?

duncanc · June 18, 2017, 7:21am

@bernard.fruga I don’t really understand what the problem is but I suggest that you try to setup the repeating campaigns so that phplist processes only one in each run. Instead of all the campaigns repeating each hour at 00 minutes, try to spread them out, say one at 00 minutes, a second at 15 minutes, etc. That is done by altering the embargo date/time on the Scheduling tab.

daf · June 4, 2018, 9:48am

Hi Bernard
I’m having a similar problem. PHPLIST with the “SegmentPlugin” installed.
Some campaigns are set so that they are sent only to specific user (based on insert date). We have about 12k users and we can’t send a campaign anymore.
After a lot of “not sent to…” the process reached “Warning: script never reached stage 5” and it ends. Did you solve this issue?