Only half of emails sent for each campaign

Product Support
1

Mautic version is: 2.15.3
PHP version is: 7.1.33
OS: CentOS Linux release 7.7.1908
Apache: 2.4.41
Postfix: 2.10.1

cron jobs:
*/5 * * * * /bin/php /var/www/my.mautic.com/app/console mautic:segments:update > /dev/null 2>&1
1,6,11,16,21,26,31,36,41,46,51,56 * * * * /bin/php /var/www/my.mautic.com/app/console mautic:campaigns:rebuild > /dev/null
2,7,12,17,22,27,32,37,42,47,52,57 * * * * /bin/php /var/www/my.mautic.com/app/console mautic:campaigns:trigger
13,28,43,58 * * * * /bin/php /var/www/my.mautic.com/app/console mautic:import
* * * * * /bin/php /var/www/my.mautic.com/app/console mautic:emails:send

My problem is:
Out of 10000 contacts in my mautic system, only a bit more than 5000 are sent sent out via email.
On the mautic dashboard it shows 10000 emails have been sent by mautic, however postfix only received half of it.
Here’s a report from the postfix log:

# pflogsumm -d today /var/log/maillog
Postfix log summaries for Jan 23

Grand Totals
------------
messages

   5217   received
   5234   delivered
      0   forwarded
     71   deferred  (591  deferrals)
     27   bounced
      2   rejected (0%)
      0   reject warnings
      0   held
      0   discarded (0%)

  75484k  bytes received
  69322k  bytes delivered
     15   senders
     14   sending hosts/domains
   5164   recipients
    110   recipient hosts/domains

These errors are showing in the log:
[2020-01-23 08:25:47] mautic.CRITICAL: Uncaught PHP Exception Doctrine\DBAL\Exception\UniqueConstraintViolationException: “An exception occurred while executing ‘INSERT INTO campaign_lead_event_log (rotation, date_triggered, is_scheduled, trigger_date, system_triggered, metadata, channel, channel_id, non_action_path_taken, event_id, lead_id, campaign_id, ip_id) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)’ with params [1, “2020-01-23 08:25:47”, 0, null, 0, “a:0:{}”, “email”, 67, 0, 178, 58803, 43, 187024]: SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry ‘178-58803-1’ for key ‘campaign_rotation’” at /var/www/my.mautic.com/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/AbstractMySQLDriver.php line 66 {“exception”:"[object] (Doctrine\DBAL\Exception\UniqueConstraintViolationException(code: 0): An exception occurred while executing ‘INSERT INTO campaign_lead_event_log (rotation, date_triggered, is_scheduled, trigger_date, system_triggered, metadata, channel, channel_id, non_action_path_taken, event_id, lead_id, campaign_id, ip_id) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)’ with params [1, “2020-01-23 08:25:47”, 0, null, 0, “a:0:{}”, “email”, 67, 0, 178, 58803, 43, 187024]:\n\nSQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry ‘178-58803-1’ for key ‘campaign_rotation’ at /var/www/my.mautic.com/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/AbstractMySQLDriver.php:66, Doctrine\DBAL\Driver\PDOException(code: 23000): SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry ‘178-58803-1’ for key ‘campaign_rotation’ at /var/www/my.mautic.com/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php:107, PDOException(code: 23000): SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry ‘178-58803-1’ for key ‘campaign_rotation’ at /var/www/my.mautic.com/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php:105)"}
[2020-01-23 08:31:13] mautic.CRITICAL: Uncaught PHP Exception Doctrine\DBAL\Exception\UniqueConstraintViolationException: “An exception occurred while executing ‘INSERT INTO campaign_lead_event_log (rotation, date_triggered, is_scheduled, trigger_date, system_triggered, metadata, channel, channel_id, non_action_path_taken, event_id, lead_id, campaign_id, ip_id) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)’ with params [1, “2020-01-23 08:31:13”, 0, null, 0, “a:0:{}”, “email”, 67, 0, 178, 12592, 43, 92337]: SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry ‘178-12592-1’ for key ‘campaign_rotation’” at /var/www/my.mautic.com/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/AbstractMySQLDriver.php line 66 {“exception”:"[object] (Doctrine\DBAL\Exception\UniqueConstraintViolationException(code: 0): An exception occurred while executing ‘INSERT INTO campaign_lead_event_log (rotation, date_triggered, is_scheduled, trigger_date, system_triggered, metadata, channel, channel_id, non_action_path_taken, event_id, lead_id, campaign_id, ip_id) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)’ with params [1, “2020-01-23 08:31:13”, 0, null, 0, “a:0:{}”, “email”, 67, 0, 178, 12592, 43, 92337]:\n\nSQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry ‘178-12592-1’ for key ‘campaign_rotation’ at /var/www/my.mautic.com/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/AbstractMySQLDriver.php:66, Doctrine\DBAL\Driver\PDOException(code: 23000): SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry ‘178-12592-1’ for key ‘campaign_rotation’ at /var/www/my.mautic.com/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php:107, PDOException(code: 23000): SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry ‘178-12592-1’ for key ‘campaign_rotation’ at /var/www/my.mautic.com/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php:105)"}

Note those error messages in the logs are appearing regularly the whole day long (even when there’s no campaign sending out emails), so they don’t seem related to the problem

Steps I have tried to fix the problem:
trying to get output from console mautic:import and console mautic:emails:send during the next campaign (tomorrow) to help identifying the root cause of the problem

While I’m waiting for more debug info, any hint on what could cause this problem ?

2

You should try fixing your database doctrine and/or schema using the Symfony console commands.
Be sure to take a backup of your DB using mysqldump or similar before proceeding.
Integrity Constraint Violation usually means there is some problem with the doctrine or schema.
This can be caused by partially completed Mautic updates in the past.

Here you can find the commands:
https://johnlinhart.com/blog/uh-oh-mautic-upgrade-was-not-successful

3

So here’s what I observed in today’s campaign:

08:36 the emails started to be send, php process with pid 1494
08:43 a new php process to send emails starts (why?) with pid 3262
It goes well until 08:45 where I see no more messages in /var/log/maillog arriving (but postfix seems still running and processing emails)
after a couple of minutes I run the pflogsumm utility and I have the good surprise to see 6305 emails were delivered (it is more than usual)
At 08:49 I decide to restart the postfix service as no more log messages arrive in /var/log/maillog
Messages are back in the /var/log/maillog BUT php process 3262 stops and gives errors:
!! Expected response code 250 but got code “”, with message “” (code: 0)
PHP Warning: fwrite(): SSL operation failed with code 1. OpenSSL Error messages:
error:140D00CF:SSL routines:SSL_write:protocol is shutdown in /var/www/my.mautic.com/vendor/swiftmailer/swiftmailer/lib/classes/Swift/Transport/StreamBuffer.php on line 231

pflogsumm tells me 6620 emails were delivered, it’s better but still 3000 missing

The app/spool/default/ is empty

The only differences to yesterday’s setup was:

  • added --batch-limit=10 to the mautic:campaigns:trigger cron job
  • campaign started at 8:30 instead of usual 8:00

I think the restart of the postfix service triggered the end of the php mautic:emails:send cron job and due to this 3000 contact won’t receive the email.
Now I have a few questions:

  • why a second php process for the mautic:emails:send cron job was triggered ?
  • why would postfix stop logging messages ?
  • shall I use the --message-limit [MESSAGE-LIMIT] option of the mautic:emails:send cron command ?

Thanks autoize for the piece of advice to fix the DB, indeed there’s been a couple of failed updates in the past. Here’s the output I got:
# php app/console doctrine:schema:update --dump-sql
DROP INDEX email_date_read ON email_stats;
ALTER TABLE emails CHANGE public_preview public_preview TINYINT(1) DEFAULT NULL;
ALTER TABLE lead_lists CHANGE is_preference_center is_preference_center TINYINT(1) NOT NULL;
DROP INDEX tracking_id ON lead_devices;
CREATE UNIQUE INDEX UNIQ_48C912F47D05ABBE ON lead_devices (tracking_id);
DROP INDEX page_hit_url ON page_hits;
ALTER TABLE reports_schedulers DROP FOREIGN KEY FK_1B66478A4BD2A4C0;
DROP INDEX idx_1b66478a4bd2a4c0 ON reports_schedulers;
CREATE INDEX IDX_C74CA6B84BD2A4C0 ON reports_schedulers (report_id);
ALTER TABLE reports_schedulers ADD CONSTRAINT FK_1B66478A4BD2A4C0 FOREIGN KEY (report_id) REFERENCES reports (id) ON DELETE CASCADE;
# php app/console doctrine:schema:update --force
Updating database schema…
Database schema updated successfully! “10” queries were executed
#

Let’s see if this helps. Any other idea is welcome :slight_smile:

4

Hi,

It seems all 10000 emails are actually well sent.
This morning I could observe again a hole of approximately 4 minutes with no messages in /var/log/maillog.
Looking at /var/log/messages I found:
Jan 27 08:08:02 vps journal: Suppressed 105 messages from /system.slice/postfix.service
Jan 27 08:08:32 vps journal: Suppressed 138 messages from /system.slice/postfix.service
Jan 27 08:11:42 vps rsyslogd: imjournal: 11410 messages lost due to rate-limiting
So it looks like journal / rsyslogd is dropping postfix messages to avoid exceeding a given threshold

This made the stats reported by the pflogsumm utility irrelevant

So I don’t think there’s a problem at all. Thanks again for your support @autoize
I’m going to try to raise the messages rate limit value.

I hope this thread will be useful to somebody to not fall into this trap !

1 Like