SMTP errors with iOS devices

emailiosiphonesmtp

I'm trying to diagnose why when an iOS device like an iPhone or iPad is set up to use email with our server for the first time, these errors occur. We choose "Other" from the initial set of choices for provider in setting up the account. You can see the connection transaction below after putting in the IMAP and SMTP server names. 69.197.220.11 is the address of the phone. We run CommuniGate Pro 6.0.10.

  • What are the errors in the log from 10:06:40.691 to 10:06:40.723?

  • What is the address listed at time 10:06:51.067 (10.33.64.161)?

The errors do not occur when setting up IMAP/SMTP on a Macbook (Mail) or PC (Outlook, Thunderbird), or Linux, or with the one Android device I've been able to test with. The protocol errors end up causing the iOS device's IP address to be blacklisted by the email server.

System log follows:

10:06:40.688 5 SMTP [0.0.0.0]:587 <- [69.197.220.11]:49426 connection request. socket=191
10:06:40.688 5 SMTP new VStream created, 1 total
10:06:40.688 5 SMTP stream thread started
10:06:40.688 4 SMTPI-011473([69.197.220.11]) [192.168.200.100]:587 <- [69.197.220.11]:49426 incoming connection(our domain.net)
10:06:40.688 5 SMTPI-011473([69.197.220.11]) out: 220 ourdomain.net ESMTP CommuniGate Pro 6.0.10\r\n
10:06:40.691 5 SMTPI-011473([69.197.220.11]) inp: \022\003\001
10:06:42.693 5 SMTPI-011473([69.197.220.11]) out: 501 Unknown command\r\n
10:06:42.693 5 SMTPI-011473([69.197.220.11]) inp: \163\001
10:06:44.696 5 SMTPI-011473([69.197.220.11]) out: 501 Unknown command\r\n
10:06:44.696 5 SMTPI-011473([69.197.220.11]) inp:
10:06:46.698 5 SMTPI-011473([69.197.220.11]) out: 501 Unknown command\r\n
10:06:46.698 5 SMTPI-011473([69.197.220.11]) inp: \159\003\001T\135 l
10:06:48.700 5 SMTPI-011473([69.197.220.11]) out: 501 Unknown command\r\n
10:06:48.700 5 SMTPI-011473([69.197.220.11]) inp: \004\225\176d2\217\180\005"]\167\176\182\131N&\183\175\218\167\200\167\245\003\246\005\221
10:06:50.702 5 SMTPI-011473([69.197.220.11]) out: 501 Unknown command\r\n
10:06:50.702 1 SMTPI-011473([69.197.220.11]) Too many protocol errors, aborting
10:06:50.723 4 SMTPI-011473([69.197.220.11]) closing connection
10:06:50.723 4 SMTPI-011473([69.197.220.11]) releasing stream
10:06:50.966 5 SMTP [0.0.0.0]:587 <- [69.197.220.11]:49427 connection request. socket=214
10:06:50.966 4 SMTPI-011474([69.197.220.11]) [192.168.200.100]:587 <- [69.197.220.11]:49427 incoming connection(ourdomain.net)
10:06:50.966 5 SMTPI-011474([69.197.220.11]) out: 220 ourdomain.net ESMTP CommuniGate Pro 6.0.10\r\n
10:06:51.067 5 SMTPI-011474([69.197.220.11]) inp: EHLO [10.233.64.161]
10:06:51.067 5 SMTPI-011474([69.197.220.11]) out: 250-ourdomain.net your name is not [10.233.64.161]\r\n250-DSN\r\n250-SIZE\r\n250-STARTTLS\r\n250-AUTH LOGIN PLAIN CRAM-MD5 GSSAPI\r\n250-ETRN\r\n250-TURN\r\n250-ATRN\r\n250-NO-SOLICITING\r\n250-8BITMIME\r\n250-HELP\r\n250-PIPELINING\r\n250 EHLO\r\n
10:06:51.165 5 SMTPI-011474([69.197.220.11]) inp: STARTTLS
10:06:51.165 5 SMTPI-011474([69.197.220.11]) out: 220 please start a TLS connection\r\n
10:06:51.549 4 SMTPI-011474([69.197.220.11]) TLSv1.0 security initiated
10:06:51.635 4 SMTPI-011474([69.197.220.11]) TLS-102107(AES256_SHA) connection accepted for 'ourdomain.net'
10:06:51.865 5 SMTPI-011474([69.197.220.11]) s-inp: EHLO [10.233.64.161]
10:06:51.865 5 SMTPI-011474([69.197.220.11]) s-out: 250-ourdomain.net your name is not [10.233.64.161]\r\n250-DSN\r\n250-SIZE\r\n250-AUTH LOGIN PLAIN CRAM-MD5 GSSAPI\r\n250-ETRN\r\n250-TURN\r\n250-ATRN\r\n250-NO-SOLICITING\r\n250-8BITMIME\r\n250-HELP\r\n250-PIPELINING\r\n250 EHLO\r\n
10:06:51.976 5 SMTPI-011474([69.197.220.11]) s-inp: AUTH PLAIN AGZ1ZGRsZXMAMWJpZ2RvZw==
10:06:51.976 5 SMTPI-011474([69.197.220.11]) SASL(PLAIN) ini: \000fuddles\0001bigdog\000
10:06:51.977 2 SMTPI-011474([69.197.220.11]) 'fuddles@ourdomain.net' connected(CLRTXT) [69.197.220.11]:49427->[192.168.200.100]:587(tls)
10:06:51.977 2 SMTPI-011474([69.197.220.11]) 'fuddles@ourdomain.net' disconnected ([69.197.220.11]:49427)
10:06:51.977 2 SMTPI-011474([69.197.220.11]) authenticated as fuddles@ourdomain.net
10:06:51.977 5 SMTPI-011474([69.197.220.11]) s-out: 235 fuddles@ourdomain.net relaying authenticated\r\n
10:06:52.086 5 SMTPI-011474([69.197.220.11]) s-inp: QUIT
10:06:52.086 5 SMTPI-011474([69.197.220.11]) s-out: 221 ourdomain.net CommuniGate Pro SMTP closing connection\r\n
10:06:52.086 4 SMTPI-011474([69.197.220.11]) TLS connection is closing
10:06:52.086 4 SMTPI-011474([69.197.220.11]) closing connection
10:06:52.086 4 SMTPI-011474([69.197.220.11]) releasing stream

Best Answer

What are the errors in the log from 10:06:40.691 to 10:06:40.723?

Line

10:06:40.691 5 SMTPI-011473([69.197.220.11]) inp: \022\003\001

was part of SSL handshake.

  • Byte 0 = 022 means SSL record type = 22 (SSL3_RT_HANDSHAKE)
  • Byte 1-2 = 0301 was means SSL version = TLS1_VERSION

See this page for reference.

But unfortunately the server on port 587 doesn't talk with SSL (SMTPS), but with STARTTLS. Server with STARTTLS expect that initial connection will sits in unencrypted channel then move to encrypted channel.

So, at initial the IOS attempted to connect with SMTPS (SMTP on top SSL protocol). But the server doesn't understand it, so it give warning Unknown command until some limits then disconnect the client.

Because the initial connection rejected, IOS do fallback action and connect again to the server with STARTTLS.

10:06:51.165 5 SMTPI-011474([69.197.220.11]) inp: STARTTLS

In this case, iOS successfully connect to server.

What is the address listed at time 10:06:51.067 (10.33.64.161)?

IP Address 10.33.64.161 seems to be IP Address from Internet Provider. Usually client will announce HELO <something> with <something> is IP address/hostname of the computer/handphone

iOS Behaviour

As I've never used IOS, so I can't tell you what iOS setting that caused this behaviour (or maybe this is default iOS behaviour). In your case, intended behaviour is directly connect via STARTSSL, bypassing SMTPS attempt so it won't be rejected and blacklisted again.

In comment, BillThor confirmed that above behavior was iOS's default behaviour.

IOS defaults to SSL (secure connection) and then offers to connect insecurely if that fails. After the SSL connection fails the user is given the option to connect insecurely. If STARTTLS is available, it is used. The activities involved in the connection discovery are being logged by the server.

Solution

The obvious solution is configure the mail server - CommuniGate Pro -, so it won't blacklist the client who behave like this. The behaviour should not be considered a failure, and should not get the device blacklisted either.

Workaround from OP

The settings for the protocol error threshold and getting blacklisted are in Settings-> Mail -> SMTP -> Receiving -> Limits. The default is Disconnect after 20 errors and Deny access for 15 minutes. I've changed mine to Disconnect after 100 errors and Deny access for 0 seconds. Not sure about the 0 seconds but it has resolved the problems with initial setup of IMAP accounts on iOS devices with our CommuniGate Pro server.

Related Topic