i've postfix + dovecot running on the same box; delivery between them is via
lmtp.
all in/out-bound, direct traffic flows as expected, securely with TLS.
i've set up a sieve redirect @ dovecot. on test send, the filter triggers,
submits the redirect to local postfix ... and then the delivery of the redirect
fails.
logs report an SSL error ... I don't know yet _what_ the source of that error
is. or if it's a red-herring.
i _suspect_ the problem is on the dovecot/sieve end; maybe my sieve service
config -- or, perhaps a bug there; either way, i'd like (dis)prove it to myself.
my initial questions at this point are simply:
do the current logs, below, suggest an obvious cause of the problem,
whether postfix- or dovecot-?
if not, what specific logging on the postfix end should be enabled, or
increased in verbosity, so as to get more detail re: relevant cause? if any.
here's what I see atm; after clean start
==> /var/log/dovecot/dovecot.log <==
Sep 27 10:08:11 mx postfix/postfix-script[14388]: starting the Postfix
mail system
Sep 27 10:08:11 mx postfix/master[14390]: daemon started -- version
3.5.7, configuration /etc/postfix
==> /var/log/dovecot/dovecot-info.log <==
2020-09-27 10:08:12 master: Info: Dovecot v2.3.10.1 (a3d0e1171)
starting up for imap, submission, lmtp, sieve
where
postfix submission listens on 10.0.1.17:465
dovecot submission listens on 10.0.1.17:60465
& dovecot config includes
submission_host = internal.mx.example.com:60465
submission_relay_host = internal.mx.example.com
submission_relay_port = 465
submission_relay_ssl = smtps
submission_relay_ssl_verify = yes
submission_relay_trusted = yes
service lmtp {
unix_listener /var/spool/postfix/private/dovecot-lmtp {
mode = 0600
user = postfix
group = postfix
}
& with a defined sieve filter,
ls -al /srv/vmail/sieve-scripts/us...@example1.net.sieve
lrwxrwxrwx 1 vmail vmail 64 Sep 26 12:31
'/srv/vmail/sieve-scripts/us...@example1.net.sieve' ->
/srv/vmail/example1.net/user1/Maildir/sieve/managesieve.sieve
cat /srv/vmail/sieve-scripts/us...@example1.net.sieve
# rule:[SIEVETEST]
if header :contains "subject" "SIEVETEST"
{
redirect "us...@example2.net";
}
mail send, NOT triggering the sieve filter,
echo "Subject: DIRECT" | /usr/sbin/sendmail.postfix us...@example1.net
succeeds/logs,
==> /var/log/dovecot/dovecot-info.log <==
2020-09-27 10:12:58 lmtp(15360): Info: Connect from local
2020-09-27 10:12:58
lmtp(us...@example1.net)<KFvkCRrIcF8APAAA+IOfAw>: Info: sieve:
msgid=<4bzsff0zm0zw...@mx.example.com>: stored mail into mailbox 'INBOX'
2020-09-27 10:12:58 lmtp(15360): Info: Disconnect from local:
Client has quit the connection (state=READY)
==> /var/log/postfix/postfix.log <==
Sep 27 10:12:58 mx postfix/pickup[15271]: 4Bzsff0zM0zWf9N:
uid=0 from=<root>
Sep 27 10:12:58 mx postfix/cleanup[15343]: 4Bzsff0zM0zWf9N:
message-id=<4bzsff0zm0zw...@mx.example.com>
Sep 27 10:12:58 mx postfix/qmgr[15270]: 4Bzsff0zM0zWf9N:
from=<r...@mx.example.com>, size=297, nrcpt=1 (queue active)
Sep 27 10:12:58 mx postfix/lmtp-relay/lmtp[15354]:
4Bzsff0zM0zWf9N: to=<us...@example1.net>,
relay=internal.mx.example.com[private/dovecot-lmtp], delay=0.08,
delays=0.01/0.01/0.01/0.04, dsn=2.0.0, status=sent (250 2.0.0
<us...@example1.net> KFvkCRrIcF8APAAA+IOfAw Saved)
Sep 27 10:12:58 mx postfix/qmgr[15270]: 4Bzsff0zM0zWf9N: removed
& mail send, NOT triggering the sieve filter,
echo "Subject: DIRECT" | /usr/sbin/sendmail.postfix us...@example2.net
also succeeds/logs
tail -f /var/log/postfix/* /var/log/dovecot/*
==> /var/log/dovecot/dovecot-info.log <==
2020-09-27 10:13:25 lmtp(15406): Info: Connect from local
==> /var/log/postfix/postfix.log <==
Sep 27 10:13:25 mx postfix/pickup[15271]: 4Bzsln6T8wzWfB1:
uid=0 from=<root>
Sep 27 10:13:25 mx postfix/cleanup[15389]: 4Bzsln6T8wzWfB1:
message-id=<4bzsln6t8wzw...@mx.example.com>
Sep 27 10:13:25 mx postfix/qmgr[15270]: 4Bzsln6T8wzWfB1:
from=<r...@mx.example.com>, size=297, nrcpt=1 (queue active)
==> /var/log/dovecot/dovecot-info.log <==
2020-09-27 10:13:25
lmtp(us...@example2.net)<52dpOCXJcF8uPAAA+IOfAw>: Info:
msgid=<4bzsln6t8wzw...@mx.example.com>: saved mail to INBOX
2020-09-27 10:13:25 lmtp(15406): Info: Disconnect from local:
Client has quit the connection (state=READY)
==> /var/log/postfix/postfix.log <==
Sep 27 10:13:25 mx postfix/lmtp-relay/lmtp[15405]:
4Bzsln6T8wzWfB1: to=<us...@example2.net>,
relay=internal.mx.example.com[private/dovecot-lmtp], delay=0.1,
delays=0.03/0.01/0.01/0.05, dsn=2.0.0, status=sent (250 2.0.0
<us...@example2.net> 52dpOCXJcF8uPAAA+IOfAw Saved)
Sep 27 10:13:25 mx postfix/qmgr[15270]: 4Bzsln6T8wzWfB1: removed
but, mail send, TRIGGERING the sieve script,
echo "Subject: SIEVETEST" | /usr/sbin/sendmail.postfix
us...@example1.net
fails/logs,
cat /var/log/dovecot/20200927-102234.15418.1.trace
Sieve trace log for message delivery:
Username: us...@example1.net
Session ID: JKRfCFrKcF86PAAA+IOfAw
Sender: <r...@mx.example.com>
Final recipient: <us...@example1.net>
Default mailbox: INBOX
00000000: ## Started executing script 'managesieve'
0000001e: 2: not jumping
00000023: 4: redirect action
00000023: 4: forward message to address
<us...@example2.net>
00000048: ## Finished executing script 'managesieve'
tail -f /var/log/postfix/* /var/log/dovecot/*
==> /var/log/dovecot/dovecot-info.log <==
2020-09-27 10:15:19 lmtp(15360): Info: Connect from local
==> /var/log/dovecot/dovecot-debug.log <==
2020-09-27 10:15:19 submission-login: Debug: SSL: where=0x10,
ret=1: before SSL initialization
2020-09-27 10:15:19 submission-login: Debug: SSL: where=0x2001,
ret=1: before SSL initialization
2020-09-27 10:15:19 submission-login: Debug: SSL: where=0x2002,
ret=-1: before SSL initialization
2020-09-27 10:15:19 submission-login: Debug: SSL: where=0x2002,
ret=-1: before SSL initialization
==> /var/log/postfix/postfix.log <==
Sep 27 10:15:19 mx postfix/pickup[15271]: 4Bzsg33hvQzWf9N:
uid=0 from=<root>
Sep 27 10:15:19 mx postfix/cleanup[15343]: 4Bzsg33hvQzWf9N:
message-id=<4bzsg33hvqzw...@mx.example.com>
Sep 27 10:15:19 mx postfix/qmgr[15270]: 4Bzsg33hvQzWf9N:
from=<r...@mx.example.com>, size=298, nrcpt=1 (queue active)
( this is a reproducible, exactly 30-second delay ... )
==> /var/log/dovecot/dovecot.log <==
2020-09-27 10:15:49
lmtp(us...@example1.net)<uHZDHy/IcF8APAAA+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-27 10:15:49
lmtp(us...@example1.net)<uHZDHy/IcF8APAAA+IOfAw>: Error: sieve:
msgid=<4bzsg33hvqzw...@mx.example.com>: redirect action: failed to redirect
message to <us...@example2.net>: smtp(internal.mx.example.com:60465): RCPT TO
failed: Connect timed out (temporary failure)
==> /var/log/dovecot/dovecot-debug.log <==
2020-09-27 10:15:49 submission-login: Debug: SSL: where=0x2002,
ret=-1: before SSL initialization
2020-09-27 10:15:49 submission-login: Debug: SSL: where=0x2002,
ret=-1: error
2020-09-27 10:15:49 submission-login: Debug: SSL error:
SSL_accept() failed: error:1408F10B:SSL routines:ssl3_get_record:wrong version
number
==> /var/log/dovecot/dovecot.log <==
2020-09-27 10:15:49 submission-login: Error: smtp-server: conn
10.0.1.17:37444 [1]: Connection lost: read((conn:10.0.1.17:37444,id=1)) failed:
SSL_accept() failed: error:1408F10B:SSL routines:ssl3_get_record:wrong version
number
2020-09-27 10:15:49
lmtp(us...@example1.net)<uHZDHy/IcF8APAAA+IOfAw>: Error: sieve: Execution of
script /srv/vmail/sieve-scripts/us...@example1.net.sieve was aborted due to
temporary failure (user logfile
/srv/vmail/sieve-scripts/us...@example1.net.sieve.log may reveal additional
details)
==> /var/log/dovecot/dovecot-debug.log <==
2020-09-27 10:15:49 submission-login: Debug: SSL error:
SSL_accept() syscall failed: Invalid argument
==> /var/log/dovecot/dovecot-info.log <==
2020-09-27 10:15:49 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-27 10:15:49 lmtp(15360): Info: Disconnect from local:
Client has quit the connection (state=READY)
==> /var/log/postfix/postfix.log <==
Sep 27 10:15:49 mx postfix/lmtp-relay/lmtp[15354]:
4Bzsg33hvQzWf9N: to=<us...@example1.net>,
relay=internal.mx.example.com[private/dovecot-lmtp], delay=30, delays=0/0/0/30,
dsn=4.2.0, status=deferred (host internal.mx.example.com[private/dovecot-lmtp]
said: 451 4.2.0 <us...@example1.net> Execution of Sieve filters was aborted due
to temporary failure (in reply to end of DATA command))
