Weird error from Emclient on mobile phone connecting

[exander77]

mox-1  | l=debug m="scram auth" pkg=imapserver authentication=XXX cid=19322540af6 delta=99.735482ms
mox-1  | l=debug m="imap command syntax error" err="parsing base64: illegal base64 data at input byte 2" pkg=imapserver cmd=authenticate duration=30.065153ms cid=19322540af6 delta=30.062616ms
mox-1  | l=info m="imap syntax error" pkg=imapserver lastline="A2 LOGOUT" cid=19322540af6 delta="15.889µs"
mox-1  | l=info m="imap command ioerror" err="unexpected EOF (io error)" pkg=imapserver cmd= duration=339.942911ms cid=19322540af6 delta=309.853999ms
mox-1  | l=info m="connection closed" err="unexpected EOF (io error)" pkg=imapserver cid=19322540af6 delta="89.573µs"
mox-1  | l=info m="new connection" pkg=imapserver remote=XXX:53580 local=XXX:993 tls=true listener=public cid=19322540af7 delta="54.315µs"

[mjl-]

I installed emclient for iOS just now and am getting the same errors. It looks
like emclient is aborting the SCRAM-SHA-1 SASL session. And instead of writing
"*" to abort, it writes "A2 LOGOUT", which mox tries to parse as base64.

The first & major issue is emclient aborting the authentication attempt
causing authentication between emclient and mox to fail completely. There must
be something in the mox response that emclient doesn't like. Could be related
to the plus-variants that it isn't chosing. I'm not seeing anything in its
logging.

The second & minor issue is that emclient doesn't use "*" to abort the connection.

IMAP: https://www.xmox.nl/xr/dev/rfc/9051.html#L1442
SMTP: https://www.xmox.nl/xr/dev/rfc/4954.html#L194

While setting up my test account with emclient I found a third issue: TLS/SSL
doesn't work out of the box. They are trying to do STARTTLS on the immediate
TLS connections... I had to choose "Use SSL/TLS on special port (legacy)" to
use immediate TLS for IMAP (imaps) on port 993 and SMTP (submissions) on port
465. Immediate TLS is the better option, certainly not legacy. Emclient used
autoconfig/autodiscover to find settings (great!) but may have misinterpreted
the TLS-related settings.

For reference, a trace of an IMAP session:

l=info m="new connection" pkg=imapserver remote=...:51516 local=...:993 tls=true listener=public cid=1935051c4f2 delta="167.299µs"
l=trace m="S: * OK [CAPABILITY IMAP4rev2 IMAP4rev1 ENABLE LITERAL+ IDLE SASL-IR BINARY UNSELECT UIDPLUS ESEARCH SEARCHRES MOVE UTF8=ACCEPT LIST-EXTENDED SPECIAL-USE LIST-STATUS AUTH=SCRAM-SHA-256-PLUS AUTH=SCRAM-SHA-256 AUTH=SCRAM-SHA-1-PLUS AUTH=SCRAM-SHA-1 AUTH=CRAM-MD5 ID APPENDLIMIT=9223372036854775807 CONDSTORE QRESYNC STATUS=SIZE QUOTA QUOTA=RES-STORAGE AUTH=PLAIN] mox imap\r\n" pkg=imapserver cid=1935051c4f2 delta=1.103916ms
l=trace m="C: A1 AUTHENTICATE SCRAM-SHA-1 [base64]\r\n" pkg=imapserver cid=1935051c4f2 delta=33.105852ms
l=debug m="scram auth" pkg=imapserver [email protected] cid=1935051c4f2 delta=1.010431ms
l=trace m="S: + [base64]\r\n" pkg=imapserver cid=1935051c4f2 delta="690.643µs"
l=trace m="C: A2 LOGOUT\r\n" pkg=imapserver cid=1935051c4f2 delta=10.173214ms
l=debug m="imap command syntax error" err="parsing base64: illegal base64 data at input byte 2" pkg=imapserver cmd=authenticate duration=11.396478ms cid=1935051c4f2 delta="500.819µs"
l=info m="imap syntax error" pkg=imapserver lastline="A2 LOGOUT" cid=1935051c4f2 delta="379.437µs"
l=trace m="S: A1 BAD AUTHENTICATE unrecognized syntax/command: parsing base64: illegal base64 data at input byte 2\r\n" pkg=imapserver cid=1935051c4f2 delta="325.356µs"
l=info m="imap command ioerror" err="unexpected EOF (io error)" pkg=imapserver cmd= duration=320.105187ms cid=1935051c4f2 delta=308.036891ms
l=info m="connection closed" err="unexpected EOF (io error)" pkg=imapserver cid=1935051c4f2 delta=3.96806ms

And logging from emclient:

10:10:32.733|016|   eM Client 10.0.3530+f0b89b73a0 (iOS)
10:10:32.734|022|   Account's UID is ca03f6b5-c504-4485-9bc6-ebbb9d89664a
10:10:32.734|022|   AccountBase.ChangeOnlineState : State changed to ONLINE due User
10:10:32.738|022|   WARNING no INBOX folder found to watch!
10:10:32.738|022|   >>> ListFoldersAsync(): Start
10:10:32.739|022|   01:   Connecting to komijn.test.xmox.nl:993 with TLS ...
10:10:32.740|022|   >>> Starting account synchronization
10:10:32.782|022|   01:   TLS stream established with Protocol: Tls12, NegotiatedCipherSuite: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, CipherAlgorithm: Aes128, HashAlgorithm: None
10:10:32.782|022|   01: * OK [CAPABILITY IMAP4rev2 IMAP4rev1 ENABLE LITERAL+ IDLE SASL-IR BINARY UNSELECT UIDPLUS ESEARCH SEARCHRES MOVE UTF8=ACCEPT LIST-EXTENDED SPECIAL-USE LIST-STATUS AUTH=SCRAM-SHA-256-PLUS AUTH=SCRAM-SHA-256 AUTH=SCRAM-SHA-1-PLUS AUTH=SCRAM-SHA-1 AUTH=CRAM-MD5 ID APPENDLIMIT=9223372036854775807 CONDSTORE QRESYNC STATUS=SIZE QUOTA QUOTA=RES-STORAGE AUTH=PLAIN] mox imap
10:10:32.783|022|   01: A1 AUTHENTICATE SCRAM-SHA-1 <Parameter removed for privacy reasons.>
10:10:32.797|022|   01: + <Parameter removed for privacy reasons.>
10:10:32.800|022|   >>> ConnectionPoolEntry.CloseAsync(): Failed to connect: System.NullReferenceException: Object reference not set to an instance of an object
10:10:32.800|022|      at MailClient.Authentication.Mechanisms.ScramMechanism.Client.Hi(Byte[] password, Byte[] salt, Int32 count)
10:10:32.800|022|      at MailClient.Authentication.Mechanisms.ScramMechanism.Client.EvaluateChallenge(Byte[] challenge)
10:10:32.800|022|      at MailClient.Imap.Base.Connection.AuthenticateAsync(SaslMechanism scheme, ClientCredential credential, Boolean useInitialResponse, CancellationToken cancellationToken)
10:10:32.800|022|      at MailClient.Protocols.Imap.ConnectionPoolEntry.ConnectInternalAsync(CancellationToken cancellationToken)
10:10:32.800|022|   01: A2 LOGOUT
10:10:32.811|022|   01: A1 BAD AUTHENTICATE unrecognized syntax/command: parsing base64: illegal base64 data at input byte 2
10:10:33.101|022|   01: --- CMD LOGOUT WAS CANCELLED
10:10:33.112|022|   01: --- RECEIVE CANCELLED
10:10:33.113|022|   01:   Connection 1 was closed, deliberate = True
10:10:33.122|022|   >>> COMMAND CONNECTION EXCEPTION (retry: True): MailClient.Accounts.ConnectionException: Object reference not set to an instance of an object
10:10:33.122|022|    ---> System.NullReferenceException: Object reference not set to an instance of an object
10:10:33.122|022|      at MailClient.Authentication.Mechanisms.ScramMechanism.Client.Hi(Byte[] password, Byte[] salt, Int32 count)
10:10:33.122|022|      at MailClient.Authentication.Mechanisms.ScramMechanism.Client.EvaluateChallenge(Byte[] challenge)
10:10:33.123|022|      at MailClient.Imap.Base.Connection.AuthenticateAsync(SaslMechanism scheme, ClientCredential credential, Boolean useInitialResponse, CancellationToken cancellationToken)
10:10:33.123|022|      at MailClient.Protocols.Imap.ConnectionPoolEntry.ConnectInternalAsync(CancellationToken cancellationToken)
10:10:33.123|022|      Exception_EndOfInnerExceptionStack
10:10:33.123|022|      at MailClient.Protocols.Imap.ConnectionPoolEntry.ConnectInternalAsync(CancellationToken cancellationToken)
10:10:33.123|022|      at MailClient.Protocols.Imap.ConnectionPool.AcquireConnectionAsync(Folder mailFolder, Boolean noSelect)
10:10:33.123|022|      at MailClient.Protocols.Imap.ConnectionContext.CreateContextAsync(ImapAccount account)
10:10:33.123|022|      at MailClient.Protocols.Imap.ImapFolderSynchronizer.ListFoldersAsync(IListFoldersProgress progress, Folder homeFolder, CancellationToken cancellationToken)
10:10:33.123|022|      at MailClient.Protocols.Imap.ImapFolderSynchronizer.GetFolderList(IListFoldersProgress progress, Folder homeFolder, CancellationToken cancellationToken)
10:10:33.123|022|      at MailClient.Protocols.Common.FolderSynchronizer.<>c__DisplayClass18_0.<EnqueueGetFolderList>b__0(WorkerStatus status, CancellationToken cancellationToken)
10:10:33.124|022|      at MailClient.Protocols.Imap.ImapActionCommand.<>c__DisplayClass11_0.<.ctor>b__0(WorkerStatus ws, CancellationToken ct)
10:10:33.124|022|      at MailClient.Protocols.Imap.ImapActionCommand.ExecuteInternalSync(WorkerStatus status)
10:10:33.124|022|      at MailClient.Protocols.Imap.ImapActionCommand.Execute(WorkerStatus status)
10:10:33.124|022|   >>> ListFoldersAsync(): Start
10:10:33.124|022|   02:   Connecting to komijn.test.xmox.nl:993 with TLS ...
10:10:33.167|022|   02:   TLS stream established with Protocol: Tls12, NegotiatedCipherSuite: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, CipherAlgorithm: Aes128, HashAlgorithm: None
10:10:33.168|022|   02: * OK [CAPABILITY IMAP4rev2 IMAP4rev1 ENABLE LITERAL+ IDLE SASL-IR BINARY UNSELECT UIDPLUS ESEARCH SEARCHRES MOVE UTF8=ACCEPT LIST-EXTENDED SPECIAL-USE LIST-STATUS AUTH=SCRAM-SHA-256-PLUS AUTH=SCRAM-SHA-256 AUTH=SCRAM-SHA-1-PLUS AUTH=SCRAM-SHA-1 AUTH=CRAM-MD5 ID APPENDLIMIT=9223372036854775807 CONDSTORE QRESYNC STATUS=SIZE QUOTA QUOTA=RES-STORAGE AUTH=PLAIN] mox imap
10:10:33.168|022|   02: A1 AUTHENTICATE SCRAM-SHA-1 <Parameter removed for privacy reasons.>
10:10:33.177|022|   02: + <Parameter removed for privacy reasons.>
10:10:33.180|022|   >>> ConnectionPoolEntry.CloseAsync(): Failed to connect: System.NullReferenceException: Object reference not set to an instance of an object
10:10:33.180|022|      at MailClient.Authentication.Mechanisms.ScramMechanism.Client.Hi(Byte[] password, Byte[] salt, Int32 count)
10:10:33.181|022|      at MailClient.Authentication.Mechanisms.ScramMechanism.Client.EvaluateChallenge(Byte[] challenge)
10:10:33.181|022|      at MailClient.Imap.Base.Connection.AuthenticateAsync(SaslMechanism scheme, ClientCredential credential, Boolean useInitialResponse, CancellationToken cancellationToken)
10:10:33.181|022|      at MailClient.Protocols.Imap.ConnectionPoolEntry.ConnectInternalAsync(CancellationToken cancellationToken)
10:10:33.181|022|   02: A2 LOGOUT
10:10:33.189|022|   02: A1 BAD AUTHENTICATE unrecognized syntax/command: parsing base64: illegal base64 data at input byte 2
10:10:33.482|022|   02: --- CMD LOGOUT WAS CANCELLED
10:10:33.496|022|   02: --- RECEIVE CANCELLED
10:10:33.496|022|   02:   Connection 2 was closed, deliberate = True
10:10:33.506|022|   >>> COMMAND CONNECTION EXCEPTION: MailClient.Accounts.ConnectionException: Object reference not set to an instance of an object
10:10:33.506|022|    ---> System.NullReferenceException: Object reference not set to an instance of an object
10:10:33.506|022|      at MailClient.Authentication.Mechanisms.ScramMechanism.Client.Hi(Byte[] password, Byte[] salt, Int32 count)
10:10:33.507|022|      at MailClient.Authentication.Mechanisms.ScramMechanism.Client.EvaluateChallenge(Byte[] challenge)
10:10:33.507|022|      at MailClient.Imap.Base.Connection.AuthenticateAsync(SaslMechanism scheme, ClientCredential credential, Boolean useInitialResponse, CancellationToken cancellationToken)
10:10:33.507|022|      at MailClient.Protocols.Imap.ConnectionPoolEntry.ConnectInternalAsync(CancellationToken cancellationToken)
10:10:33.507|022|      Exception_EndOfInnerExceptionStack
10:10:33.507|022|      at MailClient.Protocols.Imap.ConnectionPoolEntry.ConnectInternalAsync(CancellationToken cancellationToken)
10:10:33.507|022|      at MailClient.Protocols.Imap.ConnectionPool.AcquireConnectionAsync(Folder mailFolder, Boolean noSelect)
10:10:33.507|022|      at MailClient.Protocols.Imap.ConnectionContext.CreateContextAsync(ImapAccount account)
10:10:33.507|022|      at MailClient.Protocols.Imap.ImapFolderSynchronizer.ListFoldersAsync(IListFoldersProgress progress, Folder homeFolder, CancellationToken cancellationToken)
10:10:33.507|022|      at MailClient.Protocols.Imap.ImapFolderSynchronizer.GetFolderList(IListFoldersProgress progress, Folder homeFolder, CancellationToken cancellationToken)
10:10:33.507|022|      at MailClient.Protocols.Common.FolderSynchronizer.<>c__DisplayClass18_0.<EnqueueGetFolderList>b__0(WorkerStatus status, CancellationToken cancellationToken)
10:10:33.508|022|      at MailClient.Protocols.Imap.ImapActionCommand.<>c__DisplayClass11_0.<.ctor>b__0(WorkerStatus ws, CancellationToken ct)
10:10:33.508|022|      at MailClient.Protocols.Imap.ImapActionCommand.ExecuteInternalSync(WorkerStatus status)
10:10:33.508|022|      at MailClient.Protocols.Imap.ImapActionCommand.Execute(WorkerStatus status)
10:10:33.519|022|   AccountBase.GoOfflineAsync : State changed to OFFLINE due BrokenConnection

There are more log files, including for auth, but they don't seem to contain anything interesting.

Thanks for reporting. I'm going to send this issue to the emclient support@ address.

[exander77]

I would add it worked on previous Emclient version. So this must be recent change.

[filipnavara]

We are pretty sure it's bug in eM Client and not in the server. We are investigating and hopefully we will have more to share soon.

It may be specific to the mobile app and how it's built. Our tests show that it works on desktop version.

[mjl-]

Thanks for the update!
@exander77 Was authentication working with the mobile version before? I suppose it auto-updates... Or do you happen to know a previous version where it worked?

[exander77]

@mjl- Yes, it worked fine till like 4 days ago, and I confirmed that Emclient was updated. (I am not the person affected, person who has mailbox on my domain and uses Emclient is.).

[exander77]

We are pretty sure it's bug in eM Client and not in the server. We are investigating and hopefully we will have more to share soon.

It may be specific to the mobile app and how it's built. Our tests show that it works on desktop version.

Btw, hi Filip, We know each other from FEL (Radomír Polách here). So, still working for Emclient? Where is Linux version? I am waiting for years for it.

[filipnavara]

Still working there, although at slightly different role. I'm now in charge of fixing some hard issues and managing problems on the underlying frameworks (eg. .NET). 😅

This likely happened as a side-effect of some application size trimming done by the underlying framework and how it works on mobile. We had the root cause fixed for months in our development version but the current release is still done from older branch and it likely happened to regress due to some unrelated tooling update.

OT: We don't have any plans for Linux version at the moment but we do some limited testing of the desktop version using Wine and the mobile version using Waydroid. We have a big update for the mobile version in the pipeline that should get the functionality a step closer to the desktop one but no timeline for release yet. There's not much economic viability in creating a native Linux version and none of the UI frameworks that we use has direct support for it, unfortunately.

[exander77]

Still working there, although at slightly different role. I'm now in charge of fixing some hard issues and managing problems on the underlying frameworks (eg. .NET). 😅

This likely happened as a side-effect of some application size trimming done by the underlying framework and how it works on mobile. We had the root cause fixed for months in our development version but the current release is still done from older branch and it likely happened to regress due to some unrelated tooling update.

OT: We don't have any plans for Linux version at the moment but we do some limited testing of the desktop version using Wine and the mobile version using Waydroid. We have a big update for the mobile version in the pipeline that should get the functionality a step closer to the desktop one but no timeline for release yet. There's not much economic viability in creating a native Linux version and none of the UI frameworks that we use has direct support for it, unfortunately.

So sad, wrote you on LinkedIn to keep in touch and do not OT this bug report much. I have to use MailSpring for now. Maybe if the Wine support is really good I should try it.

[mjl-]

Here's a workaround from emclient support:

In settings of the given account in eM Client open the ADVANCED section 
and insert these parameters:
--force-smtp-auth CRAM-MD5
--force-imap-auth CRAM-MD5

I'm very impressed by emclient support, thanks!

[exander77]

Here's a workaround from emclient support:

In settings of the given account in eM Client open the ADVANCED section 
and insert these parameters:
--force-smtp-auth CRAM-MD5
--force-imap-auth CRAM-MD5

I'm very impressed by emclient support, thanks!

Great to hear. Yes, Emclient is good piece of software, just currently don't have native Linux version, just Windows, Mac and mobile versions.