local postfix re-delivery of dovecot sieve-redirected mail fails; normal/direct deliveries are OK ?

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

local postfix re-delivery of dovecot sieve-redirected mail fails; normal/direct deliveries are OK ?

PGNet Dev
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/[hidden email]
                lrwxrwxrwx 1 vmail vmail 64 Sep 26 12:31 '/srv/vmail/sieve-scripts/[hidden email]' -> /srv/vmail/example1.net/user1/Maildir/sieve/managesieve.sieve

        cat /srv/vmail/sieve-scripts/[hidden email]
                # rule:[SIEVETEST]
                if header :contains "subject" "SIEVETEST"
                {
                                redirect "[hidden email]";
                }


mail send, NOT triggering the sieve filter,

        echo "Subject: DIRECT" | /usr/sbin/sendmail.postfix [hidden email]

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([hidden email])<KFvkCRrIcF8APAAA+IOfAw>: Info: sieve: msgid=<[hidden email]>: 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=<[hidden email]>
                Sep 27 10:12:58 mx postfix/qmgr[15270]: 4Bzsff0zM0zWf9N: from=<[hidden email]>, size=297, nrcpt=1 (queue active)
                Sep 27 10:12:58 mx postfix/lmtp-relay/lmtp[15354]: 4Bzsff0zM0zWf9N: to=<[hidden email]>, 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 <[hidden email]> 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 [hidden email]

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=<[hidden email]>
                Sep 27 10:13:25 mx postfix/qmgr[15270]: 4Bzsln6T8wzWfB1: from=<[hidden email]>, size=297, nrcpt=1 (queue active)

                ==> /var/log/dovecot/dovecot-info.log <==
                2020-09-27 10:13:25 lmtp([hidden email])<52dpOCXJcF8uPAAA+IOfAw>: Info: msgid=<[hidden email]>: 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=<[hidden email]>, 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 <[hidden email]> 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 [hidden email]


fails/logs,

        cat /var/log/dovecot/20200927-102234.15418.1.trace

                Sieve trace log for message delivery:

                Username: [hidden email]
                Session ID: JKRfCFrKcF86PAAA+IOfAw
                Sender: <[hidden email]>
                Final recipient: <[hidden email]>
                Default mailbox: INBOX


                00000000:       ## Started executing script 'managesieve'
                0000001e:    2:   not jumping
                00000023:    4: redirect action
                00000023:    4:   forward message to address <[hidden email]>
                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=<[hidden email]>
                Sep 27 10:15:19 mx postfix/qmgr[15270]: 4Bzsg33hvQzWf9N: from=<[hidden email]>, 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([hidden email])<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([hidden email])<uHZDHy/IcF8APAAA+IOfAw>: Error: sieve: msgid=<[hidden email]>: redirect action: failed to redirect message to <[hidden email]>: 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([hidden email])<uHZDHy/IcF8APAAA+IOfAw>: Error: sieve: Execution of script /srv/vmail/sieve-scripts/[hidden email] was aborted due to temporary failure (user logfile /srv/vmail/sieve-scripts/[hidden email] 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=<[hidden email]>, 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 <[hidden email]> Execution of Sieve filters was aborted due to temporary failure (in reply to end of DATA command))


Reply | Threaded
Open this post in threaded view
|

Re: local postfix re-delivery of dovecot sieve-redirected mail fails; normal/direct deliveries are OK ?

Viktor Dukhovni
On Sun, Sep 27, 2020 at 11:31:43AM -0700, PGNet Dev wrote:

> i've postfix + dovecot running on the same box; delivery between them
> is via lmtp.

The main thing that stands to me is the timeout connecing to the
Dovecot submission port.

> ( this is a reproducible, exactly 30-second delay ... )
>
> ==> /var/log/dovecot/dovecot.log <==
> 2020-09-27 10:15:49 lmtp([hidden email])<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
------------------  PROBLEM LIKELY HERE --->
> 2020-09-27 10:15:49 lmtp([hidden email])<uHZDHy/IcF8APAAA+IOfAw>: Error: sieve: msgid=<[hidden email]>: redirect action: failed to redirect message to <[hidden email]>: smtp(internal.mx.example.com:60465): RCPT TO failed: Connect timed out (temporary failure)
------------------ <---

Since both the server and the client here are Dovecot, you might have
better luck on the Dovecot list.  However, ...

> 2020-09-27 10:15:49 submission-login: Debug: SSL error: SSL_accept() failed: error:1408F10B:SSL routines:ssl3_get_record:wrong version number

The above again looks like cleartext (e.g. "QUIT<CRLF>") sent to a port that
expects TLS.


> ==> /var/log/dovecot/dovecot-debug.log <==
> 2020-09-27 10:15:49 submission-login: Debug: SSL error: SSL_accept() syscall failed: Invalid argument

And the above may be the reason why connections are timing out...

--
    Viktor.
Reply | Threaded
Open this post in threaded view
|

Re: local postfix re-delivery of dovecot sieve-redirected mail fails; normal/direct deliveries are OK ?

PGNet Dev
On 9/28/20 1:27 PM, Viktor Dukhovni wrote:
> On Sun, Sep 27, 2020 at 11:31:43AM -0700, PGNet Dev wrote:
>
>> i've postfix + dovecot running on the same box; delivery between them
>> is via lmtp.
>
> The main thing that stands to me is the timeout connecing to the
> Dovecot submission port.

that _is_ postfix connecting "back" to dovecot via lmtp relay, _after_ receiving the redirected message from the sieve filter action, correct?

i suspect i may be incorrectly assuming that the chronology in postfix+dovecot logs is meaningfu :-/

>> ( this is a reproducible, exactly 30-second delay ... )
>>
>> ==> /var/log/dovecot/dovecot.log <==
>> 2020-09-27 10:15:49 lmtp([hidden email])<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
> ------------------  PROBLEM LIKELY HERE --->
>> 2020-09-27 10:15:49 lmtp([hidden email])<uHZDHy/IcF8APAAA+IOfAw>: Error: sieve: msgid=<[hidden email]>: redirect action: failed to redirect message to <[hidden email]>: smtp(internal.mx.example.com:60465): RCPT TO failed: Connect timed out (temporary failure)
> ------------------ <---
>

i saw that's where/when the Error: is occurring; wasn't clear whether it's the result of some message- &/or ssl- munging 'during' the sieve -> postfix -> dovecot circuit.

will look more closely here.

> However, ...
>
>> 2020-09-27 10:15:49 submission-login: Debug: SSL error: SSL_accept() failed: error:1408F10B:SSL routines:ssl3_get_record:wrong version number
> The above again looks like cleartext (e.g. "QUIT<CRLF>") sent to a port that
> expects TLS.
>
>
>> ==> /var/log/dovecot/dovecot-debug.log <==
>> 2020-09-27 10:15:49 submission-login: Debug: SSL error: SSL_accept() syscall failed: Invalid argument
>
> And the above may be the reason why connections are timing out...

i'm pausing at that 'however' ...

couple of questions:


i typically turn ON implicit TLS, with cert verification, for any all TCP transports, local or not.

when a postfix/dovecot, same-machine setup 'share' an lmtp socket, e.g.,

        @ dovecot

                ...
                service lmtp {
                        unix_listener /var/spool/postfix/private/dovecot-lmtp {
                                mode  = 0600
                                user  = postfix
                                group = postfix
                        }
                ...


        @ postfix

                ...
                virtual_transport = lmtp:unix:private/dovecot-lmtp
                ...


iiuc, there's no security need/benefit for any TLS/SSL in that handshake/transport, and can (should?) be disabled.

is that correct?


and,

re: the "port that expects TLS", that appears to be the dovecot 'submission-port'.

to be clear, do I understand your comment

> Since both the server and the client here are Dovecot

correctly that -- by that point -- postfix is out of the picutre completely, & no longer involved, and it's all a dovecot 'issue'?

> you might have better luck on the Dovecot list.

already posted; waiting on any interest/reply there.

useful to know that this is completely !postfix, if indeed the case.

Reply | Threaded
Open this post in threaded view
|

Re: local postfix re-delivery of dovecot sieve-redirected mail fails; normal/direct deliveries are OK ?

PGNet Dev
On 9/28/20 2:06 PM, PGNet Dev wrote:
> already posted; waiting on any interest/reply there.
>
> useful to know that this is completely !postfix, if indeed the case.

ironically, the problem's NOT that postfix *is* 'involved', but that it *isn't*.

use of dovecot's

        submission_host = ...

to either have sieve use dovecot's own submission port, or even postfix's, was causal.


switching

- submission_host = ...

+ sendmail_path = "/usr/sbin/sendmail.postfix"



to instead use postfix's sendmail binary does the trick.

once the switch is made, sieve script generated forwards/redirects seem to work without error.

( i _do_ need to figure out how to correctly lock down use of the binary ...

  iiuc, i think this

    authorized_submit_users = root, filter, vmail

 in postfix conf should be sufficient.
)

sounds like a dovecot submission proxy issue to me; any further chat about it I'll take to dovecot list.