dovecot - Nov 2019 - Learning ham/spam with IMAPSieve: sa-learn-ham.sh terminated abnormally, signal 11

On 17/11/2019 19:40, Jens Rey via dovecot wrote:
> Since I want to avoid debugging old and already fixed bugs, I updated to
>
> # dovecot --version
> 2.3.8 (9df20d2db)
>
> Now the debug log is a bit more chatty, but the error remains:
>
> Debug: program exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh: Created
> Debug: program exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh: Pass 
> environment: USER=user at domain.tld
> Debug: program exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh: Pass 
> environment: HOME=/var/vmail/mailboxes/domain.tld/user
> Debug: program exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh: Pass 
> environment: HOST=mail.domain.tld
> Debug: Mailbox INBOX: UID 22039: Opened mail because: mail stream
> Debug: program exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh: 
> Establishing connection
> Debug: program exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh: Forked 
> child process
> Debug: program exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (9891): 
> Connected to program
> Error: program exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (9891): 
> write(program stdin) failed: Broken pipe
> Debug: program exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (9891): 
> Failed to run program
> Debug: program exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (9891): 
> Disconnected
> Debug: program exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (9891): 
> Child process ended
> Error: program exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (9891): 
> Terminated abnormally with signal 11
> Debug: program exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (9891): 
> Destroy
> Error: sieve: pipe action: failed to pipe message to program 
> `rspamd-learn-ham.sh': refer to server log for more information. 
> [2019-11-17 19:32:40]
> sieve: left message in mailbox 'INBOX'
> Error: sieve: Execution of script 
> /usr/lib/dovecot/sieve/report-ham.sieve failed
Dovecot forks a child process to execute the program. Subsequently, at 
some point, the child process fails with a segmentation fault. Granted, 
that could still be happening in Dovecot code, but since the child 
process quickly executes the actual program (the shell in this case), it 
is more likely that this problem emerges outside Dovecot.

You can attach GDB to imap with follow-fork-mode set to 'child', so you 
can maybe see what causes the segfault.

Regards,

Stephan.

Hi,
> You can attach GDB to imap with follow-fork-mode set to 'child', so
you
> can maybe see what causes the segfault.
now I am confused. Hopefully, I used GDB correctly, but as far as I can 
see, everything seemed to work.

The only difference I can see is that I executed the whole thing as 
root, but I would hope doveadm uses the correct user (vmail). At least 
on the file system all emails still belong to vmail, so I guess that works.

For a quick reference, here is what I executed:

root at mail:~# gdb --args doveadm exec imap -u user at domain
...
(gdb) set follow-fork-mode child
(gdb) r
. SELECT Spam
. MOVE 1 Inbox

And the (imho) relevant output:

imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Debug: program 
exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh: Establishing connection
[New process 13335]
imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Debug: program 
exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh: Forked child process
imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Debug: program 
exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (13335): Connected to 
program
[Thread debugging using libthread_db enabled]
Using host libthread_db library
"/lib/x86_64-linux-gnu/libthread_db.so.1".
process 13335 is executing new program: /bin/dash
process 13335 is executing new program: /usr/bin/rspamc
[Thread debugging using libthread_db enabled]
Using host libthread_db library
"/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7fffee7ff700 (LWP 13338)]
[New Thread 0x7fffebffe700 (LWP 13339)]
[New Thread 0x7fffe97fd700 (LWP 13340)]
imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Debug: program 
exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (13335): Finished 
streaming payload to program
imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Debug: program 
exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (13335): Finished input 
to program
imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Debug: program 
exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (13335): Disconnected
imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Debug: program 
exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (13335): Waiting for 
program to finish after 886 msecs
[Thread 0x7fffe97fd700 (LWP 13340) exited]
[Thread 0x7fffebffe700 (LWP 13339) exited]
[Thread 0x7ffff7fd1140 (LWP 13335) exited]
[Inferior 2 (process 13335) exited normally]
imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Debug: program 
exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (13335): Child process ended
imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Debug: program 
exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (13335): Destroy
imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Info: sieve:
pipe
action: piped message to program `rspamd-learn-ham.sh'


There is more output, lots more, but we are talking about spam after 
all... If it is needed, please say so and I will provide it.

Regards,
Jens

Op 20-11-2019 om 8:50 schreef Jens Rey via dovecot:
> Hi,
>
>> You can attach GDB to imap with follow-fork-mode set to
'child', so
>> you can maybe see what causes the segfault.
>
> now I am confused. Hopefully, I used GDB correctly, but as far as I 
> can see, everything seemed to work.
>
> The only difference I can see is that I executed the whole thing as 
> root, but I would hope doveadm uses the correct user (vmail). At least 
> on the file system all emails still belong to vmail, so I guess that 
> works.
>
> For a quick reference, here is what I executed:
>
> root at mail:~# gdb --args doveadm exec imap -u user at domain
> ...
> (gdb) set follow-fork-mode child
> (gdb) r
> . SELECT Spam
> . MOVE 1 Inbox
>
> And the (imho) relevant output:
>
> imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Debug:
program
> exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh: Establishing connection
> [New process 13335]
> imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Debug:
program
> exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh: Forked child process
> imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Debug:
program
> exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (13335): Connected to 
> program
> [Thread debugging using libthread_db enabled]
> Using host libthread_db library 
> "/lib/x86_64-linux-gnu/libthread_db.so.1".
> process 13335 is executing new program: /bin/dash
> process 13335 is executing new program: /usr/bin/rspamc
> [Thread debugging using libthread_db enabled]
> Using host libthread_db library 
> "/lib/x86_64-linux-gnu/libthread_db.so.1".
> [New Thread 0x7fffee7ff700 (LWP 13338)]
> [New Thread 0x7fffebffe700 (LWP 13339)]
> [New Thread 0x7fffe97fd700 (LWP 13340)]
> imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Debug:
program
> exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (13335): Finished 
> streaming payload to program
> imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Debug:
program
> exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (13335): Finished 
> input to program
> imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Debug:
program
> exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (13335): Disconnected
> imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Debug:
program
> exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (13335): Waiting for 
> program to finish after 886 msecs
> [Thread 0x7fffe97fd700 (LWP 13340) exited]
> [Thread 0x7fffebffe700 (LWP 13339) exited]
> [Thread 0x7ffff7fd1140 (LWP 13335) exited]
> [Inferior 2 (process 13335) exited normally]
> imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Debug:
program
> exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (13335): Child process 
> ended
> imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Debug:
program
> exec:/usr/lib/dovecot/sieve/rspamd-learn-ham.sh (13335): Destroy
> imap(user at domain)<13290><+PcoBrjs1F3qMwAAcD3JoA>: Info:
sieve: pipe
> action: piped message to program `rspamd-learn-ham.sh'
>
>
> There is more output, lots more, but we are talking about spam after 
> all... If it is needed, please say so and I will provide it.
Hmm, so now it suddenly works. So, why would it not fail when run in GDB?
>
> Regards,
> Jens