notmuch vs. SIGPIPE

Tue Jan 21 02:47:19 PST 2020

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:87muamgspy.fsf at euler.schwinge.homeip.net 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 at entry=0x555555683620, flush=0) at gzwrite.c:89
    #2  0x00007ffff7d909ff in gzvprintf (file=0x555555683620, format=<optimized out>, va=va at entry=0x7fffffffd190) at gzwrite.c:442
    #3  0x00007ffff7d90ad4 in gzprintf (file=file at entry=0x555555683620, format=format at 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 at 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 at 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 at entry=0x555555683620, flush=0) at gzwrite.c:90
    0x00007ffff7d909ff in gzvprintf (file=0x555555683620, format=<optimized out>, va=va at 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 at entry=0x7fffffffd190) at gzwrite.c:442
    gzprintf (file=file at entry=0x555555683620, format=format at 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 at entry=0x555555683620, format=format at 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 at 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 at entry=0x555555590b89 "[%d/%d] %s; %s (", ap=ap at entry=0x7fffffffd0c0, mode_flags=mode_flags at entry=0) at ../libio/libioP.h:904
    #8  0x00007ffff7803beb in __printf (format=format at 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 at 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
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 658 bytes
Desc: not available
URL: <http://notmuchmail.org/pipermail/notmuch/attachments/20200121/d5589585/attachment.sig>