dovecot - Aug 2014 - Backtrace io_add(0x1) called twice fd= (was Exit status code 134; what is it, in the context of Dovecot Antispam plug-in?)

On 8/7/2014 11:14 AM, Steffen Kaiser wrote:
> one idea: http://www.tldp.org/LDP/abs/html/exitcodes.html
> 
> exit code 134 would be in bash's meaning (if this website is
> correct all) some program died off signal 6. This would be Abort in
> Linux.
> 
> prepend your script with
> 
> exec >> /tmp/trace 2>&1 set -vx
> 
> that will dump anything visible into /tmp/trace
> 
> - -- Steffen Kaiser
Thank you for your continued assistance, Steffen.

You seem to be exactly correct with the Abort signal.

I prepended the values you suggested to the pipe script and here's the
relevant output:

+ /usr/lib/dovecot/deliver -d sa-training at example.com -m Training.SPAM
^A^H5584 prefix=lda:
^A^F5584 io_add(0x1) called twice fd=7, callback=0x7f23489fb6f0 ->
0x7f23489aa530
^A^D5584 Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0x5e271)
[0x7f23489e9271] -> /usr/lib/dovecot/libdovecot.so.0(+0x5e34e)
[0x7f23489e934e] -> /usr/lib/dovecot/libdovecot.so.0(i_fatal+0)
[0x7f23489a4a9e] ->
/usr/lib/dovecot/libdovecot.so.0(ioloop_iolist_add+0x83)
[0x7f23489f9533] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_handle_add+0x3b)
[0x7f23489f9cbb] -> /usr/lib/dovecot/libdovecot.so.0(io_add+0x9b)
[0x7f23489f89fb] ->
/usr/lib/dovecot/libdovecot.so.0(master_service_io_listeners_add+0x69)
[0x7f23489a9e49] ->
/usr/lib/dovecot/libdovecot.so.0(master_service_init_finish+0xb0)
[0x7f23489a9f90] -> /usr/lib/dovecot/deliver(main+0x1cb)
[0x7f234939269b] ->
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5)
[0x7f23485e6ec5] -> /usr/lib/dovecot/deliver(+0x31de) [0x7f23493931de]
/usr/local/bin/sa-learn-pipe.sh: line 52:  5584 Aborted
  (core dumped) /usr/lib/dovecot/deliver -d "sa-training at
example.com"
-m "Training.$mode"
+ echo 'Exit status was 134'

Does this tell us anything more?

I don't see any indication that apparmor is at play, as there is no
profile that should apply in this context (and there is nothing in the
relevant log file):

# service apparmor status
apparmor module is loaded.
8 profiles are loaded.
8 profiles are in enforce mode.
   /sbin/dhclient
   /usr/bin/freshclam
   /usr/lib/NetworkManager/nm-dhcp-client.action
   /usr/lib/connman/scripts/dhclient-script
   /usr/sbin/clamd
   /usr/sbin/mysqld
   /usr/sbin/ntpd
   /usr/sbin/tcpdump
0 profiles are in complain mode.
4 processes have profiles defined.
4 processes are in enforce mode.
   /usr/bin/freshclam (2015)
   /usr/sbin/clamd (1897)
   /usr/sbin/mysqld (1239)
   /usr/sbin/ntpd (2472)
0 processes are in complain mode.
0 processes are unconfined but have a profile defined.

I'll try to reproduce this on an identically-configured server. I
wonder if it would be worth changing the version of Dovecot. But I
hate to play whack-a-mole if a more systematic approach is to be had.

Thanks again,

-Ben

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On Thu, 7 Aug 2014, Ben Johnson wrote:
> On 8/7/2014 11:14 AM, Steffen Kaiser wrote:
>> one idea: http://www.tldp.org/LDP/abs/html/exitcodes.html
>>
>> exit code 134 would be in bash's meaning (if this website is
>> correct all) some program died off signal 6. This would be Abort in
>> Linux.
>>
>> prepend your script with
>>
>> exec >> /tmp/trace 2>&1 set -vx
>>
>> that will dump anything visible into /tmp/trace
>>
>> - -- Steffen Kaiser
>
> Thank you for your continued assistance, Steffen.
>
> You seem to be exactly correct with the Abort signal.
>
> I prepended the values you suggested to the pipe script and here's the
> relevant output:
>
> + /usr/lib/dovecot/deliver -d sa-training at example.com -m Training.SPAM
> ^A^H5584 prefix=lda:
> ^A^F5584 io_add(0x1) called twice fd=7, callback=0x7f23489fb6f0 ->
> 0x7f23489aa530
Unfortunately the only spot found is:
http://dovecot.org/pipermail/dovecot/2012-May/135636.html

Is it the same fd=# always? Is it already open in your script?
You could check with lsof -p $$

However, you should check if Dovecot v2.2.13 already fixes the problem.
> ^A^D5584 Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0x5e271)
> [0x7f23489e9271] -> /usr/lib/dovecot/libdovecot.so.0(+0x5e34e)
> [0x7f23489e934e] -> /usr/lib/dovecot/libdovecot.so.0(i_fatal+0)
> [0x7f23489a4a9e] ->
> /usr/lib/dovecot/libdovecot.so.0(ioloop_iolist_add+0x83)
> [0x7f23489f9533] ->
> /usr/lib/dovecot/libdovecot.so.0(io_loop_handle_add+0x3b)
> [0x7f23489f9cbb] -> /usr/lib/dovecot/libdovecot.so.0(io_add+0x9b)
> [0x7f23489f89fb] ->
> /usr/lib/dovecot/libdovecot.so.0(master_service_io_listeners_add+0x69)
> [0x7f23489a9e49] ->
> /usr/lib/dovecot/libdovecot.so.0(master_service_init_finish+0xb0)
> [0x7f23489a9f90] -> /usr/lib/dovecot/deliver(main+0x1cb)
> [0x7f234939269b] ->
> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5)
> [0x7f23485e6ec5] -> /usr/lib/dovecot/deliver(+0x31de) [0x7f23493931de]
> /usr/local/bin/sa-learn-pipe.sh: line 52:  5584 Aborted
>  (core dumped) /usr/lib/dovecot/deliver -d "sa-training at
example.com"
> -m "Training.$mode"
> + echo 'Exit status was 134'
>
> Does this tell us anything more?
>
> I don't see any indication that apparmor is at play, as there is no
> profile that should apply in this context (and there is nothing in the
> relevant log file):
>
> # service apparmor status
> apparmor module is loaded.
> 8 profiles are loaded.
> 8 profiles are in enforce mode.
>   /sbin/dhclient
>   /usr/bin/freshclam
>   /usr/lib/NetworkManager/nm-dhcp-client.action
>   /usr/lib/connman/scripts/dhclient-script
>   /usr/sbin/clamd
>   /usr/sbin/mysqld
>   /usr/sbin/ntpd
>   /usr/sbin/tcpdump
> 0 profiles are in complain mode.
> 4 processes have profiles defined.
> 4 processes are in enforce mode.
>   /usr/bin/freshclam (2015)
>   /usr/sbin/clamd (1897)
>   /usr/sbin/mysqld (1239)
>   /usr/sbin/ntpd (2472)
> 0 processes are in complain mode.
> 0 processes are unconfined but have a profile defined.
>
> I'll try to reproduce this on an identically-configured server. I
> wonder if it would be worth changing the version of Dovecot. But I
> hate to play whack-a-mole if a more systematic approach is to be had.
>
> Thanks again,
>
> -Ben
>
- -- 
Steffen Kaiser
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.11 (GNU/Linux)

iQEVAwUBU+SMkXz1H7kL/d9rAQL7owf/UoNtkoN02JU/1ODYJCaccrpZFTaW1L98
hUPs40eAkh7XsCCe8ymBlG8PzTushkDlqW1EGY2JP3qr5wFV9ACG9ga1Z2oik7CE
R3ELjcB6z4D7j2gIHbSGeF+rAIwP2I8K4tVwd4bfVDm2nv+8fAC2OFo4osark1Z9
+3szhhwYIdlon3droAKkUarppXLX9AiYRHHrIpd3ITI55r1x3D6Ni8ClTmyIqKk2
fuKvrFCzU+OIkBegguLfHjhtU6iG4t6RWgb6X77YfnfNy4jHcbeHc9j0dKL4/bP8
Cy5ro1twUcqtC7qQY2kdI3Ka59+dGFhoewFczEsZ8cVOb+ivpv2MiQ==VORN
-----END PGP SIGNATURE-----

On 2014-08-07 11:41, Ben Johnson wrote:
> On 8/7/2014 11:14 AM, Steffen Kaiser wrote:
>> one idea: http://www.tldp.org/LDP/abs/html/exitcodes.html
>> 
>> exit code 134 would be in bash's meaning (if this website is
>> correct all) some program died off signal 6. This would be Abort in
>> Linux.
>> 
>> prepend your script with
>> 
>> exec >> /tmp/trace 2>&1 set -vx
>> 
>> that will dump anything visible into /tmp/trace
>> 
>> - -- Steffen Kaiser
> 
> Thank you for your continued assistance, Steffen.
> 
> You seem to be exactly correct with the Abort signal.
> 
> I prepended the values you suggested to the pipe script and here's the
> relevant output:
> 
> + /usr/lib/dovecot/deliver -d sa-training at example.com -m Training.SPAM
> ^A^H5584 prefix=lda:
> ^A^F5584 io_add(0x1) called twice fd=7, callback=0x7f23489fb6f0 ->
> 0x7f23489aa530
> ^A^D5584 Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0x5e271)
> [0x7f23489e9271] -> /usr/lib/dovecot/libdovecot.so.0(+0x5e34e)
> [0x7f23489e934e] -> /usr/lib/dovecot/libdovecot.so.0(i_fatal+0)
> [0x7f23489a4a9e] ->
> /usr/lib/dovecot/libdovecot.so.0(ioloop_iolist_add+0x83)
> [0x7f23489f9533] ->
> /usr/lib/dovecot/libdovecot.so.0(io_loop_handle_add+0x3b)
> [0x7f23489f9cbb] -> /usr/lib/dovecot/libdovecot.so.0(io_add+0x9b)
> [0x7f23489f89fb] ->
> /usr/lib/dovecot/libdovecot.so.0(master_service_io_listeners_add+0x69)
> [0x7f23489a9e49] ->
> /usr/lib/dovecot/libdovecot.so.0(master_service_init_finish+0xb0)
> [0x7f23489a9f90] -> /usr/lib/dovecot/deliver(main+0x1cb)
> [0x7f234939269b] ->
> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5)
> [0x7f23485e6ec5] -> /usr/lib/dovecot/deliver(+0x31de) [0x7f23493931de]
> /usr/local/bin/sa-learn-pipe.sh: line 52:  5584 Aborted
>   (core dumped) /usr/lib/dovecot/deliver -d "sa-training at
example.com"
> -m "Training.$mode"
> + echo 'Exit status was 134'
> 
> Does this tell us anything more?
> 
> I don't see any indication that apparmor is at play, as there is no
> profile that should apply in this context (and there is nothing in the
> relevant log file):
> 
> # service apparmor status
> apparmor module is loaded.
> 8 profiles are loaded.
> 8 profiles are in enforce mode.
>    /sbin/dhclient
>    /usr/bin/freshclam
>    /usr/lib/NetworkManager/nm-dhcp-client.action
>    /usr/lib/connman/scripts/dhclient-script
>    /usr/sbin/clamd
>    /usr/sbin/mysqld
>    /usr/sbin/ntpd
>    /usr/sbin/tcpdump
> 0 profiles are in complain mode.
> 4 processes have profiles defined.
> 4 processes are in enforce mode.
>    /usr/bin/freshclam (2015)
>    /usr/sbin/clamd (1897)
>    /usr/sbin/mysqld (1239)
>    /usr/sbin/ntpd (2472)
> 0 processes are in complain mode.
> 0 processes are unconfined but have a profile defined.
> 
> I'll try to reproduce this on an identically-configured server. I
> wonder if it would be worth changing the version of Dovecot. But I
> hate to play whack-a-mole if a more systematic approach is to be had.
> 
> Thanks again,
> 
> -Ben
Hello,

I am still struggling with this problem, and am wondering what the best 
course of action might be with regard to finding a solution.

This behavior is the same on two identically-configured Ubuntu 14.04 LTS 
servers. At least whatever the problem might be, it's consistent.

I realize that this version of Dovecot is a bit stale (2.2.9), but 
ultimately I am forced to work within official the Ubuntu repositories.

That said, for the sake of academia, I tried upgrading Dovecot to the 
latest "ee" version, to see if the problem still exists, but I receive
an "ABI version mismatch" when I try to build the Antispam plugin from
source. I posted to the mailing list about that and never did receive a 
response.

If it would be more appropriate to file a bug report on the Ubuntu 
Launchpad system, I am happy to do so.

Thank you for any further guidance,

-Ben