1

I think I have opportunistic TLS configured correctly in postfix but it seemingly never chooses to actually use TLS. It always falls back to an unencrypted connection and gives me no indication as to why.

Here is the relevant configuration for postfix:

smtp_tls_CAfile=/etc/pki/tls/certs/ca-bundle.crt
smtp_tls_security_level = may
smtp_tls_loglevel = 4
smtp_tls_session_cache_database = btree:/var/lib/postfix/smtp_scache

I'm not sure if it matters but this postfix instance is not the origin email server, the emails are relayed to this instance, and the relay is intentionally not encrypted (i.e. I have not set smtpd_tls_security_level on this instance).

Here is the log output after sending an email to a gmail account (I've redacted some info). I'm expecting to see more information about the TLS connection. It's a little confusing because there are two instances of postfix running on this one machine, one that is bound to 127.0.0.1 and relays to the other which is bound on a virtual IP 10.0.1.13; they both log to the same file so you have to do a bit of deciphering:

Jul 30 15:26:10 mail01-prd postfix/smtpd[3479]: connect from localhost[127.0.0.1]
Jul 30 15:26:10 mail01-prd postfix/smtpd[3479]: 2220221EB6B8: client=localhost[127.0.0.1]
Jul 30 15:26:10 mail01-prd postfix/cleanup[3482]: 2220221EB6B8: message-id=<800049941.22.1532985970098@mail01-prd.mydomain.local>
Jul 30 15:26:10 mail01-prd postfix/qmgr[10017]: 2220221EB6B8: from=<lands@mydomain.com>, size=492, nrcpt=1 (queue active)
Jul 30 15:26:10 mail01-prd postfix/smtpd[3479]: disconnect from localhost[127.0.0.1]
Jul 30 15:26:10 mail01-prd postfix/smtpd[3256]: connect from mail01-prd.mydomain.local[10.0.2.45]
Jul 30 15:26:10 mail01-prd postfix/smtpd[3256]: 2865A40C505D: client=mail01-prd.mydomain.local[10.0.2.45]
Jul 30 15:26:10 mail01-prd postfix/cleanup[3484]: 2865A40C505D: message-id=<800049941.22.1532985970098@mail01-prd.mydomain.local>
Jul 30 15:26:10 mail01-prd postfix/smtpd[3256]: disconnect from mail01-prd.mydomain.local[10.0.2.45]
Jul 30 15:26:10 mail01-prd postfix/smtp[3483]: 2220221EB6B8: to=<redacted.recipient@gmail.com>, relay=mail.mydomain.local[10.0.1.13]:25, delay=0.05, delays=0.01/0.01/0/0.03, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 2865A40C505D)
Jul 30 15:26:10 mail01-prd postfix/qmgr[3131]: 2865A40C505D: from=<lands@mydomain.com>, size=704, nrcpt=1 (queue active)
Jul 30 15:26:10 mail01-prd postfix/qmgr[10017]: 2220221EB6B8: removed
Jul 30 15:26:10 mail01-prd postfix/smtp[3486]: initializing the client-side TLS engine
Jul 30 15:26:10 mail01-prd postfix/smtp[3486]: 2865A40C505D: to=<redacted.recipient@gmail.com>, relay=gmail-smtp-in.l.google.com[74.125.195.26]:25, delay=0.36, delays=0.03/0.02/0.08/0.23, dsn=2.0.0, status=sent (250 2.0.0 OK 1532985970 e9-v6si12074342pgg.330 - gsmtp)
Jul 30 15:26:10 mail01-prd postfix/qmgr[3131]: 2865A40C505D: removed

Here is the email with headers that is received by gmail (host/ip/recipient names redacted):

Delivered-To: redacted.recipient@gmail.com
Received: by 2002:a4a:cb81:0:0:0:0:0 with SMTP id y1-v6csp4285688ooq;
        Mon, 30 Jul 2018 14:26:10 -0700 (PDT)
X-Google-Smtp-Source: AAOMgpciN/INPuQuWD82OjqCJbrXEYhn9T0oHqorMQRg7EiQ0FqrPrW4jb/Stjic14k9+BnU1kQ1
X-Received: by 2002:a63:bf08:: with SMTP id v8-v6mr17488862pgf.3.1532985970510;
        Mon, 30 Jul 2018 14:26:10 -0700 (PDT)
ARC-Seal: i=1; a=rsa-sha256; t=1532985970; cv=none;
        d=google.com; s=arc-20160816;
        b=Sl6ChvN8Nm3nhPipdoM5ODedUNXx4la4LKx31fCB8RDoC7PW5sREdnQIV4trnoZ6rW
         1yBSwiqjxGJ00yzQolcCtKrlv2YEnVaXW06fFpHdCWr3LMRDQSDIsWzfX76iejvy2JOD
         Y7lYwtQ3TYMGZhd97WvCABK1WrMONPIOeqYvwvfKr87znBkuPYQ/N+pntAcqzFJlLueG
         sgXr+TpJVHd82f72NbdGh1mv8wsEE4IXLlGjnujtNurnXEc93kBf7eQuQTnkV41aElAT
         drvXrtqSMhunbmODv7u2VexnluHnjlgOBwo96SrCboWr/sKoQU6P5uH3ZJqLVfNlIC8N
         0D+A==
ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816;
        h=from:content-transfer-encoding:mime-version:subject:message-id:to
         :date:arc-authentication-results;
        bh=g3zLYH4xKxcPrHOD18z9YfpQcnk/GaJedfustWU5uGs=;
        b=Ovql6aUsRnD1conm5UblwcOCwt4AQ9uOdnSqX1HoqqwT34OO0GhJLTdh2B2oX799oU
         GlrIaQaiDMGagHXxz8AYWv27G9gC0QR39pYXNAxERYLmTkpDDxkTmIPfDeRkoj2PBauh
         zyzZGOsx7E+xI7MBohxetxiy0ymlXTBsE5Y4LpnL51Z31yPVtQw2fh/ATBqnlNYOKUGP
         w1NvSgLpYQBJPz0nNlnYigFhwRhjTOS2YfZjWND4fyV3QTTDUpQS64Lu9uLjN/DLldFi
         jIP0ONSPNv4NzQocPgyu4UaAVbU9h7W274F8F30vOWbL35qdP/LabrjQ3jus29kKsY8m
         7IFw==
ARC-Authentication-Results: i=1; mx.google.com;
       spf=pass (google.com: domain of lands@mydomain.com designates 1.2.3.4 as permitted sender) smtp.mailfrom=lands@mydomain.com
Return-Path: <lands@mydomain.com>
Received: from mail.mydomain.com (mail.mydomain.com. [1.2.3.4])
        by mx.google.com with ESMTP id e9-v6si12074342pgg.330.2018.07.30.14.26.10
        for <redacted.recipient@gmail.com>;
        Mon, 30 Jul 2018 14:26:10 -0700 (PDT)
Received-SPF: pass (google.com: domain of lands@mydomain.com designates 1.2.3.4 as permitted sender) client-ip=1.2.3.4;
Authentication-Results: mx.google.com;
       spf=pass (google.com: domain of lands@mydomain.com designates 1.2.3.4 as permitted sender) smtp.mailfrom=lands@mydomain.com
Received: from mail01-prd.mydomain.local (mail01-prd.mydomain.local [10.0.2.45]) by mail.mydomain.com (Postfix) with ESMTP id 2865A40C505D for <redacted.recipient@gmail.com>; Mon, 30 Jul 2018 15:26:10 -0600 (MDT)
Received: from mail01-prd.mydomain.local (localhost [127.0.0.1]) by mail01-prd.mydomain.local (Postfix) with ESMTP id 2220221EB6B8 for <redacted.recipient@gmail.com>; Mon, 30 Jul 2018 15:26:10 -0600 (MDT)
Date: Mon, 30 Jul 2018 15:26:10 -0600 (MDT)
To: redacted.recipient@gmail.com
Message-ID: <800049941.22.1532985970098@mail01-prd.mydomain.local>
Subject: ssl 4
MIME-Version: 1.0
Content-Type: text/html; charset=us-ascii
Content-Transfer-Encoding: 7bit
From: lands@mydomain.com

test

The postfix version is 2.10.1 running on CentOS 7.2.1511, selinux is disabled, and firewalld is not running. The network firewall is configured to allow outgoing connections on ports 25, 465, and 587.

Gmail displays the red icon indicating that it wasn't encrypted and the CheckTLS service also reports that it isn't encrypted using TLS.

Nothing significant showing up in /var/log/messages or /var/log/audit/audit.log.

Any ideas?


Update 2018-07-31:

I can successfully send a non-encrypted message using telnet/smtp:

[root@mail01-prd ~]# telnet -b 10.0.1.13 gmail-smtp-in.l.google.com 25
Trying 74.125.195.27...
Connected to gmail-smtp-in.l.google.com.
Escape character is '^]'.
220 mx.google.com ESMTP d38-v6si13528460pla.422 - gsmtp
EHLO mydomain.com
250-mx.google.com at your service, [204.191.254.74]
250 SIZE 157286400
MAIL FROM:redacted.sender@mydomain.com
250 2.1.0 OK d38-v6si13528460pla.422 - gsmtp
RCPT TO:redacted.recipient@gmail.com
250 2.1.5 OK d38-v6si13528460pla.422 - gsmtp
DATA
354 Start mail input; end with <CRLF>.<CRLF>
From: redacted.recipient@mydomain.com
Subject: Test

Test
.
250 2.0.0 OK 1533054157 d38-v6si13528460pla.422 - gsmtp

But I'm unable to establish a STARTTLS connection on this port:

[root@mail01-prd ~]# openssl s_client -debug -starttls smtp -crlf -connect gmail-smtp-in.l.google.com:25
CONNECTED(00000003)
read from 0xaaeb30 [0xaf4540] (4096 bytes => 55 (0x37))
0000 - 32 32 30 20 6d 78 2e 67-6f 6f 67 6c 65 2e 63 6f   220 mx.google.co
0010 - 6d 20 45 53 4d 54 50 20-6f 36 2d 76 36 73 69 38   m ESMTP o6-v6si8
0020 - 36 34 39 31 37 39 70 6c-68 2e 32 32 36 20 2d 20   649179plh.226 - 
0030 - 67 73 6d 74 70 0d 0a                              gsmtp..
write to 0xaaeb30 [0xaf5550] (25 bytes => 25 (0x19))
0000 - 45 48 4c 4f 20 6f 70 65-6e 73 73 6c 2e 63 6c 69   EHLO openssl.cli
0010 - 65 6e 74 2e 6e 65 74 0d-0a                        ent.net..
read from 0xaaeb30 [0xaf4540] (4096 bytes => 73 (0x49))
0000 - 32 35 30 2d 6d 78 2e 67-6f 6f 67 6c 65 2e 63 6f   250-mx.google.co
0010 - 6d 20 61 74 20 79 6f 75-72 20 73 65 72 76 69 63   m at your servic
0020 - 65 2c 20 5b 32 30 34 2e-31 39 31 2e 32 35 34 2e   e, [204.191.254.
0030 - 37 34 5d 0d 0a 32 35 30-20 53 49 5a 45 20 31 35   74]..250 SIZE 15
0040 - 37 32 38 36 34 30 30 0d-0a                        7286400..
didn't found starttls in server response, try anyway...
write to 0xaaeb30 [0x7ffef414dfc0] (10 bytes => 10 (0xA))
0000 - 53 54 41 52 54 54 4c 53-0d 0a                     STARTTLS..
read from 0xaaeb30 [0x9e2e20] (8192 bytes => 40 (0x28))
0000 - 35 30 30 20 53 79 6e 74-61 78 20 65 72 72 6f 72   500 Syntax error
0010 - 2c 20 63 6f 6d 6d 61 6e-64 20 75 6e 72 65 63 6f   , command unreco
0020 - 67 6e 69 7a 65 64 0d 0a-                          gnized..
write to 0xaaeb30 [0xaf44c0] (289 bytes => 289 (0x121))
0000 - 16 03 01 01 1c 01 00 01-18 03 03 31 d6 0a a9 f9   ...........1....
0010 - 56 55 0c cd 05 8e 02 16-a9 01 f0 78 a2 f9 4b c7   VU.........x..K.
0020 - f4 03 e3 49 1f f3 f1 1a-56 3a 1c 00 00 ac c0 30   ...I....V:.....0
0030 - c0 2c c0 28 c0 24 c0 14-c0 0a 00 a5 00 a3 00 a1   .,.(.$..........
0040 - 00 9f 00 6b 00 6a 00 69-00 68 00 39 00 38 00 37   ...k.j.i.h.9.8.7
0050 - 00 36 00 88 00 87 00 86-00 85 c0 32 c0 2e c0 2a   .6.........2...*
0060 - c0 26 c0 0f c0 05 00 9d-00 3d 00 35 00 84 c0 2f   .&.......=.5.../
0070 - c0 2b c0 27 c0 23 c0 13-c0 09 00 a4 00 a2 00 a0   .+.'.#..........
0080 - 00 9e 00 67 00 40 00 3f-00 3e 00 33 00 32 00 31   ...g.@.?.>.3.2.1
0090 - 00 30 00 9a 00 99 00 98-00 97 00 45 00 44 00 43   .0.........E.D.C
00a0 - 00 42 c0 31 c0 2d c0 29-c0 25 c0 0e c0 04 00 9c   .B.1.-.).%......
00b0 - 00 3c 00 2f 00 96 00 41-c0 12 c0 08 00 16 00 13   .<./...A........
00c0 - 00 10 00 0d c0 0d c0 03-00 0a 00 07 c0 11 c0 07   ................
00d0 - c0 0c c0 02 00 05 00 04-00 ff 01 00 00 43 00 0b   .............C..
00e0 - 00 04 03 00 01 02 00 0a-00 0a 00 08 00 17 00 19   ................
00f0 - 00 18 00 16 00 23 00 00-00 0d 00 20 00 1e 06 01   .....#..... ....
0100 - 06 02 06 03 05 01 05 02-05 03 04 01 04 02 04 03   ................
0110 - 03 01 03 02 03 03 02 01-02 02 02 03 00 0f 00 01   ................
0120 - 01

I'm assuming I've done something wrong there, I just haven't figured out what it is yet.

mbosecke
  • 121
  • 5
  • That's a little strange. The mail didn't come in to Gmail encrypted. Have you tried updating the system? It's been almost three years, after all. – Michael Hampton Jul 30 '18 at 21:44
  • While you're at it, what is this "network firewall"? Your Postfix config seems correct. Aside from the advice to get your horribly out of date system updated, I would suggest looking at external factors. Is this so-called network firewall intercepting outgoing SMTP connections? How about your ISP? – Michael Hampton Jul 30 '18 at 22:00
  • Yeah that's exactly the issue; the connection between my server and google is inexplicably neglecting to use TLS . I'll upgrade postfix if I run out of other options but I couldn't find anything in the postfix changelog to imply that upgrading will solve this problem. Also, I'm running the latest version supported by CentOS 7 so I'd have to upgrade using a third-party repo which comes with risk that I'd like to avoid. – mbosecke Jul 30 '18 at 22:15
  • We have a firewall between our internal network and the internet; we're using Untangle software. It is capable of reading/intercepting/blocking outgoing SMTP connections but I'm not finding any evidence that it is interfering here. – mbosecke Jul 30 '18 at 22:17
  • You mean aside from the fact that you can't make an outgoing STARTTLS connection? That's plenty of evidence. Better look at that Untangle box. And I was referring to CentOS 7 updates, which you appear to not have installed in almost three years. You should be on CentOS 7.5... – Michael Hampton Jul 31 '18 at 12:06
  • You're coming across as a little argumentative, I'm not sure if you're intending to or not... Are you familiar of a way to debug the STARTTLS issue through postfix? I assumed setting the log level to 4 would help. Or any other concrete tips that may help (besides upgrading, I take that advice to heart, cheers). – mbosecke Jul 31 '18 at 14:36
  • [Setting the loglevel to 4](https://serverfault.com/a/419829/126632) is the way to do it. I'm not sure why you think I'm being argumentative. I'm only making suggestions based on _a lot_ of experience. You're free to reject them, but that might just delay solving the problem if it turns out one of them would have led you to the cause. – Michael Hampton Jul 31 '18 at 14:41
  • I'm not rejecting your advice. I appreciate it. I'll just keep looking I guess – mbosecke Jul 31 '18 at 14:46
  • So what happens if you get on the server and run `nc gmail-smtp-in.l.google.com 25` and then send it `EHLO yourhostname`? – Michael Hampton Jul 31 '18 at 15:10
  • I've edited the question to include outputs from manually connecting to google's smtp servers. I didn't even think to do that; I'm going to continue investigating down this path. – mbosecke Jul 31 '18 at 16:28
  • Ooooo, that's interesting. There's a whole lot of stuff missing from the EHLO response. And the `500 Syntax error, command unrecognized` looks fake. A real syntax error from a real Google mail server looks like `502 5.5.1 Unrecognized command. t80-v6si4919581qkt.159 - gsmtp`. I'm pretty convinced at this point that something is intercepting your traffic. Are you sure you checked the Untangle box? – Michael Hampton Jul 31 '18 at 16:35
  • From a quick search on that message, I found [this ancient post](https://forums.untangle.com/spam-blocker-lite/11872-telnet-smtp-session-ehlo-helo-500-syntax-error.html) from the Untangle forums which suggests that it is rewriting SMTP traffic transparently, in particular altering the EHLO command (which is what we see here). At the moment the Untangle firewall should be your prime suspect. – Michael Hampton Jul 31 '18 at 16:44
  • THANK YOU. It was in fact untangle that was secretly rewriting it and not actually logging this behavior in any way. After adding some extra bypass rules into untangle everything started working correctly. Feel free to answer this question for some sweet points, otherwise I'll answer it myself. – mbosecke Jul 31 '18 at 16:47
  • I've got plenty of points. Feel free to write up your own answer. :) – Michael Hampton Jul 31 '18 at 16:50

1 Answers1

1

It turns out it was Untangle that was actively rewriting the SMTP commands to prevent a TLS connection from being established. This became clear after telneting directly to google's SMTP server and finding out that it wasn't responding to the EHLO command with an offer for STARTTLS (because Untangle stripped it away).

I followed the instructions here:

https://forums.untangle.com/spam-blocker-lite/34567-smtp-block-starttls.html

Essentially going to Config -> networking -> bypass rules and adding an extra rule to prevent it from inspecting SMTP data.

mbosecke
  • 121
  • 5