It used to start executing a step titled "Opening script 2 of 2 from `/usr/local/etc/dovecot/sieve_after/movespam.sieve'". At this moment software seems to behave differently after server was updated. Now this step is not performed after attempt on sending e-mail in the 1st step.
Here are (redacted) logs:
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: Pigeonhole version 0.5.13 (cdd19fe3) initializing
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: include: sieve_global is not set; it is currently not possible to include :global' scripts. Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: file storage: Using active Sieve script path: /usr/home/myuser/mail/mymail@mydomain/.dovecot.sieve Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: file storage: Using script storage path: /usr/home/myuser/mail/mymail@mydomain/sieve Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: file storage: Relative path to sieve storage in active link: sieve/ Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: file storage: Using Sieve script path: /usr/home/myuser/mail/mymail@mydomain/.dovecot.sieve Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: file storage: script managesieve': Opened script managesieve' from /usr/home/myuser/mail/mymail@mydomain/.dovecot.sieve'
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: Using the following location for user's Sieve script: /usr/home/myuser/mail/mymail@mydomain/.dovecot.sieve
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: file storage: Using script storage path: /usr/local/etc/dovecot/sieve_after
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: file storage: script: Opened script movespam' from /usr/local/etc/dovecot/sieve_after/movespam.sieve'
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: executed after user's Sieve script(2): /usr/local/etc/dovecot/sieve_after/movespam.sieve
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: Opening script 1 of 2 from /usr/home/myuser/mail/mymail@mydomain/.dovecot.sieve' Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: Loading script /usr/home/myuser/mail/mymail@mydomain/.dovecot.sieve Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: Script binary /usr/home/myuser/mail/mymail@mydomain/.dovecot.svbin successfully loaded Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: binary /usr/home/myuser/mail/mymail@mydomain/.dovecot.svbin: save: not saving binary, because it is already stored Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: Executing script from /usr/home/myuser/mail/mymail@mydomain/.dovecot.svbin'
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: Started running script /usr/home/myuser/mail/mymail@mydomain/.dovecot.svbin' Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: Finished running script /usr/home/myuser/mail/mymail@mydomain/.dovecot.svbin'
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Connection created
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Created
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Add recipient
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Send
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Start
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Add transaction
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Disconnected
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Looking up IP address
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Connecting to 127.0.0.1:25
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Connecting
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Waiting for connect (fd=13) to finish for max 0 msecs
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Client connected (fd=13)
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Connected to server (from 127.0.0.1:27631)
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Received greeting from server: 220 myserver ESMTP Exim 4.94 Tue, 16 Feb 2021 11:32:29 +0100
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Sending EHLO handshake
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command EHLO: Submitted with priority
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command EHLO: Sent: EHLO myserver.host
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command EHLO: Got reply (1/1): 250 myserver Hello 1874 at myserver.host [127.0.0.1] SIZE 209715200 8BITMIME PIPELINING X_PIPE_CONNECT AUTH LOGIN PLAIN CHUNKING STARTTLS HELP (1 commands pending, 0 commands queued)
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Received handshake reply
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Received server capabilities
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Connection ready
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command EHLO: Destroy (0 commands pending, 0 commands queued)
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Start next transaction
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Connecton is ready for transaction
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Sending MAIL command
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command MAIL: Submitted
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Sending recipients
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command RCPT: Submitted
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Sending data
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command BDAT: Submitted
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: RCPT replies are still pending (1/1)
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command MAIL: Sent: MAIL FROM:<mymail@mydomain>
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command RCPT: Sent: RCPT TO:<anothermail@anotherserver>
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command BDAT: Finished reading payload stream
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command BDAT: Finished sending payload
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command BDAT: Sent: BDAT 1193 LAST
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Start timeout
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command MAIL: Got reply (1/1): 250 OK (3 commands pending, 0 commands queued)
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Reset timeout
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Got MAIL reply: 250 OK
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command MAIL: Destroy (2 commands pending, 0 commands queued)
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command RCPT: Got reply (1/1): 250 Accepted (2 commands pending, 0 commands queued)
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Reset timeout
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Got RCPT reply: 250 Accepted
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: rcpt <anothermail@anotherserver>: Aborted
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Got all RCPT replies and transaction is complete
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Initiate next transaction
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command RCPT: Destroy (1 commands pending, 0 commands queued)
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command BDAT: Got reply (1/1): 550 Stop: forwarding SPAM. (1 commands pending, 0 commands queued)
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: No commands pending; stop timeout
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: rcpt <anothermail@anotherserver>: Finished
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Finished
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Destroy
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Abort
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Abort transaction
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command BDAT: Destroy (0 commands pending, 0 commands queued)
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Disconnected
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Disconnected: Connection closed (fd=13)
Feb 16 11:32:29 lda(mymail@mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: DestroyTemat: Re: sieve_after seems to not bring any effect to life in dovecot 2.3.13 dovecot-pigeonhole-0.5.13
Data: 2021-02-16 12:16
Nadawca: "Aki Tuomi"
Adresat: "Bug Report" ; "dovecot@dovecot.org" ;
On 16/02/2021 13:00 Bug Report wrote:
it looks like sieve_after gets executed only when sending to an address defined in script failsTemat: Re: sieve_after seems to not bring any effect to life in dovecot 2.3.13 dovecot-pigeonhole-0.5.13 Data: 2021-02-12 10:27
Did you try mail_debug=yes? Can you share the logs?
Aki