Bug 495909 - selective strace is still waiting after all children exit
Summary: selective strace is still waiting after all children exit
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Fedora
Classification: Fedora
Component: strace
Version: 11
Hardware: i686
OS: Linux
low
medium
Target Milestone: ---
Assignee: Roland McGrath
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2009-04-15 14:37 UTC by John Reiser
Modified: 2009-09-22 15:02 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2009-09-22 15:02:26 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)

Description John Reiser 2009-04-15 14:37:37 UTC
Description of problem: strace is still waiting after all children have exited.


Version-Release number of selected component (if applicable):
strace-4.5.18-2.fc11.i586
kernel-PAE-2.6.29.1-70.fc11.i686


How reproducible: always


Steps to Reproduce:
1. cd /var/cache/pungi/rawhide/packages
2. strace -f -o /root/strace-yum.$$.out -e trace=file -v \
	yum --nogpgcheck --exclude kernel-PAE --exclude kernel-PAE-devel \
		--skip-broken localupdate *.fc11.i?86.rpm *.fc11.noarch.rpm
3.
  
Actual results: yum and all children finish, but strace is still waiting.

"ps axl" shows:
F   UID   PID  PPID PRI  NI    VSZ   RSS WCHAN  STAT TTY        TIME COMMAND
0     0  3410  3409  20   0   2756  1304 wait   S+   pts/1      1:01 strace -f -o /root/strace-yum.3409.out -e trace=file -v

Attaching with gdb:
0x0067c424 in __kernel_vsyscall ()
(gdb) bt
#0  0x0067c424 in __kernel_vsyscall ()
#1  0x0026f7de in wait4 () from /lib/libc.so.6
#2  0x0804ac29 in trace () at strace.c:2205
#3  0x0804bfbc in main (argc=2348, argv=0xbfb048f4) at strace.c:879

The strace output file ends with:
21837 chown32("/dev/dm-1", 0, 0)        = 0
21837 chmod("/dev/dm-1", 0)             = 0
21837 unlink("/dev/dm-1")               = 0
21837 stat64("/org/kernel/dm/multipath_event", 0xbff79ef0) = -1 ENOENT (No such file or directory)
21837 stat64("/var/run/devkit/udev_socket", 0xbff79ef0) = -1 ENOENT (No such file or directory)
3597  --- SIGCHLD (Child exited) @ 0 (0) ---
3597  unlink("/dev/.udev/failed/\\x2fdevices\\x2fvirtual\\x2fblock\\x2fdm-1") = -1 ENOENT (No such file or directory)
3597  unlink("/dev/.udev/queue/1315")   = 0
3597  rmdir("/dev/.udev/queue")         = 0
3597  rmdir("/dev/.udev")               = -1 ENOTEMPTY (Directory not empty)

The yum stdout ends with:
Complete!


Expected results: strace finishes soon after all children exit.


Additional info:

Comment 1 John Reiser 2009-04-15 18:15:30 UTC
The same problem occurs on x86_64, and with a strange involvement of /usr/sbin/gpm ?

strace-4.5.18-2.fc11.x86_64
kernel-2.6.29.1-70.fc11.x86_64

(gdb) bt
#0  0x0000003c7aca419a in wait4 () from /lib64/libc.so.6
#1  0x00000000004034d4 in trace () at strace.c:2205
#2  0x0000000000404743 in main (argc=<value optimized out>, argv=0x7fff5dbcd4c8) at strace.c:879

Tail of output file:
25883 --- SIGCHLD (Child exited) @ 0 (0) ---
26588 open("/dev/tty0", O_RDONLY)       = 4
25883 stat("/var/cache/yum/rawhide/packages/libpst-libs-0.6.36-1.fc11.x86_64.rpm", {st_dev=makedev(8, 25), st_ino=347439, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=168, st_size=77830, st_atime=2009/04/15-10:58:08, st_mtime=2009/04/14-08:19:03, st_ctime=2009/04/15-10:58:07}) = 0
25883 unlink("/var/cache/yum/rawhide/packages/libpst-libs-0.6.36-1.fc11.x86_64.rpm") = 0
25883 stat("/var/cache/yum/rawhide/headers/libpst-libs-0.6.36-1.fc11.x86_64.hdr", 0x7fff1f0cd6c0) = -1 ENOENT (No such file or directory)
25883 stat("/var/cache/yum/rawhide/packages/gpm-libs-1.20.6-3.fc11.x86_64.rpm", {st_dev=makedev(8, 25), st_ino=347438, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=56, st_size=27558, st_atime=2009/04/15-10:58:07, st_mtime=2009/04/14-00:51:02, st_ctime=2009/04/15-10:58:06}) = 0
25883 unlink("/var/cache/yum/rawhide/packages/gpm-libs-1.20.6-3.fc11.x86_64.rpm") = 0
25883 stat("/var/cache/yum/rawhide/headers/gpm-libs-1.20.6-3.fc11.x86_64.hdr", 0x7fff1f0cd6c0) = -1 ENOENT (No such file or directory)
25883 unlink("/var/lib/yum/transaction-all.2009-04-15.10:58.16") = 0
25883 unlink("/var/lib/yum/transaction-done.2009-04-15.10:58.16") = 0
25883 open("/var/lib/rpm/Conflictname", O_RDWR) = 10
25883 unlink("/var/run/yum.pid")        = 0
26588 open("/dev/tty0", O_RDONLY)       = 4
26588 open("/dev/tty0", O_RDONLY)       = 4
26588 open("/dev/tty0", O_RDONLY)       = 4
  [above line repeats about 145 times until end of current contents of file]

# ps ax | grep 26588
26588 ?        Ss     0:00 /usr/sbin/gpm -m /dev/input/mice -t exps2

Comment 2 Bug Zapper 2009-06-09 13:51:43 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 11 development cycle.
Changing version to '11'.

More information and reason for this action is here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Comment 3 Michal Nowak 2009-08-14 14:52:16 UTC
Hmm. Not reproducible for me. Can this be narrowed somehow? Like: is it important that yum is actually installing (or attempting) packages?

Comment 4 John Reiser 2009-08-14 17:27:41 UTC
Not reproducible for me, either.

strace-4.5.18-2.fc11.i586  [same]
kernel-PAE-2.6.29.6-217.2.3.fc11.i686   [updated from
           2.6.29.1-70]
yum-3.2.23-3.fc11.noarch

Comment 5 John Reiser 2009-08-15 18:01:35 UTC
But the problem re-appears in Fedora12!

(gdb) bt   ## of stalled strace when yum has finished (nothing in "ps ax")
#0  0x001ca416 in __kernel_vsyscall ()
#1  0x00aa20ee in wait4 () from /lib/libc.so.6
#2  0x0804abdd in trace () at strace.c:2205
#3  0x0804bf53 in main (argc=1993, argv=0xbf81ad84) at strace.c:879


----- installed versions
kernel-2.6.31-0.125.4.2.rc5.git2.fc12.i686  (note *not* -PAE)
strace-4.5.18-3.fc12.i686
yum-3.2.23-13.fc12.noarch
-----

----- tail of strace output  (consistent with successful finish of 'yum')
2065  open("/var/lib/rpm/Conflictname", O_RDWR|O_LARGEFILE) = 18
2065  open("/var/lib/rpm/Providename", O_RDWR|O_LARGEFILE) = 18
2065  open("/var/lib/rpm/Requirename", O_RDWR|O_LARGEFILE) = 18
2065  open("/var/lib/rpm/Group", O_RDWR|O_LARGEFILE) = 18
2065  open("/var/lib/rpm/Basenames", O_RDWR|O_LARGEFILE) = 17
2065  unlink("/var/run/yum.pid")        = 0
-----

Comment 6 Andreas Schwab 2009-09-08 12:38:38 UTC
Please check the logfile that there really aren't any traced processes left, like anything spawned from scripts.  Also, the logfile needs to end with exit_group, before that the process didn't exit.

Comment 7 Andreas Schwab 2009-09-22 15:02:26 UTC
It really looks like strace is still busy tracing a daemon spawned by one of the scripts or something like this.


Note You need to log in before you can comment on or make changes to this bug.