dovecot - Nov 2018 - execute sieve command - fails to notice script has exited

Did you look at the server logs as suggested by the logfile?

Aki
> On 13 November 2018 at 18:52 Lionel Elie Mamane <lionel at mamane.lu>
wrote:
> 
> 
> And the Sieve script:
> 
> ------- start sieve script ---------
> require ["vnd.dovecot.execute", "fileinto",
"mailbox", "vnd.dovecot.debug"];
> 
> debug_log "about to execute";
> if not execute :pipe "foofilter" {
>   debug_log "if condition fulfilled";
>   fileinto :create "test-spam";
>   debug_log "about to stop";
>   stop;
> }
> debug_log "after execute";
> ------- end sieve script ---------
> 
> The user's sieve log looks like:
> 
> sieve: info: started log at Nov 13 16:56:32.
> test-foofilter: line 3: info: DEBUG: about to execute.
> test-foofilter: line 4: error: execute action: failed to execute to program
`foofilter': refer to server log for more information. [2018-11-13
16:59:57].
> test-foofilter: line 5: info: DEBUG: if condition fulfilled.
> test-foofilter: line 7: info: DEBUG: about to stop.
> info: msgid=<20181113155632.k6pybm45sdwwp2bs at
blitz.conuropsis.org>: stored mail into mailbox 'test-spam'.
> 
> 
> On Tue, Nov 13, 2018 at 05:00:21PM +0100, Lionel Elie Mamane wrote:
> > Hi,
> > 
> > Running dovecot 2.2.27 (c0f36b0) on Debian GNU/Linux stable (version
> > 9.6), I'm trying to use the execute command in a sieve script,
with
> > direct execution (not service socket).
> > 
> > The script is executed, and returns (the process exits), but the
> > dovecot-lda process seems to not notice, and thinks the script did not
> > terminate. After sieve_execute_exec_timeout has passed, it sends a
> > TERM, a bit later a KILL and then logs a failure.
> > 
> > The "ps -Af f" looks like:
> > S      0:00  \_ /usr/sbin/exim4 -Mc 1gMazS-0007IV-RB
> > S      0:00      \_ /usr/lib/dovecot/dovecot-lda -f master at
blitz.conuropsis.org
> > Z      0:00      |   \_ [foofilter] <defunct>
> > S      0:00      \_ /usr/sbin/exim4 -Mc 1gMazS-0007IV-RB
> > 
> > The dovecot debug log looks like:
> > 
> > lda(user): Debug: Loading modules from directory:
/usr/lib/dovecot/modules
> > lda(user): Debug: Module loaded:
/usr/lib/dovecot/modules/lib90_sieve_plugin.so
> > lda(user): Debug: Effective uid=1000, gid=1000, home=/home/user
> > lda(user): Debug: maildir++: root=/home/user/Maildir, index=,
indexpvt=, control=, inbox=/home/user/Maildir, alt> > lda(user): Debug:
userdb lookup skipped, username taken from USER environment
> > lda(user): Debug: none: root=, index=, indexpvt=, control=, inbox=,
alt> > lda(user): Debug: Destination address: user at blitz.conuropsis.org
(source: user at hostname)
> > lda(user): Debug: sieve: Pigeonhole version 0.4.16 (fed8554)
initializing
> > lda(user): Debug: sieve: include: sieve_global is not set; it is
currently not possible to include `:global' scripts.
> > lda(user): Debug: sieve: Sieve imapsieve plugin for Pigeonhole version
0.4.16 (fed8554) loaded
> > lda(user): Debug: sieve: Sieve Extprograms plugin for Pigeonhole
version 0.4.16 (fed8554) loaded
> > lda(user): Debug: sieve: file storage: Using active Sieve script path:
/data/home/user/.dovecot.sieve
> > lda(user): Debug: sieve: file storage: Using script storage path:
/home/user/sieve
> > lda(user): Debug: sieve: file storage: Relative path to sieve storage
in active link: sieve/
> > lda(user): Debug: sieve: file storage: Using Sieve script path:
/data/home/user/.dovecot.sieve
> > lda(user): Debug: sieve: file script: Opened script
`test-foofilter' from `/data/home/user/.dovecot.sieve'
> > lda(user): Debug: sieve: Using the following location for user's
Sieve script: /data/home/user/.dovecot.sieve
> > lda(user): Debug: Mailbox stdin: Opened mail UID=1 because: header
Message-ID (Cache file is unusable)
> > lda(user): Debug: sieve: Opening script 1 of 1 from
`/data/home/user/.dovecot.sieve'
> > lda(user): Debug: sieve: Loading script /data/home/user/.dovecot.sieve
> > lda(user): Debug: sieve: Script binary /data/home/user/.dovecot.svbin
successfully loaded
> > lda(user): Debug: sieve: binary save: not saving binary
/data/home/user/.dovecot.svbin, because it is already stored
> > lda(user): Debug: sieve: Executing script from
`/data/home/user/.dovecot.svbin'
> > lda(user): Debug: sieve: action execute: running program: foofilter
> > lda(user): Debug: Mailbox stdin: Opened mail UID=1 because: mail
stream
> > lda(user): Debug: waiting for program
`/usr/local/lib/dovecot/sieve-execute/foofilter' to finish after 0 msecs
> > lda(user): Debug: program
`/usr/local/lib/dovecot/sieve-execute/foofilter'(24669) execution timed out
after 2000 milliseconds: sending TERM signal
> > lda(user): Debug: program
`/usr/local/lib/dovecot/sieve-execute/foofilter' (24669) did not die after
5000 milliseconds: sending KILL signal
> > 
> > 
> > and an strace on the dovecot-lda process shows it is in an
> > "epoll_wait(9 ....".
> > 
> > The script is very simple:
> > 
> > #! /bin/sh
> > 
> > cat > /dev/null
> > exit 1
> > 
> > 
> > Anyone has a clue? Thanks in advance.
> > 
> > Best Regards,
> > 
> > Lionel
> >

On Tue, Nov 13, 2018 at 07:10:47PM +0200, Aki Tuomi
wrote:
> Did you look at the server logs as suggested by the logfile?
Yes. The server log is in my first email, where I called it "dovecot
debug log". Sorry the information is over several emails.

-- 
Lionel

> On 13 November 2018 at 20:38 Lionel Elie Mamane <lionel at mamane.lu>
wrote:
> 
> 
> On Tue, Nov 13, 2018 at 07:10:47PM +0200, Aki Tuomi wrote:
> > Did you look at the server logs as suggested by the logfile?
> 
> Yes. The server log is in my first email, where I called it "dovecot
> debug log". Sorry the information is over several emails.
> 
> -- 
> Lionel
The problem is in IO handling, I'm afraid. The way you wrote the script is a
normal way how it won't work. You can't consume stdin like that in this
situation, you probably want to do something like cat </dev/stdin
>/dev/null

Aki