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@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: scriptmanagesieve': Opened scriptmanagesieve' 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 scriptmovespam' 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" ;
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