Incorrect marshalling of XDR data for NFS mkdir and create file operations

[hickeng]

Impact:
Prevents volume store creation from succeeding on some NFS servers (Linux seems to tolerate the trailing data)

Details:
XDR serialization is incorrectly including optional data from discriminated union as described here: https://tools.ietf.org/html/rfc1813#page-27

[hickeng]

Provided after the fact for reference.

Used the netapp simulator as the target NFS server, deployed in Workstation, with a braindead NFSv3 share configured.
Used the go-nfs-client test binary for diagnosics: go build -o nfstest ./vendor/github.com/vmware/go-nfs-client/nfs/example/test
Used tcpdump to compare a correct NFS mkdir request via Linux VFS mount and the incorrect request from the Go client (simple packet capture between client and netapp simulator: sudo tcpdump -i ens32 -w nfs-mkdir.pcap host 192.168.78.20 and 192.168.78.215)

Correct request processed via wireshark:

Frame 4: 230 bytes on wire (1840 bits), 230 bytes captured (1840 bits)
Ethernet II, Src: Vmware_67:1c:b5 (00:0c:29:67:1c:b5), Dst: Vmware_b9:25:d0 (00:0c:29:b9:25:d0)
Internet Protocol Version 4, Src: 192.168.78.215, Dst: 192.168.78.20
Transmission Control Protocol, Src Port: 715, Dst Port: 2049, Seq: 129, Ack: 125, Len: 164
Remote Procedure Call, Type:Call XID:0xb4a9fe0c
    Fragment header: Last fragment, 160 bytes
    XID: 0xb4a9fe0c (3031039500)
    Message Type: Call (0)
    RPC Version: 2
    Program: NFS (100003)
    Program Version: 3
    Procedure: MKDIR (9)
    [The reply to this request is in frame 5]
    Credentials
        Flavor: AUTH_UNIX (1)
        Length: 32
        Stamp: 0x010e6d41
        Machine Name: devbox
            length: 6
            contents: devbox
            fill bytes: opaque data
        UID: 0
        GID: 0
        Auxiliary GIDs (1) [0]
            GID: 0
    Verifier
        Flavor: AUTH_NULL (0)
        Length: 0
Network File System, MKDIR Call DH: 0x707bb260/test5
    [Program Version: 3]
    [V3 Procedure: MKDIR (9)]
    where
        dir
            length: 44
            [hash (CRC-32): 0x707bb260]
            FileHandle: 00000000196ace80000000004000000047251900196ace80...
        Name: test5
            length: 5
            contents: test5
            fill bytes: opaque data
    attributes
        mode: value follows
            set_it: value follows (1)
            Mode: 0755, S_IRUSR, S_IWUSR, S_IXUSR, S_IRGRP, S_IXGRP, S_IROTH, S_IXOTH
        uid: no value
        gid: no value
        size: no value
        atime: don't change
        mtime: don't change

Incorrect request - I do not have a reference for this, however it was showing an additional trailing Data section in the NFS portion of the request, and mutated depending on values set in the attributes section.

See https://github.com/davecgh/go-xdr/pull/6/files for details of required annotation structure to correctly handle discriminated unions.

[hickeng]

There is a confirmed (although not thoroughly vetted) fix in this branch: https://github.com/hickeng/vic/tree/nfs-fix
It needs to be split into a PR for the vmware/go-nfs-client project and the relatively minor logging improves from vmware/vic direct.

Also need to vet the split read and write paths - the following is vs NetApp

vagrant@devbox:~/vicsmb/src/github.com/vmware/vic$ sudo ./nfstest 192.168.78.20:/ test1
2017/10/04 03:27:43 host=192.168.78.20 target=/ dir=test1
2017/10/04 03:27:43 Connecting to 192.168.78.20:635
2017/10/04 03:27:43 using random port 629 -> 635
2017/10/04 03:27:43 Connecting to 192.168.78.20:2049
2017/10/04 03:27:43 using random port 507 -> 2049
2017/10/04 03:27:43 192.168.78.20:/ fsinfo=&nfs.FSInfo{Follows:0x1, RTMax:0x2, RTPref:0x1ff, RTMult:0x3, WTMax:0x0, WTPref:0x0, WTMult:0x0, DTPref:0x1000, Size:0x1000, TimeDelta:nfs.NFS3Time{Seconds:0x0, Nseconds:0x0}, Properties:0x0}
2017/10/04 03:27:43 root -> 0x00000000196ace80000000004000000047251900196ace800000000040000000472519004000000000000000
2017/10/04 03:27:43 No EOF for dirents so calling back for more
2017/10/04 03:27:43 No EOF for dirents so calling back for more
2017/10/04 03:27:43 dirs:
2017/10/04 03:27:43     .       0:0     024047520
2017/10/04 03:27:43     ..      0:0     024047520
2017/10/04 03:27:43     .snapshot       0:0     024047520
2017/10/04 03:27:43 root -> 0x00000000196ace80000000004000000047251900196ace800000000040000000472519004000000000000000
2017/10/04 03:27:43 mkdir(test1): created successfully (0x00000000196ace80000000007a01000048932800196ace800000000040000000472519004000000000000000)
2017/10/04 03:27:43 root -> 0x00000000196ace80000000004000000047251900196ace800000000040000000472519004000000000000000
2017/10/04 03:27:43 mkdir(test1): file already exists
2017/10/04 03:27:43 mkdir args (&{Header:{Rpcvers:2 Prog:100003 Vers:3 Proc:9 Cred:{Flavor:1 Body:[40 243 188 74 0 0 0 10 104 97 115 115 101 108 104 111 102 102 0 0 0 0 3 233 0 0 3 233 0 0 0 1 0 0 0 0]} Verf:{Flavor:0 Body:[]}} Where:{FH:[0 0 0 0 25 106 206 128 0 0 0 0 64 0 0 0 71 37 25 0 25 106 206 128 0 0 0 0 64 0 0 0 71 37 25 0 64 0 0 0 0 0 0 0] Filename:test1} Attrs:{Mode:{SetIt:true Mode:509} UID:{SetIt:false UID:0} GID:{SetIt:false UID:0} Size:{SetIt:false Size:0} Atime:{SetIt:0 Time:{Seconds:0 Nseconds:0}} Mtime:{SetIt:0 Time:{Seconds:0 Nseconds:0}}}})
2017/10/04 03:27:43 lookup(test1): FH 0x00000000196ace80000000007a01000048932800196ace800000000040000000472519004000000000000000
2017/10/04 03:27:43 mkdir(test1/a): created successfully (0x00000000196ace80000000007b01000048932800196ace800000000040000000472519004000000000000000)
2017/10/04 03:27:43 lookup(test1): FH 0x00000000196ace80000000007a01000048932800196ace800000000040000000472519004000000000000000
2017/10/04 03:27:43 lookup(a): FH 0x00000000196ace80000000007b01000048932800196ace800000000040000000472519004000000000000000
2017/10/04 03:27:43 mkdir(test1/a/b): created successfully (0x00000000196ace80000000007c01000049932800196ace800000000040000000472519004000000000000000)
2017/10/04 03:27:43 root -> 0x00000000196ace80000000004000000047251900196ace800000000040000000472519004000000000000000
2017/10/04 03:27:43 No EOF for dirents so calling back for more
2017/10/04 03:27:43 No EOF for dirents so calling back for more
2017/10/04 03:27:43 dirs:
2017/10/04 03:27:43     .       0:0     024047520
2017/10/04 03:27:43     ..      0:0     024047520
2017/10/04 03:27:43     test1   1001:1001       024047520
2017/10/04 03:27:43     .snapshot       0:0     024047520
2017/10/04 03:27:43 lookup(10mb): file does not exist
2017/10/04 03:27:43 root -> 0x00000000196ace80000000004000000047251900196ace800000000040000000472519004000000000000000
2017/10/04 03:27:43 create(10mb): created successfully
2017/10/04 03:27:43 write(00000000196ace80000000007d010000b6a62800196ace800000000040000000472519004000000000000000) len=0 offset=0 written=0 total=32768
2017/10/04 03:27:43 error copying: short write
2017/10/04 03:27:43 fail

whereas Linux NFS server gives:

vagrant@devbox:~/vicsmb/src/github.com/vmware/vic$ sudo ./nfstest 192.168.78.127:/home/nfs test1
2017/10/04 03:24:59 host=192.168.78.127 target=/home/nfs dir=test1
2017/10/04 03:25:14 Connecting to 192.168.78.127:32767
2017/10/04 03:25:14 using random port 1022 -> 32767
2017/10/04 03:25:14 Connecting to 192.168.78.127:2049
2017/10/04 03:25:14 using random port 806 -> 2049
2017/10/04 03:25:14 192.168.78.127:/home/nfs fsinfo=&nfs.FSInfo{Follows:0x0, RTMax:0x40000, RTPref:0x40000, RTMult:0x1000, WTMax:0x40000, WTPref:0x40000, WTMult:0x1000, DTPref:0x1000, Size:0xffffffff000, TimeDelta:nfs.NFS3Time{Seconds:0x1, Nseconds:0x0}, Properties:0x1b}
2017/10/04 03:25:14 root -> 0x0100070048200000000000007324754f1b6147a69b51ca6e9336375c
2017/10/04 03:25:14 Processed dirent cookie entry %!s(uint64=4551525896881367306)
2017/10/04 03:25:14 Processed dirent cookie entry %!s(uint64=9223372036854775807)
2017/10/04 03:25:14 no more entries to read for readdir: %!s(<nil>)
2017/10/04 03:25:14 Not EOF for dirents so calling back
2017/10/04 03:25:14 dirs:
2017/10/04 03:25:14     .       0:0     024050060
2017/10/04 03:25:14     ..      0:0     024050060
2017/10/04 03:25:14 root -> 0x0100070048200000000000007324754f1b6147a69b51ca6e9336375c
2017/10/04 03:25:14 mkdir(test1): created successfully (0x0100070148200000000000007324754f1b6147a69b51ca6e9336375c4f200000c91a2537)
2017/10/04 03:25:14 root -> 0x0100070048200000000000007324754f1b6147a69b51ca6e9336375c
2017/10/04 03:25:14 mkdir(test1): file already exists
2017/10/04 03:25:14 mkdir args (&{Header:{Rpcvers:2 Prog:100003 Vers:3 Proc:9 Cred:{Flavor:1 Body:[88 246 171 180 0 0 0 10 104 97 115 115 101 108 104 111 102 102 0 0 0 0 3 233 0 0 3 233 0 0 0 1 0 0 0 0]} Verf:{Flavor:0 Body:[]}} Where:{FH:[1 0 7 0 72 32 0 0 0 0 0 0 115 36 117 79 27 97 71 166 155 81 202 110 147 54 55 92] Filename:test1} Attrs:{Mode:{SetIt:true Mode:509} UID:{SetIt:false UID:0} GID:{SetIt:false UID:0} Size:{SetIt:false Size:0} Atime:{SetIt:0 Time:{Seconds:0 Nseconds:0}} Mtime:{SetIt:0 Time:{Seconds:0 Nseconds:0}}}})
2017/10/04 03:25:14 lookup(test1): FH 0x0100070148200000000000007324754f1b6147a69b51ca6e9336375c4f200000c91a2537
2017/10/04 03:25:14 mkdir(test1/a): created successfully (0x0100070148200000000000007324754f1b6147a69b51ca6e9336375c50200000ca1a2537)
2017/10/04 03:25:14 lookup(test1): FH 0x0100070148200000000000007324754f1b6147a69b51ca6e9336375c4f200000c91a2537
2017/10/04 03:25:14 lookup(a): FH 0x0100070148200000000000007324754f1b6147a69b51ca6e9336375c50200000ca1a2537
2017/10/04 03:25:14 mkdir(test1/a/b): created successfully (0x0100070148200000000000007324754f1b6147a69b51ca6e9336375c51200000cb1a2537)
2017/10/04 03:25:14 root -> 0x0100070048200000000000007324754f1b6147a69b51ca6e9336375c
2017/10/04 03:25:14 Processed dirent cookie entry %!s(uint64=2070839963876169261)
2017/10/04 03:25:14 Processed dirent cookie entry %!s(uint64=4551525896881367306)
2017/10/04 03:25:14 Processed dirent cookie entry %!s(uint64=9223372036854775807)
2017/10/04 03:25:14 no more entries to read for readdir: %!s(<nil>)
2017/10/04 03:25:14 Not EOF for dirents so calling back
2017/10/04 03:25:14 dirs:
2017/10/04 03:25:14     test1   1001:1001       024050060
2017/10/04 03:25:14     .       0:0     024050060
2017/10/04 03:25:14     ..      0:0     024050060
2017/10/04 03:25:14 lookup(10mb): file does not exist
2017/10/04 03:25:14 root -> 0x0100070048200000000000007324754f1b6147a69b51ca6e9336375c
2017/10/04 03:25:14 create(10mb): created successfully
2017/10/04 03:25:14 write(0100070148200000000000007324754f1b6147a69b51ca6e9336375c52200000cc1a2537) len=32768 offset=0 written=32768 total=32768
2017/10/04 03:25:14 write(0100070148200000000000007324754f1b6147a69b51ca6e9336375c52200000cc1a2537) len=32768 offset=32768 written=32768 total=32768
2017/10/04 03:25:14 write(0100070148200000000000007324754f1b6147a69b51ca6e9336375c52200000cc1a2537) len=32768 offset=65536 written=32768 total=32768
2017/10/04 03:25:14 write(0100070148200000000000007324754f1b6147a69b51ca6e9336375c52200000cc1a2537) len=32768 offset=98304 written=32768 total=32768
2017/10/04 03:25:14 write(0100070148200000000000007324754f1b6147a69b51ca6e9336375c52200000cc1a2537) len=32768 offset=131072 written=32768 total=32768
2017/10/04 03:25:14 write(0100070148200000000000007324754f1b6147a69b51ca6e9336375c52200000cc1a2537) len=32768 offset=163840 written=32768 total=32768
2017/10/04 03:25:14 write(0100070148200000000000007324754f1b6147a69b51ca6e9336375c52200000cc1a2537) len=32768 offset=196608 written=32768 total=32768
<snip>

[hickeng]

vmware-archive/go-nfs-client#2 opened to fix these problems - the client is still very incomplete, but the targeted tests pass vs both Linux kernel server and NetApp simulator.

[mdubya66]

putting into 1.3 and marking high pri, per @pdaigle

[hickeng]

Moved back to in-progress to follow up on:

• default values for uid, gid and proto - default values turn out to be for anon but needs to be enabled on server
• addition of testing to automated suite - deferring for now while moving to new CI infra