Permanent error "5.3.3 Command not implemented"

Mutual Help
#1

Delta Chat version

1.14.5

Expected behavior

Message is sent as indicated by a green checkmark at the bottom right of the message.

Actual behavior

A cross symbol instead of a checkmark indicates that the message has not been sent.

Below the message is an info box saying “permanent: 5.3.3 Command not implemented”.

Steps to reproduce the problem

I wanted to send a regular message to a contact as I had done without problems two weeks earlier.

I haven’t updated Delta Chat or changed the configuration in the meantime.
I only switched to a second account at some point and switched back today.

It fails also for other contacts, even in “Saved messages”.

As I understand the description on the mail provider’s page, it’s a Microsoft server:

The mailboxes of a mail domain are hosted on a central Exchange system

However, sending mails from Thunderbird and K-9 Mail works with that account as usual.
There are also no issues in Delta Chat with the second account which is on a completely different server.

I’m aware that it’s therefore probably a server issue. I don’t know what to make of the error message, though – which is the unimplemented command and why is it suddenly a problem? I also wonder why it doesn’t appear in the other e-mail applications.

Debug logs

Logs 
03-04 20:22:28.069  5237 12544 W DeltaChat: src/job.rs:254: SMTP failed to send: permanent: 5.3.3 Command not implemented
03-04 20:22:28.069  5237 12544 W DeltaChat: src/message.rs:1500: Msg#445 failed: permanent: 5.3.3 Command not implemented
03-04 20:22:28.100  5237 12544 I DeltaChat: src/job.rs:1100: Finished immediate try 0 of job #387, action SendMsgToSmtp
03-04 20:22:28.100  5237 12544 W DeltaChat: src/job.rs:1052: Smtp removes job #387, action SendMsgToSmtp as it failed with error Permanent SMTP error: permanent: 5.3.3 Command not implemented
#2

If you use Linux, I can give instructions on how to run command-line client with SMTP logs enabled.

My guess is that command not implemented is STARTTLS. You can try to fix the problem by going into “Settings” → Your avatar → “Password and account” and clicking the tickmark without changing anything. This will run autoconfiguration again and, if succeeds, overwrite your configuration with a new working one.

#3

Thanks, I do use Linux and those instructions would be highly welcome.

I had already tried the different SMTP security settings. None of them worked and after going back to the initial Automatic option, the error still appears.

#4

You need to install git (sudo apt-get install git) and Rust (from https://rustup.rs/ with a command curl --proto '=https' --tlsv1.2 -sSf https://sh.rustup.rs | sh -s -- -y --default-toolchain none running as normal non-root user).

Then clone GitHub - deltachat/deltachat-core-rust: Delta Chat Rust Core library, used by Android/iOS/desktop apps and bindings repository with git clone https://github.com/deltachat/deltachat-core-rust.git. In the folder with deltachat-core-rust source code, run RUST_LOG=info,async_smtp=trace cargo run --example repl --features repl -- deltachat.db. This will compile and run command-line client (REPL, Read-Eval-Print-Loop) with SMTP tracing enabled. There, run the command import-backup your-backup-file.bak and then configure. Or, instead of importing backup, run set addr your-address, set mail_pw your-password and then configure.

#5

Thanks, that worked. Can you read something out of these debug messages?

REPL log output 
> send test
>  INFO  repl                            > Received NewBlobFile("$BLOBDIR/${id}")
 INFO  repl                            > src/job.rs:200: saving job for Smtp-thread: Job { job_id: 0, action: SendMsgToSmtp, foreign_id: 109, desired_timestamp: 1615752864, added_timestamp: 1615752864, tries: 0, param: Params { inner: {Recipients: "${address}", File: "$BLOBDIR/${id}"} }, pending_error: None }
 INFO  repl                            > src/job.rs:1238: interrupt: smtp
 INFO  repl                            > Received MSGS_CHANGED(chat_id=Chat#10, msg_id=Msg#109)
 INFO  repl                            > src/scheduler.rs:261: smtp fake idle - interrupted
 INFO  repl                            > src/job.rs:1270: loading job for Smtp-thread
 INFO  repl                            > src/scheduler.rs:253: executing smtp job
 INFO  repl                            > src/job.rs:1075: Smtp-job #32, action SendMsgToSmtp started...
 INFO  repl                            > src/job.rs:1144: Smtp begin immediate try 0 of job #32, action SendMsgToSmtp
 DEBUG async_smtp::smtp::client::inner > << 220 ${host} Microsoft ESMTP MAIL Service ready at Sun, 14 Mar 2021 21:14:23 +0100<CRLF>
 DEBUG async_smtp::smtp::smtp_client   > connection established to ${ip_1}:587
 DEBUG async_smtp::smtp::client::inner > >> EHLO [127.0.0.1]<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>250-PIPELINING<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>250-PIPELINING<CRLF>250-DSN<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>250-PIPELINING<CRLF>250-DSN<CRLF>250-ENHANCEDSTATUSCODES<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>250-PIPELINING<CRLF>250-DSN<CRLF>250-ENHANCEDSTATUSCODES<CRLF>250-STARTTLS<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>250-PIPELINING<CRLF>250-DSN<CRLF>250-ENHANCEDSTATUSCODES<CRLF>250-STARTTLS<CRLF>250-AUTH GSSAPI NTLM<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>250-PIPELINING<CRLF>250-DSN<CRLF>250-ENHANCEDSTATUSCODES<CRLF>250-STARTTLS<CRLF>250-AUTH GSSAPI NTLM<CRLF>250-8BITMIME<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>250-PIPELINING<CRLF>250-DSN<CRLF>250-ENHANCEDSTATUSCODES<CRLF>250-STARTTLS<CRLF>250-AUTH GSSAPI NTLM<CRLF>250-8BITMIME<CRLF>250-BINARYMIME<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>250-PIPELINING<CRLF>250-DSN<CRLF>250-ENHANCEDSTATUSCODES<CRLF>250-STARTTLS<CRLF>250-AUTH GSSAPI NTLM<CRLF>250-8BITMIME<CRLF>250-BINARYMIME<CRLF>250-CHUNKING<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>250-PIPELINING<CRLF>250-DSN<CRLF>250-ENHANCEDSTATUSCODES<CRLF>250-STARTTLS<CRLF>250-AUTH GSSAPI NTLM<CRLF>250-8BITMIME<CRLF>250-BINARYMIME<CRLF>250-CHUNKING<CRLF>250 SMTPUTF8<CRLF>
 DEBUG async_smtp::smtp::smtp_client   > server ${host} with {EightBitMime, SmtpUtfEight, StartTls}
 DEBUG async_smtp::smtp::client::inner > >> STARTTLS<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 220 2.0.0 SMTP server ready<CRLF>
 DEBUG async_smtp::smtp::smtp_client   > connection encrypted
 DEBUG async_smtp::smtp::client::inner > >> EHLO [127.0.0.1]<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>250-PIPELINING<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>250-PIPELINING<CRLF>250-DSN<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>250-PIPELINING<CRLF>250-DSN<CRLF>250-ENHANCEDSTATUSCODES<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>250-PIPELINING<CRLF>250-DSN<CRLF>250-ENHANCEDSTATUSCODES<CRLF>250-AUTH GSSAPI NTLM LOGIN<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>250-PIPELINING<CRLF>250-DSN<CRLF>250-ENHANCEDSTATUSCODES<CRLF>250-AUTH GSSAPI NTLM LOGIN<CRLF>250-8BITMIME<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>250-PIPELINING<CRLF>250-DSN<CRLF>250-ENHANCEDSTATUSCODES<CRLF>250-AUTH GSSAPI NTLM LOGIN<CRLF>250-8BITMIME<CRLF>250-BINARYMIME<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>250-PIPELINING<CRLF>250-DSN<CRLF>250-ENHANCEDSTATUSCODES<CRLF>250-AUTH GSSAPI NTLM LOGIN<CRLF>250-8BITMIME<CRLF>250-BINARYMIME<CRLF>250-CHUNKING<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 250-${host} Hello [${ip_2}]<CRLF>250-SIZE 41943040<CRLF>250-PIPELINING<CRLF>250-DSN<CRLF>250-ENHANCEDSTATUSCODES<CRLF>250-AUTH GSSAPI NTLM LOGIN<CRLF>250-8BITMIME<CRLF>250-BINARYMIME<CRLF>250-CHUNKING<CRLF>250 SMTPUTF8<CRLF>
 DEBUG async_smtp::smtp::smtp_client   > server ${host} with {Authentication(Login), SmtpUtfEight, EightBitMime}
 DEBUG async_smtp::smtp::client::inner > >> AUTH LOGIN<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 334 ${string_1}<CRLF>
 DEBUG async_smtp::smtp::commands      > auth encoded challenge: ${string_1}
 DEBUG async_smtp::smtp::commands      > auth decoded challenge: Username:
 DEBUG async_smtp::smtp::client::inner > >> ${string_2}=<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 334 ${string_3}<CRLF>
 DEBUG async_smtp::smtp::commands      > auth encoded challenge: ${string_3}
 DEBUG async_smtp::smtp::commands      > auth decoded challenge: Password:
 DEBUG async_smtp::smtp::client::inner > >> ${string_4}==<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 235 2.7.0 Authentication successful<CRLF>
 INFO  repl                            > [SMTP_CONNECTED] SMTP-LOGIN as ${address} ok
 DEBUG async_smtp::smtp::client::inner > >> MAIL FROM:<${address}> BODY=8BITMIME SMTPUTF8<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 502 5.3.3 Command not implemented<CRLF>
 DEBUG async_smtp::smtp::client::inner > >> QUIT<CRLF>
 DEBUG async_smtp::smtp::client::inner > << 221 2.0.0 Service closing transmission channel<CRLF>
 WARN  repl                            > src/job.rs:256: SMTP failed to send: permanent: 5.3.3 Command not implemented
 WARN  repl                            > src/message.rs:1676: Msg#109 failed: Permanent SMTP error: permanent: 5.3.3 Command not implemented
 INFO  repl                            > Received MsgFailed { chat_id: ChatId(10), msg_id: MsgId(109) }
 INFO  repl                            > src/job.rs:1168: Finished immediate try 0 of job #32, action SendMsgToSmtp
 WARN  repl                            > src/job.rs:1120: Smtp removes job #32, action SendMsgToSmtp as it failed with error Permanent SMTP error: permanent: 5.3.3 Command not implemented
#6

Looks like the server advertises 8BITMIME and SMTPUTF8 in response to EHLO, but then rejects MAIL FROM:<${address}> BODY=8BITMIME SMTPUTF8 after successful STARTTLS and AUTH with 502 5.3.3 Command not implemented.

Looks like a bug in MS exchange, but I wonder why Thunderbird and K-9 work, they probably have some workaround for this.

#7

Thanks, I planned on researching about these advertised properties, but didn’t have much time in the recent weeks.

Fortunately, the problem “fixed itself” in the meantime. I can send messages as previously again without having done anything.

Thanks again for your hints!