Re: 2.6.25.3: su gets stuck for root

Joe Peterson
2008-06-14T20:52:21Z

[-- Attachment #1: Type: text/plain, Size: 2153 bytes --]

Vegard Nossum wrote:
> Yeah, a user-space process can do this, and it's the right behaviour
> for the kernel. I did post a program that would "reproduce" what
> you're seeing. I do now believe that it's something timing-related, as
> Alan suggested initially. (But timing-related with your scripts, that
> is. I must say, that "sleep 2" does look a bit suspicious; I have no
> idea what that is supposed to do :-))

Ah, that is something I put in there to artificially make it more
reproducible. Here's the reason: when I first encountered the problem,
it was happening if the home dir of the user was on the "btrfs"
filesystem (the new checksumming one from Oracle). This made me suspect
btrfs initially. But I reproduced the problem [more sporadically] when
the home was on ext3 as well. Since btrfs has a different performance
profile, especially when first accessed after a mount (and it is a
filesystem still under development, so some optimizations are yet to
come), I figured it might be timing-related, and sure enough, adding the
"sleep 2" proved that.

So without the sleep 2 and with a home of ext3, it rarely happens, since
it takes very little time to read the homedir files (.bashrc, etc.).
Putting in the sleep makes it almost always happen. It seems like the
delay invoked by the sleep causes that subsequent stty call to hang.

> I suppose it would be more useful to see a trace where you include a
> few more system calls, can you try:
>
> # strace -e trace=process,ioctl,setpgid -f su foo
>
> instead?

OK, attached.

> Just for the record, I'm probably not the best person to debug this,
> so I'm just trying to figure it out as we go. On the other hand, I
> don't see better suggestions from anybody else. Thank you for
> persisting, though! :-)
>
> (And the fact that the results differ with the kernel versions does
> make this relevant for LKML still.)

Thanks for helping. Yes, this is the kind of nagging issue that really
bugs me, since it is intermittent and makes things feel unstable. If we
determine the problem is in something else (like stty or bash), then at
least I can file a bug with them.

-Joe

[-- Attachment #2: strace_su.log --]
[-- Type: text/x-log, Size: 5681 bytes --]

9738 execve("/bin/su", ["su", "foo"], [/* 50 vars */]) = 0
9738 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9738 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9738 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9738 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7dfc708) = 9740
9738 waitpid(-1, <unfinished ...>
9740 execve("/bin/bash", ["bash"], [/* 50 vars */]) = 0
9740 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9740 ioctl(2, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9740 ioctl(255, TIOCGPGRP, [9737]) = 0
9740 setpgid(0, 9740) = 0
9740 ioctl(255, TIOCSPGRP, [9740]) = 0
9740 ioctl(255, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9740 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7df1708) = 9741
9741 exit_group(0) = ?
9740 --- SIGCHLD (Child exited) @ 0 (0) ---
9740 waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG) = 9741
9740 waitpid(-1, 0xbfb187fc, WNOHANG) = -1 ECHILD (No child processes)
9740 ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbfb18774) = -1 ENOTTY (Inappropriate ioctl for device)
9740 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7df1708) = 9742
9742 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7df1708) = 9743
9742 waitpid(-1, <unfinished ...>
9743 execve("/usr/bin/dircolors", ["dircolors", "-b", "/etc/DIR_COLORS"], [/* 49 vars */]) = 0
9743 exit_group(0) = ?
9742 <... waitpid resumed> [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0) = 9743
9742 --- SIGCHLD (Child exited) @ 0 (0) ---
9742 waitpid(-1, 0xbfb17fbc, WNOHANG) = -1 ECHILD (No child processes)
9742 exit_group(0) = ?
9740 --- SIGCHLD (Child exited) @ 0 (0) ---
9740 waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG) = 9742
9740 waitpid(-1, 0xbfb1824c, WNOHANG) = -1 ECHILD (No child processes)
9740 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7df1708) = 9744
9740 waitpid(-1, <unfinished ...>
9744 execve("/bin/sleep", ["sleep", "2"], [/* 49 vars */]) = 0
9744 exit_group(0) = ?
9740 <... waitpid resumed> [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0) = 9744
9740 ioctl(255, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9740 ioctl(255, TIOCGWINSZ, {ws_row=30, ws_col=80, ws_xpixel=724, ws_ypixel=454}) = 0
9740 ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9740 ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9740 ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9740 ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9740 ioctl(1, TIOCGWINSZ, {ws_row=30, ws_col=80, ws_xpixel=724, ws_ypixel=454}) = 0
9740 ioctl(0, TIOCGWINSZ, {ws_row=30, ws_col=80, ws_xpixel=724, ws_ypixel=454}) = 0
9740 --- SIGCHLD (Child exited) @ 0 (0) ---
9740 waitpid(-1, 0xbfb18d3c, WNOHANG) = -1 ECHILD (No child processes)
9740 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7df1708) = 9745
9740 waitpid(-1, <unfinished ...>
9745 execve("/bin/stty", ["stty", "-ixany"], [/* 49 vars */]) = 0
9745 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9745 ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig icanon echo ...}) = 0
9745 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9745 exit_group(0) = ?
9740 <... waitpid resumed> [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0) = 9745
9740 ioctl(255, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9740 ioctl(255, TIOCGWINSZ, {ws_row=30, ws_col=80, ws_xpixel=724, ws_ypixel=454}) = 0
9740 --- SIGCHLD (Child exited) @ 0 (0) ---
9740 waitpid(-1, 0xbfb18d3c, WNOHANG) = -1 ECHILD (No child processes)
9740 ioctl(255, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9740 ioctl(255, TIOCGWINSZ, {ws_row=30, ws_col=80, ws_xpixel=724, ws_ypixel=454}) = 0
9740 ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9740 ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9740 ioctl(1, TIOCGWINSZ, {ws_row=30, ws_col=80, ws_xpixel=724, ws_ypixel=454}) = 0
9740 ioctl(0, TIOCGWINSZ, {ws_row=30, ws_col=80, ws_xpixel=724, ws_ypixel=454}) = 0
9740 ioctl(0, TIOCSWINSZ, {ws_row=30, ws_col=80, ws_xpixel=724, ws_ypixel=454}) = 0
9740 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9740 ioctl(255, TIOCSPGRP, [9740]) = 0
9740 ioctl(0, TIOCGWINSZ, {ws_row=30, ws_col=80, ws_xpixel=724, ws_ypixel=454}) = 0
9740 ioctl(0, TIOCSWINSZ, {ws_row=30, ws_col=80, ws_xpixel=724, ws_ypixel=454}) = 0
9740 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
9740 ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig -icanon -echo ...}) = 0
9740 ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig icanon echo ...}) = 0
9740 ioctl(255, TIOCSPGRP, [9737]) = 0
9740 setpgid(0, 9737) = 0
9740 exit_group(0) = ?
9738 <... waitpid resumed> [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WSTOPPED) = 9740
9738 exit_group(0) = ?