NFS (vfs-related) syscall logging

NFS (vfs-related) syscall logging

[Roberto Nibali]

[-- Attachment #1: Type: text/plain, Size: 1860 bytes --]

Hello,

I'm trying to find a good way to log NFS syscalls related to direct file 
handling, such as for example nfsd_create_v3() or nfsd_unlink(). I've 
written up a patch (Al Viro, please close both your eyes) which is 
appended but somehow I don't know if this is the best way of doing it. I 
will extend it and add yet another proc-fs variable in /proc/sys/sunrpc/ 
which will represent a bitmask to selectively enable/disable which 
syscalls should be logged. Could someone please comment on following 
questions/ideas:

Wouldn't it be better to have such a logging facility on the VFS layer 
for all callback functions in general?

Could I maybe combine my effort with the LSM approach done for 
additional security hooks as seen in functions like 
security_ops->inode_ops->put_your_favourite syscall()?

Did I miss some part in the NFS code where this is already done but not 
enabled or has someone else already done something better and more 
efficient?

Either I was smoking too much pot or I've really sometimes seen 
nfs_create() followed by a nfs_create_v3(). Is this possible?

Sidenote: I've seen that in smbfs:smb_build_path() the pathname is built 
up with a helper function reverse_string(). As you can see I've made a 
recursive function which I think is easier to read and also faster and 
has smaller cache footprint. Is there a common makro somewhere defined 
on how to get the pathname as a string or is everyone writing up their 
own implementation of it? I'm talking about the

while(!IS_ROOT(dentry)) dentry=dentry->d_parent;

approach. It would be nice to have this a makro or a function. Maybe 
noone really needs it?

Please be kind with me because normally I don't fiddle around with (v)fs 
parts in the kernel ;)

Best regards,
Roberto Nibali, ratz
-- 
echo '[q]sa[ln0=aln256%Pln256/snlbx]sb3135071790101768542287578439snlbxq'|dc

[-- Attachment #2: nfslog-2.4.19p10-3.diff --]
[-- Type: text/plain, Size: 3748 bytes --]

--- /usr/src/linux/fs/nfsd/vfs.c	Wed May  8 14:25:38 2002
+++ vfs.c	Fri Jun 14 15:24:05 2002
@@ -77,6 +77,15 @@
 static struct raparms *		raparml;
 static struct raparms *		raparm_cache;
 
+static void print_dirname(struct dentry *getdentry) {
+	if ((getdentry != NULL) && !IS_ROOT(getdentry)){
+		print_dirname(getdentry->d_parent);
+	}
+	if (!IS_ROOT(getdentry)) {
+		printk("/%s", getdentry->d_name.name);
+	}
+}
+
 /*
  * Look up one component of a pathname.
  * N.B. After this call _both_ fhp and resfh need an fh_put
@@ -490,6 +499,13 @@
 			 */
 			atomic_dec(&filp->f_count);
 		}
+		printk(KERN_INFO "NFSLOG UID=%d GID=%d FILE=",
+			rqstp->rq_cred.cr_uid,
+			rqstp->rq_cred.cr_gid);
+		print_dirname(dentry);
+		printk(" OP=%s IP=%d.%d.%d.%d\n",
+			__FUNCTION__,
+			NIPQUAD(rqstp->rq_addr.sin_addr.s_addr));
 	}
 out_nfserr:
 	if (err)
@@ -648,6 +664,14 @@
 		err = 0;
 	} else 
 		err = nfserrno(err);
+
+	printk(KERN_INFO "NFSLOG UID=%d GID=%d FILE=",
+		rqstp->rq_cred.cr_uid,
+		rqstp->rq_cred.cr_gid);
+	print_dirname(fhp->fh_dentry);
+	printk(" OP=%s IP=%d.%d.%d.%d\n",
+		__FUNCTION__,
+		NIPQUAD(rqstp->rq_addr.sin_addr.s_addr));
 out_close:
 	nfsd_close(&file);
 out:
@@ -769,6 +793,14 @@
 		err = 0;
 	else 
 		err = nfserrno(err);
+
+	printk(KERN_INFO "NFSLOG UID=%d GID=%d FILE=",
+		rqstp->rq_cred.cr_uid,
+		rqstp->rq_cred.cr_gid);
+	print_dirname(fhp->fh_dentry);
+	printk(" OP=%s IP=%d.%d.%d.%d\n",
+		__FUNCTION__,
+		NIPQUAD(rqstp->rq_addr.sin_addr.s_addr));
 out_close:
 	nfsd_close(&file);
 out:
@@ -925,6 +957,14 @@
 	 */
 	if (!err)
 		err = fh_update(resfhp);
+		printk(KERN_INFO "NFSLOG UID=%d GID=%d FILE=",
+			rqstp->rq_cred.cr_uid,
+			rqstp->rq_cred.cr_gid);
+		print_dirname(dentry);
+		printk("/%s", fname);
+		printk(KERN_INFO " OP=%s IP=%d.%d.%d.%d\n",
+			__FUNCTION__,
+			NIPQUAD(rqstp->rq_addr.sin_addr.s_addr));
 out:
 	return err;
 
@@ -1036,6 +1076,15 @@
 	if (err)
 		goto out;
 
+	printk(KERN_INFO "NFSLOG UID=%d GID=%d FILE=",
+		rqstp->rq_cred.cr_uid,
+		rqstp->rq_cred.cr_gid);
+	print_dirname(dentry);
+	printk("/%s", fname);
+	printk(" OP=%s IP=%d.%d.%d.%d\n",
+		__FUNCTION__,
+		NIPQUAD(rqstp->rq_addr.sin_addr.s_addr));
+
 	if (createmode == NFS3_CREATE_EXCLUSIVE) {
 		/* Cram the verifier into atime/mtime/mode */
 		iap->ia_valid = ATTR_MTIME|ATTR_ATIME
@@ -1103,6 +1152,13 @@
 		goto out_nfserr;
 	*lenp = err;
 	err = 0;
+	printk(KERN_INFO "NFSLOG UID=%d GID=%d FILE=",
+		rqstp->rq_cred.cr_uid,
+		rqstp->rq_cred.cr_gid);
+	print_dirname(dentry);
+	printk(" OP=%s IP=%d.%d.%d.%d\n",
+		__FUNCTION__,
+		NIPQUAD(rqstp->rq_addr.sin_addr.s_addr));
 out:
 	return err;
 
@@ -1163,6 +1219,13 @@
 
 	/* Compose the fh so the dentry will be freed ... */
 	cerr = fh_compose(resfhp, fhp->fh_export, dnew, fhp);
+	printk(KERN_INFO "NFSLOG UID=%d GID=%d FILE=",
+		rqstp->rq_cred.cr_uid,
+		rqstp->rq_cred.cr_gid);
+	print_dirname(dentry);
+	printk(" OP=%s IP=%d.%d.%d.%d\n",
+		__FUNCTION__,
+		NIPQUAD(rqstp->rq_addr.sin_addr.s_addr));
 	if (err==0) err = cerr;
 out:
 	return err;
@@ -1302,6 +1365,14 @@
 	}
 	dput(ndentry);
 
+	printk(KERN_INFO "NFSLOG UID=%d GID=%d FILE=",
+		rqstp->rq_cred.cr_uid,
+		rqstp->rq_cred.cr_gid);
+	print_dirname(fdentry);
+	printk(" OP=%s IP=%d.%d.%d.%d\n",
+		__FUNCTION__,
+		NIPQUAD(rqstp->rq_addr.sin_addr.s_addr));
+
  out_dput_old:
 	dput(odentry);
  out_nfserr:
@@ -1373,6 +1444,15 @@
 		goto out_nfserr;
 	if (EX_ISSYNC(fhp->fh_export)) 
 		nfsd_sync_dir(dentry);
+
+	printk(KERN_INFO "NFSLOG UID=%d GID=%d FILE=",
+		rqstp->rq_cred.cr_uid,
+		rqstp->rq_cred.cr_gid);
+	print_dirname(dentry);
+	printk("/%s", fname);
+	printk(" OP=%s IP=%d.%d.%d.%d\n",
+		__FUNCTION__,
+		NIPQUAD(rqstp->rq_addr.sin_addr.s_addr)); //ratz
 
 out:
 	return err;

Re: NFS (vfs-related) syscall logging

[Trond Myklebust]

>>>>> " " == Roberto Nibali <ratz@drugphish.ch> writes:

     > I will extend it and add yet another proc-fs variable in
     > /proc/sys/sunrpc/ which will represent a bitmask to selectively
     > enable/disable which syscalls should be logged.


Ugh...

The volume of information you propose to log is going to be seriously
huge and *will* affect performance. It would probably be a lot more
efficient to log using 'tcpdump' (and the libpcap binary format)
instead of all those printks.

Cheers,
  Trond

Re: NFS (vfs-related) syscall logging

[Roberto Nibali]

Hi,

>      > I will extend it and add yet another proc-fs variable in
>      > /proc/sys/sunrpc/ which will represent a bitmask to selectively
>      > enable/disable which syscalls should be logged.
> 
> 
> Ugh...
> 
> The volume of information you propose to log is going to be seriously
> huge and *will* affect performance. It would probably be a lot more

I'm fully aware of that. But we have the problem that we need C2'ish 
audit trails and logging facilities. It's a requirement in the company I 
work for. Linux unfortunately isn't quite there yet but with the LSM 
framework it would be possible. I know that SGI at a certain point had 
put a lot of effort into getting something like that into the LSM 
framework. I simply can't wait (for that specific NFS requirement) until 
it is part of the official kernel tree so I hacked that patch together. 
It's easier to forward port my simple patch than to have LSM and a patch.

[Besides all that my boss thinks we can handle the amount of overhead 
and the logged data and he pays my check, so I do it. :)]

> efficient to log using 'tcpdump' (and the libpcap binary format)
> instead of all those printks.

Can't do that, company policy and I doubt this would be more efficient 
since you need a damn intelligent parser to get the same information 
from a packet dump.

But thanks for your input. Maybe you or someone else would be able to 
give me a response to my other questions too, if possible. I'd really 
appreciate it.

Best regards and thanks for your effort,
Roberto Nibali, ratz
-- 
echo '[q]sa[ln0=aln256%Pln256/snlbx]sb3135071790101768542287578439snlbxq'|dc

Re: NFS (vfs-related) syscall logging

[Trond Myklebust]

On Monday 17 June 2002 18:39, Roberto Nibali wrote:
> > efficient to log using 'tcpdump' (and the libpcap binary format)
> > instead of all those printks.
>
> Can't do that, company policy and I doubt this would be more efficient
> since you need a damn intelligent parser to get the same information
> from a packet dump.

'ethereal' *is* a damned intelligent parser that understands RPC/NFS/... ;-)
You should be able to use its read filtering capabilities to cherry-pick 
exactly the information that interests you.

>
> But thanks for your input. Maybe you or someone else would be able to
> give me a response to my other questions too, if possible. I'd really
> appreciate it.

If you are going to insist on logging using printks, you might as well just 
use the existing RPC debugging code. Just rewrite your printks to the format

dfprintk(BITMASK, format,...)

The value of BITMASK can be whatever you want, although the masks between 
0x0001 and 0x0200 are already used by the existing nfsd debugging code (see 
include/linux/nfsd/debug.h).

Then just 'echo BITMASK >/proc/sys/sunrpc/nfsd_debug' in order to begin 
logging.

Cheers,
  Trond

Re: NFS (vfs-related) syscall logging

[Roberto Nibali]

Hello,

> 'ethereal' *is* a damned intelligent parser that understands RPC/NFS/... ;-)
                     ^^^^^^
                       :)

Yes, it does, but it is a pain to get for example nfsd_unlink or 
nfsd_create_v3 calls and filter out the UID, GID and pathname. And 
fiddling around with nfs.data is quite a pain too. Plus (t)ethereal 
opens yet another code path in the TCP/IP stack via skb_clone() to add 
it to the ptype_all list while running. I'd like to do things where they 
should be done ;).

> You should be able to use its read filtering capabilities to cherry-pick 
> exactly the information that interests you.

I tried for a while but I found it easier to extend the current NFS code 
  with my needs, especially after you gave me the hint below!

> If you are going to insist on logging using printks, you might as well just 
> use the existing RPC debugging code. Just rewrite your printks to the format
> 
> dfprintk(BITMASK, format,...)
> 
> The value of BITMASK can be whatever you want, although the masks between 
> 0x0001 and 0x0200 are already used by the existing nfsd debugging code (see 
> include/linux/nfsd/debug.h).
> 
> Then just 'echo BITMASK >/proc/sys/sunrpc/nfsd_debug' in order to begin 
> logging.

Thank you very much for this valuable hint. Since I'm using a recursive 
function in my patch to print the pathname along with the according 
syscall it turned out to be stupid to use dfprintk for the first part of 
the output and then trying to patch together the rest. What I did was 
following (basic chunk of code responsible for a syscall):

+ 
if (nfsd_debug & NFSDDBG_SYSREAD){
+ 
	printk(KERN_INFO "NFSLOG UID=%d GID=%d FILE=",
+ 
		rqstp->rq_cred.cr_uid,
+ 
		rqstp->rq_cred.cr_gid);
+ 
	print_dirname(fhp->fh_dentry);
+ 
	printk(" OP=%s IP=%d.%d.%d.%d\n",
+ 
		__FUNCTION__,
+ 
		NIPQUAD(rqstp->rq_addr.sin_addr.s_addr));

I enhanced the debug.h with 5 new bitmasks (no more left now) and use 
them like that, despite the fact that dfprintk would add the NFSDDBG_ 
part. print_dirname now can be kept simple:

+static void print_dirname(struct dentry *getdentry) {
+ 
if ((getdentry != NULL) && !IS_ROOT(getdentry)){
+ 
	print_dirname(getdentry->d_parent);
+ 
}
+ 
if (!IS_ROOT(getdentry)) {
+ 
	printk("/%s", getdentry->d_name.name);
+ 
}
+}

Now another interesting thing I found was that the fname in nfsd_unlink 
is not always passed up correctly. I haven't tracked it down to the 
exact byte but you can reproduce it like follows:

1. mount a NFS export
2. create a deeply nested directory tree with let's say 30 Bytes as a
    pathname
3. now do a: echo "test" > test && rm -f ./test
4. watch the output of fname in unlink via a well placed printk().
5. fname must have length 4 and the tree must have a certain length too,
    I haven't found that one out yet

fname is already passed over in a wrong way at ../fs/nfsd/nfs3proc.c in 
nfsd3_proc_remove(). In my case with a printk("fname=%s", fname) I get
fname=test^A for nfsd_unlink and fname=test for nfsd_create_v3. Could 
you have a look into that one, please?

Best regards,
Roberto Nibali, ratz
-- 
echo '[q]sa[ln0=aln256%Pln256/snlbx]sb3135071790101768542287578439snlbxq'|dc