SMTP errors with iOS devices

Question

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

How would we know? The error states `Unknown command`. Do you think that we magically know what `Unknown command` is being sent and is causing the errors? Run a network sniffer on the server so that you can capture the session and try to figure out what the `Unknown command` is. — joeqwerty, Dec 11 '14 at 00:58
I think the lines that say "Inp:" are the commands that the server does not understand, i.e inp: \022\003\001 etc. — Roberto, Dec 11 '14 at 01:05
@joeqwerty Someone obviously managed to magically know what happened... — glglgl, Dec 11 '14 at 07:37

score 8 · Accepted Answer · edited Jun 11 '20 at 10:02

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.

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. These are log messages, not errors. I wouldn't expect this level of detail in a log unless debugging was enabled. I would expect other devices and software to behave the same when discovering the server. — BillThor, Dec 11 '14 at 04:13
@BillThor Thanks for info. Yes those log was more verbose log because OP want to know why the iOS device blacklisted due some errors showed by this log `Too many protocol errors, aborting ` — masegaloeh, Dec 11 '14 at 04:30
Blacklisting for an initial failure seems excessive, and the log seems to indicate that they are not blacklisted. The initial connection is dropped after a few failures, which is normal mail server behavior. It is not uncommon to get connections using the wrong protocol. The second connection completes a secure login and disconnects. This should not be considered a failure, and should not get the device blacklisted either. — BillThor, Dec 11 '14 at 04:47
Well, that's another issue of OP mail server :). I just explain why this error happened. Apparently OP seems doesn't aware this is iOS default behaviour. — masegaloeh, Dec 11 '14 at 04:56
Yes I had debugging level on to diagnose this. Other devices (non iOS devices) like PC's (Outlook, Thunderbird) do not show the errors, nor do they get blacklisted. I can post another log showing the complete transaction and where the device is actually blacklisted for nnn seconds, but I understand what is going on now - thank you. — Roberto, Dec 11 '14 at 13:43