Well, I ran into problems in dumping the contents of the mds_sid array, DTrace does not iterate. To fix this, I decided to use a thread counter in the code for mds_ds_path_to_mds_sid:entry. I then increment it in the mds_ds_path_to_mds_sid:return. This allows me to enumerate the data set names.

#!/usr/sbin/dtrace -s

nfsv4:::spe-i-check_open
{
 	printf("%d (%d) from %s is checking %s",
            (uid_t)arg0, (gid_t)arg1, stringof(arg3), stringof(arg2));
}

nfsv4:::spe-i-policy_eval
{
 	printf("Policy %d %s with error %d from %s",
            (uint_t)arg0, (boolean_t)arg1 ? "matched" : "did not match",
            (int)arg2, stringof(arg3));
}

::nfs41_spe_allocate:entry
{
 	self->addr = (struct netbuf *)arg2;
	self->stripe_count = (count4 *)arg4;
	self->unit_size = (uint32_t *)arg5;
	self->mds_sids = (mds_sid **)arg6;

	self->loaded_sids = 0;
}

::nfs41_spe_allocate:return
/args[1] == 0/
{
 	printf("Policy has %d stripes and %u block size",
            *self->stripe_count, *self->unit_size);
}

::nfs41_spe_allocate:return
/args[1] != 0/
{
 	printf("No matching policy");
}

::mds_ds_path_to_mds_sid:entry
{
 	self->ustring = (utf8string *)arg0;
	self->ss_name = stringof(self->ustring->utf8string_val);
	self->mds_sid = (struct mds_sid *)arg1;
}

::mds_ds_path_to_mds_sid:return
/args[1] == 0/
{
 	ss_name = (char *)alloca(self->ustring->utf8string_len + 1);
	 bcopy(self->ustring->utf8string_val, ss_name,
            self->ustring->utf8string_len);
    	 ss_name[self->ustring->utf8string_len + 1] = '\0';
	printf("mds_sid[%d] = %s", self->loaded_sids++,
            stringof(ss_name));
}

::mds_ds_path_to_mds_sid:return
/args[1] != 0/
{
}

The remaining problem was that my first attempt to dump the utf8string resulted in garbage at the end of the output. Which makes sense, as such strings are not NUL terminated. Here is the original code:

::mds_ds_path_to_mds_sid:entry
{
 	u = (utf8string *)arg0;
  	self->ss_name = stringof(u->utf8string_val);
	self->mds_sid = (struct mds_sid *)arg1;
}

::mds_ds_path_to_mds_sid:return
/args[1] == 0/
{
 	printf("mds_sid[%d] = %s", self->loaded_sids++, self->ss_name);
}

There was an interesting thread of discussion over at: [dtrace-discuss] getting extra characters with printf(copyin(a, b)). I tried the approaches suggested by both Chad and Adam, but no luck. I get on getting:

dtrace: error on enabled probe ID 7 (ID 63585: fbt:nfssrv:mds_ds_path_to_mds_sid:return): invalid address (0xffffff01f6a103f8) in action #2 at DIF offset 56

Which to be fair, I more than expected. The issue is that the copyin and copyinstr work on user land memory and the stuff I want to dump is in the kernel. Where that thread really helped me though was it pointed me to using bcopy(). With that in play, things went well:

  1   3502 nfs41_spe_allocate:spe-i-check_open 0 (0) from 10.1.233.12 is checking /pnfs1/nfs41/pnfs-4-02/2/spek.txt
  1   3501 nfs41_spe_allocate:spe-i-policy_eval Policy 1000 did not match with error 0 from 10.1.233.12
  1   3501 nfs41_spe_allocate:spe-i-policy_eval Policy 2000 matched with error 0 from 10.1.233.12
  1  63585    mds_ds_path_to_mds_sid:return mds_sid[0] = pnfs-17-22:pnfs1/ds1n
  1  63585    mds_ds_path_to_mds_sid:return mds_sid[1] = pnfs-17-22:pnfs1/ds8n
  1  63585    mds_ds_path_to_mds_sid:return mds_sid[2] = pnfs-17-22:pnfs2/ds2n
  1  63585    mds_ds_path_to_mds_sid:return mds_sid[3] = pnfs-17-23:pnfs1/ds3n
  1  63585    mds_ds_path_to_mds_sid:return mds_sid[4] = pnfs-17-23:pnfs1/ds7n
  1  63585    mds_ds_path_to_mds_sid:return mds_sid[5] = pnfs-17-23:pnfs2/ds4f
  1  63585    mds_ds_path_to_mds_sid:return mds_sid[6] = pnfs-4-01:pnfs1/d10n
  1  63585    mds_ds_path_to_mds_sid:return mds_sid[7] = pnfs-4-01:pnfs1/ds4
  1  62825        nfs41_spe_allocate:return Policy has 8 stripes and 1000 block size

It is time to get rid of the remaining debug printfs in the kspe code. The answer is DTrace.

I've added the following:

        /*
         * Give the client, uid, gid, and path.
         */
        DTRACE_NFSV4_4(spe__i__check_open, uid_t, pat.uid,
            gid_t, pat.gid, char *, dir_path, char *, address);

Which will allow me to determine the relevant parameters to doing a check in the policies. And:

                /*
                 * Give the policy id, match, result, and client.
                 */
                DTRACE_NFSV4_4(spe__i__policy_eval, uint_t, sp->sp_id,
                    boolean_t, b, int, result, char *, address);

Will allow me to see the result of each policy lookup. I could probably do this with a function return, I would just have to pass in the address. But this is just as much an exercise in learning more about DTrace as anything else.

The last piece I will do as a function return. But I will lose the client address!

[root@pnfs-17-24 ~]> more spe.d 
#!/usr/sbin/dtrace -s

nfsv4:::spe-i-check_open
{
        co_uid = (uid_t)arg0;
        co_gid = (gid_t)arg1;
        co_path = (char *)arg2;
        co_addr = (char *)arg3;

        printf("%d (%d) from %s is checking %s",
            co_uid, co_gid, stringof(co_path), stringof(co_addr));
}

nfsv4:::spe-i-policy_eval
{
        pe_id = (uint_t)arg0;
        pe_match = (boolean_t)arg1;
        pe_res = (int)arg2;
        pe_addr = (char *)arg3;

        printf("Policy %d %s with error %d from %s",
            pe_id, pe_match ? "matched" : "did not match",
            pe_res, stringof(pe_addr));
}

Yields:

[root@pnfs-17-24 ~]> ./spe.d
dtrace: script './spe.d' matched 2 probes
CPU     ID                    FUNCTION:NAME
  0   3502 nfs41_spe_allocate:spe-i-check_open 0 (0) from /pnfs2/pnfs/pnfs-4-02/spek4.txt is checking 0.0.0.0
  0   3501 nfs41_spe_allocate:spe-i-policy_eval Policy 1000 did not match with error 0 from 0.0.0.0

Okay, my address and path is backwards on the first one. And the addresses look wrong. The uid and gid are actually probably okay, I'm doing my tests as root after all.

And a quick sanity check shows I am right:

[root@pnfs-17-24 ~]> ./spe.d 
dtrace: script './spe.d' matched 2 probes
CPU     ID                    FUNCTION:NAME
  1   3502 nfs41_spe_allocate:spe-i-check_open 3533 (10) from 0.0.0.0 is checking /pnfs1/nfs41/ds1tmds3.snoop
  1   3501 nfs41_spe_allocate:spe-i-policy_eval Policy 1000 did not match with error 0 from 0.0.0.0
  1   3501 nfs41_spe_allocate:spe-i-policy_eval Policy 2000 matched with error 0 from 0.0.0.0

Turns out that the passed in address is bogus:

[root@pnfs-17-24 ~]> Jul 28 21:12:24 pnfs-17-24 nfssrv: Address is 4294901760 for FFFF0000

This was working at one point, maybe. :->

I ended up doing some further investigation and added another probe:

nfsv4:::mds-i-create_address
{
        ca_req = (struct svc_req *)arg0;
        ca_addr = (struct netbuf *)arg1;

        a = (char *)ca_req->rq_xprt->xp_xpc.xpc_rtaddr.buf;
        iaddr = 0;
        iaddr = (a[0] << 24) | (a[1] << 16) | (a[2] << 8) | a[3];
        r1 = (iaddr & (0xff << 24)) >> 24;
        r2 = (iaddr & (0xff << 16)) >> 16;
        r3 = (iaddr & (0xff << 8)) >> 8;
        r4 = iaddr & 0xff;

        printf("Address is %u.%u.%u.%u", r1, r2, r3, r4);
}

It is late and DTrace does not do iteration. The code mimics what I do in C. It gives a consistent answer:

  0   3564 mds_createfile_get_layout:mds-i-create_address Address is 255.255.255.254
  0   3478 nfs41_spe_allocate:spe-i-check_open 0 (0) from 255.255.255.254 is checking /pnfs1/nfs41/ddsssss

Hmm, it is not changing as I change the client I'm making the request from.

I don't think it is working in OpenSolaris...

I think the bug isn't in the code, but in the way I am unpacking the netbuf. I'm looking at 4 bytes and the buffer is typically 16 bytes.

Yes, I ended up looking at our (OpenSolaris) source for __inet_taddr2uaddr() to figure out what was going on. I needed to go from:

1094         /*
1095          * XXX: Assuming IPv4!
1096          */
1097         a = (char *)addr->buf;
1098         for (i = 0; i < 4; i++) {
1099                 iaddr |= a[i] << ((3-i) * 8);
1100         }
1101 
1102         pat.addr = iaddr;

To:

1111         struct sockaddr_in      *sa;
...
1115         sa = (struct sockaddr_in *)(addr->buf);
1116 
1117         /*
1118          * XXX: Assuming IPv4!
1119          */
1120         a = (unsigned char *)&sa->sin_addr;
1121         for (i = 0; i < 4; i++) {
1122                 iaddr |= a[i] << ((3-i) * 8);
1123         }
1124 
1125         pat.addr = iaddr;

And we see this output:

  0  19974 nfs41_spe_allocate:spe-i-check_open 0 (0) from 10.1.233.12 is checking /pnfs1/nfs41/jk19

Well, I still need to finish up the DTRace script to dump the found layout upon return. And I should figure out how to dump the client address via DTrace.

The important lesson here is to test the stuff you think you've already tested. I know I tested the address logic in the stand alone prototype. And I thought I also tested it in a special kernel version, but I must not have done so. In fact, it makes sense with some of the debug logic I pulled out earlier this week.

In all, I'm happy, I fixed a very nasty bug.

I'm trying to track down whether the client address is ever being set in a NFS request. I've checked with build 117, 112, 109, 85, and now I'm trying 79a. I've got a VMWare image running on a laptop. But for some reason my probe isn't loading:

# ./req.d
dtrace: failed to compile script ./req.d: line 3: probe description ::rfs_dispatch:entry does not match any probes
# dtrace -f rfs_dispatch
dtrace: invalid probe specifier rfs_dispatch: probe description ::rfs_dispatch: does not match any probes

A clue can be found here:

# share
#

The clue is that with no shares loaded, then the 'nfssrv' module is not loaded. If we create a share, we see:

# share -F nfs -o rw,anon=0 /export/home
# dtrace -f rfs_dispatch
dtrace: description 'rfs_dispatch' matched 2 probes
^C

# ./req.d
dtrace: script './req.d' matched 1 probe

We have success!