Проблема с тайм-аутом блокировки NFS-сервера в Debian Linux

Question

Проблема с тайм-аутом блокировки NFS-сервера в Debian Linux

Недавно мы обновили сервер NFS (называемый "ian"), и после обновления NFS сломался, тогда как раньше этого не было. На сервере сейчас запущен Debian "lenny" с версией ядра 2.6.26-2; это действительно древний Dell PowerEdge 2650. Вот подробности проблемы, которые мы записали в нашей системе тикетов:

Вот некоторые сообщения журнала на ian, связанные с этим:

kern.log:

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

daemon.log:

Oct 7 10:59:33 ian rpc.statd[3991]: Can't callback ian (100021,3), giving up.
[and many more]

(nb 100021 - RPC-сервис lockd.)

Вскоре после этого это было в 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 ]---

Учитывая, что проблема, по-видимому, началась до того, как эта ошибка ядра была зарегистрирована, это может быть не причиной проблемы, или фактически связано с ней. Эта ошибка в ядре появилась только один раз, несмотря на то, что проблема возникла после нескольких перезагрузок.

Хотя проблема началась вчера (и, по-видимому, была вызвана обновлением ОС Иана прошлой ночью), до сегодняшнего дня она не была доведена до нашего сведения.

Некоторые другие тесты отладки:

$ 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

Мы перезагрузились в предыдущее ядро (vmlinuz-2.6.20.6 от 2007-04-07), и у нас все еще была проблема.

Мы включили сообщения отладки для 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

linux debian nfs

Источник

TimB 08 окт '10 в 07:36

2 ответа

Другие вопросы по тегам linux debian nfs

Xian 04 дек '12 в 21:49 2012-12-04 21:49 · Answer 1 · 2012-12-04 21:49

Я нашел ответ на это здесь: 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 на клиенте просто чтобы быть уверенным.

natxo asenjo 08 окт '10 в 07:53 2010-10-08 07:53 · Answer 2 · 2010-10-08 07:53

Единственное, что я могу вам сказать, это то, что у нас есть несколько серверов NFS, на которых работает lenny без каких-либо проблем. Аппаратное обеспечение старое (пролиант 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