notmuch vs. SIGPIPE

classic Classic list List threaded Threaded
3 messages Options
Thomas Schwinge-2 Thomas Schwinge-2
Reply | Threaded
Open this post in threaded view
|

notmuch vs. SIGPIPE

Hi!

While looking a bit into the item raised in
id:[hidden email] I noticed the following
(mis?)behavior by notmuch.

To set the stage:

    $ yes | head -n 1
    y
    $ echo "${PIPESTATUS[@]}"
    141 0

As expected, the 'yes' process exits with SIGPIPE right after the 'head'
process terminated.  However:

    $ notmuch search \* | head -n 1 & sleep 22; jobs; ps -f
    [1] 622009
    thread:0000000000032bb2   the future [1/1] Jenna Moss; Steve Burbon, Washington (hurd list spam)
    [1]+  Running                 notmuch search \* | head -n 1 &
    UID          PID    PPID  C STIME TTY          TIME CMD
    thomas    621851    4297  0 12:38 pts/38   00:00:00 /bin/bash
    thomas    622008  621851 99 12:48 pts/38   00:00:22 /home/thomas/command/notmuch.real search \*
    thomas    622013  621851  0 12:48 pts/38   00:00:00 ps -f

Even after its "pipe-consumer" 'head' process has terminated, the
'notmuch' process still keeps running, and running, and running...  It
has to be killed manually (unless it before exits because of concurrent
database modification).  This doesn't seem expected behavior to me?

Now, I do have a patch or two (actually dozensa; reverts, WIP etc.) on
top of months-old notmuch sources, so I'll later try to reproduce that
with clean sources.


Grüße
 Thomas

_______________________________________________
notmuch mailing list
[hidden email]
https://notmuchmail.org/mailman/listinfo/notmuch

signature.asc (671 bytes) Download Attachment
Thomas Schwinge-2 Thomas Schwinge-2
Reply | Threaded
Open this post in threaded view
|

Re: notmuch vs. SIGPIPE

Hi!

On 2020-01-20T12:55:28+0100, I wrote:

> While looking a bit into the item raised in
> id:[hidden email] I noticed the following
> (mis?)behavior by notmuch.
>
> To set the stage:
>
>     $ yes | head -n 1
>     y
>     $ echo "${PIPESTATUS[@]}"
>     141 0
>
> As expected, the 'yes' process exits with SIGPIPE right after the 'head'
> process terminated.

See also <https://pmhahn.github.io/SIGPIPE/>, for example.

> However:
>
>     $ notmuch search \* | head -n 1 & sleep 22; jobs; ps -f
>     [1] 622009
>     thread:0000000000032bb2   the future [1/1] Jenna Moss; Steve Burbon, Washington (hurd list spam)
>     [1]+  Running                 notmuch search \* | head -n 1 &
>     UID          PID    PPID  C STIME TTY          TIME CMD
>     thomas    621851    4297  0 12:38 pts/38   00:00:00 /bin/bash
>     thomas    622008  621851 99 12:48 pts/38   00:00:22 /home/thomas/command/notmuch.real search \*
>     thomas    622013  621851  0 12:48 pts/38   00:00:00 ps -f
>
> Even after its "pipe-consumer" 'head' process has terminated, the
> 'notmuch' process still keeps running, and running, and running...  It
> has to be killed manually (unless it before exits because of concurrent
> database modification).  This doesn't seem expected behavior to me?
>
> Now, I do have a patch or two (actually dozensa; reverts, WIP etc.) on
> top of months-old notmuch sources, so I'll later try to reproduce that
> with clean sources.

    $ gdb -q --args notmuch dump
    Reading symbols from notmuch...
    (gdb) break sigaction
    Breakpoint 1 at 0xe130
    (gdb) r
    Starting program: [...]/notmuch dump
    [Thread debugging using libthread_db enabled]
    Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
   
    Breakpoint 1, __GI___sigaction (sig=13, act=0x0, oact=0x7fffffffd4e0) at ../nptl/sigaction.c:24
    24      ../nptl/sigaction.c: No such file or directory.
    (gdb) bt
    #0  0x00007ffff77e92f0 in __GI___sigaction (sig=13, act=0x0, oact=0x7fffffffd4e0) at ../nptl/sigaction.c:24
    #1  0x00007ffff75bfa8d in  () at /usr/lib/x86_64-linux-gnu/libgpgme.so.11
    #2  0x00007ffff75c64cd in gpgme_check_version () at /usr/lib/x86_64-linux-gnu/libgpgme.so.11
    #3  0x00007ffff75c6667 in gpgme_check_version_internal () at /usr/lib/x86_64-linux-gnu/libgpgme.so.11
    #4  0x00007ffff7f456b3 in g_mime_init () at /usr/lib/x86_64-linux-gnu/libgmime-3.0.so.0
    #5  0x000055555556539d in main (argc=2, argv=0x7fffffffd828) at notmuch.c:469

So, libgpgme via libgmime initialization is doing something with signals.
Here, 'sig=13' is SIGPIPE, 'act=0x0' means to just query, and store
current handling into 'oact':

    (gdb) finish
    Run till exit from #0  __GI___sigaction (sig=13, act=0x0, oact=0x7fffffffd4e0) at ../nptl/sigaction.c:24
    0x00007ffff75bfa8d in ?? () from /usr/lib/x86_64-linux-gnu/libgpgme.so.11
    Value returned is $1 = 0
    (gdb) print *(struct sigaction *) 0x7fffffffd4e0
    $2 = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {0, 8, 93824992565632, 0, 32, 88, 0, 22, 0, 140733193388034, 93823560581120, 7, 93824992559120, 32, 5, 93824992694848}}, sa_flags = 0, sa_restorer = 0x0}

A '0x0' '__sigaction_handler' means 'SIG_DFL', which for SIGPIPE means to
terminate the process.  This is as expected.  However, then:

    (gdb) continue
    Continuing.
   
    Breakpoint 1, __GI___sigaction (sig=13, act=0x7fffffffd4e0, oact=0x0) at ../nptl/sigaction.c:24
    24      in ../nptl/sigaction.c
    (gdb) bt
    #0  0x00007ffff77e92f0 in __GI___sigaction (sig=13, act=0x7fffffffd4e0, oact=0x0) at ../nptl/sigaction.c:24
    #1  0x00007ffff75bfadc in  () at /usr/lib/x86_64-linux-gnu/libgpgme.so.11
    #2  0x00007ffff75c64cd in gpgme_check_version () at /usr/lib/x86_64-linux-gnu/libgpgme.so.11
    #3  0x00007ffff75c6667 in gpgme_check_version_internal () at /usr/lib/x86_64-linux-gnu/libgpgme.so.11
    #4  0x00007ffff7f456b3 in g_mime_init () at /usr/lib/x86_64-linux-gnu/libgmime-3.0.so.0
    #5  0x000055555556539d in main (argc=2, argv=0x7fffffffd828) at notmuch.c:469
    (gdb) print *act
    $3 = {__sigaction_handler = {sa_handler = 0x1, sa_sigaction = 0x1}, sa_mask = {__val = {0 <repeats 16 times>}}, sa_flags = 0, sa_restorer = 0x0}

A '0x1' '__sigaction_handler' means 'SIG_IGN', ignore any such signals.
This is unexpected (to me, at least), not what I'd expect with notmuch?

According to a (very quick) check/survey, this has apparently been the
case "forever", and is documented on
<https://www.gnupg.org/documentation/manuals/gpgme/Signal-Handling.html>,
together with some rationale.  Aha, aha, OK, I see.

So, assuming we want to keep it that way (given the gpgme rationale), is
the problem then that we fail to handle appropriately in notmuch any
EPIPE that we may be getting from 'write' etc.?  This remains to be
explored another day.


Grüße
 Thomas
_______________________________________________
notmuch mailing list
[hidden email]
https://notmuchmail.org/mailman/listinfo/notmuch
Thomas Schwinge-2 Thomas Schwinge-2
Reply | Threaded
Open this post in threaded view
|

Re: notmuch vs. SIGPIPE

Hi!

On 2020-01-20T23:36:51+0100, I wrote:

> On 2020-01-20T12:55:28+0100, I wrote:
>> While looking a bit into the item raised in
>> id:[hidden email] I noticed the following
>> (mis?)behavior by notmuch.
>>
>> To set the stage:
>>
>>     $ yes | head -n 1
>>     y
>>     $ echo "${PIPESTATUS[@]}"
>>     141 0
>>
>> As expected, the 'yes' process exits with SIGPIPE right after the 'head'
>> process terminated.
>
> See also <https://pmhahn.github.io/SIGPIPE/>, for example.
>
>> However:
>>
>>     $ notmuch search \* | head -n 1 & sleep 22; jobs; ps -f
>>     [1] 622009
>>     thread:0000000000032bb2   the future [1/1] Jenna Moss; Steve Burbon, Washington (hurd list spam)
>>     [1]+  Running                 notmuch search \* | head -n 1 &
>>     UID          PID    PPID  C STIME TTY          TIME CMD
>>     thomas    621851    4297  0 12:38 pts/38   00:00:00 /bin/bash
>>     thomas    622008  621851 99 12:48 pts/38   00:00:22 /home/thomas/command/notmuch.real search \*
>>     thomas    622013  621851  0 12:48 pts/38   00:00:00 ps -f
>>
>> Even after its "pipe-consumer" 'head' process has terminated, the
>> 'notmuch' process still keeps running, and running, and running...

> So, libgpgme via libgmime initialization is doing something with signals.
> Here, 'sig=13' is SIGPIPE

>     Breakpoint 1, __GI___sigaction (sig=13, act=0x7fffffffd4e0, oact=0x0) at ../nptl/sigaction.c:24

>     (gdb) print *act
>     $3 = {__sigaction_handler = {sa_handler = 0x1, sa_sigaction = 0x1}, sa_mask = {__val = {0 <repeats 16 times>}}, sa_flags = 0, sa_restorer = 0x0}
>
> A '0x1' '__sigaction_handler' means 'SIG_IGN', ignore any such signals.
> This is unexpected (to me, at least), not what I'd expect with notmuch?
>
> According to a (very quick) check/survey, this has apparently been the
> case "forever", and is documented on
> <https://www.gnupg.org/documentation/manuals/gpgme/Signal-Handling.html>,
> together with some rationale.  Aha, aha, OK, I see.
>
> So, assuming we want to keep it that way (given the gpgme rationale), is
> the problem then that we fail to handle appropriately in notmuch any
> EPIPE that we may be getting from 'write' etc.?  This remains to be
> explored another day.
Indeed.  Using a FIFO to simulate a pipe:

    $ mkfifo f
    $ head -n 1 < f &
    [1] 775394

(This will trigger SIGPIPE/EPIPE after one line.)

    $ gdb -q notmuch
    Reading symbols from notmuch...
    (gdb) break write
    Breakpoint 1 at 0xd420
    (gdb) run dump > f
    Starting program: [...]/notmuch dump > f
    [Thread debugging using libthread_db enabled]
    Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
   
    Breakpoint 1, __GI___libc_write (fd=8, buf=0x555555683710, nbytes=8192) at ../sysdeps/unix/sysv/linux/write.c:26
    26      ../sysdeps/unix/sysv/linux/write.c: No such file or directory.
    (gdb) bt
    #0  0x00007ffff789a8f0 in __GI___libc_write (fd=8, buf=0x555555683710, nbytes=8192) at ../sysdeps/unix/sysv/linux/write.c:26
    #1  0x00007ffff7d8ff99 in gz_comp (state=state@entry=0x555555683620, flush=0) at gzwrite.c:89
    #2  0x00007ffff7d909ff in gzvprintf (file=0x555555683620, format=<optimized out>, va=va@entry=0x7fffffffd190) at gzwrite.c:442
    #3  0x00007ffff7d90ad4 in gzprintf (file=file@entry=0x555555683620, format=format@entry=0x55555558f54e " -- %s\n") at gzwrite.c:457
    #4  0x000055555556964e in dump_tags_message (size_p=0x7fffffffd2d0, buffer_p=0x7fffffffd2c8, output=0x555555683620, output_format=1, message=0x5555556884e0, ctx=0x5555555d01b0) at notmuch-dump.c:203
    #5  0x000055555556964e in database_dump_file (include=<optimized out>, output_format=1, query_str=<optimized out>, output=0x555555683620, notmuch=0x5555555d01b0) at notmuch-dump.c:254
    #6  0x000055555556964e in notmuch_database_dump (notmuch=0x5555555d01b0, output_file_name=0x0, query_str=<optimized out>, output_format=DUMP_FORMAT_BATCH_TAG, include=<optimized out>, gzip_output=<optimized out>) at notmuch-dump.c:314
    #7  0x0000555555569e4b in notmuch_dump_command (config=<optimized out>, argc=<optimized out>, argv=0x7fffffffd860) at notmuch-dump.c:413
    #8  0x0000555555565426 in main (argc=2, argv=0x7fffffffd858) at notmuch.c:505

This is the libz 'printf' pass-through code via 'notmuch dump'.

    (gdb) finish
    Run till exit from #0  __GI___libc_write (fd=8, buf=0x555555683710, nbytes=8192) at ../sysdeps/unix/sysv/linux/write.c:26
    #notmuch-dump batch-tag:3 config,properties,tags

First line got printed.

    gz_comp (state=state@entry=0x555555683620, flush=0) at gzwrite.c:90
    90      gzwrite.c: No such file or directory.
    Value returned is $1 = 8192

Supposedly 8192 bytes have been written, which seems a bit dubious, but I
have not studies the fine details of how FIFO buffering vs. SIGPIPE/EPIPE
work -- presumably indeed 8192 bytes were written into the FIFO buffer,
but then only line read, then the FIFO/buffer closed, so the other bytes
lost, and then only on the next 'write', we get...

    (gdb) c
    Continuing.
   
    Breakpoint 1, __GI___libc_write (fd=8, buf=0x555555683710, nbytes=8192) at ../sysdeps/unix/sysv/linux/write.c:26
    26      ../sysdeps/unix/sysv/linux/write.c: No such file or directory.
    (gdb) finish
    Run till exit from #0  __GI___libc_write (fd=8, buf=0x555555683710, nbytes=8192) at ../sysdeps/unix/sysv/linux/write.c:26
   
    Program received signal SIGPIPE, Broken pipe.

... the expected SIGPIPE (though, ignored thanks to gpgme
initialization), and...

    0x00007ffff789a904 in __GI___libc_write (fd=8, buf=0x555555683710, nbytes=8192) at ../sysdeps/unix/sysv/linux/write.c:26
    26      in ../sysdeps/unix/sysv/linux/write.c
    (gdb) finish
    Run till exit from #0  0x00007ffff789a904 in __GI___libc_write (fd=8, buf=0x555555683710, nbytes=8192) at ../sysdeps/unix/sysv/linux/write.c:26
    gz_comp (state=state@entry=0x555555683620, flush=0) at gzwrite.c:90
    90      gzwrite.c: No such file or directory.
    Value returned is $2 = -1

... the 'write' fails...

    (gdb) print errno
    $3 = 32

... with EPIPE...

    (gdb) finish
    Run till exit from #0  gz_comp (state=state@entry=0x555555683620, flush=0) at gzwrite.c:90
    0x00007ffff7d909ff in gzvprintf (file=0x555555683620, format=<optimized out>, va=va@entry=0x7fffffffd190) at gzwrite.c:442
    442     in gzwrite.c
    Value returned is $4 = -1

..., which gets propagated up...

    (gdb) finish
    Run till exit from #0  0x00007ffff7d909ff in gzvprintf (file=0x555555683620, format=<optimized out>, va=va@entry=0x7fffffffd190) at gzwrite.c:442
    gzprintf (file=file@entry=0x555555683620, format=format@entry=0x55555558f54e " -- %s\n") at gzwrite.c:459
    459     in gzwrite.c
    Value returned is $5 = -1

..., and propagated up...

    (gdb) finish
    Run till exit from #0  gzprintf (file=file@entry=0x555555683620, format=format@entry=0x55555558f54e " -- %s\n") at gzwrite.c:459
    0x000055555556964e in dump_tags_message (size_p=<optimized out>, buffer_p=<optimized out>, output=<optimized out>, output_format=<optimized out>, message=<optimized out>, ctx=<optimized out>) at notmuch-dump.c:203
    203             gzprintf (output, " -- %s\n", *buffer_p);
    Value returned is $6 = -1
    (gdb) print errno  
    $7 = 32

..., and propagated up, but ignored here.  :-(

    (gdb) list
    198                                    buffer_p, size_p)) {
    199                 fprintf (stderr, "Error quoting message id %s: %s\n",
    200                          message_id, strerror (errno));
    201                 return EXIT_FAILURE;
    202             }
    203             gzprintf (output, " -- %s\n", *buffer_p);
    204         }
    205         return EXIT_SUCCESS;
    206     }
    207

Indeed there is a lot of code in 'notmuch-dump.c' that doesn't check
return values for 'printf'-like function calls.

Unrelated to the task that triggered me to look into this, it's of course
bad that we don't handle such error returns.

So, do we have to fix up all these individually (can GCC's
'-Wunused-result', 'warn_unused_result' function attribute help?), or
switch to a programming language/framework that provides a little bit
more convenience regarding such things?  Can C++ do it?  ;-P


Same story for 'notmuch search':

    $ mkfifo f
    $ head -n 1 < f &
    [1] 775782
    $ gdb -q notmuch
    Reading symbols from notmuch...
    (gdb) break write
    Breakpoint 1 at 0xd420
    (gdb) run search \* > f
    Starting program: [...]/notmuch search \* > f
    [Thread debugging using libthread_db enabled]
    Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
   
    Breakpoint 1, __GI___libc_write (fd=1, buf=0x555555629a80, nbytes=4096) at ../sysdeps/unix/sysv/linux/write.c:26
    26      ../sysdeps/unix/sysv/linux/write.c: No such file or directory.
    (gdb) bt
    #0  0x00007ffff789a8f0 in __GI___libc_write (fd=1, buf=0x555555629a80, nbytes=4096) at ../sysdeps/unix/sysv/linux/write.c:26
    #1  0x00007ffff782cc85 in _IO_new_file_write (f=0x7ffff7969760 <_IO_2_1_stdout_>, data=0x555555629a80, n=4096) at fileops.c:1183
    #2  0x00007ffff782c016 in new_do_write
        (fp=0x7ffff7969760 <_IO_2_1_stdout_>, data=0x555555629a80 "thread:", '0' <repeats 11 times>, "32bb2   the future [1/1] Jenna Moss; Steve Burbon, Washington (hurd list spam)\nthread:", '0' <repeats 11 times>, "4105a   the future [1/1] \346\257\217\345\244\251\344\273\205\061\060\345\205\203; \344\273\205\062\071\070\345\205\203,\346\234\200\346\226\260\061\061\062\345\261\212 2012\347\247\213\345\255\243\345\271\277\344\272\244\344\274\232\344\271"..., to_do=to_do@entry=4096) at libioP.h:904
    #3  0x00007ffff782dd99 in _IO_new_do_write (to_do=4096, data=<optimized out>, fp=<optimized out>) at fileops.c:430
    #4  0x00007ffff782dd99 in _IO_new_do_write (fp=<optimized out>, data=<optimized out>, to_do=4096) at fileops.c:430
    #5  0x00007ffff782d30e in _IO_new_file_xsputn (n=12, data=<optimized out>, f=<optimized out>) at libioP.h:904
    #6  0x00007ffff782d30e in _IO_new_file_xsputn (f=0x7ffff7969760 <_IO_2_1_stdout_>, data=<optimized out>, n=12) at fileops.c:1204
    #7  0x00007ffff7817346 in __vfprintf_internal (s=0x7ffff7969760 <_IO_2_1_stdout_>, format=format@entry=0x555555590b89 "[%d/%d] %s; %s (", ap=ap@entry=0x7fffffffd0c0, mode_flags=mode_flags@entry=0) at ../libio/libioP.h:904
    #8  0x00007ffff7803beb in __printf (format=format@entry=0x555555590b89 "[%d/%d] %s; %s (") at printf.c:33
    #9  0x0000555555570b19 in do_search_threads (ctx=0x5555555a3160 <search_context>) at notmuch-search.c:182
    #10 0x0000555555570b19 in notmuch_search_command (config=<optimized out>, argc=<optimized out>, argv=<optimized out>) at notmuch-search.c:851
    #11 0x0000555555565426 in main (argc=3, argv=0x7fffffffd848) at notmuch.c:505
    (gdb) finish
    Run till exit from #0  __GI___libc_write (fd=1, buf=0x555555629a80, nbytes=4096) at ../sysdeps/unix/sysv/linux/write.c:26
    thread:0000000000032bb2   the future [1/1] Jenna Moss; Steve Burbon, Washington (hurd list spam)
    _IO_new_file_write (f=0x7ffff7969760 <_IO_2_1_stdout_>, data=0x555555629a80, n=4096) at fileops.c:1189
    1189    fileops.c: No such file or directory.
    Value returned is $1 = 4096
    (gdb) c
    Continuing.
   
    Breakpoint 1, __GI___libc_write (fd=1, buf=0x555555629a80, nbytes=4096) at ../sysdeps/unix/sysv/linux/write.c:26
    26      ../sysdeps/unix/sysv/linux/write.c: No such file or directory.
    (gdb) finish
    Run till exit from #0  __GI___libc_write (fd=1, buf=0x555555629a80, nbytes=4096) at ../sysdeps/unix/sysv/linux/write.c:26
   
    Program received signal SIGPIPE, Broken pipe.
    0x00007ffff789a904 in __GI___libc_write (fd=1, buf=0x555555629a80, nbytes=4096) at ../sysdeps/unix/sysv/linux/write.c:26
    26      in ../sysdeps/unix/sysv/linux/write.c
    (gdb) finish
    Run till exit from #0  0x00007ffff789a904 in __GI___libc_write (fd=1, buf=0x555555629a80, nbytes=4096) at ../sysdeps/unix/sysv/linux/write.c:26
    _IO_new_file_write (f=0x7ffff7969760 <_IO_2_1_stdout_>, data=0x555555629a80, n=4096) at fileops.c:1189
    1189    fileops.c: No such file or directory.
    Value returned is $2 = -1
    (gdb) print errno
    $3 = 32
    ['finish' a few frames]
    (gdb) finish
    Run till exit from #0  __printf (format=format@entry=0x555555590b89 "[%d/%d] %s; %s (") at printf.c:36
    0x0000555555570b19 in do_search_threads (ctx=0x5555555a3160 <search_context>) at notmuch-search.c:182
    182                         printf ("[%d/%d] %s; %s (",
    Value returned is $7 = -1
    (gdb) print errno
    $8 = 32
    (gdb) list
    177                     /* Special case for the text formatter */
    178                     printf ("thread:%s %12s ",
    179                             thread_id,
    180                             relative_date);
    181                     if (total == files)
    182                         printf ("[%d/%d] %s; %s (",
    183                                 matched,
    184                                 total,
    185                                 sanitize_string (ctx_quote, authors),
    186                                 sanitize_string (ctx_quote, subject));


Grüße
 Thomas

_______________________________________________
notmuch mailing list
[hidden email]
https://notmuchmail.org/mailman/listinfo/notmuch

signature.asc (671 bytes) Download Attachment