PHP mail() function not working

Discussion in 'Installation/Configuration' started by faberchr, May 18, 2015.

  1. faberchr

    faberchr New Member

    Hello,
    I did a clean installation of ISPConfig 3 following all the steps provided here: https://www.howtoforge.com/perfect-...sl-pureftpd-bind-postfix-doveot-and-ispconfig

    The server is going good but I've got a problem I cannot solve by myself: all the emails sent via PHP mail() function aren't delivered. I double checked both inbox and spam directory and nothing arrives from the server. At the same time, no particular error is raised by PHP.
    I've searched both in "google" and in this forum but I cannot figure out how to solve this problem.
    What I already did
    • Checked if the port 25 is open and reachable. And it is.
    • Changed the Courier/Dovecot option in ISPConfig panel, system -> serve config -> myserver -> mail
    • Followed those steps, but I think it's not regarding my problem: https://www.howtoforge.com/community/threads/php-mail-not-working.56564/
    • Testing recursively with a simple mail() function, that shows no error.
    What you should know
    netstat -tap
    Code:
    tcp        0      0 *:pop3                  *:*                     LISTEN      1231/dovecot
    tcp        0      0 *:imap2                 *:*                     LISTEN      1231/dovecot
    tcp        0      0 *:urd                   *:*                     LISTEN      4319/master
    tcp        0      0 *:ftp                   *:*                     LISTEN      2454/pure-ftpd (SER
    tcp        0      0 107.XXX.XXX.XXX.v:domain *:*                     LISTEN      1368/named
    tcp        0      0 localhost:domain        *:*                     LISTEN      1368/named
    tcp        0      0 *:ssh                   *:*                     LISTEN      1230/sshd
    tcp        0      0 *:smtp                  *:*                     LISTEN      4319/master
    tcp        0      0 localhost:953           *:*                     LISTEN      1368/named
    tcp        0      0 *:imaps                 *:*                     LISTEN      1231/dovecot
    tcp        0      0 *:pop3s                 *:*                     LISTEN      1231/dovecot
    tcp        0      0 localhost:10025         *:*                     LISTEN      4319/master
    tcp        0      0 *:submission            *:*                     LISTEN      4319/master
    tcp        0      0 localhost:11211         *:*                     LISTEN      1849/memcached
    tcp        0      0 localhost:42022         localhost:mysql         ESTABLISHED 4500/smtp
    tcp        0      1 107.XXX.XXX.XXX.vu:42860 mtain-b-mtc-c.mx.a:smtp SYN_SENT    4505/smtp
    tcp        0    464 107.XXX.XXX.XXX.vult:ssh host17-107-dynami:53330 ESTABLISHED 3191/2
    tcp        0     33 107.XXX.XXX.XXX.vult:ftp 43.225.250.171:56912    ESTABLISHED 4133/pure-ftpd (IDL
    tcp        0      0 localhost:41987         localhost:mysql         TIME_WAIT   -
    tcp        0      0 localhost:41994         localhost:mysql         TIME_WAIT   -
    tcp        0      1 107.XXX.XXX.XXX.vu:54356 mta-v6.mail.vip.bf:smtp SYN_SENT    4506/smtp
    tcp        0      1 107.XXX.XXX.XXX.vu:36225 mta-v2.mail.vip.gq:smtp SYN_SENT    4502/smtp
    tcp6       0      0 [::]:pop3               [::]:*                  LISTEN      1231/dovecot
    tcp6       0      0 [::]:imap2              [::]:*                  LISTEN      1231/dovecot
    tcp6       0      0 [::]:http-alt           [::]:*                  LISTEN      3832/apache2
    tcp6       0      0 [::]:http               [::]:*                  LISTEN      3832/apache2
    tcp6       0      0 [::]:urd                [::]:*                  LISTEN      4319/master
    tcp6       0      0 [::]:tproxy             [::]:*                  LISTEN      3832/apache2
    tcp6       0      0 [::]:ftp                [::]:*                  LISTEN      2454/pure-ftpd (SER
    tcp6       0      0 [::]:domain             [::]:*                  LISTEN      1368/named
    tcp6       0      0 [::]:ssh                [::]:*                  LISTEN      1230/sshd
    tcp6       0      0 [::]:smtp               [::]:*                  LISTEN      4319/master
    tcp6       0      0 localhost:953           [::]:*                  LISTEN      1368/named
    tcp6       0      0 [::]:https              [::]:*                  LISTEN      3832/apache2
    tcp6       0      0 [::]:imaps              [::]:*                  LISTEN      1231/dovecot
    tcp6       0      0 [::]:pop3s              [::]:*                  LISTEN      1231/dovecot
    tcp6       0      0 [::]:mysql              [::]:*                  LISTEN      2349/mysqld
    tcp6       0      0 [::]:submission         [::]:*                  LISTEN      4319/master
    tcp6       0      0 107.XXX.XXX.XXX.vu:https crawl-66-249-67-1:59761 TIME_WAIT   -
    tcp6       0      0 107.XXX.XXX.XXX.vu:https crawl-66-249-67-1:58773 TIME_WAIT   -
    tcp6       0      0 107.XXX.XXX.XXX.vu:mysql host17-107-dynami:53694 ESTABLISHED 2349/mysqld
    tcp6       0      0 107.XXX.XXX.XXX.vu:https host73-133-dynami:56374 ESTABLISHED 3842/apache2
    tcp6       0      1 2001:19f0:6800:85:38656 sa-in-x1a.1e100.ne:smtp SYN_SENT    -
    tcp6       0      0 107.XXX.XXX.XXX.vu:https host168-204-dynam:13883 TIME_WAIT   -
    tcp6       0      0 107.XXX.XXX.XXX.vu:mysql host17-107-dynami:53674 ESTABLISHED 2349/mysqld
    tcp6       0      0 localhost:54381         localhost:ftp           TIME_WAIT   -
    tcp6       0      0 107.XXX.XXX.XXX.vu:https host73-133-dynami:56373 ESTABLISHED 4089/apache2
    tcp6       0      0 107.XXX.XXX.XXX.vu:https 5.90.64.240:1202        ESTABLISHED 4509/apache2
    tcp6       0      0 107.XXX.XXX.XXX.vu:https host31-206-dynami:59531 TIME_WAIT   -
    tcp6       0      0 107.XXX.XXX.XXX.vu:https host31-206-dynami:59532 TIME_WAIT   -
    iptables -L
    Code:
    Chain INPUT (policy ACCEPT)
    target     prot opt source               destination
    fail2ban-postfix-sasl  tcp  --  anywhere             anywhere             multiport dports smtp
    fail2ban-dovecot-pop3imap  tcp  --  anywhere             anywhere             multiport dports pop3,pop3s,imap2,imaps
    fail2ban-pureftpd  tcp  --  anywhere             anywhere             multiport dports ftp
    fail2ban-ssh  tcp  --  anywhere             anywhere             multiport dports ssh
    
    Chain FORWARD (policy ACCEPT)
    target     prot opt source               destination
    
    Chain OUTPUT (policy ACCEPT)
    target     prot opt source               destination
    
    Chain fail2ban-dovecot-pop3imap (1 references)
    target     prot opt source               destination
    RETURN     all  --  anywhere             anywhere
    
    Chain fail2ban-postfix-sasl (1 references)
    target     prot opt source               destination
    RETURN     all  --  anywhere             anywhere
    
    Chain fail2ban-pureftpd (1 references)
    target     prot opt source               destination
    RETURN     all  --  anywhere             anywhere
    
    Chain fail2ban-ssh (1 references)
    target     prot opt source               destination
    REJECT     all  --  221.229.166.29       anywhere             reject-with icmp-port-unreachable
    REJECT     all  --  222.186.160.52       anywhere             reject-with icmp-port-unreachable
    RETURN     all  --  anywhere             anywhere
    
    Mail error-log is empty, while mail warning-log gives this error: "Unable to read /var/log/mail.warn"
     
  2. till

    till Super Moderator Staff Member ISPConfig Developer

    which messages do you get in the mail.log file?
     
  3. faberchr

    faberchr New Member

    Thanks for your reply. This is what I see.
    Code:
    May 18 18:01:39 vultr postfix/smtp[4809]: connect to ALT1.ASPMX.L.GOOGLE.COM[2a00:1450:4010:c07::1b]:25: Connection timed out
    May 18 18:01:39 vultr postfix/smtp[4809]: 28E3111C32: to=<[email protected]>, relay=none, delay=394002, delays=393851/0.03/151/0, dsn=4.4.1, status=deferred (connect to ALT1.ASPMX.L.GOOGLE.COM[2a00:1450:4010:c07::1b]:25: Connection timed out)
    May 18 18:01:39 vultr postfix/smtp[4808]: 2BF5511B86: to=<[email protected]>, relay=none, delay=225314, delays=225163/0.03/151/0, dsn=4.4.1, status=deferred (connect to ALT2.ASPMX.L.GOOGLE.COM[2404:6800:4003:c00::1a]:25: Connection timed out)
    May 18 18:02:01 vultr postfix/smtpd[4360]: connect from localhost[::1]
    May 18 18:02:01 vultr postfix/smtpd[4360]: lost connection after CONNECT from localhost[::1]
    May 18 18:02:01 vultr postfix/smtpd[4360]: disconnect from localhost[::1]
    May 18 18:02:01 vultr dovecot: imap-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=::1, lip=::1, secured, session=<40Gj/V4WpwAAAAAAAAAAAAAAAAAAAAAB>
    May 18 18:02:01 vultr dovecot: pop3-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=::1, lip=::1, secured, session=<MEqj/V4WkwAAAAAAAAAAAAAAAAAAAAAB>
    May 18 18:03:01 vultr postfix/smtpd[4360]: connect from localhost[::1]
    May 18 18:03:01 vultr postfix/smtpd[4360]: lost connection after CONNECT from localhost[::1]
    May 18 18:03:01 vultr postfix/smtpd[4360]: disconnect from localhost[::1]
    May 18 18:03:01 vultr dovecot: imap-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=::1, lip=::1, secured, session=<zzA4AV8WrwAAAAAAAAAAAAAAAAAAAAAB>
    May 18 18:03:01 vultr dovecot: pop3-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=::1, lip=::1, secured, session=<WTc4AV8WmwAAAAAAAAAAAAAAAAAAAAAB>
    May 18 18:04:01 vultr postfix/smtpd[4360]: connect from localhost[::1]
    May 18 18:04:01 vultr postfix/smtpd[4360]: lost connection after CONNECT from localhost[::1]
    May 18 18:04:01 vultr postfix/smtpd[4360]: disconnect from localhost[::1]
    May 18 18:04:01 vultr dovecot: imap-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=::1, lip=::1, secured, session=<eDjNBF8WuwAAAAAAAAAAAAAAAAAAAAAB>
    May 18 18:04:01 vultr dovecot: pop3-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=::1, lip=::1, secured, session=<2jvNBF8WpwAAAAAAAAAAAAAAAAAAAAAB>
    May 18 18:04:09 vultr postfix/qmgr[4323]: 295E811B2D: from=<[email protected]>, size=1553, nrcpt=1 (queue active)
    May 18 18:04:09 vultr postfix/qmgr[4323]: 8B1A511BF6: from=<[email protected]>, size=1135, nrcpt=1 (queue active)
    May 18 18:04:09 vultr postfix/qmgr[4323]: 8CD4E11BFB: from=<[email protected]>, size=739, nrcpt=1 (queue active)
    May 18 18:04:09 vultr postfix/qmgr[4323]: B70E911B7E: from=<[email protected]>, size=1570, nrcpt=1 (queue active)
    May 18 18:04:09 vultr postfix/qmgr[4323]: C714111BFC: from=<[email protected]>, size=438, nrcpt=1 (queue active)
    May 18 18:04:09 vultr postfix/qmgr[4323]: C1C09119CC: from=<[email protected]>, size=1565, nrcpt=1 (queue active)
    May 18 18:04:09 vultr postfix/qmgr[4323]: 37E2811BFA: from=<[email protected]>, size=868, nrcpt=1 (queue active)
    May 18 18:04:09 vultr postfix/qmgr[4323]: D1F1C11BF4: from=<[email protected]>, size=438, nrcpt=1 (queue active)
    May 18 18:04:09 vultr postfix/qmgr[4323]: D260511AD2: from=<[email protected]>, size=1555, nrcpt=1 (queue active)
    May 18 18:04:09 vultr postfix/qmgr[4323]: 09E1211BFE: from=<[email protected]>, size=438, nrcpt=1 (queue active)
    May 18 18:04:09 vultr postfix/qmgr[4323]: 03F6911C02: from=<[email protected]>, size=1123, nrcpt=1 (queue active)
    May 18 18:04:09 vultr postfix/qmgr[4323]: 06B7911BF3: from=<[email protected]>, size=732, nrcpt=1 (queue active)
    May 18 18:04:09 vultr postfix/qmgr[4323]: 1D938119D3: from=<[email protected]>, size=1562, nrcpt=1 (queue active)
    May 18 18:04:09 vultr postfix/qmgr[4323]: 92E33119EB: from=<[email protected]>, size=1576, nrcpt=1 (queue active)
    May 18 18:04:09 vultr postfix/qmgr[4323]: 9988F11B08: from=<[email protected]>, size=1563, nrcpt=1 (queue active)
    May 18 18:04:09 vultr postfix/qmgr[4323]: 90E3D119DB: from=<[email protected]>, size=1600, nrcpt=1 (queue active)
    May 18 18:04:09 vultr postfix/smtp[5042]: connect to 127.0.0.1[127.0.0.1]:10024: Connection refused
    May 18 18:04:09 vultr postfix/smtp[5042]: 8B1A511BF6: to=<[email protected]>, relay=none, delay=2591, delays=2591/0.02/0/0, dsn=4.4.1, status=deferred (connect to 127.0.0.1[127.0.0.1]:10024: Connection refused)
    May 18 18:04:09 vultr postfix/smtp[5042]: connect to 127.0.0.1[127.0.0.1]:10024: Connection refused
    May 18 18:04:09 vultr postfix/smtp[5044]: connect to 127.0.0.1[127.0.0.1]:10024: Connection refused
    May 18 18:04:09 vultr postfix/smtp[5042]: 8CD4E11BFB: to=<[email protected]>, relay=none, delay=2591, delays=2591/0.02/0/0, dsn=4.4.1, status=deferred (connect to 127.0.0.1[127.0.0.1]:10024: Connection refused)
    May 18 18:04:09 vultr postfix/smtp[5042]: connect to 127.0.0.1[127.0.0.1]:10024: Connection refused
    May 18 18:04:09 vultr postfix/smtp[5044]: C714111BFC: to=<[email protected]>, relay=none, delay=2549, delays=2549/0.02/0/0, dsn=4.4.1, status=deferred (connect to 127.0.0.1[127.0.0.1]:10024: Connection refused)
    May 18 18:04:09 vultr postfix/smtp[5042]: D1F1C11BF4: to=<[email protected]>, relay=none, delay=1183, delays=1183/0.02/0/0, dsn=4.4.1, status=deferred (connect to 127.0.0.1[127.0.0.1]:10024: Connection refused)
    May 18 18:04:09 vultr postfix/error[5050]: 09E1211BFE: to=<[email protected]>, relay=none, delay=1725, delays=1725/0.03/0/0, dsn=4.4.1, status=deferred (delivery temporarily suspended: connect to 127.0.0.1[127.0.0.1]:10024: Connection refused)
    May 18 18:04:09 vultr postfix/error[5050]: 03F6911C02: to=<[email protected]>, relay=none, delay=365, delays=365/0.03/0/0, dsn=4.4.1, status=deferred (delivery temporarily suspended: connect to 127.0.0.1[127.0.0.1]:10024: Connection refused)
    May 18 18:04:09 vultr postfix/error[5050]: 06B7911BF3: to=<[email protected]>, relay=none, delay=365, delays=365/0.03/0/0, dsn=4.4.1, status=deferred (delivery temporarily suspended: connect to 127.0.0.1[127.0.0.1]:10024: Connection refused)
    May 18 18:04:40 vultr postfix/smtp[5054]: connect to fmx.freemail.hu[195.228.245.2]:25: Connection timed out
    May 18 18:04:40 vultr postfix/smtp[5054]: 92E33119EB: to=<[email protected]>, relay=none, delay=378880, delays=378850/0.04/30/0, dsn=4.4.1, status=deferred (connect to fmx.freemail.hu[195.228.245.2]:25: Connection timed out)
    May 18 18:04:40 vultr postfix/smtp[5055]: connect to mail.qaqmail.com[155.133.19.61]:25: Connection timed out
    May 18 18:04:40 vultr postfix/smtp[5053]: connect to mail.qaqmail.com[155.133.19.61]:25: Connection timed out
    May 18 18:04:40 vultr postfix/smtp[5055]: 9988F11B08: to=<[email protected]>, relay=none, delay=378884, delays=378853/0.04/30/0, dsn=4.4.1, status=deferred (connect to mail.qaqmail.com[155.133.19.61]:25: Connection timed out)
    May 18 18:04:40 vultr postfix/smtp[5053]: 1D938119D3: to=<[email protected]>, relay=none, delay=295368, delays=295338/0.04/30/0, dsn=4.4.1, status=deferred (connect to mail.qaqmail.com[155.133.19.61]:25: Connection timed out)
    May 18 18:04:40 vultr postfix/smtp[5051]: connect to mail.qaqmail.com[155.133.19.61]:25: Connection timed out
    May 18 18:04:40 vultr postfix/smtp[5041]: connect to mail.qaqmail.com[155.133.19.61]:25: Connection timed out
    May 18 18:04:40 vultr postfix/smtp[5051]: D260511AD2: to=<[email protected]>, relay=none, delay=378872, delays=378842/0.03/30/0, dsn=4.4.1, status=deferred (connect to mail.qaqmail.com[155.133.19.61]:25: Connection timed out)
    May 18 18:04:40 vultr postfix/smtp[5041]: 295E811B2D: to=<[email protected]>, relay=none, delay=122069, delays=122039/0.03/30/0, dsn=4.4.1, status=deferred (connect to mail.qaqmail.com[155.133.19.61]:25: Connection timed out)
    May 18 18:04:40 vultr postfix/smtp[5056]: connect to mx.discard.email[5.45.100.19]:25: Connection timed out
    May 18 18:04:40 vultr postfix/smtp[5056]: 90E3D119DB: to=<[email protected]>, relay=none, delay=379486, delays=379455/0.05/30/0, dsn=4.4.1, status=deferred (connect to mx.discard.email[5.45.100.19]:25: Connection timed out)
    May 18 18:04:40 vultr postfix/smtp[5043]: connect to mx.yandex.ru[87.250.250.89]:25: Connection timed out
    May 18 18:04:40 vultr postfix/smtp[5048]: connect to mx.zoho.com[74.201.154.201]:25: Connection timed out
    May 18 18:04:40 vultr postfix/smtp[5046]: connect to docs.zonerig.com[198.44.25.90]:25: Connection timed out
    May 18 18:04:40 vultr postfix/smtp[5046]: C1C09119CC: to=<[email protected]>, relay=none, delay=378880, delays=378849/0.02/31/0, dsn=4.4.1, status=deferred (connect to docs.zonerig.com[198.44.25.90]:25: Connection timed out)
    May 18 18:05:01 vultr postfix/smtpd[4360]: connect from localhost[::1]
    May 18 18:05:01 vultr postfix/smtpd[4360]: lost connection after CONNECT from localhost[::1]
    May 18 18:05:01 vultr postfix/smtpd[4360]: disconnect from localhost[::1]
    May 18 18:05:01 vultr dovecot: pop3-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=::1, lip=::1, secured, session=<sZliCF8WzwAAAAAAAAAAAAAAAAAAAAAB>
     
  4. till

    till Super Moderator Staff Member ISPConfig Developer

    Seems as if port 25 outgoing (not incoming) is blocked. Do you run the server in a datacenter or at home or in office? When the server is not in a datacneter, then your internet access provider blocks port 25 to external servers.
     
  5. faberchr

    faberchr New Member

    I run the serve in a datacenter. Thank you for heading me the right way! I'll contact the host.
     
  6. faberchr

    faberchr New Member

    I did a quick check but, maybe I am wrong, the outgoing port seems not blocked.
    Code:
    [email protected]:~# telnet myhostname.tld 25
    Trying 107.XXX.XXX.XX ...
    Connected to myhostname.tld.
    Escape character is '^]'.
    220 myhostname.tld ESMTP Postfix (Ubuntu)
    helo myhostname.tld
    250 myhostname.tld
    quit
    221 2.0.0 Bye
    Connection closed by foreign host.
    
     
  7. till

    till Super Moderator Staff Member ISPConfig Developer

    Try this (run on the shell of your server):

    telnet ALT1.ASPMX.L.GOOGLE.COM 25
     
  8. faberchr

    faberchr New Member

    It fails :\
     
  9. till

    till Super Moderator Staff Member ISPConfig Developer

    Then you should talk with your dataceter. If you cant reach the google mailserer on port 25 with telnet, then your mailserver (postfix) cant reach it as well and this is not a server config issue in your mailsystem.
     
  10. faberchr

    faberchr New Member

    I've got a response from my datacenter. They say that "port 25 is still unblocked".
     
  11. till

    till Super Moderator Staff Member ISPConfig Developer

    run:

    iptables --flush

    and try again to test with telnet port 25 to google mailserver.
     
  12. faberchr

    faberchr New Member

    Unfortunately, the cache flushing has no effect.
    This is my resolv.conf, maybe it helps.
    Code:
    [email protected]:~# cat /etc/resolv.conf
    # Dynamic resolv.conf(5) file for glibc resolver(3) generated by resolvconf(8)
    #     DO NOT EDIT THIS FILE BY HAND -- YOUR CHANGES WILL BE OVERWRITTEN
    nameserver 108.61.10.10
    nameserver 2001:4860:4860::8888
    nameserver 2001:4860:4860::8844
    
     

Share This Page