I?m running dovecot 2.2.27 and pigeonhole 0.4.16 on FreeBSD 11.
I?m using the pigeonhole/sieve external pipe plugin to run a Perl program to
send a Pushover notification when certain messages are received.
The Perl script is executed, and the notification is sent. But then the script
task seems to go zombie until it is killed after a timeout.
In the user?s sieve log, I get a message like
error: msgid=<20170112191921.66140.qmail at v1.redhorse.me>: pipe action:
failed to pipe message to program `sievepush.pl': refer to server log for
more information. [2017-01-12 14:19:36].
(even though the message really was piped to the program successfully)
In the dovecot server log, I see
Jan 12 14:19:21 v1 dovecot: lda(matt): Debug: sieve: Executing script from
`/usr/home/matt/maildoms/.dovecot.svbin'
Jan 12 14:19:21 v1 dovecot: lda(matt): Debug: sieve: action pipe: running
program: sievepush.pl
Jan 12 14:19:21 v1 dovecot: lda(matt): Debug: Mailbox stdin: Opened mail UID=1
because: mail stream
Jan 12 14:19:21 v1 dovecot: lda(matt): Debug: waiting for program
`/usr/local/lib/dovecot/sieve-pipe/sievepush.pl' to finish after 0 msecs
Jan 12 14:19:31 v1 dovecot: lda(matt): Debug: program
`/usr/local/lib/dovecot/sieve-pipe/sievepush.pl'(66145) execution timed out
after 10000 milliseconds: sending TERM signal
Jan 12 14:19:36 v1 dovecot: lda(matt): Debug: program
`/usr/local/lib/dovecot/sieve-pipe/sievepush.pl' (66145) did not die after
5000 milliseconds: sending KILL signal
In the process list during that 10 second interval, I see
matt 66142 29972 801 801 0 S - 0:00.00 bin/qmail-local --
matt /home/matt/maildoms jmn-matt - jmn-m
matt 66143 66142 801 801 0 S - 0:00.00
/var/qmail/bin/preline -f /usr/local/libexec/dovecot/dovecot
matt 66144 66143 801 801 0 S - 0:00.01
/usr/local/libexec/dovecot/dovecot-lda
matt 66145 66144 801 801 0 Z - 0:00.65 <defunct>
I?m not a Unix programming ace, but from what I?ve been able to find out, this
seems to mean that the lda process is forking another process to run the pipe
script, and not getting the proper notification when it finishes (not issuing a
wait?). So after 10 seconds, it sends a TERM to the task which is no longer
running, and when that doesn?t work, it sends a KILL. Anybody know what?s
happening here?
doveconf -n
# 2.2.27 (c0f36b0): /usr/local/etc/dovecot/dovecot.conf
# Pigeonhole version 0.4.16 (fed8554)
# OS: FreeBSD 11.0-RELEASE-p2 amd64
auth_verbose = yes
default_vsz_limit = 128 M
lock_method = flock
mail_debug = yes
mail_location = maildir:~/Maildir
mail_privileged_group = mail
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 index ihave duplicate
mime foreverypart extracttext vnd.dovecot.pipe vnd.dovecot.execute
namespace inbox {
inbox = yes
location prefix }
passdb {
args = imap
driver = pam
}
plugin {
recipient_delimiter = -
sieve = file:~/sieve;active=~/.dovecot.sieve
sieve_execute_bin_dir = /usr/local/lib/dovecot/sieve-pipe
sieve_extensions = +vnd.dovecot.pipe +vnd.dovecot.execute
sieve_pipe_bin_dir = /usr/local/lib/dovecot/sieve-pipe
sieve_pipe_exec_timeout = 10s
sieve_plugins = sieve_extprograms
}
protocols = imap
service auth {
unix_listener auth-master {
group = qnofiles
mode = 0660
user = alias
}
user = root
}
service imap-login {
process_min_avail = 3
vsz_limit = 94 M
}
ssl_cert = </usr/local/etc/letsencrypt/live/dummy.redhorse.me/cert.pem
ssl_key = # hidden, use -P to show it
syslog_facility = local0
userdb {
driver = passwd
}
verbose_proctitle = yes
protocol lda {
mail_plugins = " sieve"
}
> On January 12, 2017 at 9:55 PM Matt Simpson <dclist at list.jmatt.net> wrote: > > > I?m running dovecot 2.2.27 and pigeonhole 0.4.16 on FreeBSD 11. > > I?m using the pigeonhole/sieve external pipe plugin to run a Perl program to send a Pushover notification when certain messages are received. > > The Perl script is executed, and the notification is sent. But then the script task seems to go zombie until it is killed after a timeout. > > In the user?s sieve log, I get a message like > > error: msgid=<20170112191921.66140.qmail at v1.redhorse.me>: pipe action: failed to pipe message to program `sievepush.pl': refer to server log for more information. [2017-01-12 14:19:36]. > > (even though the message really was piped to the program successfully) > > In the dovecot server log, I see > > Jan 12 14:19:21 v1 dovecot: lda(matt): Debug: sieve: Executing script from `/usr/home/matt/maildoms/.dovecot.svbin' > Jan 12 14:19:21 v1 dovecot: lda(matt): Debug: sieve: action pipe: running program: sievepush.pl > Jan 12 14:19:21 v1 dovecot: lda(matt): Debug: Mailbox stdin: Opened mail UID=1 because: mail stream > Jan 12 14:19:21 v1 dovecot: lda(matt): Debug: waiting for program `/usr/local/lib/dovecot/sieve-pipe/sievepush.pl' to finish after 0 msecs > Jan 12 14:19:31 v1 dovecot: lda(matt): Debug: program `/usr/local/lib/dovecot/sieve-pipe/sievepush.pl'(66145) execution timed out after 10000 milliseconds: sending TERM signal > Jan 12 14:19:36 v1 dovecot: lda(matt): Debug: program `/usr/local/lib/dovecot/sieve-pipe/sievepush.pl' (66145) did not die after 5000 milliseconds: sending KILL signal > > In the process list during that 10 second interval, I see > > matt 66142 29972 801 801 0 S - 0:00.00 bin/qmail-local -- matt /home/matt/maildoms jmn-matt - jmn-m > matt 66143 66142 801 801 0 S - 0:00.00 /var/qmail/bin/preline -f /usr/local/libexec/dovecot/dovecot > matt 66144 66143 801 801 0 S - 0:00.01 /usr/local/libexec/dovecot/dovecot-lda > matt 66145 66144 801 801 0 Z - 0:00.65 <defunct> > > I?m not a Unix programming ace, but from what I?ve been able to find out, this seems to mean that the lda process is forking another process to run the pipe script, and not getting the proper notification when it finishes (not issuing a wait?). So after 10 seconds, it sends a TERM to the task which is no longer running, and when that doesn?t work, it sends a KILL. Anybody know what?s happening here? >Seems that we are not doing waitpid() on your program when it's killed. Also, I guess we should wait longer than 0 msecs. I'll try and see if I can replicate this. Aki
On 2017-01-12 21:55, Matt Simpson wrote:> I?m running dovecot 2.2.27 and pigeonhole 0.4.16 on FreeBSD 11. > > I?m using the pigeonhole/sieve external pipe plugin to run a Perl program to send a Pushover notification when certain messages are received. > > The Perl script is executed, and the notification is sent. But then the script task seems to go zombie until it is killed after a timeout. > > In the user?s sieve log, I get a message like > > error: msgid=<20170112191921.66140.qmail at v1.redhorse.me>: pipe action: failed to pipe message to program `sievepush.pl': refer to server log for more information. [2017-01-12 14:19:36]. > > (even though the message really was piped to the program successfully) > > In the dovecot server log, I see > > Jan 12 14:19:21 v1 dovecot: lda(matt): Debug: sieve: Executing script from `/usr/home/matt/maildoms/.dovecot.svbin' > Jan 12 14:19:21 v1 dovecot: lda(matt): Debug: sieve: action pipe: running program: sievepush.pl > Jan 12 14:19:21 v1 dovecot: lda(matt): Debug: Mailbox stdin: Opened mail UID=1 because: mail stream > Jan 12 14:19:21 v1 dovecot: lda(matt): Debug: waiting for program `/usr/local/lib/dovecot/sieve-pipe/sievepush.pl' to finish after 0 msecs > Jan 12 14:19:31 v1 dovecot: lda(matt): Debug: program `/usr/local/lib/dovecot/sieve-pipe/sievepush.pl'(66145) execution timed out after 10000 milliseconds: sending TERM signal > Jan 12 14:19:36 v1 dovecot: lda(matt): Debug: program `/usr/local/lib/dovecot/sieve-pipe/sievepush.pl' (66145) did not die after 5000 milliseconds: sending KILL signal > > In the process list during that 10 second interval, I see > > matt 66142 29972 801 801 0 S - 0:00.00 bin/qmail-local -- matt /home/matt/maildoms jmn-matt - jmn-m > matt 66143 66142 801 801 0 S - 0:00.00 /var/qmail/bin/preline -f /usr/local/libexec/dovecot/dovecot > matt 66144 66143 801 801 0 S - 0:00.01 /usr/local/libexec/dovecot/dovecot-lda > matt 66145 66144 801 801 0 Z - 0:00.65 <defunct> > > I?m not a Unix programming ace, but from what I?ve been able to find out, this seems to mean that the lda process is forking another process to run the pipe script, and not getting the proper notification when it finishes (not issuing a wait?). So after 10 seconds, it sends a TERM to the task which is no longer running, and when that doesn?t work, it sends a KILL. Anybody know what?s happening here? > > doveconf -n > # 2.2.27 (c0f36b0): /usr/local/etc/dovecot/dovecot.conf > # Pigeonhole version 0.4.16 (fed8554) > # OS: FreeBSD 11.0-RELEASE-p2 amd64 > auth_verbose = yes > default_vsz_limit = 128 M > lock_method = flock > mail_debug = yes > mail_location = maildir:~/Maildir > mail_privileged_group = mail > 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 index ihave duplicate mime foreverypart extracttext vnd.dovecot.pipe vnd.dovecot.execute > namespace inbox { > inbox = yes > location > prefix > } > passdb { > args = imap > driver = pam > } > plugin { > recipient_delimiter = - > sieve = file:~/sieve;active=~/.dovecot.sieve > sieve_execute_bin_dir = /usr/local/lib/dovecot/sieve-pipe > sieve_extensions = +vnd.dovecot.pipe +vnd.dovecot.execute > sieve_pipe_bin_dir = /usr/local/lib/dovecot/sieve-pipe > sieve_pipe_exec_timeout = 10s > sieve_plugins = sieve_extprograms > } > protocols = imap > service auth { > unix_listener auth-master { > group = qnofiles > mode = 0660 > user = alias > } > user = root > } > service imap-login { > process_min_avail = 3 > vsz_limit = 94 M > } > ssl_cert = </usr/local/etc/letsencrypt/live/dummy.redhorse.me/cert.pem > ssl_key = # hidden, use -P to show it > syslog_facility = local0 > userdb { > driver = passwd > } > verbose_proctitle = yes > protocol lda { > mail_plugins = " sieve" > }Hi! I tried reproducing your issue, but unfortunately using the exact version you are using yielded nothing useful. Feb 23 19:47:45 lda(testuser1): Debug: program `/home/cmouse/dovecot22/sieve-pipe/test-program.pl'(8691) execution timed out after 10000 milliseconds: sending TERM signal Feb 23 19:47:45 lda(testuser1): Error: program `/home/cmouse/dovecot22/sieve-pipe/test-program.pl' was forcibly terminated with signal 15 ... Feb 23 19:47:45 lda(testuser1): Info: sieve: Execution of script /home/cmouse/dovecot22/home/vmail/testuser1/.dovecot.sieve failed, but implicit keep was successful (user logfile /home/cmouse/dovecot22/home/vmail/testuser1/.dovecot.sieve.log may reveal additional details) Do you think you could try if v2.2.28rc2 fixes the problem? Aki
> On Feb 23, 2017, at 12:50 PM, Aki Tuomi <aki.tuomi at dovecot.fi> wrote: > > I tried reproducing your issue, but unfortunately using the exact version you are using yielded nothing useful. > > Do you think you could try if v2.2.28rc2 fixes the problem?That wouldn?t be easy. Dovecot is installed on my system via FreeBSD package, not compiled from source. Installing a test version that isn?t released as a package would be a little inconvenient.