sieve_after seems to not bring any effect to life in dovecot 2.3.13 dovecot-pigeonhole-0.5.13
dovecot 2.3.13 (89f716dc2)
dovecot-pigeonhole-0.5.13
OS: FreeBSD amd64 12.2-RELEASE
After following code
require ["copy"];
# rule:[redirect]
if true
{
redirect :copy "mail@mail.com";
keep;}
(both with keep and without keep) is executed sieve_after seems to not execute at all.
Same code together with sieve_after was working as supposed in earlier versions.
On 11/02/2021 13:30 Bug Report <bug.report@interia.pl> wrote:
dovecot 2.3.13 (89f716dc2)
dovecot-pigeonhole-0.5.13
OS: FreeBSD amd64 12.2-RELEASE
After following code
require ["copy"];
# rule:[redirect]
if true
{
redirect :copy "mail@mail.com"; keep;}
(both with keep and without keep) is executed sieve_after seems to not execute at all.
Same code together with sieve_after was working as supposed in earlier versions.
Please provide output of doveconf -n.
Aki
# 2.3.13 (89f716dc2): /usr/local/etc/dovecot/dovecot.conf
# Pigeonhole version 0.5.13 (cdd19fe3)
# OS: FreeBSD 12.2-RELEASE-p2 amd64
auth_mechanisms = plain login
debug_log_path = /var/log/dovecot/dovecot-debug.log
default_client_limit = 1400
disable_plaintext_auth = no
first_valid_gid = 6
imap_idle_notify_interval = 1 mins
last_valid_gid = 1000
last_valid_uid = 65532
lda_mailbox_autocreate = yes
lda_mailbox_autosubscribe = yes
log_path = /var/log/dovecot/dovecot.log
login_trusted_networks = (my ip address)
mail_fsync = never
mail_location = maildir:/usr/local/virtual/trash
mail_plugins = quota
maildir_stat_dirs = yes
managesieve_notify_capability = mailto
managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date ihave vacation-seconds
mmap_disable = yes
namespace inbox {
inbox = yes
location =
mailbox Drafts {
special_use = \Drafts
}
mailbox Junk {
auto = subscribe
special_use = \Junk
}
mailbox Sent {
auto = subscribe
special_use = \Sent
}
mailbox "Sent Messages" {
special_use = \Sent
}
mailbox Trash {
auto = subscribe
special_use = \Trash
}
prefix =
}
passdb {
args = /usr/local/etc/dovecot/dovecot-sql.conf
driver = sql
}
plugin {
quota = maildir:User quota
quota_rule = *:bytes=0
recipient_delimiter = +
sieve = file:~/sieve;active=~/.dovecot.sieve
sieve_after = /usr/local/etc/dovecot/sieve_after
sieve_extensions = +vacation-seconds
sieve_max_actions = 50
sieve_max_redirects = 50
sieve_max_script_size = 1M
sieve_redirect_envelope_from = recipient
sieve_vacation_default_period = 7d
sieve_vacation_max_period = 0
sieve_vacation_min_period = 1s
}
protocols = imap pop3 sieve
service auth {
unix_listener auth-client {
mode = 0660
user = mailnull
}
unix_listener auth-userdb {
group = mail
mode = 0660
user = mailnull
}
}
service imap-login {
process_limit = 1000
process_min_avail = 0
}
service imap {
process_limit = 8192
vsz_limit = 320 M
}
service managesieve-login {
inet_listener sieve {
port = 4190
}
process_min_avail = 0
service_count = 1
vsz_limit = 256 M
}
service pop3 {
process_limit = 8192
}
ssl_cert = </etc/ssl/certs/pem
ssl_dh = # hidden, use -P to show it
ssl_key = # hidden, use -P to show it
submission_host = 127.0.0.1:25
userdb {
args = /usr/local/etc/dovecot/dovecot-sql.conf
driver = sql
}
verbose_proctitle = yes
protocol lda {
mail_plugins = quota sieve
}
protocol imap {
mail_max_userip_connections = 40
mail_plugins = quota imap_quota
}
protocol pop3 {
mail_max_userip_connections = 40
}
protocol sieve {
managesieve_logout_format = bytes=%i/%o
}Temat: Re: sieve_after seems to not bring any effect to life in dovecot 2.3.13 dovecot-pigeonhole-0.5.13
Data: 2021-02-11 12:46
Nadawca: "Aki Tuomi"
Adresat: "Bug Report" ; dovecot@dovecot.org;
On 11/02/2021 13:30 Bug Report wrote:
dovecot 2.3.13 (89f716dc2)
dovecot-pigeonhole-0.5.13
OS: FreeBSD amd64 12.2-RELEASE
After following code
require ["copy"];
# rule:[redirect]
if true
{
redirect :copy "mail@mail.com"; keep;}
(both with keep and without keep) is executed sieve_after seems to not execute at all.
Same code together with sieve_after was working as supposed in earlier versions.
Please provide output of
doveconf -n.Aki
Can you try turning on mail_debug=yes and see if it sheds any light why the script(s) aren't executed?
Aki
Data: 2021-02-11 12:46 Nadawca: "Aki Tuomi" Adresat: "Bug Report" ; dovecot@dovecot.org;
On 11/02/2021 13:30 Bug Report wrote:
dovecot 2.3.13 (89f716dc2)
dovecot-pigeonhole-0.5.13
OS: FreeBSD amd64 12.2-RELEASE
After following code
require ["copy"];
# rule:[redirect]
if true
{
redirect :copy "mail@mail.com"; keep;}
(both with keep and without keep) is executed sieve_after seems to not execute at all.
Same code together with sieve_after was working as supposed in earlier versions.
Please provide output of
doveconf -n.Aki
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 Nadawca: "Aki Tuomi" Adresat: "Bug Report" ; "dovecot@dovecot.org" ;
Can you try turning on mail_debug=yes and see if it sheds any light why the script(s) aren't executed?
Aki
Data: 2021-02-11 12:46 Nadawca: "Aki Tuomi" Adresat: "Bug Report" ; dovecot@dovecot.org;
On 11/02/2021 13:30 Bug Report wrote:
dovecot 2.3.13 (89f716dc2)
dovecot-pigeonhole-0.5.13
OS: FreeBSD amd64 12.2-RELEASE
After following code
require ["copy"];
# rule:[redirect]
if true
{
redirect :copy "mail@mail.com"; keep;}
(both with keep and without keep) is executed sieve_after seems to not execute at all.
Same code together with sieve_after was working as supposed in earlier versions.
Please provide output of
doveconf -n.Aki
On 16/02/2021 13:00 Bug Report <bug.report@interia.pl> 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
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
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
participants (3)
-
Aki Tuomi
-
Bug Report
-
Stephan Bosch