Nós atualizamos recentemente um servidor NFS (chamado "ian"), e após a atualização, o NFS está quebrado, enquanto não foi antes. O servidor está agora executando Debian "lenny", com a versão do kernel 2.6.26-2; é um Dell PowerEdge 2650 verdadeiramente antigo. Aqui estão os detalhes do problema, conforme os registramos em nosso sistema de tickets:
Aqui estão algumas das mensagens de log relacionadas a isso:
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]
(n.b. 100021 é o serviço RPC lockd.)
Pouco depois, isso aconteceu no 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 ]---
Dado que o problema parece ter começado antes que este bug do kernel fosse registrado, ele pode não ser a causa do problema, ou de fato relacionado a todos. Esse bug do kernel só apareceu desta vez, mesmo que o problema tenha reaparecido após várias reinicializações.
Embora o problema tenha começado ontem (e foi presumivelmente causado pela atualização do sistema operacional na noite anterior), ele não foi trazido à nossa atenção até hoje.
Alguns outros testes de depuração:
$ 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
Descobrimos que após a reinicialização do ian (que fizemos algumas vezes), o NFS realmente funcionou por um tempo. Enquanto estava funcionando, o comando acima deu essa saída:
$ 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
Nós reinicializamos o kernel anterior (vmlinuz-2.6.20.6 de 2007-04-07) e ainda tivemos o problema.
Ativamos as mensagens de depuração para o lockd / nlockmgr / nlm desta forma:
# echo 2047 > / proc / sys / sunrpc / nlm_debug
As mensagens não foram obviamente úteis. Aqui é quando o NFS está funcionando bem:
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
E a mesma coisa depois de lockd não respondeu:
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)
Observe a linha "falha na abertura (erro 117440512)"; nós também temos "aberto falhou (erro 16777216)"
Parece que o disparo dessa falha pode estar relacionado à carga. Depois de reiniciar os serviços NFS, o NFS continuou a funcionar por um bom tempo (mas com poucos clientes conectando
como poderíamos dizer) antes de falhar novamente.
Não há firewall em execução neste servidor; /etc/hosts.allow e /etc/hosts.deny estão vazios (exceto para comentários).
Estamos atualmente em um beco sem saída com esse problema. Não temos uma maneira fácil de voltar ao estado de pré-atualização. No entanto, estamos acelerando nossos planos de migrar esse serviço para um novo servidor, mas como ele estará executando mais ou menos o mesmo sistema operacional e kernel do servidor que está tendo problemas atualmente, seria bom ter uma ideia melhor de apenas o que está causando o problema, para que possamos ter alguma confiança de que não os encontraremos no novo servidor também.
Alguma idéia ou dicas para outras coisas investigarem ou tentarem?
Obrigado,
Tim.