Bug 495909 - selective strace is still waiting after all children exit
selective strace is still waiting after all children exit
Status: CLOSED NOTABUG
Product: Fedora
Classification: Fedora
Component: strace (Show other bugs)
11
i686 Linux
low Severity medium
: ---
: ---
Assigned To: Roland McGrath
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2009-04-15 10:37 EDT by John Reiser
Modified: 2009-09-22 11:02 EDT (History)
3 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2009-09-22 11:02:26 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:


Attachments (Terms of Use)

  None (edit)
Description John Reiser 2009-04-15 10:37:37 EDT
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 14:15:30 EDT
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 09:51:43 EDT
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 10:52:16 EDT
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 13:27:41 EDT
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 14:01:35 EDT
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 08:38:38 EDT
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 11:02:26 EDT
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.