25

The Day “/Proc” Died

 4 years ago
source link: https://www.tuicool.com/articles/YZ3Mz2U
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.

Solaris'd...

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 today.
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.

So I logged in expecting a mundane failure:

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
^C
^C

~.

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.

workstation$ ssh milkyway1
milkyway1$ sudo -i
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
^C
^C

~.

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, which can be tragic.

workstation$ ssh milkyway1
milkyway1$ sudo -i
milkyway1# ls -ln /proc & echo $!
20023
milkyway1# mdb -k
> 0t20023::pid2proc
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)
>

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 .

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.

> 302765d6078 $p
debugger context set to proc 302765d6078
Segmentation Fault
milkyway1#

Oh. Well, that wasn't nice. Let's try it another way...

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"
>

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:

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

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?" ?

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 ]
> 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)
>

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 ?

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.

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.

Hooray.


About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK