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.