Changes to 27-JAN-2011: The day "/proc" died between r2 and r10
'''Solaris'd...'''
The setup:
This morning I got an email from our group manager asking about a UNIX server out at one of the districts:
Date: Thu, 27 Jan 2011 14:14:49
From: "UNIX Manager"
To: UNIX_SA_GROUP
Subject: Milky Way District UNIX Server
Someone take a look into whats going on with Milky Way District UNIX Server server
Someone take a look into whats going on with Milky Way District UNIX Server today.
today. The server is up but is acting really strange, I was not able to get a --> The server is up but is acting really strange, I was not able to get a
response from ps or ptree commands. Please note, there was not any server
consolidation work at this site last night.
--
A. Manager
Enterprise Unix & Storage Systems Manager
Spacely Sprockets, Inc.
---
(blank line)
# ls -ln /proc & echo $!
20023
# mdb -k
> 0t20023::pid2proc
(blank line)
(blank line)
302765d6078 --> So I logged in expecting a mundane failure:
> 302765d6078::walk thread
300e3d5e100
workstation$ ssh milkyway1
milkyway1$ ps -eaf
UID PID PPID C STIME TTY TIME CMD
root 0 0 0 Dec 08 ? 0:45 sched
root 1 0 0 Dec 08 ? 72:15 /sbin/init
root 2 0 0 Dec 08 ? 0:00 pageout
root 3 0 0 Dec 08 ? 5514:24 fsflush
root 59 1 0 Dec 08 ? 0:00 /lib/svc/method/iscsid
root 7 1 0 Dec 08 ? 1:48 /lib/svc/bin/svc.startd
root 9 1 0 Dec 08 ? 3:13 /lib/svc/bin/svc.configd
root 149 1 0 Dec 08 ? 0:04 devfsadmd
daemon 168 1 0 Dec 08 ? 73:17 /usr/lib/crypto/kcfd
> 300e3d5e100::findstack -v --> ^C
stack pointer for thread 300e3d5e100: 2a10d548d71 --> ^C
~.
(blank line)
So far, so good. It does indeed appear to be broken. It probably can't talk to its LDAP server or something silly. I check "`nsswitch.conf`" and the only thing configured for "ldap" is "sudoers" and "netgroup". Suspiciously normal.
(blank line)
workstation$ ssh milkyway1
milkyway1$ sudo su -
milkyway1$ cd /proc
milkyway1$ echo *
0 1 10045 10116 10162 10163 10169 10176 10240 10243 10244 10246 10263 10318 10386
10483 10489...
milkyway1$ ls -ln
[ 000002a10d548d71 cv_wait+0x38() ] --> ^C
000002a10d548e21 pr_p_lock+0x80(0, 60032d48030, 60032d58600, 300b84af968, ff000000, 18f8218) --> ^C
(blank line)
~.
(blank line)
Hmm. Curiouser and curiouser. Why is my "ls" hanging ? What HAS science done ? Let's take a look at what the kernel thinks about what is going on with that process while it is "hung" (being able to attach a debugger to the running kernel is one of the ''MOST USEFUL'' things about Solaris. However it sometimes gets abused, see [Why Solaris is Retarded]).
(blank line)
workstation$ ssh milkyway1
milkyway1$ sudo su -
milkyway1# ls -ln /proc & echo $!
20023
milkyway1# mdb -k
> 0t20023::pid2proc
000002a10d548ed1 prgetattr+0x2d4(30025ce8240, 2a10d549998, 149, ffffffffffffffef, 300bd1a8da8, 0) --> 302765d6078
> 302765d6078::walk thread
300e3d5e100
> 300e3d5e100::findstack -v
stack pointer for thread 300e3d5e100: 2a10d548d71
[ 000002a10d548d71 cv_wait+0x38() ]
000002a10d548e21 pr_p_lock+0x80(0, 60032d48030, 60032d58600, 300b84af968, ff000000, 18f8218)
000002a10d548ed1 prgetattr+0x2d4(30025ce8240, 2a10d549998, 149, ffffffffffffffef, 300bd1a8da8, 0)
000002a10d548f91 fop_getattr+0x18(30025ce8240, 2a10d549998, 0, 3025fb17d00, 2a10d549ad8, 1362e00)
000002a10d549041 cstat64_32+0x1c(30025ce8240, ffbffb20, 0, 3025fb17d00, 3fff, 3c00)
000002a10d549221 cstatat64_32+0x5c(ffffffffffd19553, 26578, 1000, ffbffb20, 1000, 0)
000002a10d5492e1 syscall_trap32+0xcc(26578, ffbffb20, ffffffffffffffff, 27f68, 6c, 1b)
>
(blank line)
Simple enough, it seems to be waiting for a conditional variable (''cv_wait()'') as part of a mutex lock after a 32-bit process has made a system call (''syscall_trap32()'') for ''stat()'' with the file whose name is stored at `0x26578`.
(blank line)
This pointer will probably point to a string that is a filename under "/proc" since that's what I was running "`ls`" on after all. I'll have to switch to the context of that process to interpret that memory.
(blank line)
> 302765d6078 $p
debugger context set to proc 302765d6078
Segmentation Fault
milkyway1#
(blank line)
Oh. Well, that wasn't nice. Let's try it another way...
(blank line)
milkyway1# mdb -p 20023
mdb: failed to initialize /lib/libc_db.so.1: libthread_db call failed unexpectedly
mdb: warning: debugger will only be able to examine raw LWPs
Loading modules: [ ld.so.1 libc.so.1 libavl.so.1 ]
> 26578::print -i char*
0x26578 "/proc/26936"
# --> >
# mdb -p 20023
mdb: failed to initialize /lib/libc_db.so.1: libthread_db call failed unexpectedly
mdb: warning: debugger will only be able to examine raw LWPs
Loading modules: [ ld.so.1 libc.so.1 libavl.so.1 ]
> 26578::print -i char*
0x26578 "/proc/26936"
>
# echo '::ps -f' | mdb -k | grep 26936
S PID PPID PGID SID UID FLAGS ADDR NAME
R 26133 19481 26131 19469 0 0x4a004000 0000030276c7c4a0 grep 26936
R 26936 26935 26935 26935 1000 0x4a014000 00000300b84af968
# echo '::ps -fz' | mdb -k | grep 26936
S PID PPID PGID SID ZONE UID FLAGS ADDR NAME
R 26936 26935 26935 26935 3 1000 0x4a014000 00000300b84af968
(blank line)
So my "`ls`" is hanging because "''stat()''" is being called on "/proc/26936". What is running with the PID of 26936 ? Hmm... Well, we can't just run "ps" since that will "''stat()''" that file in "/proc" and hang. The modular debugger to the rescue, again:
(blank line)
# mdb -k --> milkyway1# echo '::ps -fz' | mdb -k | grep 26936
S PID PPID PGID SID ZONE UID FLAGS ADDR NAME
R 26936 26935 26935 26935 3 1000 0x4a014000 00000300b84af968
(blank line)
So that process corresponds to a command with no name (what ?) run by the UID 1000 in the zone 3. Now we know the "who", what about the "what in the world is it doing?" ?
(blank line)
milkyway1# mdb -k
Loading modules: [ unix genunix specfs dtrace ufs sd mpt px md ldc ip hook neti sctp arp usba fcp fctl emlxs qlc lofs zfs ssd random crypto fcip logindmux ptm nfs ipc ] --> Loading modules: [ unix genunix specfs dtrace ufs sd mpt px md ldc ip hook neti sctp
arp usba fcp fctl emlxs qlc lofs zfs ssd random crypto fcip logindmux ptm nfs ipc ]
> 00000300b84af968::walk thread
3000f654d40
> 3000f654d40::findstack -v
stack pointer for thread 3000f654d40: 2a109f38a61
[ 000002a109f38a61 cv_wait+0x38() ]
000002a109f38b11 txg_wait_open+0x54(6003f983d20, 16533a, 0, 6003f983d64, 6003f983d66, 6003f983d18)
000002a109f38bc1 zfs_putapage+0x1e0(6004d6fae40, 5b, 2a109f39570, 2a109f39568, 400, 10a6ac0)
000002a109f38cb1 zfs_putpage+0x1b8(3002836dd40, b7c1a000, 0, 400, 30114c15318, 7000f9c9d80)
000002a109f38d81 fop_putpage+0x1c(3002836dd40, 0, b7c1a000, 400, 30114c15318, 7b262c7c)
000002a109f38e31 zfs_delmap+0x6c(3002836dd40, 0, 10a6800, 30114c15318, b7c1a000, b)
000002a109f38ef1 zfs_shim_delmap+0x3c(3002836dd40, 30114c15318, 1, 1, f, b)
000002a109f38fc1 fop_delmap+0x40(3002836dd40, 30114c15318, 1, f, b7c1a000, b)
000002a109f39091 segvn_unmap+0x180(3017e8a0bd0, fffffffec0000000, b7c1a000, b7c1a000, f, 600439d6b78)
000002a109f39181 as_unmap+0xe4(300ee744d20, 3017e8a0bd0, 300de51bd88, b7c1a000, 1, 1)
000002a109f39231 munmap+0x78(1fff, b7c1a000, 10a6800, 300b84af968, 300b84af968, fffffffec0000000)
000002a109f392e1 syscall_trap+0xac(fffffffec0000000, b7c1a000, 0, 8, 10012c4d0, 10012c460)
>
(blank line)
Hmm, well that process ALSO seems to be waiting on a conditional variable in a mutex lock as part of the ZFS kernel module. Maybe they're related ?
(blank line)
I look at the storage available to the zone with the ID of 3 (obtained via "zoneadm list -v") and noticed that the zpool that provides most of the storage to that zone (including it's "/") is 100% full.
(blank line)
I send out an email detailing my findings and someone logs into that zone and cleans a few files up and things magically start working again.
(blank line)
Hooray.
Only in r2
Only in r10 --> Modified slightly between r2 and r10