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: 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" ;
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
