我们最近升级了一台 NFS 服务器(名为“ian”),升级后,NFS 出现故障,而之前并没有出现故障。该服务器现在运行的是 Debian“lenny”,内核版本为 2.6.26-2;它是一台真正古老的 Dell PowerEdge 2650。以下是我们在票务系统中记录的问题详情:
以下是 ian 上与此相关的一些日志消息:
内核日志:
Oct 7 10:37:50 ian kernel: [60831.093676] statd: server localhost not responding, timed out
Oct 7 10:37:50 ian kernel: [60831.093739] lockd: cannot monitor jade-30.example.com
Oct 7 10:38:20 ian kernel: [60871.021326] statd: server localhost not responding, timed out
Oct 7 10:38:20 ian kernel: [60871.021403] lockd: cannot monitor jade-30.example.com
Oct 7 10:38:50 ian kernel: [60913.065830] statd: server localhost not responding, timed out
Oct 7 10:38:50 ian kernel: [60913.065892] lockd: cannot monitor jade-30.example.com
Oct 7 10:39:20 ian kernel: [60956.671592] statd: server localhost not responding, timed out
Oct 7 10:39:20 ian kernel: [60956.671592] lockd: cannot monitor jade-30.example.com
Oct 7 10:39:50 ian kernel: [61000.167660] statd: server localhost not responding, timed out
Oct 7 10:39:50 ian kernel: [61000.167738] lockd: cannot unmonitor jade-43.example.com
Oct 7 10:40:20 ian kernel: [61046.297937] statd: server localhost not responding, timed out
Oct 7 10:40:20 ian kernel: [61046.298000] lockd: cannot unmonitor jade-48.example.com
Oct 7 10:40:50 ian kernel: [61097.378121] statd: server localhost not responding, timed out
Oct 7 10:40:50 ian kernel: [61097.378190] lockd: cannot unmonitor jade-56.example.com
Oct 7 10:41:20 ian kernel: [61140.563304] rpcbind: server jade-42.example.com not responding, timed out
Oct 7 10:41:20 ian kernel: [61140.566912] statd: server localhost not responding, timed out
Oct 7 10:41:20 ian kernel: [61140.566912] lockd: cannot monitor jade-30.example.com
Oct 7 10:41:20 ian kernel: [61140.563304] rpcbind: server jade-27.example.com not responding, timed out
Oct 7 10:41:50 ian kernel: [61185.324223] rpcbind: server jade-30.example.com not responding, timed out
Oct 7 10:41:50 ian kernel: [61185.324223] statd: server localhost not responding, timed out
Oct 7 10:41:50 ian kernel: [61185.324223] lockd: cannot monitor jade-30.example.com
[etc.]
守护进程日志:
Oct 7 10:59:33 ian rpc.statd[3991]: Can't callback ian (100021,3), giving up.
[and many more]
(nb 100021 是 lockd RPC 服务。)
此后不久,kern.log 中出现了以下内容:
Oct 7 11:02:20 ian kernel: [62963.093217] ------------[ cut here ]------------
Oct 7 11:02:20 ian kernel: [62963.093217] kernel BUG at kernel/workqueue.c:273!
Oct 7 11:02:20 ian kernel: [62963.093217] invalid opcode: 0000 [#1] <5>rpcbind: server jade-52.example.com not responding, timed out
Oct 7 11:02:20 ian kernel: [62963.093217] SMP
Oct 7 11:02:20 ian kernel: [62963.093217] Modules linked in: ipmi_devintf ipmi_si ipmi_msghandler ppdev parport_pc lp parport ipv6 nfsd auth_rpcgss exportfs nfs lockd nfs_acl sunrpc dm_snapshot dm_mirror dm_log dm_mod snd_pcm snd_timer snd soundcore snd_page_alloc pcspkr shpchp pci_hotplug i2c_piix4 i2c_core button sworks_agp agpgart evdev dcdbas ext3 jbd mbcache sg sd_mod ide_cd_mod cdrom ata_generic libata dock ohci_hcd floppy aacraid usbcore tg3 scsi_mod e1000 serverworks ide_pci_generic ide_core thermal processor fan thermal_sys [last unloaded: scsi_wait_scan]
Oct 7 11:02:20 ian kernel: [62963.093217]
Oct 7 11:02:20 ian kernel: [62963.093217] Pid: 3999, comm: rpciod/0 Not tainted (2.6.26-2-686 #1)
Oct 7 11:02:20 ian kernel: [62963.093217] EIP: 0060:[<c012f0a0>] EFLAGS: 00010203 CPU: 0
Oct 7 11:02:20 ian kernel: [62963.093217] EIP is at run_workqueue+0x66/0xf2
Oct 7 11:02:20 ian kernel: [62963.093217] EAX: 00000000 EBX: f7de6f80 ECX: dd54f2dc EDX: dd54f2dc
Oct 7 11:02:20 ian kernel: [62963.093217] ESI: dd54f2d8 EDI: f8b72afd EBP: 00000000 ESP: dec0bfac
Oct 7 11:02:20 ian kernel: [62963.093217] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
Oct 7 11:02:20 ian kernel: [62963.093217] Process rpciod/0 (pid: 3999, ti=dec0a000 task=f75595e0 task.ti=dec0a000)
Oct 7 11:02:20 ian kernel: [62963.093217] Stack: f7de6f80 c012f789 f7de6f8c c012f83c 00000000 f75595e0 c0131a44 dec0bfc8
Oct 7 11:02:20 ian kernel: [62963.093217] dec0bfc8 f7de6f80 00000000 c0131983 c013194b 00000000 c01044f7 dd5bde04
Oct 7 11:02:20 ian kernel: [62963.093217] 00000000 00000000 00000000 00000000 00000000
Oct 7 11:02:20 ian kernel: [62963.093217] Call Trace:
Oct 7 11:02:20 ian kernel: [62963.093217] [<c012f789>] worker_thread+0x0/0xbd
Oct 7 11:02:20 ian kernel: [62963.093217] [<c012f83c>] worker_thread+0xb3/0xbd
Oct 7 11:02:20 ian kernel: [62963.093217] [<c0131a44>] autoremove_wake_function+0x0/0x2d
Oct 7 11:02:20 ian kernel: [62963.093217] [<c0131983>] kthread+0x38/0x5d
Oct 7 11:02:20 ian kernel: [62963.093217] [<c013194b>] kthread+0x0/0x5d
Oct 7 11:02:20 ian kernel: [62963.093217] [<c01044f7>] kernel_thread_helper+0x7/0x10
Oct 7 11:02:20 ian kernel: [62963.093217] =======================
Oct 7 11:02:20 ian kernel: [62963.093217] Code: 7e 0c 89 73 18 8b 11 8b 41 04 89 42 04 89 10 89 49 04 89 09 f0 fe 03 fb 90 8d b4 26 00 00 00 00 90 8b 41 fc 83 e0 fc 39 d8 74 04 <0f> 0b eb fe f0 0f ba 71 fc 00 89 f0 ff d7 89 e0 25 00 e0 ff ff
Oct 7 11:02:20 ian kernel: [62963.093217] EIP: [<c012f0a0>] run_workqueue+0x66/0xf2 SS:ESP 0068:dec0bfac
Oct 7 11:02:20 ian kernel: [62963.097562] ---[ end trace 661db88ca1ec8ada ]---
鉴于问题似乎在记录此内核错误之前就已经出现,它可能不是问题的原因,或者实际上根本不相关。此内核错误仅出现过一次,尽管问题在多次重启后再次出现。
虽然这个问题昨天就开始出现了(大概是前一天晚上 ian 的操作系统升级导致的),但直到今天我们才注意到。
其他一些调试测试:
$ rpcinfo -p localhost
program vers proto port
100000 2 tcp 111 portmapper
100000 2 udp 111 portmapper
100021 1 udp 58030 nlockmgr
100021 3 udp 58030 nlockmgr
100021 4 udp 58030 nlockmgr
100021 1 tcp 52602 nlockmgr
100021 3 tcp 52602 nlockmgr
100021 4 tcp 52602 nlockmgr
100024 1 udp 55130 status
100024 1 tcp 36082 status
100003 2 udp 2049 nfs
100003 3 udp 2049 nfs
100003 4 udp 2049 nfs
100003 2 tcp 2049 nfs
100003 3 tcp 2049 nfs
100003 4 tcp 2049 nfs
100005 1 udp 60186 mountd
100005 1 tcp 59282 mountd
100005 2 udp 60186 mountd
100005 2 tcp 59282 mountd
100005 3 udp 60186 mountd
100005 3 tcp 59282 mountd
$ rpcinfo -u localhost nlockmgr
rpcinfo: RPC: Timed out
program 100021 version 0 is not available
我们发现,在重启 ian(我们重启了几次)后,NFS 确实可以工作一段时间。当它工作时,上面的命令给出了以下输出:
$ rpcinfo -u localhost nlockmgr
program 100021 version 1 ready and waiting
rpcinfo: RPC: Program/version mismatch; low version = 1, high version = 4
program 100021 version 2 is not available
program 100021 version 3 ready and waiting
program 100021 version 4 ready and waiting
我们重新启动到以前的内核(2007-04-07 的 vmlinuz-2.6.20.6),但问题仍然存在。
我们为 lockd/nlockmgr/nlm 启用了调试消息,如下所示:# echo 2047 > /proc/sys/sunrpc/nlm_debug
这些信息显然没什么帮助。以下是 NFS 正常运行时的信息:
Oct 8 15:45:12 ian kernel: [ 222.037132] lockd: request from 192.168.246.17, port=896
Oct 8 15:45:12 ian kernel: [ 222.037151] lockd: LOCK_MSG called
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: nlm_lookup_host(192.168.240.55->192.168.246.17, p=17, v=4, my role=server, name=jade-45.example.com)
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: get host jade-45.example.com
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: LOCK called
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: nlm_lookup_host(192.168.240.55->192.168.246.17, p=17, v=4, my role=server, name=jade-45.example.com)
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: get host jade-45.example.com
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: nsm_monitor(jade-45.example.com)
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: nlm_lookup_file (01060001 fc22606e bd478947 777f518d 58ff17ac 028b086c 999bb476 00000000)
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: creating file for (01060001 fc22606e bd478947 777f518d 58ff17ac 028b086c 999bb476 00000000)
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: found file f5c21080 (count 0)
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: nlmsvc_lock(sda8/42666092, ty=1, pi=1886, 0-9223372036854775807, bl=1)
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: nlm_lookup_host(192.168.240.55->192.168.246.17, p=17, v=4, my role=server, name=jade-45.example.com)
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: get host jade-45.example.com
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: nlmsvc_lookup_block f=f5c21080 pd=1886 0-9223372036854775807 ty=1
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: get host jade-45.example.com
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: created block f6b882c0...
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: vfs_lock_file returned 0
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: freeing block f6b882c0...
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: release host jade-45.example.com
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: nlm_release_file(f5c21080, ct = 2)
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: release host jade-45.example.com
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: nlmsvc_lock returned 0
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: LOCK status 0
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: release host jade-45.example.com
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: nlm_release_file(f5c21080, ct = 1)
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: call procedure 12 on jade-45.example.com (async)
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: nlm_bind_host(192.168.240.55->192.168.246.17)
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: 20145 callback returned 0
Oct 8 15:45:12 ian kernel: [ 222.037171] lockd: release host jade-45.example.com
lockd 未能响应后,也出现了同样的事情:
Oct 8 15:48:09 ian kernel: [ 461.693824] lockd: request from 192.168.246.96, port=940
Oct 8 15:48:09 ian kernel: [ 461.693901] lockd: LOCK_MSG called
Oct 8 15:48:09 ian kernel: [ 461.693974] lockd: nlm_lookup_host(192.168.240.55->192.168.246.96, p=17, v=4, my role=server, name=librarybrowser-06.local)
Oct 8 15:48:09 ian kernel: [ 461.694072] lockd: get host librarybrowser-06.local
Oct 8 15:48:09 ian kernel: [ 461.694142] lockd: LOCK called
Oct 8 15:48:09 ian kernel: [ 461.694212] lockd: nlm_lookup_host(192.168.240.55->192.168.246.96, p=17, v=4, my role=server, name=librarybrowser-06.local)
Oct 8 15:48:09 ian kernel: [ 461.694308] lockd: get host librarybrowser-06.local
Oct 8 15:48:09 ian kernel: [ 461.694377] lockd: nsm_monitor(librarybrowser-06.local)
Oct 8 15:48:09 ian kernel: [ 461.694448] lockd: nlm_lookup_file (01060001 fc22606e bd478947 777f518d 58ff17ac 027c0411 999bb54b 00000000)
Oct 8 15:48:09 ian kernel: [ 461.694543] lockd: creating file for (01060001 fc22606e bd478947 777f518d 58ff17ac 027c0411 999bb54b 00000000)
Oct 8 15:48:09 ian kernel: [ 461.694644] lockd: open failed (error 117440512)
Oct 8 15:48:09 ian kernel: [ 461.694713] lockd: release host librarybrowser-06.local
Oct 8 15:48:09 ian kernel: [ 461.694783] lockd: call procedure 12 on librarybrowser-06.local (async)
Oct 8 15:48:09 ian kernel: [ 461.694857] lockd: nlm_bind_host(192.168.240.55->192.168.246.96)
请注意“打开失败(错误 117440512)”行;我们还收到“打开失败(错误 16777216)”
似乎触发此故障的原因可能与负载有关。重新启动 NFS 服务后,NFS 继续工作了一段时间(但据我们所知,连接的客户端很少),然后再次发生故障。
该服务器上没有运行防火墙;/etc/hosts.allow 和 /etc/hosts.deny 都是空的(除了注释)。
目前,我们已陷入了解决这个问题的死胡同。我们没有简单的方法可以恢复到升级前的状态。但是,我们正在加快将此服务迁移到新服务器的计划,但由于新服务器将运行与当前出现问题的服务器大致相同的操作系统和内核,因此最好更好地了解导致问题的原因,这样我们就可以确信在新服务器上不会遇到这些问题。
还有什么想法或建议可以调查或尝试其他的事情吗?
谢谢,
蒂姆。
答案1
我在这里找到了答案:http://sophiedogg.com/?p=141
/var/lib/nfs/statd/sm
- 包含 statd 监视器列表的目录/var/lib/nfs/statd/sm.bak
- 包含 statd 通知列表的目录
在删除这些文件之前,您应该停止 rpcbind、statd 和 lockd 服务。下面是在基于 RPM 的发行版上修复此问题需要运行的命令列表。
service rpcbind stop
service nfslock stop
rm -rf /var/lib/nfs/statd/sm/*
rm -rf /var/lib/nfs/statd/sm.bak/*
service rpcbind start
service nfslock start
运行这些命令后,最好重新启动 NFS 服务器。
在 Debian 及其衍生版本中,命令如下:
service nfs-kernel-server stop
service rpcbind stop
service nfs-common stop
service rpcbind start
service nfs-common start
service nfs-kernel-server start
service nfs-common restart
为了确保万无一失,我也在客户端上做了此操作。
答案2
我唯一能告诉你的是,我们有一些 NFS 服务器运行 lenny 时没有任何问题。硬件比较旧(如果我没记错的话,是 proliants g4,我现在不在工作),但磁盘是快速 scsi 15krpm,所以这才是最重要的。
调试 nfs 问题可能令人沮丧。我发现这可以帮助您从日志中获取更多信息:
* RPC debugging:
echo 2048 > /proc/sys/sunrpc/rpc_debug
grep . /proc/net/rpc/*/content
ls -l /proc/fs/nfsd
cat /proc/fs/nfs/exports
* NFS debugging:
# turn on linux nfs debug
echo 1 > /proc/sys/sunrpc/nfs_debug
# turn off linux nfs debug
echo 0 > /proc/sys/sunrpc/nfs_debug