[PATCH v5 3/4] Implement -e status=set option

[Paul Chaignon]

On Tue, Jul 02, 2019 at 06:28:14PM +0200, Paul Chaignon wrote:
> Thanks for testing Burkhard!
>
> On Tue, Jul 02, 2019 at 03:01:19PM +0000, Kohl, Burkhard wrote:
> [...]
>
> > For any combination of "strace -d -e status=<list>" I see in the debug output
> > that strace_close_memstream() wants to publish a closed memstream when
> > a process has exited:
> >
> >       ./strace: next_event: queued pid 19858
> >       ./strace: next_event: dequeued pid 19858
> >       16:42:53 exit_group(0)                  = ?
> >       ./strace: [wait(0x000000) = 19858] WIFEXITED,exitcode=0
> >       ./strace: next_event: queued pid 19858
> >       ./strace: next_event: dequeued pid 19858
> >       16:42:53 +++ exited with 0 +++
> >       ./strace: dropped tcb for pid 19858, 0 remain
> >       ./strace: memstream already closed
>
> I'm wondering if this could be because print_event_exit() already closed
> the memstream on PTRACE_EVENT_EXIT (you should have such an event just
> before the debug logs you included here).  I'll get a gdb backtrace to be
> sure.

The first call to strace_close_memstream() is indeed caused by a
PTRACE_EVENT_EXIT (see gdb backtrace below).  We then call
strace_close_memstream() again in droptcb() because droptcb() could have
been called for another reason than exit/exit_group, so we don't know if
we've seen a PTRACE_EVENT_EXIT before.

I don't think there's anything to fix here.

Paul


(gdb) b strace_close_memstream
Breakpoint 1 at 0xa1f20: file stage_output.c, line 45.
(gdb) r -de status=detached ./test.out
...
/home/paul/strace/strace: [wait(0x06057f) = 6693] WIFSTOPPED,sig=SIGTRAP,EVENT_EXIT (6)
/home/paul/strace/strace: next_event: queued pid 6693
/home/paul/strace/strace: next_event: dequeued pid 6693

Breakpoint 1, strace_close_memstream (tcp=0x5555556c0770, publish=false) at stage_output.c:45
45              if (!tcp->real_outf) {
(gdb) x tcp->real_outf
0x7ffff77a5680 <_IO_2_1_stderr_>:       0xfbad2a85
(gdb) bt
#0  strace_close_memstream (tcp=0x5555556c0770, publish=false) at stage_output.c:45
#1  0x00005555555f999d in print_event_exit (tcp=0x5555556c0770) at strace.c:2230
#2  dispatch_event (wd=0x5555556bf4a0) at strace.c:2713
#3  0x00005555555c2a87 in main (argc=<optimized out>, argv=<optimized out>) at strace.c:2880
(gdb) c
Continuing.
/home/paul/strace/strace: syscall output dropped: exit_group(0)                           = ?

/home/paul/strace/strace: [wait(0x000000) = 6693] WIFEXITED,exitcode=0
/home/paul/strace/strace: next_event: queued pid 6693
/home/paul/strace/strace: next_event: dequeued pid 6693
+++ exited with 0 +++
/home/paul/strace/strace: dropped tcb for pid 6693, 0 remain

Breakpoint 1, strace_close_memstream (tcp=0x5555556c0770, publish=true) at stage_output.c:45
45              if (!tcp->real_outf) {
(gdb) x tcp->real_outf
0x0:    Cannot access memory at address 0x0
(gdb) bt
#0  strace_close_memstream (tcp=0x5555556c0770, publish=true) at stage_output.c:45
#1  0x00005555555f7200 in droptcb (tcp=0x5555556c0770) at strace.c:814
#2  0x00005555555f968a in droptcb (tcp=<optimized out>) at strace.c:786
#3  dispatch_event (wd=0x5555556bf4a0) at strace.c:2652
#4  0x00005555555c2a87 in main (argc=<optimized out>, argv=<optimized out>) at strace.c:2880