Problems in Subprocesses of Tracees

Jun Inoue jun.lambda at gmail.com
Fri Dec 8 06:51:20 UTC 2017


On Fri, Dec 8, 2017 at 7:13 AM, Robert O'Callahan <robert at ocallahan.org> wrote:
> That log suggests the problem might be insufficient recording of memory
> modified by the kernel by one of these ioctl syscalls that ifconfig is
> performing. Your log shows that the last two ioctls before the divergence
> are SIOCGIFBRDADDR and SIOCGIFNETMASK. You could make sure src/test/sioc.c
> passes on your system (or better still just run all the rr tests).

The sioc test passes:

~/src/rr/build$ ctest -R sioc
Test project /home/hrp5puser/src/rr/build
    Start 542: sioc
1/4 Test #542: sioc .............................   Passed    0.12 sec
    Start 543: sioc-no-syscallbuf
2/4 Test #543: sioc-no-syscallbuf ...............   Passed    0.11 sec
    Start 1622: sioc-32
3/4 Test #1622: sioc-32 ..........................   Passed    0.13 sec
    Start 1623: sioc-32-no-syscallbuf
4/4 Test #1623: sioc-32-no-syscallbuf ............   Passed    0.12 sec

100% tests passed, 0 tests failed out of 4

Total Test time (real) =   0.54 sec

A dozen other tests time out, but apparently due to rather trivial
reasons: for example, signal_number locks up because the version of
gdb on this system requires an extra gdb_expect('(rr)') call in
signal_number.py.

>
> It looks like you didn't pass the -b flag so we can't

That's odd.  I just tried it again, this time definitely with -b, but
I got the exact same dump, byte-for-byte.  The command was:

$ sudo rr dump -b -m -p ~/.local/share/rr/rtcd-4 0-1816 >
~/src/rr/rtcd-4-0-1816-with-b.log

(sudo because rtcd requires root privileges, and I called rr with sudo.)


>
> It would also be useful to have a general idea of what /sbin/ifconfig is
> doing between event 1814 and 1816.

Events 1814 and 1815 are cleaning up after ifconfig, and 1816 is
flushing stdout as part of exit().  rtcd invokes ifconfig as

        popen ("ifconfig lo 2> /dev/null")

Events 1814-1816 happen while executing this code in main():

        int err = if_print(ifr.ifr_name); // line 333
        (void) close(skfd); // line 334
        exit(err < 0);  // line 335

ifr.ifr_name points to "lo".  if_print() reads info from
"/proc/net/if_inet6" and prints to stdout.  Event 1814 is the munmap
of the buffer associated with the FILE pointer for
"/proc/net/if_inet6", event 1815 is the close(skfd), and event 1816 is
a write() to stdout inside the exit(), if I understand the backtraces
right.

I got to the backtraces by rr replay -g <event number>, but IIUC
there's some skid and I had to compensate for it.  For instance, rr
replay -g 1814 prints
--------------------------------------------------
 ---> Reached target process 0 at event 1816.
--------------------------------------------------
and stops at what appears to be the close() at event 1815.  If I do rr
replay -g 1813 instead, the same message says event 1814 is reached.

Detailed backtraces follow, for events 1802 (the last ioctl), 1814,
1815, and 1816.  These are obtained with a version of ifconfig
recompiled with -g -O0.  The rr dump for this execution (obtained by
sudo rr dump -b -m -p ~/.local/share/rr/rtcd-9 0-1816 >
rtcd-9-0-1816.log) is available here:
https://drive.google.com/open?id=18n2P6tlGee9_5gf6biMVgA_YeehpGOE4
The corresponding ifconfig source tarball is here (it's just net-tools
1.60-25ubuntu2.1):
https://drive.google.com/open?id=1ECxNT-2BixqadjeTbcHTo7i2Ney9IPA4

<sudo rr replay -g 1801 / I understood this as event 1802>
#0  0x0000000070000002 in ?? ()
#1  0x00007f62fa63df2c in _raw_syscall () at
/home/hrp5puser/src/rr/src/preload/raw_syscall.S:120
#2  0x00007f62fa63aca5 in traced_raw_syscall (call=call at entry=0x681fffa0)
    at /home/hrp5puser/src/rr/src/preload/syscallbuf.c:203
#3  0x00007f62fa63bdaa in syscall_hook_internal (call=0x681fffa0)
    at /home/hrp5puser/src/rr/src/preload/syscallbuf.c:2542
#4  syscall_hook (call=0x681fffa0) at
/home/hrp5puser/src/rr/src/preload/syscallbuf.c:2576
#5  0x00007f62fa63ab0a in _syscall_hook_trampoline () at
/home/hrp5puser/src/rr/src/preload/syscall_hook.S:282
#6  0x00007f62fa63ab3a in __morestack () at
/home/hrp5puser/src/rr/src/preload/syscall_hook.S:417
#7  0x00007f62fa63ab40 in _syscall_hook_trampoline_48_3d_01_f0_ff_ff ()
    at /home/hrp5puser/src/rr/src/preload/syscall_hook.S:423
#8  0x00007f62fa365e6d in ioctl () at ../sysdeps/unix/syscall-template.S:81
#9  0x0000000000409b49 in if_fetch (ife=0xe5f1f0) at interface.c:502
#10 0x0000000000409e08 in do_if_fetch (ife=0xe5f1f0) at interface.c:567
#11 0x0000000000401bff in if_print (ifname=0x7ffe0e1f3c50 "lo") at
ifconfig.c:118
#12 0x000000000040260c in main (argc=1, argv=0x7ffe0e1f3e10) at ifconfig.c:333

<sudo rr replay -g 1813 / I understood this as event 1814>
#0  0x0000000070000002 in ?? ()
#1  0x00007f62fa63df2c in _raw_syscall () at
/home/hrp5puser/src/rr/src/preload/raw_syscall.S:120
#2  0x00007f62fa63aca5 in traced_raw_syscall (call=call at entry=0x681fffa0)
    at /home/hrp5puser/src/rr/src/preload/syscallbuf.c:203
#3  0x00007f62fa63bdaa in syscall_hook_internal (call=0x681fffa0)
    at /home/hrp5puser/src/rr/src/preload/syscallbuf.c:2542
#4  syscall_hook (call=0x681fffa0) at
/home/hrp5puser/src/rr/src/preload/syscallbuf.c:2576
#5  0x00007f62fa63ab0a in _syscall_hook_trampoline () at
/home/hrp5puser/src/rr/src/preload/syscall_hook.S:282
#6  0x00007f62fa63ab3a in __morestack () at
/home/hrp5puser/src/rr/src/preload/syscall_hook.S:417
#7  0x00007f62fa63ab40 in _syscall_hook_trampoline_48_3d_01_f0_ff_ff ()
    at /home/hrp5puser/src/rr/src/preload/syscall_hook.S:423
#8  0x00007f62fa36952d in munmap () at ../sysdeps/unix/syscall-template.S:81
#9  0x00007f62fa2ec472 in __GI__IO_setb (f=f at entry=0xe60bf0,
b=b at entry=0x0, eb=eb at entry=0x0, a=a at entry=0)
    at genops.c:401
#10 0x00007f62fa2eabb0 in _IO_new_file_close_it (fp=fp at entry=0xe60bf0)
at fileops.c:185
#11 0x00007f62fa2dea50 in _IO_new_fclose (fp=0xe60bf0) at iofclose.c:59
#12 0x000000000040a7aa in ife_print_long (ptr=0xe5f1f0) at interface.c:755
#13 0x000000000040b491 in ife_print (i=0xe5f1f0) at interface.c:935
#14 0x0000000000401c14 in if_print (ifname=0x7ffe0e1f3c50 "lo") at
ifconfig.c:120
#15 0x000000000040260c in main (argc=1, argv=0x7ffe0e1f3e10) at ifconfig.c:333

<sudo rr replay -g 1814 / I understood this as event 1815>
#0  0x00007f62fa63df3c in _breakpoint_table_entry_end () at
/home/hrp5puser/src/rr/src/preload/breakpoint_table.S:13
#1  0x00007f62fa63af46 in commit_raw_syscall (syscallno=<optimized
out>, record_end=<optimized out>, ret=0)
    at /home/hrp5puser/src/rr/src/preload/syscallbuf.c:910
#2  0x00007f62fa63b66e in sys_generic_nonblocking_fd
(call=call at entry=0x681fffa0)
    at /home/hrp5puser/src/rr/src/preload/syscallbuf.c:1018
#3  0x00007f62fa63bd7a in syscall_hook_internal (call=0x681fffa0)
    at /home/hrp5puser/src/rr/src/preload/syscallbuf.c:2521
#4  syscall_hook (call=0x681fffa0) at
/home/hrp5puser/src/rr/src/preload/syscallbuf.c:2576
#5  0x00007f62fa63ab0a in _syscall_hook_trampoline () at
/home/hrp5puser/src/rr/src/preload/syscall_hook.S:282
#6  0x00007f62fa63ab3a in __morestack () at
/home/hrp5puser/src/rr/src/preload/syscall_hook.S:417
#7  0x00007f62fa63ab40 in _syscall_hook_trampoline_48_3d_01_f0_ff_ff ()
    at /home/hrp5puser/src/rr/src/preload/syscall_hook.S:423
#8  0x00007f62fa360a96 in __close_nocancel () at
../sysdeps/unix/syscall-template.S:81
#9  0x000000000040261f in main (argc=1, argv=0x7ffe0e1f3e10) at ifconfig.c:334

<sudo rr replay -g 1815>
#0  0x00007f62fa63df3c in _breakpoint_table_entry_end () at
/home/hrp5puser/src/rr/src/preload/breakpoint_table.S:13
#1  0x00007f62fa63af46 in commit_raw_syscall (syscallno=<optimized
out>, record_end=<optimized out>, ret=0)
    at /home/hrp5puser/src/rr/src/preload/syscallbuf.c:910
#2  0x00007f62fa63b66e in sys_generic_nonblocking_fd
(call=call at entry=0x681fffa0)
    at /home/hrp5puser/src/rr/src/preload/syscallbuf.c:1018
#3  0x00007f62fa63bd7a in syscall_hook_internal (call=0x681fffa0)
    at /home/hrp5puser/src/rr/src/preload/syscallbuf.c:2521
#4  syscall_hook (call=0x681fffa0) at
/home/hrp5puser/src/rr/src/preload/syscallbuf.c:2576
#5  0x00007f62fa63ab0a in _syscall_hook_trampoline () at
/home/hrp5puser/src/rr/src/preload/syscall_hook.S:282
#6  0x00007f62fa63ab3a in __morestack () at
/home/hrp5puser/src/rr/src/preload/syscall_hook.S:417
#7  0x00007f62fa63ab40 in _syscall_hook_trampoline_48_3d_01_f0_ff_ff ()
    at /home/hrp5puser/src/rr/src/preload/syscall_hook.S:423
#8  0x00007f62fa360a96 in __close_nocancel () at
../sysdeps/unix/syscall-template.S:81
#9  0x000000000040261f in main (argc=1, argv=0x7ffe0e1f3e10) at ifconfig.c:334

<sudo rr replay -g 1816, followed by pasting the "gdb '-l' ..."
command to attach to ifconfig>
#0  0x00007f62fa36038e in __write_nocancel () at
../sysdeps/unix/syscall-template.S:81
#1  0x00007f62fa2e9f13 in _IO_new_file_write (f=0x7f62fa634400
<_IO_2_1_stdout_>, data=0x7f62faa86000, n=427)
    at fileops.c:1261
#2  0x00007f62fa2eb3ec in new_do_write (to_do=427,
    data=0x7f62faa86000 "lo        Link encap:Local Loopback  \n
   inet addr:127.0.0.1  Mask:255.0.0.0\n          UP LOOPBACK RUNNING
MTU:65536  Metric:1\n          RX packets:15107 errors:0 dropped:0
overruns:0 frame:0\n"..., fp=0x7f62fa634400 <_IO_2_1_stdout_>) at
fileops.c:538
#3  _IO_new_do_write (fp=0x7f62fa634400 <_IO_2_1_stdout_>,
    data=0x7f62faa86000 "lo        Link encap:Local Loopback  \n
   inet addr:127.0.0.1  Mask:255.0.0.0\n          UP LOOPBACK RUNNING
MTU:65536  Metric:1\n          RX packets:15107 errors:0 dropped:0
overruns:0 frame:0\n"..., to_do=427) at fileops.c:511
#4  0x00007f62fa2ecf6e in _IO_flush_all_lockp
(do_lock=do_lock at entry=0) at genops.c:848
#5  0x00007f62fa2ed0ca in _IO_cleanup () at genops.c:1013
#6  0x00007f62fa2ad15b in __run_exit_handlers (status=0, listp=<optimized out>,
    run_list_atexit=run_list_atexit at entry=true) at exit.c:95
#7  0x00007f62fa2ad1f5 in __GI_exit (status=<optimized out>) at exit.c:104
#8  0x0000000000402632 in main (argc=1, argv=0x7ffe0e1f3e10) at ifconfig.c:335


>
> Rob
> --
> lbir ye,ea yer.tnietoehr  rdn rdsme,anea lurpr  edna e hnysnenh hhe uresyf
> toD
> selthor  stor  edna  siewaoeodm  or v sstvr  esBa  kbvted,t
> rdsme,aoreseoouoto
> o l euetiuruewFa  kbn e hnystoivateweh uresyf tulsa rehr  rdm  or rnea lurpr
> .a war hsrer holsa rodvted,t  nenh hneireseoouot.tniesiewaoeivatewt sstvr
> esn



-- 
Jun Inoue


More information about the rr-dev mailing list