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@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@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