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=<[email protected]>
    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=<[email protected]>, size=1174, nrcpt=2 (queue active)
    Apr  2 16:39:32 server amavis[19869]: (19869-06) Passed CLEAN {RelayedOpenRelay}, <[email protected]> -> <[email protected]>,<[email protected]>, Message-ID: <[email protected]>, mail_id: kPBazIRbRnM0, Hits: 1.74, size: 760, queued_as: 433319E245CB, 28866 ms
    Apr  2 16:39:32 server postfix/smtp[7284]: 426959E245CC: to=<[email protected]>, 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=<[email protected]>, 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=<[email protected]>, 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=<[email protected]>, 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=<[email protected]>
    Apr  2 22:04:11 server postfix/qmgr[3806]: 5082F9E245EF: from=<[email protected]>, 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=<[email protected]>, 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=<[email protected]>, 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=<[email protected]>
    Apr 6 06:05:16 localhost postfix/qmgr[29829]: 4D0879E27098: from=<[email protected]>, 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=<[email protected]>
    Apr 6 06:05:22 localhost postfix/qmgr[29829]: A9F9B9E27097: from=<[email protected]>, 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}, <[email protected]> -> <[email protected]>,<[email protected]>,<[email protected]>, Message-ID: <[email protected]>, mail_id: 93X8pKlGq9Sh, Hits: 1.74, size: 792, queued_as: A9F9B9E27097, 6338 ms
    Apr 6 06:05:22 localhost postfix/smtp[17901]: 4D0879E27098: to=<[email protected]>, 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=<[email protected]>, 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=<[email protected]>, 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=<[email protected]>, 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=<[email protected]>, 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=<[email protected]>, 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=<[email protected]>
    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=<[email protected]>, 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 <[email protected]> User doesn't exist: [email protected] (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 any other answers on Server Fault.

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