Php mail is erratic: sometimes sends, sometimes doesn't

Dave Coventry asked:

I have a server set up to use postfix to send mail from the server.

When a user registers at my WordPress site, an email is sent to the administrators, both of whom have gmail addresses.

Sometimes it works and the emails are sent out to the administrators.

Sometimes the mail works fine

    Apr  2 16:39:32 server postfix/cleanup[7279]: 433319E245CB: message-id=<20160402163903.426959E245CC@mail.example.com>
    Apr  2 16:39:32 server postfix/smtpd[7289]: disconnect from localhost.localdomain[127.0.0.1]
    Apr  2 16:39:32 server postfix/qmgr[3806]: 433319E245CB: from=<www-data@example.co.uk>, size=1174, nrcpt=2 (queue active)
    Apr  2 16:39:32 server amavis[19869]: (19869-06) Passed CLEAN {RelayedOpenRelay}, <www-data@example.co.uk> -> <bwisxxxxxx@gmail.com>,<dgcoxxxxxx@gmail.com>, Message-ID: <20160402163903.426959E245CC@mail.example.com>, mail_id: kPBazIRbRnM0, Hits: 1.74, size: 760, queued_as: 433319E245CB, 28866 ms
    Apr  2 16:39:32 server postfix/smtp[7284]: 426959E245CC: to=<bwisxxxxxx@gmail.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=29, delays=0.19/0.05/0.01/29, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 433319E245CB)
    Apr  2 16:39:32 server postfix/smtp[7284]: 426959E245CC: to=<dgcoxxxxxx@gmail.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=29, delays=0.19/0.05/0.01/29, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 433319E245CB)
    Apr  2 16:39:32 server postfix/qmgr[3806]: 426959E245CC: removed
    Apr  2 16:39:32 server postfix/smtp[7292]: 433319E245CB: to=<bwisxxxxxx@gmail.com>, relay=gmail-smtp-in.l.google.com[2a00:1450:4013:c00::1b]:25, delay=0.56, delays=0.01/0.02/0.2/0.33, dsn=5.7.1, status=bounced (host gmail-smtp-in.l.google.com[2a00:1450:4013:c00::1b] said: 550-5.7.1 [2a00:d880:5:87f::4927] Our system has detected that this message does 550-5.7.1 not meet IPv6 sending guidelines regarding PTR records and 550-5.7.1 authentication. Please review 550-5.7.1  https://support.google.com/mail/?p=ipv6_authentication_error for more 550 5.7.1 information. q140si4479035wmg.33 - gsmtp (in reply to end of DATA command))
    Apr  2 16:39:32 server postfix/smtp[7292]: 433319E245CB: to=<dgcoxxxxxx@gmail.com>, relay=gmail-smtp-in.l.google.com[2a00:1450:4013:c00::1b]:25, delay=0.56, delays=0.01/0.02/0.2/0.33, dsn=5.7.1, status=bounced (host gmail-smtp-in.l.google.com[2a00:1450:4013:c00::1b] said: 550-5.7.1 [2a00:d880:5:87f::4927] Our system has detected that this message does 550-5.7.1 not meet IPv6 sending guidelines regarding PTR records and 550-5.7.1 authentication. Please review 550-5.7.1  https://support.google.com/mail/?p=ipv6_authentication_error for more 550 5.7.1 information. q140si4479035wmg.33 - gsmtp (in reply to end of DATA command))

But sometimes the emails are never sent:

    Apr  2 22:04:11 server postfix/pickup[16625]: 5082F9E245EF: uid=33 from=<www-data>
    Apr  2 22:04:11 server postfix/cleanup[18820]: 5082F9E245EF: message-id=<20160402220411.5082F9E245EF@mail.example.com>
    Apr  2 22:04:11 server postfix/qmgr[3806]: 5082F9E245EF: from=<www-data@example.co.uk>, size=761, nrcpt=2 (queue active)
    Apr  2 22:04:11 server postfix/smtp[18824]: connect to 127.0.0.1[127.0.0.1]:10024: Connection refused
    Apr  2 22:04:11 server postfix/smtp[18824]: 5082F9E245EF: to=<bwisxxxxxx@gmail.com>, relay=none, delay=0.07, delays=0.06/0.01/0/0, dsn=4.4.1, status=deferred (connect to 127.0.0.1[127.0.0.1]:10024: Connection refused)
    Apr  2 22:04:11 server postfix/smtp[18824]: 5082F9E245EF: to=<dgcoxxxxxxx@gmail.com>, relay=none, delay=0.07, delays=0.06/0.01/0/0, dsn=4.4.1, status=deferred (connect to 127.0.0.1[127.0.0.1]:10024: Connection refused)

I am at a loss to figure it out

=====Added 6th April 2016=======

Mail has stopped being sent by phpmail. My mail.log has this:

    Apr 6 06:05:16 localhost postfix/pickup[15610]: 4D0879E27098: uid=33 from=<www-data>
    Apr 6 06:05:16 localhost postfix/cleanup[17898]: 4D0879E27098: message-id=<20160406060516.4D0879E27098@example.co.uk>
    Apr 6 06:05:16 localhost postfix/qmgr[29829]: 4D0879E27098: from=<www-data@example.co.uk>, size=793, nrcpt=3 (queue active)
    Apr 6 06:05:16 localhost amavis[18554]: (18554-07) NOTICE: reconnecting in response to: err=2006, HY000, DBD::mysql::st execute failed: MySQL server has gone away at (eval 111) line 170, <GEN38> line 20469.
    Apr 6 06:05:22 localhost postfix/smtpd[17907]: connect from localhost.localdomain[127.0.0.1]
    Apr 6 06:05:22 localhost postfix/smtpd[17907]: A9F9B9E27097: client=localhost.localdomain[127.0.0.1]
    Apr 6 06:05:22 localhost postfix/cleanup[17898]: A9F9B9E27097: message-id=<20160406060516.4D0879E27098@example.co.uk>
    Apr 6 06:05:22 localhost postfix/qmgr[29829]: A9F9B9E27097: from=<www-data@example.co.uk>, size=1210, nrcpt=3 (queue active)
    Apr 6 06:05:22 localhost postfix/smtpd[17907]: disconnect from localhost.localdomain[127.0.0.1]
    Apr 6 06:05:22 localhost amavis[18554]: (18554-07) Passed CLEAN {RelayedOpenRelay}, <www-data@example.co.uk> -> <bwisexxxx@gmail.com>,<dgcxxx@gmail.com>,<dgcxxx@hotmail.co.uk>, Message-ID: <20160406060516.4D0879E27098@example.co.uk>, mail_id: 93X8pKlGq9Sh, Hits: 1.74, size: 792, queued_as: A9F9B9E27097, 6338 ms
    Apr 6 06:05:22 localhost postfix/smtp[17901]: 4D0879E27098: to=<bwisexxxx@gmail.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=6.5, delays=0.08/0.02/0.09/6.3, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as A9F9B9E27097)
    Apr 6 06:05:22 localhost postfix/smtp[17901]: 4D0879E27098: to=<dgcxxx@gmail.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=6.5, delays=0.08/0.02/0.09/6.3, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as A9F9B9E27097)
    Apr 6 06:05:22 localhost postfix/smtp[17901]: 4D0879E27098: to=<dgcxxx@hotmail.co.uk>, relay=127.0.0.1[127.0.0.1]:10024, delay=6.5, delays=0.08/0.02/0.09/6.3, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as A9F9B9E27097)
    Apr 6 06:05:22 localhost postfix/qmgr[29829]: 4D0879E27098: removed
    Apr 6 06:05:23 localhost postfix/smtp[17910]: A9F9B9E27097: to=<bwisexxxx@gmail.com>, relay=gmail-smtp-in.l.google.com[2a00:1450:4013:c01::1b]:25, delay=0.77, delays=0.02/0.03/0.33/0.39, dsn=5.7.1, status=bounced (host gmail-smtp-in.l.google.com[2a00:1450:4013:c01::1b] said: 550-5.7.1 [2a00:d880:5:87f::4927] Our system has detected that this message does 550-5.7.1 not meet IPv6 sending guidelines regarding PTR records and 550-5.7.1 authentication. Please review 550-5.7.1  https://support.google.com/mail/?p=ipv6_authentication_error for more 550 5.7.1 information. k188si1960277wmd.53 - gsmtp (in reply to end of DATA command))
    Apr 6 06:05:23 localhost postfix/smtp[17910]: A9F9B9E27097: to=<dgcxxx@gmail.com>, relay=gmail-smtp-in.l.google.com[2a00:1450:4013:c01::1b]:25, delay=0.77, delays=0.02/0.03/0.33/0.39, dsn=5.7.1, status=bounced (host gmail-smtp-in.l.google.com[2a00:1450:4013:c01::1b] said: 550-5.7.1 [2a00:d880:5:87f::4927] Our system has detected that this message does 550-5.7.1 not meet IPv6 sending guidelines regarding PTR records and 550-5.7.1 authentication. Please review 550-5.7.1  https://support.google.com/mail/?p=ipv6_authentication_error for more 550 5.7.1 information. k188si1960277wmd.53 - gsmtp (in reply to end of DATA command))
    Apr 6 06:05:24 localhost postfix/smtp[17911]: A9F9B9E27097: to=<dgcxxx@hotmail.co.uk>, relay=mx4.hotmail.com[65.55.37.120]:25, delay=1.8, delays=0.02/0.04/1.5/0.19, dsn=5.0.0, status=bounced (host mx4.hotmail.com[65.55.37.120] said: 550 SC-001 (COL004-MC4F18) Unfortunately, messages from xxx.xxx.xxx.xxx weren't sent. Please contact your Internet service provider since part of their network is on our block list. You can also refer your provider to http://mail.live.com/mail/troubleshooting.aspx#errors. (in reply to MAIL FROM command))
    Apr 6 06:05:24 localhost postfix/smtp[17911]: A9F9B9E27097: lost connection with mx4.hotmail.com[65.55.37.120] while sending RCPT TO
    Apr 6 06:05:24 localhost postfix/cleanup[17898]: 7528D9E27099: message-id=<20160406060524.7528D9E27099@example.co.uk>
    Apr 6 06:05:24 localhost postfix/qmgr[29829]: 7528D9E27099: from=<>, size=5791, nrcpt=1 (queue active)
    Apr 6 06:05:24 localhost postfix/bounce[17913]: A9F9B9E27097: sender non-delivery notification: 7528D9E27099
    Apr 6 06:05:24 localhost postfix/qmgr[29829]: A9F9B9E27097: removed
    Apr 6 06:05:24 localhost dovecot: lmtp(17915): Connect from local
    Apr 6 06:05:24 localhost dovecot: auth-worker(17916): mysql(127.0.0.1): Connected to database mailserver
    Apr 6 06:05:24 localhost postfix/lmtp[17914]: 7528D9E27099: to=<www-data@example.co.uk>, relay=example.co.uk[private/dovecot-lmtp], delay=0.06, delays=0/0.01/0.01/0.03, dsn=5.1.1, status=bounced (host example.co.uk[private/dovecot-lmtp] said: 550 5.1.1 <www-data@example.co.uk> User doesn't exist: www-data@example.co.uk (in reply to RCPT TO command))
    Apr 6 06:05:24 localhost dovecot: lmtp(17915): Disconnect from local: Client quit (in reset)
    Apr 6 06:05:24 localhost postfix/qmgr[29829]: 7528D9E27099: removed

My answer:


In your second set of log entries, it appears that amavis is not running, so the mail can’t be scanned for viruses, and thus it gets held in queue until such time as someone comes along and restarts amavis.


View the full question and answer on Server Fault.

Creative Commons License
This work is licensed under a Creative Commons Attribution-ShareAlike 3.0 Unported License.