sieve_after seems to not bring any effect to life in dovecot 2.3.13 dovecot-pigeonhole-0.5.13

Fri Feb 26 13:43:02 EET 2021

On 16/02/2021 14:19, Bug Report wrote:
> 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 at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: Pigeonhole version 0.5.13 (cdd19fe3) initializing
> Feb 16 11:32:29 lda(mymail at 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 at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: file storage: Using active Sieve script path: /usr/home/myuser/mail/mymail at mydomain/.dovecot.sieve
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: file storage: Using script storage path: /usr/home/myuser/mail/mymail at mydomain/sieve
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: file storage: Relative path to sieve storage in active link: sieve/
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: file storage: Using Sieve script path: /usr/home/myuser/mail/mymail at mydomain/.dovecot.sieve
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: file storage: script `managesieve': Opened script `managesieve' from `/usr/home/myuser/mail/mymail at mydomain/.dovecot.sieve'
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: Using the following location for user's Sieve script: /usr/home/myuser/mail/mymail at mydomain/.dovecot.sieve
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: file storage: Using script storage path: /usr/local/etc/dovecot/sieve_after
> Feb 16 11:32:29 lda(mymail at 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 at 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 at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: Opening script 1 of 2 from `/usr/home/myuser/mail/mymail at mydomain/.dovecot.sieve'
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: Loading script /usr/home/myuser/mail/mymail at mydomain/.dovecot.sieve
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: Script binary /usr/home/myuser/mail/mymail at mydomain/.dovecot.svbin successfully loaded
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: binary /usr/home/myuser/mail/mymail at mydomain/.dovecot.svbin: save: not saving binary, because it is already stored
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: Executing script from `/usr/home/myuser/mail/mymail at mydomain/.dovecot.svbin'
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: Started running script `/usr/home/myuser/mail/mymail at mydomain/.dovecot.svbin'
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: sieve: Finished running script `/usr/home/myuser/mail/mymail at mydomain/.dovecot.svbin'
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Connection created
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Created
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Add recipient
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Send
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Start
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Add transaction
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Disconnected
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Looking up IP address
> Feb 16 11:32:29 lda(mymail at 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 at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Connecting
> Feb 16 11:32:29 lda(mymail at 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 at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Client connected (fd=13)
> Feb 16 11:32:29 lda(mymail at 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 at 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 at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Sending EHLO handshake
> Feb 16 11:32:29 lda(mymail at 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 at 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 at 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 at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Received handshake reply
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Received server capabilities
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Connection ready
> Feb 16 11:32:29 lda(mymail at 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 at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Start next transaction
> Feb 16 11:32:29 lda(mymail at 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 at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Sending MAIL command
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command MAIL: Submitted
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Sending recipients
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command RCPT: Submitted
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Sending data
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command BDAT: Submitted
> Feb 16 11:32:29 lda(mymail at 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 at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command MAIL: Sent: MAIL FROM:<mymail at mydomain>
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: command RCPT: Sent: RCPT TO:<anothermail at anotherserver>
> Feb 16 11:32:29 lda(mymail at 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 at 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 at 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 at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Start timeout
> Feb 16 11:32:29 lda(mymail at 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 at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Reset timeout
> Feb 16 11:32:29 lda(mymail at 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 at 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 at 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 at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Reset timeout
> Feb 16 11:32:29 lda(mymail at 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 at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: rcpt <anothermail at anotherserver>: Aborted
> Feb 16 11:32:29 lda(mymail at 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 at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Initiate next transaction
> Feb 16 11:32:29 lda(mymail at 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 at 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 at 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 at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: rcpt <anothermail at anotherserver>: Finished
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Finished
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Destroy
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: transaction: Abort
> Feb 16 11:32:29 lda(mymail at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Abort transaction
> Feb 16 11:32:29 lda(mymail at 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 at mydomain)<36105><ptwfDdEf22RyjQRRZ3caGf>: Debug: smtp-client: conn 127.0.0.1:25 [1]: Disconnected
> Feb 16 11:32:29 lda(mymail at 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 at 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 at dovecot.org" ;

The log ends here abruptly, which makes no sense. Also the SMTP log 
tells me the remote server is not accepting the message ("550 Stop: 
forwarding SPAM."), which is ample reason not to continue executing the 
next Sieve script.

Regards,

Stephan.
>
>>> 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
>>
>>