Incrementar los logs de NFS

Hace poco me encontré con que no podía montar por NFS un sistema de archivos, y el cliente de NFS lo único que me daba era un simple timeout.

[root@client ~]# mount -vv -t nfs server:/data /mnt/test
mount: trying 192.168.1.11 prog 100003 vers 3 prot tcp port 2049
mount: mount to NFS server '192.168.1.11' failed: timed out (retrying).
...

En el /var/log/messages del servidor tampoco se volcaba nada.

Buscando por Internet descubrí que para incrementar los logs del servicio nfsd, había que modificar el valor de ciertos ficheros del sistema, que por defecto están a 0.

[root@server ~]$  echo 32767 > /proc/sys/sunrpc/rpc_debug

[root@server ~]$  echo 32767 > /proc/sys/sunrpc/nfsd_debug

Y para incrementar los logs en el cliente NFS:

[root@client ~]$  echo 32767 > /proc/sys/sunrpc/nfs_debug

Repitiendo la prueba con los logs en modo debug en el servidor, el único mensaje legible a destacar que pude observar fue el siguiente:

[root@server ~]$  tail -f /var/log/messages
...
Mar 31 14:19:57 client kernel: nfsd: connect from unprivileged port: 192.168.1.10:24498
Mar 31 14:19:57 client kernel: nfsd: connect from 192.168.1.10:5fb2

Venía a decir algo como que el cliente NFS (mount) se estaba intentando conectar desde un puerto del cual no podía. Como esto me seguía sin decir nada, al final tuve que recurrir a la herramienta de red por excelencia: tcpdump.

[root@server ~]$  tcpdump -nni eth0 \(tcp or udp\) and host 192.168.1.10
...
14:52:56.461748 IP 192.168.1.10.18036 > 192.168.1.11.111: S 3772663234:3772663234(0) win 5840 <mss 1460,nop,nop,timestamp 2288725875 0,nop,wscale 9>
14:52:56.462668 IP 192.168.1.11.111 > 192.168.1.10.18036: S 2887405046:2887405046(0) ack 3772663235 win 5792 <mss 1460,nop,nop,timestamp 2048429110 2288725875,nop,wscale 2>
...
14:52:56.476846 IP 192.168.1.10.61166 > 192.168.1.11.2049: . ack 29 win 12 <nop,nop,timestamp 2288725890 2048429124>
14:52:56.477097 IP 192.168.1.10.61166 > 192.168.1.11.2049: F 45:45(0) ack 29 win 12 <nop,nop,timestamp 2288725890 2048429124>
14:52:56.477761 IP 192.168.1.11.2049 > 192.168.1.10.61166: F 29:29(0) ack 46 win 1448 <nop,nop,timestamp 2048429126 2288725890>
14:52:56.478850 IP 192.168.1.10.61166 > 192.168.1.11.2049: . ack 30 win 12 <nop,nop,timestamp 2288725892 2048429126>


[root@client ~]# tcpdump -nni eth0 \(tcp or udp\) and host 192.168.1.11
...
14:52:56.459882 IP 192.168.1.10.18036 > 192.168.1.11.111: S 3772663234:3772663234(0) win 5840 <mss 1460,sackOK,timestamp 2288725875 0,nop,wscale 9>
14:52:56.461103 IP 192.168.1.11.111 > 192.168.1.10.18036: S 2887405046:2887405046(0) ack 3772663235 win 5792 <mss 1460,nop,nop,timestamp 2048429110 2288725875,nop,wscale 2>
...
14:52:56.475095 IP 192.168.1.10.61166 > 192.168.1.11.2049: . ack 29 win 12 <nop,nop,timestamp 2288725890 2048429124>
14:52:56.475257 IP 192.168.1.10.61166 > 192.168.1.11.2049: F 44:44(0) ack 29 win 12 <nop,nop,timestamp 2288725890 2048429124>
14:52:56.475400 IP 192.168.1.10.19867 > 192.168.1.11.111: UDP, length 56
14:52:56.477158 IP 192.168.1.11.2049 > 192.168.1.10.61166: F 29:29(0) ack 45 win 1448 <nop,nop,timestamp 2048429126 2288725890>
14:52:56.477173 IP 192.168.1.10.61166 > 192.168.1.11.2049: . ack 30 win 12 <nop,nop,timestamp 2288725892 2048429126>

Pues bien, en la traza del cliente puede observarse cómo éste estaba intentando mandar un paquete a través del protocolo UDP, el cual nunca llegaba al servidor. Lo que estaba ocurriendo es que el firewall situado entre ambas máquinas estaba cortando el tráfico UDP.