Roundcube sees SMTP 220 as an error response instead of OK, after sending STARTTLS

[Ratchet-master]

SMTP code 220 is perfectly acceptable and generally means the mail server is ready to continue but roundcube sees this as an error code and displays authentication error and uses QUIT after STARTTLS was accepted.

Example:

[05-Jan-2021 23:35:41 +0000]: <knedr1j4> Connecting to tls://***REDACTED***:587...
[05-Jan-2021 23:35:41 +0000]: <knedr1j4> Recv: 220 ***REDACTED*** ESMTP Postfix (3.3.1)
[05-Jan-2021 23:35:41 +0000]: <knedr1j4> Send: EHLO ***REDACTED***
[05-Jan-2021 23:35:41 +0000]: <knedr1j4> Recv: 250-***REDACTED***
[05-Jan-2021 23:35:41 +0000]: <knedr1j4> Recv: 250-PIPELINING
[05-Jan-2021 23:35:41 +0000]: <knedr1j4> Recv: 250-SIZE 10240000
[05-Jan-2021 23:35:41 +0000]: <knedr1j4> Recv: 250-VRFY
[05-Jan-2021 23:35:41 +0000]: <knedr1j4> Recv: 250-ETRN
[05-Jan-2021 23:35:41 +0000]: <knedr1j4> Recv: 250-STARTTLS
[05-Jan-2021 23:35:41 +0000]: <knedr1j4> Recv: 250-ENHANCEDSTATUSCODES
[05-Jan-2021 23:35:41 +0000]: <knedr1j4> Recv: 250-8BITMIME
[05-Jan-2021 23:35:41 +0000]: <knedr1j4> Recv: 250-DSN
[05-Jan-2021 23:35:41 +0000]: <knedr1j4> Recv: 250 SMTPUTF8
[05-Jan-2021 23:35:41 +0000]: <knedr1j4> Send: STARTTLS
[05-Jan-2021 23:35:41 +0000]: <knedr1j4> Recv: 220 2.0.0 Ready to start TLS
[05-Jan-2021 23:35:41 +0000]: <knedr1j4> Send: QUIT

[Ratchet-master]

running #1.4.10

[alecpl]

I saw that in the past. The problem is not with 220, which is perfectly fine. The problem is with TLS negotiation. Is there no other error in log? One of the reasons that it fails might be a difference in configured/allowed SSL?TLS protocol versions between PHP and SMTP server.

There's not much we can do about it from our side. You may try setting crypto_method via smtp_conn_options, but it might not work. Probably easier is to change the SMTP server (or maybe its some SSL system-wide) config.

[Ratchet-master]

found the root of the issue.

current setup now:
$config['smtp_conn_options'] = array(
'ssl' => array(
'verify_peer' => false,
'verify_peer_name' => false,
'allow_self_signed' => true,
'verify_depth' => 3,
'cafile' => '/etc/openssl/certs/ca.crt',
),
);

$config['smtp_timeout'] = 60;

Issue I found is that after the ssl config options above, below it had another line as follows:
$config['smtp_conn_options'] = null;

which I had to comment out to get SSL working.

[damaltor]

Hi,
i have a similar problem and am searching for info: I am using roundcube for a few years now and never had problems. I now updated debian from buster to bullseye, and instlles more updates to roundcube and dovecot/postfix, and after that i could no longer send emails - i always got error 250 (auth error). i then added "tls://" to the smtp host config, after that i did get error 220 and the same problem you had - roundcube lost connection after receiving the 220. i then added similar lines like you did in your last post, now it works again.
as you seem to know what you are doing :) can you tell me, is it right that that configuration skips the check of the certificates hostname? why is that needed? is there a better way, like changing the certificate maybe?
I wondered why these errors come up now, but roundcube worked nicely for years and years without needing them...

[sebix]

I had the exact same issue and solved it the same way, although I think that's a hack. My roundcube instance is also from an upgraded Debian system

The only "220" I see in the transcript is this:

Apr 28 14:22:12 host postfix/smtpd[14980]: > localhost[127.0.0.1]: 220 2.0.0 Ready to start TLS

Maybe this line gets misinterpreted?

[damaltor]

Yeah, it looks like that. And the "solution" feels very hacky.

[sebix]

This is the full transcript. I removed the milters' logs to reduce the complexity

Apr 28 14:07:56 host postfix/smtpd[12840]: connect from localhost[127.0.0.1]
Apr 28 14:07:56 host postfix/smtpd[12840]: smtp_stream_setup: maxtime=300 enable_deadline=0
Apr 28 14:07:56 host postfix/smtpd[12840]: match_hostname: smtpd_client_event_limit_exceptions: localhost ~? 127.0.0.1/32
Apr 28 14:07:56 host postfix/smtpd[12840]: match_hostaddr: smtpd_client_event_limit_exceptions: 127.0.0.1 ~? 127.0.0.1/32
Apr 28 14:07:56 host postfix/smtpd[12840]: report connect to all milters
Apr 28 14:07:56 host postfix/smtpd[12840]: trying... [127.0.0.1]
Apr 28 14:07:56 host postfix/smtpd[12840]: vstream_tweak_tcp: TCP_MAXSEG 32741
Apr 28 14:07:56 host postfix/smtpd[12840]: fd=24: stream buffer size old=0 new=130964
Apr 28 14:07:56 host postfix/smtpd[12840]: event: SMFIC_CONNECT; macros: j=host.example.com {daemon_name}=ORIGINATING {daemon_addr}=127.0.0.1 v=Postfix 3.4.14
Apr 28 14:07:56 host postfix/smtpd[12840]: reply: SMFIR_CONTINUE data 0 bytes
Apr 28 14:07:56 host postfix/smtpd[12840]: trying... [127.0.0.1]
Apr 28 14:07:56 host postfix/smtpd[12840]: vstream_tweak_tcp: TCP_MAXSEG 32741
Apr 28 14:07:56 host postfix/smtpd[12840]: fd=25: stream buffer size old=0 new=130964
Apr 28 14:07:56 host postfix/smtpd[12840]: event: SMFIC_CONNECT; macros: j=host.example.com {daemon_name}=ORIGINATING {daemon_addr}=127.0.0.1 v=Postfix 3.4.14
Apr 28 14:07:56 host postfix/smtpd[12840]: reply: SMFIR_ACCEPT data 0 bytes
Apr 28 14:07:56 host postfix/smtpd[12840]: > localhost[127.0.0.1]: 220 host.example.com ESMTP
Apr 28 14:07:56 host postfix/smtpd[12840]: watchdog_pat: 0x$abc
Apr 28 14:07:56 host postfix/smtpd[12840]: < localhost[127.0.0.1]: EHLO webmail.example.com
Apr 28 14:07:56 host postfix/smtpd[12840]: report helo to all milters
Apr 28 14:07:56 host postfix/smtpd[12840]: match_list_match: localhost: no match
Apr 28 14:07:56 host postfix/smtpd[12840]: match_list_match: 127.0.0.1: no match
Apr 28 14:07:56 host postfix/smtpd[12840]: > localhost[127.0.0.1]: 250-host.example.com
Apr 28 14:07:56 host postfix/smtpd[12840]: > localhost[127.0.0.1]: 250-PIPELINING
Apr 28 14:07:56 host postfix/smtpd[12840]: > localhost[127.0.0.1]: 250-SIZE 102400000
Apr 28 14:07:56 host postfix/smtpd[12840]: > localhost[127.0.0.1]: 250-ETRN
Apr 28 14:07:56 host postfix/smtpd[12840]: > localhost[127.0.0.1]: 250-STARTTLS
Apr 28 14:07:56 host postfix/smtpd[12840]: > localhost[127.0.0.1]: 250-ENHANCEDSTATUSCODES
Apr 28 14:07:56 host postfix/smtpd[12840]: > localhost[127.0.0.1]: 250-8BITMIME
Apr 28 14:07:56 host postfix/smtpd[12840]: > localhost[127.0.0.1]: 250-DSN
Apr 28 14:07:56 host postfix/smtpd[12840]: > localhost[127.0.0.1]: 250-SMTPUTF8
Apr 28 14:07:56 host postfix/smtpd[12840]: > localhost[127.0.0.1]: 250 CHUNKING
Apr 28 14:07:56 host postfix/smtpd[12840]: watchdog_pat: 0x$abc
Apr 28 14:07:56 host postfix/smtpd[12840]: < localhost[127.0.0.1]: STARTTLS
Apr 28 14:07:56 host postfix/smtpd[12840]: query milter states for other event
Apr 28 14:07:56 host postfix/smtpd[12840]: > localhost[127.0.0.1]: 220 2.0.0 Ready to start TLS
Apr 28 14:07:56 host postfix/smtpd[12840]: abort all milters
Apr 28 14:07:56 host postfix/smtpd[12840]: send attr request = seed
Apr 28 14:07:56 host postfix/smtpd[12840]: send attr size = 32
Apr 28 14:07:56 host postfix/smtpd[12840]: private/tlsmgr: wanted attribute: status
Apr 28 14:07:56 host postfix/smtpd[12840]: input attribute name: status
Apr 28 14:07:56 host postfix/smtpd[12840]: input attribute value: 0
Apr 28 14:07:56 host postfix/smtpd[12840]: private/tlsmgr: wanted attribute: seed
Apr 28 14:07:56 host postfix/smtpd[12840]: input attribute name: seed
Apr 28 14:07:56 host postfix/smtpd[12840]: input attribute value: $base64
Apr 28 14:07:56 host postfix/smtpd[12840]: private/tlsmgr: wanted attribute: (list terminator)
Apr 28 14:07:56 host postfix/smtpd[12840]: input attribute name: (end)
Apr 28 14:07:56 host postfix/smtpd[12840]: send attr request = tktkey
Apr 28 14:07:56 host postfix/smtpd[12840]: send attr keyname = [data 0 bytes]
Apr 28 14:07:56 host postfix/smtpd[12840]: private/tlsmgr: wanted attribute: status
Apr 28 14:07:56 host postfix/smtpd[12840]: input attribute name: status
Apr 28 14:07:56 host postfix/smtpd[12840]: input attribute value: 0
Apr 28 14:07:56 host postfix/smtpd[12840]: private/tlsmgr: wanted attribute: keybuf
Apr 28 14:07:56 host postfix/smtpd[12840]: input attribute name: keybuf
Apr 28 14:07:56 host postfix/smtpd[12840]: input attribute value: $base64
Apr 28 14:07:56 host postfix/smtpd[12840]: private/tlsmgr: wanted attribute: (list terminator)
Apr 28 14:07:56 host postfix/smtpd[12840]: input attribute name: (end)
Apr 28 14:07:56 host postfix/smtpd[12840]: Anonymous TLS connection established from localhost[127.0.0.1]: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
Apr 28 14:07:56 host postfix/smtpd[12840]: xsasl_dovecot_server_create: SASL service=smtp, realm=host.example.com
Apr 28 14:07:56 host postfix/smtpd[12840]: name_mask: noanonymous
Apr 28 14:07:56 host postfix/smtpd[12840]: xsasl_dovecot_server_connect: Connecting
Apr 28 14:07:56 host postfix/smtpd[12840]: xsasl_dovecot_server_connect: auth reply: VERSION?1?2
Apr 28 14:07:56 host postfix/smtpd[12840]: xsasl_dovecot_server_connect: auth reply: MECH?PLAIN?plaintext
Apr 28 14:07:56 host postfix/smtpd[12840]: name_mask: plaintext
Apr 28 14:07:56 host postfix/smtpd[12840]: xsasl_dovecot_server_connect: auth reply: MECH?LOGIN?plaintext
Apr 28 14:07:56 host postfix/smtpd[12840]: name_mask: plaintext
Apr 28 14:07:56 host postfix/smtpd[12840]: xsasl_dovecot_server_connect: auth reply: SPID?$XXX
Apr 28 14:07:56 host postfix/smtpd[12840]: xsasl_dovecot_server_connect: auth reply: CUID?$XXX
Apr 28 14:07:56 host postfix/smtpd[12840]: xsasl_dovecot_server_connect: auth reply: COOKIE?$XXX
Apr 28 14:07:56 host postfix/smtpd[12840]: xsasl_dovecot_server_connect: auth reply: DONE
Apr 28 14:07:56 host postfix/smtpd[12840]: xsasl_dovecot_server_mech_filter: keep mechanism: PLAIN
Apr 28 14:07:56 host postfix/smtpd[12840]: xsasl_dovecot_server_mech_filter: keep mechanism: LOGIN
Apr 28 14:07:56 host postfix/smtpd[12840]: watchdog_pat: 0x$abc
Apr 28 14:07:56 host postfix/smtpd[12840]: smtp_get: EOF
Apr 28 14:07:56 host postfix/smtpd[12840]: match_hostname: smtpd_client_event_limit_exceptions: localhost ~? 127.0.0.1/32
Apr 28 14:07:56 host postfix/smtpd[12840]: match_hostaddr: smtpd_client_event_limit_exceptions: 127.0.0.1 ~? 127.0.0.1/32
Apr 28 14:07:56 host postfix/smtpd[12840]: lost connection after STARTTLS from localhost[127.0.0.1]
Apr 28 14:07:56 host postfix/smtpd[12840]: disconnect event to all milters
Apr 28 14:07:57 host postfix/smtpd[12840]: disconnect from localhost[127.0.0.1] ehlo=1 starttls=1 commands=2
Apr 28 14:07:57 host postfix/smtpd[12840]: free all milters

[bretton]

I had this issue with a FreeBSD13.2 -> FreeBDB14.0 upgrade in May 2024, which included php80->php82. Several php82 packages had to be installed manually.

The system was working fine before upgrade, but after it wouldn't display message previews or send smtp mail.

This config

$config['smtp_host'] = 'tls://my.mailserver.com:587';

got this smtp log response when sending mail

STARTTLS failed
Invalid response code received from server
STARTTLS failed: TLS go ahead (Code: 220)

Then I tried without tls:// so that my config.inc.php has

$config['imap_host'] = 'ssl://my.mailserver.com:993';

$config['smtp_host'] = 'my.mailserver.com:587';

$config['smtp_conn_options'] = array(
   'ssl' => array(
   'verify_peer' => false,
   'verify_peer_name' => false,
  ),
);

and it's working fine to send SMTP messages again.

[ipitsec]

Hello!

This bug should be fixed. I spent some hours to investigate with uncle google, why my roundcube installation can't send any mails and showing SMTP error 220.
@bretton reply helped me - remove tls from $config['smtp_host'] fixed this nasty bug.

I use AlmaLinux 9.4 and sendmail as MTA/MSA

Some there is hardly wrong.

Best

[alecpl]

It looks like certificate validation problem with misleading error message. pear/Net_SMTP#83. There's not much we can do here.