Fork me on GitHub

At work, we have a Netgear ReadyNAS 1100. It’s a 4TB NAS appliance, a cute little 1U half-depth Linux box with 4 SATA disks, a RAID controller, and some firmware to do a whole bunch of fancy stuff (mainly geared towards consumers and very small shops - all configuration is point-and-click web UI). We’ve been using it for storing archived log data and low-priority backups. At the beginning of this problem, it was running RAIDiator 4.1.6 firmware since December of last year (over 6 months), and hadn’t had any configuration changes in at least 4 months.

Last week, I had to power off the unit and remove the power cables for some rack maintenance. I went through the usual full shutdown procedure in the web UI, and also told it to `fsck` the volumes, as that hadn’t been done in quite some time. Unfortunately, when the unit came back up, even after I could log into the web UI, I couldn’t mount the NFS shares on my backup server. I kept getting messages like:

[root@backup-server ~]# mount -a
mount: mount to NFS server 'css-readynas' failed: RPC Error: Program not registered.

so my next step was to check RPC status of the readynas, from the client. That was also a bit of a surprise:

[root@backup-server ~]# rpcinfo -p css-readynas                        
   program vers proto   port                                              
    100000    2   tcp    111  portmapper                                  
    100000    2   udp    111  portmapper                                  
    100011    1   udp    620  rquotad                                     
    100011    2   udp    620  rquotad                                     
    100011    1   tcp    623  rquotad                                     
    100011    2   tcp    623  rquotad                                     
    100024    1   udp  32765  status                                      
    100024    1   tcp  32765  status                                      
    100005    1   udp   2051  mountd                                      
    100005    1   tcp   3006  mountd                                      
    100005    2   udp   2051  mountd                                      
    100005    2   tcp   3006  mountd                                      
    100005    3   udp   2051  mountd                                      
    100005    3   tcp   3006  mountd 

Somewhere in that list is supposed to be nfsd, listening on port 2049. Next, I did an nmap (port scan) of the readynas:

[root@backup-server ~]# nmap -sU -p2047-2050 css-readynas             

Starting Nmap 4.11 ( http://www.insecure.org/nmap/ ) at 2011-06-23 15:21 EDT
Interesting ports on css-readynas.rutgers.edu (172.16.25.108):              
PORT     STATE         SERVICE                                              
2047/udp closed        dls                                                  
2048/udp closed        dls-monitor                                          
2049/udp open|filtered nfs                                                  
2050/udp closed        unknown  

Interesting. The port scan shows that something is listening on port 2049. But rpcinfo doesn’t seem to recognize it as a NFS server.

At this point, through FrontView (the web UI) I backed up the configuration and went through a few reboot cycles, with no change. I then started tweaking everything I could that I thought would restart the NFS server - I added and removed allowed hosts for the NFS share, enabled and disabled sync mode, etc. I started searching the ReadyNAS Forum and found a post that reported a very similar problem - upnpd grabbing nfsd port. The user reported that he was getting the same “RPC Error: Program not registered” message, and in daemon.log on the ReadyNAS, found a line including “storage nfsd[1087]: nfssvc: Address already in use”. I remembered that I’d setup the ReadyNAS to forward all logs to our central syslog server and, sure enough, found an identical message that something had already bound to UDP port 2049 when NFS was starting. I tried confirming that upnpd was disabled and rebooting, but that didn’t help. Grepping my logs for “nfs” returned:

daemon.log:Jun 23 12:43:43 css-readynas nfsd[2331]: nfssvc: Address already in use
daemon.log:Jun 23 15:26:33 css-readynas nfsd[2724]: nfssvc: Address already in use
kern.log:Jun 23 11:35:29 css-readynas kernel: Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
kern.log:Jun 23 12:43:43 css-readynas kernel: NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory
kern.log:Jun 23 12:43:43 css-readynas kernel: NFSD: starting 90-second grace period
kern.log:Jun 23 14:56:20 css-readynas kernel: Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
kern.log:Jun 23 15:12:41 css-readynas kernel: NFSD: starting 90-second grace period
kern.log:Jun 23 15:26:33 css-readynas kernel: NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory
kern.log:Jun 23 15:26:33 css-readynas kernel: NFSD: starting 90-second grace period

My next step was a few more reboots, with no change. I then upgraded the RAIDiator firmware to the latest, 4.1.7. Still no luck. I installed the Enable root SSH addon, and that’s when things became very clear:

css-readynas:/var/log# netstat -unlp
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name   
udp        0      0 0.0.0.0:2049            0.0.0.0:*                           794/snmpd           
udp        0      0 0.0.0.0:514             0.0.0.0:*                           673/syslogd         
udp        0      0 172.16.25.108:137       0.0.0.0:*                           1672/nmbd           
udp        0      0 0.0.0.0:137             0.0.0.0:*                           1672/nmbd           
udp        0      0 172.16.25.108:138       0.0.0.0:*                           1672/nmbd           
udp        0      0 0.0.0.0:138             0.0.0.0:*                           1672/nmbd           
udp        0      0 0.0.0.0:161             0.0.0.0:*                           794/snmpd           
udp        0      0 0.0.0.0:162             0.0.0.0:*                           802/snmptrapd       
udp        0      0 0.0.0.0:2086            0.0.0.0:*                           1565/rpc.mountd     
udp        0      0 127.0.0.1:22081         0.0.0.0:*                           1599/raidard        
udp        0      0 172.16.25.108:22081     0.0.0.0:*                           1599/raidard        
udp        0      0 0.0.0.0:22081           0.0.0.0:*                           1599/raidard        
udp        0      0 0.0.0.0:988             0.0.0.0:*                           819/rpc.rquotad     
udp        0      0 0.0.0.0:5353            0.0.0.0:*                           729/avahi-daemon: r 
udp        0      0 0.0.0.0:111             0.0.0.0:*                           666/portmap         
udp        0      0 0.0.0.0:881             0.0.0.0:*                           1553/rpc.statd      
udp        0      0 0.0.0.0:32765           0.0.0.0:*                           1553/rpc.statd     

For some very strange reason, snmpd had bound to port 2049 (the nfs port) instead of 161. That left no port for nfs to bind to.

Solution:

css-readynas:/var/log# /etc/init.d/snmpd stop                                                       
Stopping network management services: snmpd snmptrapd readynas-agent.                               
css-readynas:/var/log# /etc/init.d/nfs-kernel-server start
Exporting directories for NFS kernel daemon...done.
Starting NFS kernel daemon:mount: nfsd already mounted or /proc/fs/nfsd/ busy
mount: according to mtab, nfsd is mounted on /proc/fs/nfsd
 statd nfsd mountd.
css-readynas:/var/log# /etc/init.d/snmpd start
Starting network management services: snmpd snmptrapd readynas-agent.

Stop snmpd, restart nfs-kernel-server so that it grabs port 2049 like it should, and then start snmpd back up. If all went well, nfsd should now be listening on UDP 2049, and snmpd should be listening on UDP 161 like it should. To confirm:

css-readynas:/var/log# netstat -unlp
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
udp        0      0 0.0.0.0:2049            0.0.0.0:*                           -
udp        0      0 0.0.0.0:514             0.0.0.0:*                           673/syslogd
udp        0      0 172.16.25.108:137       0.0.0.0:*                           1672/nmbd
udp        0      0 0.0.0.0:137             0.0.0.0:*                           1672/nmbd
udp        0      0 172.16.25.108:138       0.0.0.0:*                           1672/nmbd
udp        0      0 0.0.0.0:138             0.0.0.0:*                           1672/nmbd
udp        0      0 0.0.0.0:161             0.0.0.0:*                           26161/snmpd
udp        0      0 0.0.0.0:162             0.0.0.0:*                           26163/snmptrapd
udp        0      0 0.0.0.0:2086            0.0.0.0:*                           1565/rpc.mountd
udp        0      0 127.0.0.1:22081         0.0.0.0:*                           1599/raidard
udp        0      0 172.16.25.108:22081     0.0.0.0:*                           1599/raidard
udp        0      0 0.0.0.0:22081           0.0.0.0:*                           1599/raidard
udp        0      0 0.0.0.0:988             0.0.0.0:*                           819/rpc.rquotad
udp        0      0 0.0.0.0:5353            0.0.0.0:*                           729/avahi-daemon: r
udp        0      0 0.0.0.0:2158            0.0.0.0:*                           -
udp        0      0 0.0.0.0:111             0.0.0.0:*                           666/portmap
udp        0      0 0.0.0.0:2160            0.0.0.0:*                           26161/snmpd
udp        0      0 0.0.0.0:881             0.0.0.0:*                           1553/rpc.statd
udp        0      0 0.0.0.0:32765           0.0.0.0:*                           1553/rpc.statd

All is well. Now to confirm this from the client machine:

[root@backup-server ~]# rpcinfo -p css-readynas
   program vers proto   port
    100000    2   tcp    111  portmapper
    100000    2   udp    111  portmapper
    100011    1   udp    988  rquotad
    100011    2   udp    988  rquotad
    100011    1   tcp    991  rquotad
    100011    2   tcp    991  rquotad
    100024    1   udp  32765  status
    100024    1   tcp  32765  status
    100005    1   udp   2086  mountd
    100005    1   tcp   3131  mountd
    100005    2   udp   2086  mountd
    100005    2   tcp   3131  mountd
    100005    3   udp   2086  mountd
    100005    3   tcp   3131  mountd
    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
    100021    1   udp   2158  nlockmgr
    100021    3   udp   2158  nlockmgr
    100021    4   udp   2158  nlockmgr
    100021    1   tcp   4189  nlockmgr
    100021    3   tcp   4189  nlockmgr
    100021    4   tcp   4189  nlockmgr

Ok, NFS is now there. It all looks good, and re-running mount -a on the client successfully mounts the NFS share.

We’ll see what happens next time I have to reboot the ReadyNAS. In the mean time, I’m going to try to bring this to the attention of Netgear support and hope they do something about it.


Comments

comments powered by Disqus