Postfix unable to receive from Gmail?

[poorangus]

Hello,

Under Ubuntu 12.04 LTS, Postfix receives all mail 100% of the time from every service, except Gmail. I have researched this problem extensively but so far have come up empty.

This is what gets written to mail.log when GMail tries to deliver the email:

May 17 10:23:29 myhostname postfix/smtpd[3547]: connect from mail-pb0-f51.google.com[209.85.160.51]
May 17 10:23:29 myhostname postfix/smtpd[3547]: warning: TLS library problem: 3547:error:140943FC:SSL routines:SSL3_READ_BYTES:sslv3 alert bad record mac:s3_pkt.c:1247:SSL alert number 20:
May 17 10:23:29 myhostname postfix/smtpd[3547]: lost connection after EHLO from mail-pb0-f51.google.com[209.85.160.51]
May 17 10:23:29 myhostname postfix/smtpd[3547]: disconnect from mail-pb0-f51.google.com[209.85.160.51]

The connection is being dropped immediately. I'm concerned about the "TLS library problem" but don't know how much this has to do with this particular issue. Any guidance would be appreciated, thanks.

EDIT: It should also be noted that mail sent through GMail's web interface is delivered as expected. Only email sent from an email client using Gmail's SMTP server has this issue. Bizarre.

[lambart]

Having same problems here... exact same error messages BUT for me even mails sent from gmail.com don't work.

I'm still investigating... will post fix here when I figure it out.

Eric

[lisati]

Looks like some kind of SSL (or possibly TLS) error to me. My best guess at the momemnt might be to check your SSL settings.

[poorangus]

Anything specific I should check for? The setup process handles that area of the configuration fairly automatically..

[lambart]

Some research.... no solution yet.

Got as far as to confirm (unsurprisingly) it's not actually limited to google/gmail. It appears to be the cipher type (@poorangus, did you leave out the log line starting with "Anonymous TLS connection established..."?)

From who-knows-who:

May 15 05:47:12 myhostname postfix/smtpd[1366]: Anonymous TLS connection established from unknown[209.85.213.47]: TLSv1 with cipher RC4-MD5 (128/128 bits)
May 15 05:47:12 myhostname postfix/smtpd[1366]: warning: TLS library problem: 1366:error:140943FC:SSL routines:SSL3_READ_BYTES:sslv3 alert bad record mac:s3_pkt.c:1247:SSL alert number 20:
May 15 05:47:12 myhostname postfix/smtpd[1366]: lost connection after EHLO from unknown[209.85.213.47]


From google:
May 15 05:53:37 myhostname postfix/smtpd[1675]: Anonymous TLS connection established from unknown[209.85.213.47]: TLSv1 with cipher RC4-MD5 (128/128 bits)
May 15 05:53:37 myhostname postfix/smtpd[1675]: warning: TLS library problem: 1675:error:140943FC:SSL routines:SSL3_READ_BYTES:sslv3 alert bad record mac:s3_pkt.c:1247:SSL alert number 20:
May 15 05:53:37 myhostname postfix/smtpd[1675]: lost connection after EHLO from unknown[209.85.213.47]

TLS connections using with other ciphers including DHE-RSA-AES256-SHA (256/256 bits), ECDHE-RSA-RC4-SHA (128/128 bits) and RC4-SHA (among others, probably) seem to work. mail-*.google.com usually uses RC4-MD5 (always causing a warning/lost collection), but sometimes uses ECDHE-RSA-RC4-SHA (128/128 bits) --maybe that's why you are getting some messages through, @poorangus?

[lambart]

I don't mean to be hijacking your thread, @poorangus, but since we seem to be having the same problem I hope we can figure it out together. By setting smtpd_tls_loglevel=2 and waiting for a mail from google.com, I got this, more detailed logging. Not sure if this will help anyone to help us...

May 17 15:43:02 myhostname postfix/smtpd[28328]: initializing the server-side TLS engine
May 17 15:43:02 myhostname postfix/smtpd[28328]: connect from mail-yw0-f47.google.com[209.85.213.47]
May 17 15:43:03 myhostname postfix/smtpd[28328]: setting up TLS connection from mail-yw0-f47.google.com[209.85.213.47]
May 17 15:43:03 myhostname postfix/smtpd[28328]: mail-yw0-f47.google.com[209.85.213.47]: TLS cipher list "aNULL:-aNULL:ALL:+RC4:@STRENGTH"
May 17 15:43:03 myhostname postfix/smtpd[28328]: SSL_accept:before/accept initialization
May 17 15:43:03 myhostname postfix/smtpd[28328]: SSL_accept:SSLv3 read client hello A
May 17 15:43:03 myhostname postfix/smtpd[28328]: SSL_accept:SSLv3 write server hello A
May 17 15:43:03 myhostname postfix/smtpd[28328]: SSL_accept:SSLv3 write certificate A
May 17 15:43:03 myhostname postfix/smtpd[28328]: SSL_accept:SSLv3 write server done A
May 17 15:43:03 myhostname postfix/smtpd[28328]: SSL_accept:SSLv3 flush data
May 17 15:43:03 myhostname postfix/smtpd[28328]: SSL_accept:SSLv3 read client key exchange A
May 17 15:43:03 myhostname postfix/smtpd[28328]: SSL_accept:SSLv3 read finished A
May 17 15:43:03 myhostname postfix/smtpd[28328]: SSL_accept:SSLv3 write change cipher spec A
May 17 15:43:03 myhostname postfix/smtpd[28328]: SSL_accept:SSLv3 write finished A
May 17 15:43:03 myhostname postfix/smtpd[28328]: SSL_accept:SSLv3 flush data
May 17 15:43:03 myhostname postfix/smtpd[28328]: mail-yw0-f47.google.com[209.85.213.47]: save session DC174AEAF16104F9B5ACF53EFD8E242ED70DD37C4957B17780 133B84CE85D295&s=smtp to smtpd cache
May 17 15:43:03 myhostname postfix/tlsmgr[28319]: put smtpd session id=DC174AEAF16104F9B5ACF53EFD8E242ED70DD37C4957B17 780133B84CE85D295&s=smtp [data 127 bytes]
May 17 15:43:03 myhostname postfix/tlsmgr[28319]: write smtpd TLS cache entry DC174AEAF16104F9B5ACF53EFD8E242ED70DD37C4957B17780 133B84CE85D295&s=smtp: time=1337294583 [data 127 bytes]
May 17 15:43:03 myhostname postfix/smtpd[28328]: Anonymous TLS connection established from mail-yw0-f47.google.com[209.85.213.47]: TLSv1 with cipher RC4-MD5 (128/128 bits)
May 17 15:43:03 myhostname postfix/smtpd[28328]: SSL3 alert read:fatal:bad record mac
May 17 15:43:03 myhostname postfix/smtpd[28328]: warning: TLS library problem: 28328:error:140943FC:SSL routines:SSL3_READ_BYTES:sslv3 alert bad record mac:s3_pkt.c:1247:SSL alert number 20:
May 17 15:43:03 myhostname postfix/smtpd[28328]: lost connection after EHLO from mail-yw0-f47.google.com[209.85.213.47]
May 17 15:43:03 myhostname postfix/smtpd[28328]: disconnect from mail-yw0-f47.google.com[209.85.213.47]

[poorangus]

In confirming the absence of "Anonymous TLS connection established...", I initially arrived at DIFFERENT results.

Here's what was written to mail.log:

May 17 15:34:57 myhostname postfix/smtpd[4282]: connect from mail-pz0-f51.google.com[209.85.210.51]
May 17 15:34:57 myhostname postfix/master[3316]: warning: process /usr/lib/postfix/smtpd pid 4282 killed by signal 11
May 17 15:34:57 myhostname postfix/master[3316]: warning: /usr/lib/postfix/smtpd: bad command startup -- throttling

When I tried again, the previous behavior returned:

May 17 15:37:14 myhostname postfix/smtpd[4289]: connect from mail-pz0-f51.google.com[209.85.210.51]
May 17 15:37:14 myhostname postfix/smtpd[4289]: warning: TLS library problem: 4289:error:140943FC:SSL routines:SSL3_READ_BYTES:sslv3 alert bad record mac:s3_pkt.c:1247:SSL alert number 20:
May 17 15:37:14 myhostname postfix/smtpd[4289]: lost connection after EHLO from mail-pz0-f51.google.com[209.85.210.51]
May 17 15:37:14 myhostname postfix/smtpd[4289]: disconnect from mail-pz0-f51.google.com[209.85.210.51]

I'll take a closer look at the ones that are making it through ..

[poorangus]

No worries on the hijack .. though I'm wondering whether we do have the same problem, since you're getting "Anonymous TLS connection established..." and I'm not.

[lambart]

No worries on the hijack .. though I'm wondering whether we do have the same problem, since you're getting "Anonymous TLS connection established..." and I'm not.

I expect that's a result of slightly different postfix configurations, maybe just a difference in logging config? It seems your setup isn't loging the cipher type at all, which certainly seems relevant.

Except for the cert/key/CA file settings, this is everything in my /etc/postfix/main.cf file that is related to TLS:

smtpd_use_tls = yes
smtpd_tls_session_cache_database = btree:${data_directory}/smtpd_scache
smtp_tls_session_cache_database = btree:${data_directory}/smtp_scache

smtp_tls_security_level = may
smtpd_tls_security_level = may
#smtpd_tls_auth_only = yes
smtp_tls_note_starttls_offer = yes
# TODO increase this loglevel if necessary for testing:
smtpd_tls_loglevel = 2
smtpd_tls_received_header = yes
smtpd_tls_session_cache_timeout = 3600s
tls_random_source = dev:/dev/urandom
home_mailbox = Maildir/
smtp_use_tls = yes
smtpd_tls_mandatory_protocols = SSLv3, TLSv1
smtpd_tls_mandatory_ciphers = medium

debug_peer_list = .google.com

That last line isn't TLS-related but I added it to try to debug this issue, and it doesn't appear to be helping at all. Note that the tls_loglevel was originally 1.

[poorangus]

@lambart - I synced my config with yours to make sure I arrived at the same result .. and I do not. To sync, I commented smtpd_tls_auth_only, and added tls_random_source, smtp_tls_security_level, smtpd_tls_security_level, smtp_tls_note_starttls_offer, and tls_random_source, then restarted the service.

Unfortunately this did not affect the behavior