NFSv3 Usage and Audit Logging

NFSv3 Usage and Audit Logging

It seems counter-intuitive that something that is as old and widespread as NFS would be severely lacking in the access logging area.  However, that does indeed appear to be the case.  Recently I’ve been able to take a break from my project management related activities to spend some time in something deeply technical to help prevent myself from getting stale.  The scenario started out very simply: take advantage of a hardware lifecycle refresh to move a legacy service that is small, ill-defined and running on bare metal and mature it to be a properly architected service running on virtual infrastructure.  In the process however, I discovered an NFSv3 share that is being served (and relied on for years) that has no defined and documented owner, users or requirements; just bits of associated tribal knowledge.  I needed to figure out who is using this NFS share to clear up the ambiguity and consequently find out if it’s even in use anymore…  That should be easy, right?  Well, turns out, not so much…

NFS is a stateless service that provides remote clients with the ability to mount a location on the NFS Server locally to their own machine.  It’s quite useful and very widespread and if you’re familiar with Windows it’s similar to CIFS.  For example, I can mount the contents of the /data/share directory on 192.168.1.127 locally at /opt/myshare as shown below.
[code language=”bash”]
client1# mount 192.168.1.127:/data/share /opt/myshare
[/code]
From here, I can read, create and modify files on the remote server as I please.  The question is, how can I tell what/who is doing this too?
First off, as far as I can tell there is no default NFS logging unless you’re running Solaris.  Odd, but ok…  There are several helpful articles floating around that point you correctly in the direction of enabling rpcdebug which is indeed helpful, and as far as I can tell, the only way to go on RHEL/CentOS 6.  Before we do that however, let’s explore NFS a bit more in-depth to help us understand the technology so that we can answer our two critical questions:

  • Who is using our share?
  • What are they accessing?

When an NFSv3 client attempts to connect to an NFS Share it sends a mount request that your NFS Server checks to see if you have the correct permissions to access the share that you have requested.  This information is something that you’re familiar with when you run:
[code language=”bash”]
exportfs
[/code]
 

However, this lookup actually is happening against the file /var/lib/nfs/etab which contains more information that is present in the output of the exportfs command.  If your remote client is authorized, then it will add an entry to the /var/lib/nfs/rmtab file showing that your IP Address has mounted the requested share.  This information is also presented in a user friendly method using
[code language=”bash”]
showmount -a
[/code]
 

Ok, so we know that once your client (and everybody else’s) initially mounts the mountpoint that a record is entered into the rmtab file!  Perfect!  Oh wait… according to the rpc.mountd man page, this information is notoriously unreliable to show you who is actually using the share because to get your entry removed, you actually have to send an unmount request to the server.  This means that we probably have a lot of stale records.  Well, at least it’s something that gives us the largest list possible of who our clients could be.  Now, how do we narrow that list down?
The easiest way that I’ve come up with is comparing that list of possible IPs from rmtab and seeing which ones of them actually connect to my NFS Server.  It’s a bit of a guessing game however if you have multiple shares on the same host, because there is no guarantee that they are only actively using the other shares and not the one we’re interested in.  If you’re reading this and have something better, please let me know!  Until then, here’s a screenshot of the code that I wrote doing it’s job in a test environment.

 
That sounds anti-climatic, and it is… turns out after investigating a bunch of different methods there isn’t a good way to find out who is actively accessing a file…. What’s that you say?  Check the logs….  Oh yes, let’s do that 😉
Like I mentioned before, there isn’t any native NFSv3 logging that I could find without enabling rpcdebug.  Enabling it is easy, but impactful.  If you don’t restart your NFS Service, you’ll be missing data and stuff won’t actually show up correctly.
[code language=”bash”]
rpcdebug -m nfsd -s all
[/code]
One other thing that you might want to do is to change your log rotation for /var/log/messages/ so that they don’t grow out of control.  The easiest way to do this is by modifying /etc/logrotate/syslog to change the rotation of the messages log to be a daily rotation and potentially lower the number of files to retain.

Now that we have logging enabled let’s take a look at what they contain using the output from a mount request.
[code language=”bash”]
Nov 9 11:08:13 testnfs kernel: nfsd_dispatch: vers 3 proc 4
Nov 9 11:08:13 testnfs kernel: nfsd: ACCESS(3)</strong> 28: 00070001 0017e804 00000000 f78d9021 0d4168ae ab78c3a7 0x1f
Nov 9 11:08:13 testnfs kernel: nfsd: fh_verify(28: 00070001 0017e804 00000000 f78d9021 0d4168ae ab78c3a7)
Nov 9 11:08:13 testnfs kernel: svc_export_request: pth /test
Nov 9 11:08:13 testnfs kernel: svc_export_parse: ‘* /test 1541788693 1056 65534 65534 0 secinfo 1 1 1056 uuid \x21908df7ae68410da7c378abdbd193b7 ‘
Nov 9 11:08:13 testnfs kernel: nfsd_dispatch: vers 3 proc 3
Nov 9 11:08:13 testnfs kernel: nfsd: LOOKUP(3) 28: 00070001 0017e804 00000000 f78d9021 0d4168ae ab78c3a7 10.X.X.110:
Nov 9 11:08:13 testnfs kernel: nfsd: nfsd_lookup(fh 28: 00070001 0017e804 00000000 f78d9021 0d4168ae ab78c3a7, 10.X.X.110:)
Nov 9 11:08:13 testnfs kernel: nfsd: fh_verify(28: 00070001 0017e804 00000000 f78d9021 0d4168ae ab78c3a7)
Nov 9 11:08:13 testnfs kernel: nfsd: fh_compose(exp fd:00/1566724 test/10.126.178.110:, ino=0)
Nov 9 11:08:13 testnfs kernel: svc: 10.X.X.108, port=679: unknown version (4 for prog 100003, nfsd)
Nov 9 11:08:13 testnfs kernel: svc: 10.X.X.108, port=763: unknown version (4 for prog 100003, nfsd)
Nov 9 11:08:13 testnfs kernel: nfsd_dispatch: vers 3 proc 0
Nov 9 11:08:13 testnfs rpc.mountd[13581]: authenticated mount request from 10.X.X.108:814 for /test (/test)
Nov 9 11:08:13 testnfs kernel: svc_export_parse: ‘* /test 1541788693 1056 65534 65534 0 secinfo 1 1 1056 uuid \x21908df7ae68410da7c378abdbd193b7 ‘
Nov 9 11:08:13 testnfs kernel: nfsd: exp_rootfh(/test [ffff880124f36900] *:dm-0/1566724)
Nov 9 11:08:13 testnfs kernel: nfsd: fh_compose(exp fd:00/1566724 //test, ino=1566724)
Nov 9 11:08:13 testnfs kernel: nfsd_dispatch: vers 3 proc 19
Nov 9 11:08:13 testnfs kernel: nfsd: FSINFO(3) 28: 00070001 0017e804 00000000 f78d9021 0d4168ae ab78c3a7
Nov 9 11:08:13 testnfs kernel: nfsd: fh_verify(28: 00070001 0017e804 00000000 f78d9021 0d4168ae ab78c3a7)
Nov 9 11:08:13 testnfs kernel: nfsd_dispatch: vers 3 proc 20
Nov 9 11:08:13 testnfs kernel: nfsd: PATHCONF(3) 28: 00070001 0017e804 00000000 f78d9021 0d4168ae ab78c3a7
Nov 9 11:08:13 testnfs kernel: nfsd: fh_verify(28: 00070001 0017e804 00000000 f78d9021 0d4168ae ab78c3a7)
Nov 9 11:08:13 testnfs kernel: nfsd_dispatch: vers 3 proc 1
Nov 9 11:08:13 testnfs kernel: nfsd: GETATTR(3) 28: 00070001 0017e804 00000000 f78d9021 0d4168ae ab78c3a7
Nov 9 11:08:13 testnfs kernel: nfsd: fh_verify(28: 00070001 0017e804 00000000 f78d9021 0d4168ae ab78c3a7)
Nov 9 11:08:13 testnfs kernel: nfsd_dispatch: vers 3 proc 0
Nov 9 11:08:13 testnfs kernel: nfsd_dispatch: vers 3 proc 19
Nov 9 11:08:13 testnfs kernel: nfsd: FSINFO(3) 28: 00070001 0017e804 00000000 f78d9021 0d4168ae ab78c3a7
Nov 9 11:08:13 testnfs kernel: nfsd: fh_verify(28: 00070001 0017e804 00000000 f78d9021 0d4168ae ab78c3a7)
Nov 9 11:08:13 testnfs kernel: nfsd_dispatch: vers 3 proc 1
Nov 9 11:08:13 testnfs kernel: nfsd: GETATTR(3) 28: 00070001 0017e804 00000000 f78d9021 0d4168ae ab78c3a7
Nov 9 11:08:13 testnfs kernel: nfsd: fh_verify(28: 00070001 0017e804 00000000 f78d9021 0d4168ae ab78c3a7)
[/code]
Well, that’s not very intuitive… but let’s dissect it a little bit using the NFSv3 Protocol Specification as our guide.  The first thing to notice is that the only identifying information for the remote client is in rpc.mountd’s entry “authenticated mount request for 10.x.x.108” and the share name.  This is the blocker that prevents us from getting good access level logs.  In the end NFS is a stateless application and it is not aware of who is accessing what, just the object being accessed.  In theory, NSM (Network Status Monitor) is responsible for locking files and tracking access.  However, during my testing I was never able to experience success in using file locks to identify the remote hosts.  Additionally, as a side note if you delete the entries in the /var/lib/nfs/rmtab file with the hope of having them regenerated to show current use, that doesn’t work.  The entries in the rmtab file are ONLY added upon a remote host sending a mount request to the NFS Server.  Also, even with a missing entry, the remote hosts can continue to access the share without issue.
 
Let’s dive into the above log file a bit more, with me skipping straight to the point:

  • nfsd logs the initial request such as “LOOKUP”, “GETATTR” and “ACCESS”.  The next line is the response back.
  • ACCESS(3) has two types that I was able to identify. 0x1f which indicates a list operation such as ll and 0x2d which indicates reading the contents of the file.

Only a few operations actually mention useful information in a single line context:

  • LOOKUP(3) – last bit of data shows the folder or file name accessed.
  • “nfsd_lookup(<lots of data> <file name> – This is redundant of the above so only use one of the two.
  • “fh_compose(exp fd:00/261125 data/test2, ino=261260) – shows the file being returned to the NFS client and the associated inode.
  • CREATE(3) – last bit of data shows the name of a file/folder being created.
  • fh_compose(exp fd:00/1566724 test/.newfile.txt.swp, ino=0) – Again, duplication but notice that the inode number is 0.
  • REMOVE(3) – Same as CREATE(3).

Let’s take this and apply it to an operation where the remote client is accessing a file with the intent of creating a logging rule to indicate file access…
[code language=”bash”]
Nov  9 09:26:26 testnfs kernel: nfsd_dispatch: vers 3 proc 4
Nov  9 09:26:26 testnfs kernel: nfsd: ACCESS(3)   28: 00070001 0003fc05 00000000 f78d9021 0d4168ae ab78c3a7 <b>0x1f</b>
Nov  9 09:26:26 testnfs kernel: nfsd: fh_verify(28: 00070001 0003fc05 00000000 f78d9021 0d4168ae ab78c3a7)
Nov  9 09:26:26 testnfs kernel: nfsd_dispatch: vers 3 proc 3
Nov  9 09:26:26 testnfs kernel: nfsd: LOOKUP(3)   28: 00070001 0003fc05 00000000 f78d9021 0d4168ae ab78c3a7 <b>30mb.log</b>
Nov  9 09:26:26 testnfs kernel: nfsd: nfsd_lookup(fh 28: 00070001 0003fc05 00000000 f78d9021 0d4168ae ab78c3a7, 30mb.log)
Nov  9 09:26:26 testnfs kernel: nfsd: fh_verify(28: 00070001 0003fc05 00000000 f78d9021 0d4168ae ab78c3a7)
Nov  9 09:26:26 testnfs kernel: nfsd: fh_compose(exp fd:00/261125 <b>data/30mb.log</b>, ino=261257)
Nov  9 09:26:26 testnfs kernel: nfsd_dispatch: vers 3 proc 1
Nov  9 09:26:26 testnfs kernel: nfsd: GETATTR(3)  36: 01070001 0003fc05 00000000 f78d9021 0d4168ae ab78c3a7
Nov  9 09:26:26 testnfs kernel: nfsd: fh_verify(36: 01070001 0003fc05 00000000 f78d9021 0d4168ae ab78c3a7)
Nov  9 09:26:26 testnfs kernel: nfsd_dispatch: vers 3 proc 4
Nov  9 09:26:26 testnfs kernel: nfsd: ACCESS(3)   36: 01070001 0003fc05 00000000 f78d9021 0d4168ae ab78c3a7<b> 0x2d</b>
Nov  9 09:26:26 testnfs kernel: nfsd: fh_verify(36: 01070001 0003fc05 00000000 f78d9021 0d4168ae ab78c3a7)
Nov  9 09:26:26 testnfs kernel: nfsd_dispatch: vers 3 proc 6
Nov  9 09:26:26 testnfs kernel: nfsd: READ(3) 36: 01070001 0003fc05 00000000 f78d9021 0d4168ae ab78c3a7 524288 bytes at 0
Nov  9 09:26:26 testnfs kernel: nfsd: fh_verify(36: 01070001 0003fc05 00000000 f78d9021 0d4168ae ab78c3a7)
Nov  9 09:26:26 testnfs kernel: nfsd_dispatch: vers 3 proc 6
Nov  9 09:26:26 testnfs kernel: nfsd: READ(3) 36: 01070001 0003fc05 00000000 f78d9021 0d4168ae ab78c3a7 524288 bytes at 524288
Nov  9 09:26:26 testnfs kernel: nfsd: fh_verify(36: 01070001 0003fc05 00000000 f78d9021 0d4168ae ab78c3a7)
Nov  9 09:26:26 testnfs kernel: nfsd_dispatch: vers 3 proc 6
Nov  9 09:26:26 testnfs kernel: nfsd: READ(3) 36: 01070001 0003fc05 00000000 f78d9021 0d4168ae ab78c3a7 524288 bytes at 1048576
Nov  9 09:26:26 testnfs kernel: nfsd: fh_verify(36: 01070001 0003fc05 00000000 f78d9021 0d4168ae ab78c3a7)
Nov  9 09:26:26 testnfs kernel: nfsd_dispatch: vers 3 proc 6
[/code]
It appears that we have two options here.

  1. Create a parser to recognize the LOOKUP(3) entry
  2. Create a parser to recognize the associated fh_compose string

I’m frankly not sure at this point which one is best but I’ve chosen to use the fh_compose for a simple reason.  If I use the file handle composer (assuming that’s what “fh” means) entry than I can identify the creation of a new file vs. the reading of an existing file based on the value of the specified inode.  The downside here is that there is no way to tell in a single event if the file was accessed in a list capability or if the contents were actually read.
So there you have it.  In short, there isn’t a great way that I’ve discovered to track who is accessing what files on an NFSv3 Server.  However, using some solid data and educated guessing we can narrow down the who for our list of potential users based on rmtab and current connection information.  At the same time we can use rpcdebug information to tell what is being accessed, but not with a direct correlation to who.

Leave a Reply

Your email address will not be published. Required fields are marked *