dovecot - Sep 2020 - managesieve script 'redirect' fails @ "Error: sieve: ... aborted due to temporary failure; Error: smtp-server: ... failed: SSL_accept() failed: error:1408F10B:SSL routines:ssl3_get_record:wrong version number"; direct send OK ?

I run

	dovecot --version
		2.3.10.1 (a3d0e1171)

	postconf mail_version
		mail_version = 3.5.7

with three valid accounts on the server,

	user1 at example1.net
	user2 at example2.net
	admin at mx.example.com

I can send/receive from each -- both to/from external addresses, as well as
between one another.

E.g., on mail sent to

	user2 at example2.net -> admin at mx.example.com

logs of the successful delivery are

	==> /var/log/dovecot/dovecot-info.log <=	2020-09-26 16:00:33
submission-login: Info: Login: user=<sender at mx.example.com>,
method=PLAIN, rip=10.0.1.9, lip=10.0.1.17, mpid=7178, TLS
	2020-09-26 16:00:33 submission(sender at
mx.example.com)<gQePZj+wUuesHgsH>: Info: Successfully relayed message:
from=<user2 at example2.net>, size=449, id=WjpMLRHIb18KHAAA+IOfAw,
nrcpt=1, reply=`250 2.0.0 Ok: queued as 4BzPQ95QwwzWf9g'
	2020-09-26 16:00:33 submission(sender at
mx.example.com)<gQePZj+wUuesHgsH>: Info: Disconnect from 10.0.1.9: Client
has quit the connection in=566 out=114 (state=READY)
	2020-09-26 16:00:33 imap(user2 at example2.net)<YzPbWj+wzNCsHgsH>: Info:
save: box=Sent, uid=42, msgid=<9ca622bd-cdc3-ca26-8650-556d4132fe6c at
example2.net>, size=434
	2020-09-26 16:00:33 lmtp(7183): Info: Connect from local
	2020-09-26 16:00:33 lmtp(admin at
mx.example.com)<2HI4MBHIb18PHAAA+IOfAw>: Info:
msgid=<9ca622bd-cdc3-ca26-8650-556d4132fe6c at example2.net>: saved mail
to INBOX
	2020-09-26 16:00:33 lmtp(7183): Info: Disconnect from local: Client has quit
the connection (state=READY)

	==> /var/log/postfix/postfix.log <=	Sep 26 16:00:33 mx
postfix/submit-from-dovecot-proxy/smtpd[7179]: connect from
internal.mx.example.com[10.0.1.17]
	Sep 26 16:00:33 mx postfix/submit-from-dovecot-proxy/smtpd[7179]: Trusted TLS
connection established from internal.mx.example.com[10.0.1.17]: TLSv1.3 with
cipher TLS_CHACHA20_POLY1305_SHA256 (256/256 bits) key-exchange X25519
server-signature ECDSA (P-384) server-digest SHA384 client-signature ECDSA
(P-384) client-digest SHA384
	Sep 26 16:00:33 mx postfix/submit-from-dovecot-proxy/smtpd[7179]:
4BzPQ95QwwzWf9g: client=internal.mx.example.com[10.0.1.17]
	Sep 26 16:00:33 mx postfix/qmgr[6928]: 4BzPQ95QwwzWf9g: from=<user2 at
example2.net>, size=824, nrcpt=1 (queue active)
	Sep 26 16:00:33 mx postfix/submit-from-dovecot-proxy/smtpd[7179]: disconnect
from internal.mx.example.com[10.0.1.17] ehlo=1 mail=1 rcpt=1 data=1 quit=1
commands=5
	Sep 26 16:00:33 mx postfix/lmtp[7182]: 4BzPQ95QwwzWf9g: to=<admin at
mx.example.com>, relay=mx.example.com[private/dovecot-lmtp], delay=0.06,
delays=0.03/0.01/0.01/0.02, dsn=2.0.0, status=sent (250 2.0.0 <admin at
mx.example.com> 2HI4MBHIb18PHAAA+IOfAw Saved)
	Sep 26 16:00:33 mx postfix/qmgr[6928]: 4BzPQ95QwwzWf9g: removed

	==> /var/log/dovecot/dovecot-info.log <=	2020-09-26 16:00:33 imap(user2
at example2.net)<YzPbWj+wzNCsHgsH>: Info: Connection closed (IDLE running
for 0.001 + waiting input for 0.009 secs, 2 B in + 10 B out, state=wait-input)
in=1199 out=3082 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=271
body_count=0 body_bytes=0
	2020-09-26 16:00:33 imap-login: Info: Login: user=<user2 at
example2.net>, method=PLAIN, rip=10.0.1.9, lip=10.0.1.17, mpid=7185, TLS



I've added a user sieve script for user == user2 at example2.net


	cat /srv/mail/sieve-scripts/user2 at example2.net.sieve
		# rule:[SIEVETEST]
		if header :contains "subject" "SIEVETEST"
		{
				redirect "admin at mx.example.com";
		}

where the redirect is to the valid address tested/demonstrated above, admin at
mx.example.com

in dovecot config,

	submission_host = internal.mx.example.com:60465

currently,

	host mx.example.com
		mx.example.com has address 10.0.1.17
		mx.example.com has IPv6 address fd70:10:0:1::17
	host internal.mx.example.com
		internal.mx.example.com has address 10.0.1.17
		internal.mx.example.com has IPv6 address fd70:10:0:1::17


on test send from user1 at example1.net to user2 at example2.net, with Subject
== SIEVETEST

the user sieve _is_ triggered/executed

	cat 20200926-160636.7461.1.trace
		Sieve trace log for message delivery:

		Username: user2 at example2.net
		Session ID: E851MXzJb18lHQAA+IOfAw
		Sender: <user1 at example1.net>
		Final recipient: <user2 at example2.net>
		Default mailbox: INBOX


			## Started executing script 'managesieve'
		2:   not jumping
		4: redirect action
		4:   forward message to address <admin at mx.example.com>
			## Finished executing script 'managesieve'

but the mail redirect delivery fails

	2020-09-26 16:06:36 submission-login: Info: Login: user=<sender at
mx.example.com>, method=PLAIN, rip=10.0.1.9, lip=10.0.1.17, mpid=7455, TLS
	2020-09-26 16:06:36 submission(sender at
mx.example.com)<VbsxfD+wXOesHgsH>: Info: Successfully relayed message:
from=<user1 at example1.net>, size=466, id=lvK6LnzJb18fHQAA+IOfAw,
nrcpt=1, reply=`250 2.0.0 Ok: queued as 4BzPY85g9czWf8L'
	2020-09-26 16:06:36 submission(sender at
mx.example.com)<VbsxfD+wXOesHgsH>: Info: Disconnect from 10.0.1.9: Client
has quit the connection in=567 out=114 (state=READY)
	2020-09-26 16:06:36 lmtp(7461): Info: Connect from local
	2020-09-26 16:06:36 imap(user1 at example1.net)<0ZZlej+w2NCsHgsH>: Info:
save: box=Sent, uid=13177, msgid=<28930f55-5a39-c8bd-67c2-39e581aa7551 at
example1.net>, size=450

	==> /var/log/postfix/postfix.log <=	Sep 26 16:06:36 mx
postfix/submit-from-dovecot-proxy/smtpd[7456]: connect from
internal.mx.example.com[10.0.1.17]
	Sep 26 16:06:36 mx postfix/submit-from-dovecot-proxy/smtpd[7456]: Trusted TLS
connection established from internal.mx.example.com[10.0.1.17]: TLSv1.3 with
cipher TLS_CHACHA20_POLY1305_SHA256 (256/256 bits) key-exchange X25519
server-signature ECDSA (P-384) server-digest SHA384 client-signature ECDSA
(P-384) client-digest SHA384
	Sep 26 16:06:36 mx postfix/submit-from-dovecot-proxy/smtpd[7456]:
4BzPY85g9czWf8L: client=internal.mx.example.com[10.0.1.17]
	Sep 26 16:06:36 mx postfix/qmgr[7362]: 4BzPY85g9czWf8L: from=<user1 at
example1.net>, size=812, nrcpt=1 (queue active)
	Sep 26 16:06:36 mx postfix/submit-from-dovecot-proxy/smtpd[7456]: disconnect
from internal.mx.example.com[10.0.1.17] ehlo=1 mail=1 rcpt=1 data=1 quit=1
commands=5

	==> /var/log/dovecot/dovecot.log <=	2020-09-26 16:07:06 lmtp(user2 at
example2.net)<E851MXzJb18lHQAA+IOfAw>: Error: smtp-client: conn
internal.mx.example.com:60465 (10.0.1.17:60465) [1]:
connect(internal.mx.example.com:60465) failed: Connection timed out after 30
seconds
	2020-09-26 16:07:06 lmtp(user2 at example2.net)<E851MXzJb18lHQAA+IOfAw>:
Error: sieve: msgid=<28930f55-5a39-c8bd-67c2-39e581aa7551 at
example1.net>: redirect action: failed to redirect message to <admin at
mx.example.com>: smtp(internal.mx.example.com:60465): RCPT TO failed: Connect
timed out (temporary failure)
	2020-09-26 16:07:06 lmtp(user2 at example2.net)<E851MXzJb18lHQAA+IOfAw>:
Error: sieve: Execution of script /srv/mail/sieve-scripts/user2 at
example2.net.sieve was aborted due to temporary failure (user logfile
/srv/mail/sieve-scripts/user2 at example2.net.sieve.log may reveal additional
details)
	2020-09-26 16:07:06 submission-login: Error: smtp-server: conn 10.0.1.17:50578
[1]: Connection lost: read((conn:10.0.1.17:50578,id=1)) failed: SSL_accept()
failed: error:1408F10B:SSL routines:ssl3_get_record:wrong version number
	2020-09-26 16:07:06 submission-login: Info: Read failure (client didn't
send a cert): user=<>, rip=10.0.1.17, lip=10.0.1.17, TLS handshaking:
SSL_accept() syscall failed: Invalid argument
	2020-09-26 16:07:06 lmtp(7461): Info: Disconnect from local: Client has quit
the connection (state=READY)

	==> /var/log/postfix/postfix.log <=	Sep 26 16:07:06 mx
postfix/lmtp[7460]: 4BzPY85g9czWf8L: to=<user2 at example2.net>,
relay=mx.example.com[private/dovecot-lmtp], delay=30, delays=0.04/0/0/30,
dsn=4.2.0, status=deferred (host mx.example.com[private/dovecot-lmtp] said: 451
4.2.0 <user2 at example2.net> Execution of Sieve filters was aborted due
to temporary failure (in reply to end of DATA command))

&

	cat /srv/mail/sieve-scripts/user2 at example2.net.sieve.log
		sieve: info: started log at Sep 26 16:07:06.
		error: msgid=<28930f55-5a39-c8bd-67c2-39e581aa7551 at example1.net>:
redirect action: failed to redirect message to <admin at mx.example.com>:
smtp(internal.mx.example.com:60465): RCPT TO failed: Connect timed out
(temporary failure).

and remains stuck in postfix queue

	postqueue -p
		----Queue ID----- --Size-- ---Arrival Time---- --Sender/Recipient------
		4BzPY85g9czWf8L        812 Sat Sep 26 16:06:36 user1 at example1.net
		(host mx.example.com[private/dovecot-lmtp] said: 451 4.2.0 <user2 at
example2.net> Execution of Sieve filters was aborted due to temporary failure
(in reply to end of DATA command))
													user2 at example2.net

		-- 0 Kbytes in 1 Request.


it appears there's an SSL/cert problem -- but only in the case of the
redirect.

i.e.., this direct send,

	user2 at example2.net --SEND--> admin at mx.example.com

works, but the redirect

	user1 at example1.net (subjet == "SIEVETEST") --SEND--> user2 at
example2.net --REDIRECT--> admin at mx.example.com

does not, failing as above.

i suspect i'm missing config, but what/where in the dovecot submission/sieve
configs addresses this^ point in the SSL transaction?

i've been able to consistently reproduced the issue.  no luck ID'ing the
specific cause, yet.

fyi, i've asked as well @

 http://postfix.1071664.n5.nabble.com/local-postfix-re-delivery-of-dovecot-sieve-redirected-mail-fails-normal-direct-deliveries-are-OK-td107691.html

with slightly simple config and cleaner log detail.

adding a second, non-redirect action to the sieve rule in order to test,

+	require ["copy","fileinto"];
	# rule:[SIEVETEST]
	if header :contains "subject" "SIEVETEST"
	{
+			fileinto :copy "testing";
			redirect "user2 at example2.com";
	}

on send exec, the 'fileinto' action does work as expected.

the 'redirect' fails as above.

so the problem appears not to be the result of a general sieve-processing fail,
but rather tied to the the redirect action/transaction