Postfix Wont Send Mail

carlosinfl · 01-08-2011, 11:31 AM

I'm having a problem with Postfix sending email. To be more specific, Postfix sends mail perfect but when my web server running webmail (RoundCube) connects to my mail server to send email, it fails & there is nothing in the logs that explain to me why:

Code:

Jan  8 11:53:02 mail dovecot: imap-login: Login: user=<carlos>, method=PLAIN, rip=192.168.0.201, lip=192.168.0.200, mpid=2161, TLS
Jan  8 11:53:02 mail postfix/smtpd[2162]: connect from www.iamghost.org[192.168.0.201]
Jan  8 11:53:02 mail postfix/smtpd[2162]: setting up TLS connection from www.iamghost.org[192.168.0.201]
Jan  8 11:53:02 mail postfix/smtpd[2162]: Anonymous TLS connection established from www.iamghost.org[192.168.0.201]: TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)
Jan  8 11:53:02 mail postfix/smtpd[2162]: disconnect from www.iamghost.org[192.168.0.201]
Jan  8 11:53:02 mail dovecot: imap(carlos): Disconnected: Logged out bytes=12/341

When I try sending mail from a client like Thunderbird / Evolution, it works perfect. When I try to send mail from my web server [192.168.0.201], I get a browser error:

SMTP Error: 250 (Authentication Error)

However I don't see a detailed error in /var/log/mail.log as shown above. How can I find out what's causing the error?

My web server [192.168.0.201] is listed in 'mynetworks' for trusted relay. My mail server in question is obviously 192.168.0.200.

Anyone know what I need to do in order to have Postfix give me some info on why my web server can't send mail from webmail?

bobloblian · 01-08-2011, 01:34 PM

I often find the best thing you can do to troubleshoot email is to bypass the client and run the session yourself.
Look here for a rough guide on how to do that using TLS: http://qmail.jms1.net/test-auth.shtml
If you run this test from your webserver, the mail server will most likely tell you during the session what the problem is...

Noway2 · 01-09-2011, 07:22 AM

You may want to turn on debugging in Dovecot. It has been a while since I have done so, but there are three places/lines where you can enable debugging and verbose logging. This may help.

In case it helps you, I too am using Postfix, Dovecot, with Roundcube mail. I sent a message through Roundcube and captured the log files. I posted them below for you to compare against. One thing that I do notice, but I am not sure if it is the problem or not, is the Anonymous TLS connection. If you notice, my TLS connection is handled a little differently as shown in the first line of the log snippit. I think there may be a postfix setting for "no anonymous". I would also compare against a message sent with your regular mail client and see if there are any differences.

Code:

Jan  9 08:12:55 mrgutsy dovecot: imap-login: Login: user=<invalid@noway2.net>, method=PLAIN, rip=96.10.215.210, lip=96.10.215.210, TLS
Jan  9 08:12:55 mrgutsy postfix/smtpd[22715]: connect from mrgutsy.midsouth.biz.rr.com[96.10.215.210]
Jan  9 08:12:55 mrgutsy postfix/smtpd[22715]: F216D60524: client=mrgutsy.midsouth.biz.rr.com[96.10.215.210], sasl_method=PLAIN, sasl_username=invalid@noway2.net
Jan  9 08:12:55 mrgutsy postfix/cleanup[22719]: F216D60524: message-id=<b282379dc6514e13d61ccc3ec7efb0e7@mrgutsy.noway2.net>
Jan  9 08:12:56 mrgutsy postfix/qmgr[1692]: F216D60524: from=<invalid@noway2.net>, size=958, nrcpt=1 (queue active)
Jan  9 08:12:56 mrgutsy dovecot: IMAP(invalid@noway2.net): Disconnected: Logged out bytes=8/43
Jan  9 08:12:56 mrgutsy postfix/smtpd[22715]: disconnect from mrgutsy.midsouth.biz.rr.com[96.10.215.210]
Jan  9 08:12:56 mrgutsy postfix/smtpd[22722]: connect from localhost[127.0.0.1]
Jan  9 08:12:56 mrgutsy postfix/smtpd[22722]: 306F660539: client=localhost[127.0.0.1]
Jan  9 08:12:56 mrgutsy postfix/cleanup[22719]: 306F660539: message-id=<b282379dc6514e13d61ccc3ec7efb0e7@mrgutsy.noway2.net>
Jan  9 08:12:56 mrgutsy postfix/smtpd[22722]: disconnect from localhost[127.0.0.1]
Jan  9 08:12:56 mrgutsy postfix/qmgr[1692]: 306F660539: from=<invalid@noway2.net>, size=1347, nrcpt=1 (queue active)
Jan  9 08:12:56 mrgutsy amavis[1227]: (01227-12) Passed CLEAN, [96.10.215.210] [96.10.215.210] <invalid@noway2.net> -> <invalid@noway2.thruhere.net>, Message-ID: <b282379dc6514e13d61ccc3ec7efb0e7@mrgutsy.noway2.net>, mail_id: M-8ZUXTdi5Gb, Hits: -, size: 958, queued_as: 306F660539, 222 ms
Jan  9 08:12:56 mrgutsy postfix/smtp[22720]: F216D60524: to=<invalid@noway2.thruhere.net>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.3, delays=0.05/0.01/0.01/0.23, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=01227-12, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 306F660539)
Jan  9 08:12:56 mrgutsy postfix/qmgr[1692]: F216D60524: removed
Jan  9 08:12:56 mrgutsy dovecot: imap-login: Login: user=<invalid@noway2.net>, method=PLAIN, rip=96.10.215.210, lip=96.10.215.210, TLS
Jan  9 08:12:56 mrgutsy dovecot: IMAP(invalid@noway2.net): Disconnected: Logged out bytes=46/418
Jan  9 08:12:56 mrgutsy postfix/smtp[22723]: 306F660539: to=<invalid@noway2.thruhere.net>, relay=noway2.thruhere.net[96.10.215.214]:25, delay=0.44, delays=0.09/0.06/0.22/0.08, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 8DB704C0)
Jan  9 08:12:56 mrgutsy postfix/qmgr[1692]: 306F660539: removed
Jan  9 08:12:57 mrgutsy dovecot: imap-login: Login: user=<invalid@noway2.net>, method=PLAIN, rip=96.10.215.210, lip=96.10.215.210, TLS
Jan  9 08:12:57 mrgutsy dovecot: IMAP(invalid@noway2.net): Disconnected: Logged out bytes=71/469
Jan  9 08:13:04 mrgutsy dovecot: pop3-login: Login: user=<invalid@noway2.net>, method=PLAIN, rip=96.10.215.211, lip=96.10.215.210, TLS
Jan  9 08:13:04 mrgutsy dovecot: POP3(invalid@noway2.net): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0
~

carlosinfl · 01-10-2011, 10:05 AM

Quote:

Originally Posted by Noway2

You may want to turn on debugging in Dovecot.

I'm a little confused because Dovecot (IMAP4) is working perfect from both Thunderbird and Webmail (RoundCube) so I would think I would want to debug Postfix for SMTP issues from my web server's incoming IP (192.168.0.201) and not Dovecot, right?

I enabled debugging on Postfix for the 192.168.0.201 IP only and when I try to send email from RoundCube, below is what I get:

Code:

Jan 10 10:58:24 mail postfix/smtpd[3327]: connect from www.iamghost.com[192.168.0.201]
Jan 10 10:58:24 mail postfix/smtpd[3327]: match_hostname: www.iamghost.com ~? 127.0.0.0/8
Jan 10 10:58:24 mail postfix/smtpd[3327]: match_hostaddr: 192.168.0.201 ~? 127.0.0.0/8
Jan 10 10:58:24 mail postfix/smtpd[3327]: match_hostname: www.iamghost.com ~? 192.168.0.0/24
Jan 10 10:58:24 mail postfix/smtpd[3327]: match_hostaddr: 192.168.0.201 ~? 192.168.0.0/24
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 220 mail.iamghost.com ESMTP Postfix
Jan 10 10:58:24 mail postfix/smtpd[3327]: watchdog_pat: 0xfbdcf0
Jan 10 10:58:24 mail postfix/smtpd[3327]: < www.iamghost.com[192.168.0.201]: EHLO www.iamghost.com
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 250-mail.iamghost.com
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 250-PIPELINING
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 250-SIZE 20480000
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 250-VRFY
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 250-ETRN
Jan 10 10:58:24 mail postfix/smtpd[3327]: match_list_match: www.iamghost.com: no match
Jan 10 10:58:24 mail postfix/smtpd[3327]: match_list_match: 192.168.0.201: no match
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 250-STARTTLS
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 250-ENHANCEDSTATUSCODES
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 250-8BITMIME
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 250 DSN
Jan 10 10:58:24 mail postfix/smtpd[3327]: watchdog_pat: 0xfbdcf0
Jan 10 10:58:24 mail postfix/smtpd[3327]: < www.iamghost.com[192.168.0.201]: STARTTLS
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 220 2.0.0 Ready to start TLS
Jan 10 10:58:24 mail postfix/smtpd[3327]: setting up TLS connection from www.iamghost.com[192.168.0.201]
Jan 10 10:58:24 mail postfix/smtpd[3327]: send attr request = seed
Jan 10 10:58:24 mail postfix/smtpd[3327]: send attr size = 32
Jan 10 10:58:24 mail postfix/smtpd[3327]: private/tlsmgr: wanted attribute: status
Jan 10 10:58:24 mail postfix/smtpd[3327]: input attribute name: status
Jan 10 10:58:24 mail postfix/smtpd[3327]: input attribute value: 0
Jan 10 10:58:24 mail postfix/smtpd[3327]: private/tlsmgr: wanted attribute: seed
Jan 10 10:58:24 mail postfix/smtpd[3327]: input attribute name: seed
Jan 10 10:58:24 mail postfix/smtpd[3327]: input attribute value: Tnsb0ltCEsdgdgfhgjghmjddvfQ/sYHNRjg=
Jan 10 10:58:24 mail postfix/smtpd[3327]: private/tlsmgr: wanted attribute: (list terminator)
Jan 10 10:58:24 mail postfix/smtpd[3327]: input attribute name: (end)
Jan 10 10:58:24 mail postfix/smtpd[3327]: Anonymous TLS connection established from www.iamghost.com[192.168.0.201]: TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)
Jan 10 10:58:24 mail postfix/smtpd[3327]: watchdog_pat: 0xfbdcf0
Jan 10 10:58:24 mail postfix/smtpd[3327]: < www.iamghost.com[192.168.0.201]: EHLO www.iamghost.com
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 250-mail.iamghost.com
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 250-PIPELINING
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 250-SIZE 20480000
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 250-VRFY
Jan 10 10:58:24 mail postfix/smtpd[3327]: match_list_match: www.iamghost.com: no match
Jan 10 10:58:24 mail postfix/smtpd[3327]: match_list_match: 192.168.0.201: no match
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 250-ETRN
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 250-ENHANCEDSTATUSCODES
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 250-8BITMIME
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 250 DSN
Jan 10 10:58:24 mail postfix/smtpd[3327]: watchdog_pat: 0xfbdcf0
Jan 10 10:58:24 mail postfix/smtpd[3327]: < www.iamghost.com[192.168.0.201]: RSET
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 250 2.0.0 Ok
Jan 10 10:58:24 mail postfix/smtpd[3327]: watchdog_pat: 0xfbdcf0
Jan 10 10:58:24 mail postfix/smtpd[3327]: < www.iamghost.com[192.168.0.201]: QUIT
Jan 10 10:58:24 mail postfix/smtpd[3327]: > www.iamghost.com[192.168.0.201]: 221 2.0.0 Bye
Jan 10 10:58:24 mail postfix/smtpd[3327]: match_hostname: www.iamghost.com ~? 127.0.0.0/8
Jan 10 10:58:24 mail postfix/smtpd[3327]: match_hostaddr: 192.168.0.201 ~? 127.0.0.0/8
Jan 10 10:58:24 mail postfix/smtpd[3327]: match_hostname: www.iamghost.com ~? 192.168.0.0/24
Jan 10 10:58:24 mail postfix/smtpd[3327]: match_hostaddr: 192.168.0.201 ~? 192.168.0.0/24
Jan 10 10:58:24 mail dovecot: imap(carlos): Disconnected: Logged out bytes=12/341
Jan 10 10:58:24 mail postfix/smtpd[3327]: disconnect from www.iamghost.com[192.168.0.201]

Does this explain anything for anyone? I'm curious if I disable TLS on Postfix, would I then be able to send mail or would it still fail? I need to research the 'noanonymous' entry and see if that works or doesn't but from the logs above, it looks like a DNS issue and still not TLS related, right? Thoughts?

carlosinfl · 01-11-2011, 02:07 PM

Anyone?

okovalchuk · 01-11-2011, 11:51 PM

Crazy question: is permit_mynetworks listed in "smtpd_recipient_restrictions ="?

Noway2 · 01-12-2011, 03:49 AM

Take a look a this discussion thread. I am not sure if it is the same problem you are having, but on the surface at least, it seems to match the symptoms. The thread summary is that they had a timing issue with the DNS that caused a lot of 'no match' statements like in your log, followed by a disconnection due to the timeout. It might make a good test case to relax the some of your recipient / sender restrictions based upon this information. In essence, yes, I agree that it looks like it may be a DNS issue.

Also, the reason I mentioned dovecot debugging is because my initial thought was that you were having an authentication issue with Roundcube mail. This could be caused by things like messed up hashing (e.g. different salt values) that cause passwords to not match or picking up the wrong part of the username.domain string. I now doubt it will help in this case, but it is good to know in case you need this feature.

carlosinfl · 01-12-2011, 07:53 AM

Quote:

Originally Posted by okovalchuk

Crazy question: is permit_mynetworks listed in "smtpd_recipient_restrictions ="?

Yes it is:

Code:

[root@mail postfix]# postconf -n | grep -i "mynetworks"
mynetworks = $config_directory/mynetworks
smtpd_recipient_restrictions = permit_mynetworks,	reject_unauth_destination,	reject_non_fqdn_recipient,   	reject_unknown_recipient_domain,   	reject_non_fqdn_helo_hostname,   	reject_invalid_helo_hostname,	reject_rbl_client zen.spamhaus.org,   	reject_rbl_client bl.spamcop.net,	check_client_access             hash:/etc/postfix/client_access
smtpd_sender_restrictions = permit_mynetworks