NFS (vfs-related) syscall logging

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

@@ -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;

> 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

Hi,

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. :)]

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

'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.

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

Hello,

                    ^^^^^^
                      :)

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 ;).

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!

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