Can't send mail with Postfix

January 25, 2015 2.1k views

I run an Ubuntu 14.04 droplet on which I have installed Postfix, Dovecot, and RoundCube according to this guide. When I send mail through Roundcube, it gives me a (250) error SMTP Authentication Failed. (Sending mail through the Mac Mail client also fails, and I can post logs for that as well.) /var/log/mail.log contains the following after an unsuccessful send:

Jan 24 16:06:36 shuster postfix/smtpd[6521]: name_mask: all
Jan 24 16:06:36 shuster postfix/smtpd[6521]: inet_addr_local: configured 2 IPv4 addresses
Jan 24 16:06:36 shuster postfix/smtpd[6521]: inet_addr_local: configured 2 IPv6 addresses
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: process generation: 11 (11)
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: mynetworks ~? debug_peer_list
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: mynetworks ~? fast_flush_domains
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: mynetworks ~? mynetworks
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: relay_domains ~? debug_peer_list
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: relay_domains ~? fast_flush_domains
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: relay_domains ~? mynetworks
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: relay_domains ~? permit_mx_backup_networks
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: relay_domains ~? qmqpd_authorized_clients
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: relay_domains ~? relay_domains
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: permit_mx_backup_networks ~? debug_peer_list
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: permit_mx_backup_networks ~? fast_flush_domains
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: permit_mx_backup_networks ~? mynetworks
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: permit_mx_backup_networks ~? permit_mx_backup_networks
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: connect to subsystem private/proxymap
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: send attr request = open
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: send attr table = unix:passwd.byname
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: send attr flags = 0
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: private/proxymap socket: wanted attribute: status
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: input attribute name: status
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: input attribute value: 0
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: private/proxymap socket: wanted attribute: flags
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: input attribute name: flags
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: input attribute value: 16
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: private/proxymap socket: wanted attribute: (list terminator)
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: input attribute name: (end)
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: dict_proxy_open: connect to map=unix:passwd.byname status=0 server_flags=fixed
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: dict_open: proxy:unix:passwd.byname
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: Compiled against Berkeley DB: 5.3.28?
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: Run-time linked against Berkeley DB: 5.3.28?
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: dict_open: hash:/etc/aliases
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-alias-maps.cf: user = mail
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-alias-maps.cf: password = present in file
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-alias-maps.cf: dbname = mail
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-alias-maps.cf: result_format = %s
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-alias-maps.cf: option_file = <NULL>
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-alias-maps.cf: option_group = <NULL>
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-alias-maps.cf: tls_key_file = /etc/ssl/private/ssl-cert-snakeoil.key
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-alias-maps.cf: tls_cert_file = /etc/ssl/certs/ssl-cert-snakeoil.pem
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-alias-maps.cf: tls_CAfile = <NULL>
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-alias-maps.cf: tls_CApath = <NULL>
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-alias-maps.cf: tls_ciphers = <NULL>
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_bool: /etc/postfix/mysql-virtual-alias-maps.cf: tls_verify_cert = on
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_int: /etc/postfix/mysql-virtual-alias-maps.cf: expansion_limit = 0
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-alias-maps.cf: query = SELECT destination FROM virtual_aliases WHERE source='%s'
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-alias-maps.cf: domain = 
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-alias-maps.cf: hosts = 127.0.0.1
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: dict_open: mysql:/etc/postfix/mysql-virtual-alias-maps.cf
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-mailbox-maps.cf: user = mail
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-mailbox-maps.cf: password = present in file
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-mailbox-maps.cf: dbname = mail
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-mailbox-maps.cf: result_format = %s
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-mailbox-maps.cf: option_file = <NULL>
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-mailbox-maps.cf: option_group = <NULL>
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-mailbox-maps.cf: tls_key_file = /etc/ssl/private/ssl-cert-snakeoil.key
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-mailbox-maps.cf: tls_cert_file = /etc/ssl/certs/ssl-cert-snakeoil.pem
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-mailbox-maps.cf: tls_CAfile = <NULL>
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-mailbox-maps.cf: tls_CApath = <NULL>
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-mailbox-maps.cf: tls_ciphers = <NULL>
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_bool: /etc/postfix/mysql-virtual-mailbox-maps.cf: tls_verify_cert = on
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_int: /etc/postfix/mysql-virtual-mailbox-maps.cf: expansion_limit = 0
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-mailbox-maps.cf: query = SELECT 1 FROM virtual_users WHERE email='%s'
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-mailbox-maps.cf: domain = 
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: cfg_get_str: /etc/postfix/mysql-virtual-mailbox-maps.cf: hosts = 127.0.0.1
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: dict_open: mysql:/etc/postfix/mysql-virtual-mailbox-maps.cf
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: smtpd_access_maps ~? debug_peer_list
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: smtpd_access_maps ~? fast_flush_domains
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: smtpd_access_maps ~? mynetworks
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: smtpd_access_maps ~? permit_mx_backup_networks
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: smtpd_access_maps ~? qmqpd_authorized_clients
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: smtpd_access_maps ~? relay_domains
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: smtpd_access_maps ~? smtpd_access_maps
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: unknown_helo_hostname_tempfail_action = defer_if_permit
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: unknown_address_tempfail_action = defer_if_permit
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: unverified_recipient_tempfail_action = defer_if_permit
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: unverified_sender_tempfail_action = defer_if_permit
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: debug_peer_list ~? debug_peer_list
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: name_mask: 0
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: auto_clnt_create: transport=local endpoint=private/tlsmgr
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: auto_clnt_open: connected to private/tlsmgr
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: send attr request = seed
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: send attr size = 32
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: private/tlsmgr: wanted attribute: status
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: input attribute name: status
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: input attribute value: 0
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: private/tlsmgr: wanted attribute: seed
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: input attribute name: seed
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: input attribute value: ByHwfdlagoZN5PODvKlXQyP4N/YY9+TmN8a1EU3JUsg=
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: private/tlsmgr: wanted attribute: (list terminator)
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: input attribute name: (end)
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: send attr request = policy
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: send attr cache_type = smtpd
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: private/tlsmgr: wanted attribute: status
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: input attribute name: status
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: input attribute value: 0
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: private/tlsmgr: wanted attribute: cachable
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: input attribute name: cachable
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: input attribute value: 1
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: private/tlsmgr: wanted attribute: timeout
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: input attribute name: timeout
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: input attribute value: 3600
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: private/tlsmgr: wanted attribute: (list terminator)
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: input attribute name: (end)
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: fast_flush_domains ~? debug_peer_list
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_string: fast_flush_domains ~? fast_flush_domains
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: auto_clnt_create: transport=local endpoint=private/anvil
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: connection established
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: master_notify: status 0
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: name_mask: resource
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: name_mask: software
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: connect from localhost.localdomain[127.0.0.1]
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_list_match: localhost.localdomain: no match
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_list_match: 127.0.0.1: no match
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_list_match: localhost.localdomain: no match
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_list_match: 127.0.0.1: no match
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_hostname: localhost.localdomain ~? 127.0.0.1
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_hostaddr: 127.0.0.1 ~? 127.0.0.1
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: smtp_stream_setup: maxtime=300 enable_deadline=0
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_hostname: localhost.localdomain ~? 127.0.0.0/8
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_hostaddr: 127.0.0.1 ~? 127.0.0.0/8
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: > localhost.localdomain[127.0.0.1]: 220 shuster.house ESMTP Postfix (Ubuntu)
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: watchdog_pat: 0x7f3f875f9450
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: vstream_fflush_some: fd 17 flush 42
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: vstream_buf_get_ready: fd 17 got 28
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: < localhost.localdomain[127.0.0.1]: EHLO webmail.shuster.house
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_list_match: localhost.localdomain: no match
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_list_match: 127.0.0.1: no match
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: > localhost.localdomain[127.0.0.1]: 250-shuster.house
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: > localhost.localdomain[127.0.0.1]: 250-PIPELINING
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: > localhost.localdomain[127.0.0.1]: 250-SIZE 10240000
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: > localhost.localdomain[127.0.0.1]: 250-VRFY
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: > localhost.localdomain[127.0.0.1]: 250-ETRN
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: > localhost.localdomain[127.0.0.1]: 250-STARTTLS
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: > localhost.localdomain[127.0.0.1]: 250-ENHANCEDSTATUSCODES
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: > localhost.localdomain[127.0.0.1]: 250-8BITMIME
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: > localhost.localdomain[127.0.0.1]: 250 DSN
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: watchdog_pat: 0x7f3f875f9450
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: vstream_fflush_some: fd 17 flush 136
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: vstream_buf_get_ready: fd 17 got 6
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: < localhost.localdomain[127.0.0.1]: RSET
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: > localhost.localdomain[127.0.0.1]: 530 5.7.0 Must issue a STARTTLS command first
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: watchdog_pat: 0x7f3f875f9450
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: vstream_fflush_some: fd 17 flush 47
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: vstream_buf_get_ready: fd 17 got 6
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: < localhost.localdomain[127.0.0.1]: QUIT
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: > localhost.localdomain[127.0.0.1]: 221 2.0.0 Bye
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_hostname: localhost.localdomain ~? 127.0.0.0/8
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: match_hostaddr: 127.0.0.1 ~? 127.0.0.0/8
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: disconnect from localhost.localdomain[127.0.0.1]
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: master_notify: status 1
Jan 24 16:06:36 shuster postfix/submission/smtpd[6521]: connection closed
Jan 24 16:06:41 shuster postfix/submission/smtpd[6521]: proxymap stream disconnect
Jan 24 16:06:41 shuster postfix/submission/smtpd[6521]: auto_clnt_close: disconnect private/tlsmgr stream
Jan 24 16:07:42 shuster dovecot: imap-login: Login: user=<tyler@shuster.house>, method=PLAIN, rip=71.9.129.220, lip=162.243.144.234, mpid=6531, TLS, session=<zHaGz24NSgBHCYHc>
Jan 24 16:07:42 shuster dovecot: imap-login: Login: user=<tyler@shuster.house>, method=PLAIN, rip=71.9.129.220, lip=162.243.144.234, mpid=6532, TLS, session=<RuyGz24NSABHCYHc>
Jan 24 16:07:42 shuster dovecot: imap-login: Login: user=<elizabeth@shuster.house>, method=PLAIN, rip=71.9.129.220, lip=162.243.144.234, mpid=6534, TLS, session=</diHz24NSwBHCYHc>
Jan 24 16:07:42 shuster dovecot: imap-login: Login: user=<elizabeth@shuster.house>, method=PLAIN, rip=71.9.129.220, lip=162.243.144.234, mpid=6536, TLS, session=<U9mHz24NSQBHCYHc>
Jan 24 16:07:42 shuster dovecot: imap(tyler@shuster.house): Connection closed in=54 out=804
Jan 24 16:07:43 shuster dovecot: imap(tyler@shuster.house): Connection closed in=23 out=657
Jan 24 16:07:43 shuster dovecot: imap(elizabeth@shuster.house): Connection closed in=54 out=741
Jan 24 16:07:43 shuster dovecot: imap(elizabeth@shuster.house): Connection closed in=23 out=523

2 Answers

I don't see the actual error. Could you share your Postfix configuration with us? You could use Pastebin to share it with us.

If possible, share the latest mail.err and mail.log as well.

  • The error is a popup window in RoundCube that says "SMTP Error (250): Authentication failed."

    NOTE: I have fixed the spamc permission problem, but that wasn't the problem, so you can probably ignore the "spamc[7644]: exec failed: Permission denied"

    Main.cf: http://pastebin.com/TDt1rm5r
    Master.cf: http://pastebin.com/rz8n00kF
    Mail.log: http://pastebin.com/k3kWhmBV
    Mail.err: http://pastebin.com/wvup3JAX

  • To be honest, I see a lot warnings and errors which shouldn't be there in your logs :) .

    We have to spit the logs out, so please disable spamassasin as a beginning. Or reinstall the mailserver with just Postfix/Dovecot on it.

  • Thanks for giving it a look. I ended up reinstalling the server and going with Virtualmin, which seems more appropriate to what I'm doing. As educational as poring over configuration files was - I don't need that granular control right now.

Have another answer? Share your knowledge.