Skip to contentSkip to conversation

NFS: nfs4_reclaim_open_state: Lock reclaim failed! log spew

DISCUSSION Jason L Tibbitts III 5 participants 27 messages Feb 24, 2016 – Nov 21, 2016

Subsystems (2)
lore
Share & tools
lore
#0 lore raw

My NFS infrastructure has servers running current RHEL7.2 (mostly kernel 3.10.0-327.4.5.el7 with a one-line patch needed to fix a soft lockup in nfs4_laundromat) and clients running current Fedora 23 (4.3.5-300.fc23.x86_64). Everything is mounted NFS4.1 with sec=krb5p.

Occasionally a client will get into a state where it just hammers the server with network traffic, sometimes at full line rate, with:

NFS: nfs4_reclaim_open_state: Lock reclaim failed!

spewed to the log about 500 times a second. The load goes up quite a bit (to 5-7 or so). The machine isn't doing anything and there isn't even a user logged in. However, there are always a few user processes hanging around, usually kwin_x11 for whatever reason. (My guess is because of a lock on ~/.Xauthority.)

When I kill those user processes, this is logged once:

NFS: nfs4_reclaim_open_state: unhandled error -10068

-10068 is NFS4ERR_RETRY_UNCACHED_REP.

Unfortunately I did not grab any of that traffic (I just wanted it to stop). This happens to me periodically so I'll be sure to do that when it hits again.

One theory is that this is related to a user's kerberos ticket expiring. I see some hits when I search for the line that's spewed, but they're either not recent or or weren't reproducible. I don't find any hits for that specific unhandled error.

- J<

#1 lore raw
Quoted 16 lines · Jason L Tibbitts III

My NFS infrastructure has servers running current RHEL7.2 (mostly kernel 3.10.0-327.4.5.el7 with a one-line patch needed to fix a soft lockup in nfs4_laundromat) and clients running current Fedora 23 (4.3.5-300.fc23.x86_64). Everything is mounted NFS4.1 with sec=krb5p.

Occasionally a client will get into a state where it just hammers the server with network traffic, sometimes at full line rate, with:

NFS: nfs4_reclaim_open_state: Lock reclaim failed!

spewed to the log about 500 times a second. The load goes up quite a bit (to 5-7 or so). The machine isn't doing anything and there isn't even a user logged in. However, there are always a few user processes hanging around, usually kwin_x11 for whatever reason. (My guess is because of a lock on ~/.Xauthority.)

Quoted 5 lines

When I kill those user processes, this is logged once:

NFS: nfs4_reclaim_open_state: unhandled error -10068

-10068 is NFS4ERR_RETRY_UNCACHED_REP.

The only place the server sets that error is in
fs/nfsd/nfs4state.c:nfsd4_enc_sequence_replay.

If the server's correct, then the client attempted to resend a request that the server was not required to cache. In which case NFS4ERR_RETRY_UNCACHED_REP is a valid error, and the client should give up (or retry with a new slot/seqid?).

In any case, something's wrong with the 4.1 reply caching logic on client or server.....

Quoted 3 lines

Unfortunately I did not grab any of that traffic (I just wanted it to stop). This happens to me periodically so I'll be sure to do that when it hits again.

OK, that'd be helpful. Unfortunately what would probably be *most* helpful would be the traffic that lead up to this--by the time the client and server get into this loop the interesting problem may have already happened--but just seeing the loop may be useful too.

--b.

Quoted 10 lines

One theory is that this is related to a user's kerberos ticket expiring. I see some hits when I search for the line that's spewed, but they're either not recent or or weren't reproducible. I don't find any hits for that specific unhandled error.

- J<
--
To unsubscribe from this list: send the line "unsubscribe linux-nfs" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

#2 lore raw
Quoted 5 lines
Quoted 5 lines
Quoted 1 line
Quoted 1 line
Quoted 1 line

"JBF" == J Bruce Fields <[email protected]> writes:

Unfortunately I did not grab any of that traffic (I just wanted it to stop). This happens to me periodically so I'll be sure to do that when it hits again.

JBF> OK, that'd be helpful.

I waited a bit and it's happened again from a few clients. I captured some traffic from one of them and it's just an endless stream of Call/Reply:

8 0.002842000 172.21.86.135 -> 172.21.86.78 NFS 406 V4 Call
9 0.003493000 172.21.86.78 -> 172.21.86.135 NFS 518 V4 Reply (Call In 8)
10 0.003536000 172.21.86.135 -> 172.21.86.78 NFS 406 V4 Call 11 0.004168000 172.21.86.78 -> 172.21.86.135 NFS 518 V4 Reply (Call In 10) 12 0.004252000 172.21.86.135 -> 172.21.86.78 NFS 406 V4 Call 13 0.004854000 172.21.86.78 -> 172.21.86.135 NFS 518 V4 Reply (Call In 12) 14 0.004931000 172.21.86.135 -> 172.21.86.78 NFS 406 V4 Call 15 0.005613000 172.21.86.78 -> 172.21.86.135 NFS 518 V4 Reply (Call In 14)

Here's a call:

Frame 8: 406 bytes on wire (3248 bits), 406 bytes captured (3248 bits) on interface 0
Interface id: 0 (eno1)
Encapsulation type: Ethernet (1)
Arrival Time: Feb 29, 2016 16:48:17.376573000 CST
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1456786097.376573000 seconds
[Time delta from previous captured frame: 0.000049000 seconds]
[Time delta from previous displayed frame: 0.000000000 seconds]
[Time since reference or first frame: 0.002842000 seconds]
Frame Number: 8
Frame Length: 406 bytes (3248 bits)
Capture Length: 406 bytes (3248 bits)
[Frame is marked: False]
[Frame is ignored: False]
[Protocols in frame: eth:ethertype:ip:tcp:rpc:gss-api:spnego-krb5:spnego-krb5]
Ethernet II, Src: AsustekC_6d:f1:7e (f0:79:59:6d:f1:7e), Dst: SuperMic_19:86:94 (00:25:90:19:86:94)

    Destination: SuperMic_19:86:94 (00:25:90:19:86:94)
        Address: SuperMic_19:86:94 (00:25:90:19:86:94)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Source: AsustekC_6d:f1:7e (f0:79:59:6d:f1:7e)
        Address: AsustekC_6d:f1:7e (f0:79:59:6d:f1:7e)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Type: IP (0x0800)
Internet Protocol Version 4, Src: 172.21.86.135 (172.21.86.135), Dst: 172.21.86.78 (172.21.86.78)
    Version: 4
    Header Length: 20 bytes
    Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00: Not-ECT (Not ECN-Capable Transport))
        0000 00.. = Differentiated Services Codepoint: Default (0x00)
        .... ..00 = Explicit Congestion Notification: Not-ECT (Not ECN-Capable Transport) (0x00)
    Total Length: 392
    Identification: 0x79da (31194)
    Flags: 0x02 (Don't Fragment)
        0... .... = Reserved bit: Not set
        .1.. .... = Don't fragment: Set
        ..0. .... = More fragments: Not set
    Fragment offset: 0
    Time to live: 64
    Protocol: TCP (6)
    Header checksum: 0xba95 [validation disabled]
        [Good: False]
        [Bad: False]
    Source: 172.21.86.135 (172.21.86.135)
    Destination: 172.21.86.78 (172.21.86.78)
    [Source GeoIP: Unknown]
    [Destination GeoIP: Unknown]
Transmission Control Protocol, Src Port: 863 (863), Dst Port: 2049 (2049), Seq: 1361, Ack: 2261, Len: 340
    Source Port: 863 (863)
    Destination Port: 2049 (2049)
    [Stream index: 0]
    [TCP Segment Len: 340]
    Sequence number: 1361    (relative sequence number)
    [Next sequence number: 1701    (relative sequence number)]
    Acknowledgment number: 2261    (relative ack number)
    Header Length: 32 bytes
    .... 0000 0001 1000 = Flags: 0x018 (PSH, ACK)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Nonce: Not set
        .... 0... .... = Congestion Window Reduced (CWR): Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...1 .... = Acknowledgment: Set
        .... .... 1... = Push: Set
        .... .... .0.. = Reset: Not set
        .... .... ..0. = Syn: Not set
        .... .... ...0 = Fin: Not set
    Window size value: 24576
    [Calculated window size: 24576]
    [Window size scaling factor: -1 (unknown)]
    Checksum: 0x067b [validation disabled]
        [Good Checksum: False]
        [Bad Checksum: False]
    Urgent pointer: 0
    Options: (12 bytes), No-Operation (NOP), No-Operation (NOP), Timestamps
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        Timestamps: TSval 1220154220, TSecr 882989725
            Kind: Time Stamp Option (8)
            Length: 10
            Timestamp value: 1220154220
            Timestamp echo reply: 882989725
    [SEQ/ACK analysis]
        [This is an ACK to the segment in frame: 7]
        [The RTT to ACK the segment was: 0.000049000 seconds]
        [Bytes in flight: 340]
Remote Procedure Call, Type:Call XID:0xffb2b86a
    Fragment header: Last fragment, 336 bytes
        1... .... .... .... .... .... .... .... = Last Fragment: Yes
        .000 0000 0000 0000 0000 0001 0101 0000 = Fragment Length: 336
    XID: 0xffb2b86a (4289902698)
    Message Type: Call (0)
    RPC Version: 2
    Program: NFS (100003)
    Program Version: 4
    Procedure: COMPOUND (1)
    Credentials
        Flavor: RPCSEC_GSS (6)
        Length: 28
        GSS Version: 1
        GSS Procedure: RPCSEC_GSS_DATA (0)
        GSS Sequence Number: 59958333
        GSS Service: rpcsec_gss_svc_privacy (3)
        GSS Context
            GSS Context Length: 8
            GSS Context: 6d35000000000000
    Verifier
        Flavor: RPCSEC_GSS (6)
        GSS Token: 0000001c040404ffffffffff000000001bb5b424f2b2f47f...
            GSS Token Length: 28
            GSS-API Generic Security Service Application Program Interface
                krb5_blob: 040404ffffffffff000000001bb5b424f2b2f47fb068d17e...
                    krb5_tok_id: KRB_TOKEN_CFX_GetMic (0x0404)
                    krb5_cfx_flags: 0x04
                        .... .1.. = AcceptorSubkey: Set
                        .... ..0. = Sealed: Not set
                        .... ...0 = SendByAcceptor: Not set
                    krb5_filler: ffffffffff
                    krb5_cfx_seq: 464892964
                    krb5_sgn_cksum: f2b2f47fb068d17e40fca641
GSS-Wrap
    Length: 236
    GSS Data: 050406ff00000000000000001bb5b425d745e53e92ca2305...
    krb5_blob: 050406ff00000000000000001bb5b425d745e53e92ca2305...
        krb5_tok_id: KRB_TOKEN_CFX_WRAP (0x0405)
        krb5_cfx_flags: 0x06
            .... .1.. = AcceptorSubkey: Set
            .... ..1. = Sealed: Set
            .... ...0 = SendByAcceptor: Not set
        krb5_filler: ff
        krb5_cfx_ec: 0
        krb5_cfx_rrc: 0
        krb5_cfx_seq: 464892965
        krb5_sgn_cksum: d745e53e92ca2305e3b1f3bdbb6c710bd731fcc684b8dba8...

Network File System
[Program Version: 4]
[V4 Procedure: COMPOUND (1)]

And here's a reply:

Frame 9: 518 bytes on wire (4144 bits), 518 bytes captured (4144 bits) on interface 0
Interface id: 0 (eno1)
Encapsulation type: Ethernet (1)
Arrival Time: Feb 29, 2016 16:48:17.377224000 CST
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1456786097.377224000 seconds
[Time delta from previous captured frame: 0.000651000 seconds]
[Time delta from previous displayed frame: 0.000000000 seconds]
[Time since reference or first frame: 0.003493000 seconds]
Frame Number: 9
Frame Length: 518 bytes (4144 bits)
Capture Length: 518 bytes (4144 bits)
[Frame is marked: False]
[Frame is ignored: False]
[Protocols in frame: eth:ethertype:ip:tcp:rpc:gss-api:spnego-krb5:spnego-krb5]
Ethernet II, Src: SuperMic_19:86:94 (00:25:90:19:86:94), Dst: AsustekC_6d:f1:7e (f0:79:59:6d:f1:7e)

    Destination: AsustekC_6d:f1:7e (f0:79:59:6d:f1:7e)
        Address: AsustekC_6d:f1:7e (f0:79:59:6d:f1:7e)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Source: SuperMic_19:86:94 (00:25:90:19:86:94)
        Address: SuperMic_19:86:94 (00:25:90:19:86:94)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Type: IP (0x0800)
Internet Protocol Version 4, Src: 172.21.86.78 (172.21.86.78), Dst: 172.21.86.135 (172.21.86.135)
    Version: 4
    Header Length: 20 bytes
    Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00: Not-ECT (Not ECN-Capable Transport))
        0000 00.. = Differentiated Services Codepoint: Default (0x00)
        .... ..00 = Explicit Congestion Notification: Not-ECT (Not ECN-Capable Transport) (0x00)
    Total Length: 504
    Identification: 0x2bf6 (11254)
    Flags: 0x02 (Don't Fragment)
        0... .... = Reserved bit: Not set
        .1.. .... = Don't fragment: Set
        ..0. .... = More fragments: Not set
    Fragment offset: 0
    Time to live: 64
    Protocol: TCP (6)
    Header checksum: 0x080a [validation disabled]
        [Good: False]
        [Bad: False]
    Source: 172.21.86.78 (172.21.86.78)
    Destination: 172.21.86.135 (172.21.86.135)
    [Source GeoIP: Unknown]
    [Destination GeoIP: Unknown]
Transmission Control Protocol, Src Port: 2049 (2049), Dst Port: 863 (863), Seq: 2261, Ack: 1701, Len: 452
    Source Port: 2049 (2049)
    Destination Port: 863 (863)
    [Stream index: 0]
    [TCP Segment Len: 452]
    Sequence number: 2261    (relative sequence number)
    [Next sequence number: 2713    (relative sequence number)]
    Acknowledgment number: 1701    (relative ack number)
    Header Length: 32 bytes
    .... 0000 0001 1000 = Flags: 0x018 (PSH, ACK)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Nonce: Not set
        .... 0... .... = Congestion Window Reduced (CWR): Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...1 .... = Acknowledgment: Set
        .... .... 1... = Push: Set
        .... .... .0.. = Reset: Not set
        .... .... ..0. = Syn: Not set
        .... .... ...0 = Fin: Not set
    Window size value: 32885
    [Calculated window size: 32885]
    [Window size scaling factor: -1 (unknown)]
    Checksum: 0x8ac4 [validation disabled]
        [Good Checksum: False]
        [Bad Checksum: False]
    Urgent pointer: 0
    Options: (12 bytes), No-Operation (NOP), No-Operation (NOP), Timestamps
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        No-Operation (NOP)
            Type: 1
                0... .... = Copy on fragmentation: No
                .00. .... = Class: Control (0)
                ...0 0001 = Number: No-Operation (NOP) (1)
        Timestamps: TSval 882989725, TSecr 1220154220
            Kind: Time Stamp Option (8)
            Length: 10
            Timestamp value: 882989725
            Timestamp echo reply: 1220154220
    [SEQ/ACK analysis]
        [This is an ACK to the segment in frame: 8]
        [The RTT to ACK the segment was: 0.000651000 seconds]
        [Bytes in flight: 452]
Remote Procedure Call, Type:Reply XID:0xffb2b86a
    Fragment header: Last fragment, 448 bytes
        1... .... .... .... .... .... .... .... = Last Fragment: Yes
        .000 0000 0000 0000 0000 0001 1100 0000 = Fragment Length: 448
    XID: 0xffb2b86a (4289902698)
    Message Type: Reply (1)
    [Program: NFS (100003)]
    [Program Version: 4]
    [Procedure: COMPOUND (1)]
    Reply State: accepted (0)
    [This is a reply to a request in frame 8]
    [Time from request: 0.000651000 seconds]
    Verifier
        Flavor: RPCSEC_GSS (6)
        GSS Token: 0000001c040405ffffffffff000000003480887866d9d129...
            GSS Token Length: 28
            GSS-API Generic Security Service Application Program Interface
                krb5_blob: 040405ffffffffff000000003480887866d9d129415f2ea7...
                    krb5_tok_id: KRB_TOKEN_CFX_GetMic (0x0404)
                    krb5_cfx_flags: 0x05
                        .... .1.. = AcceptorSubkey: Set
                        .... ..0. = Sealed: Not set
                        .... ...1 = SendByAcceptor: Set
                    krb5_filler: ffffffffff
                    krb5_cfx_seq: 880838776
                    krb5_sgn_cksum: 66d9d129415f2ea76c509189
    Accept State: RPC executed successfully (0)
GSS-Wrap
    Length: 392
    GSS Data: 050407ff000000000000000034808879d55c1d7af7af82f5...
    krb5_blob: 050407ff000000000000000034808879d55c1d7af7af82f5...
        krb5_tok_id: KRB_TOKEN_CFX_WRAP (0x0405)
        krb5_cfx_flags: 0x07
            .... .1.. = AcceptorSubkey: Set
            .... ..1. = Sealed: Set
            .... ...1 = SendByAcceptor: Set
        krb5_filler: ff
        krb5_cfx_ec: 0
        krb5_cfx_rrc: 0
        krb5_cfx_seq: 880838777
        krb5_sgn_cksum: d55c1d7af7af82f5384db9579420a0e8eb2bf20013a66022...

Network File System
[Program Version: 4]
[V4 Procedure: COMPOUND (1)]

The calls and replies all appear to be identical. Sorry for the length of those but I wouldn't want to trim anything that might be important.

JBF> Unfortunately what would probably be *most* helpful would be the JBF> traffic that lead up to this--by the time the client and server get JBF> into this loop the interesting problem may have already JBF> happened--but just seeing the loop may be useful too.

Yeah, there's basically no chance of capturing that, and I have no way to make it happen. I can't just snarf all of the NFS traffic, and once this starts it generates so many packets....

Note that this doesn't appear to be caused by something like a kerberos ticket; the user last logged in well under the maximum ticket renewal time, and SSSD has been dutifully renewing them.

- J<

#3 lore raw
Quoted 22 lines · Jason L Tibbitts III
Quoted 5 lines
Quoted 5 lines
Quoted 1 line
Quoted 1 line
Quoted 1 line

"JBF" == J Bruce Fields <[email protected]> writes:

Unfortunately I did not grab any of that traffic (I just wanted it to stop). This happens to me periodically so I'll be sure to do that when it hits again.

JBF> OK, that'd be helpful.

I waited a bit and it's happened again from a few clients. I captured some traffic from one of them and it's just an endless stream of Call/Reply:

8 0.002842000 172.21.86.135 -> 172.21.86.78 NFS 406 V4 Call
9 0.003493000 172.21.86.78 -> 172.21.86.135 NFS 518 V4 Reply (Call In 8)
10 0.003536000 172.21.86.135 -> 172.21.86.78 NFS 406 V4 Call 11 0.004168000 172.21.86.78 -> 172.21.86.135 NFS 518 V4 Reply (Call In 10) 12 0.004252000 172.21.86.135 -> 172.21.86.78 NFS 406 V4 Call 13 0.004854000 172.21.86.78 -> 172.21.86.135 NFS 518 V4 Reply (Call In 12) 14 0.004931000 172.21.86.135 -> 172.21.86.78 NFS 406 V4 Call 15 0.005613000 172.21.86.78 -> 172.21.86.135 NFS 518 V4 Reply (Call In 14)

Quoted 3 lines

Here's a call:

GSS Service: rpcsec_gss_svc_privacy (3)

Argh, it's all encrypted, so we all we have to go on is the size of the request and reply:

Quoted 2 lines

GSS-Wrap

    Length: 236

...

Quoted 1 line

And here's a reply:

...

Quoted 2 lines

GSS-Wrap

    Length: 392

Anyway, just knowing the error may be enough for us to work out the problem--I just need to dig a little more.

Quoted 11 lines

The calls and replies all appear to be identical. Sorry for the length of those but I wouldn't want to trim anything that might be important.

JBF> Unfortunately what would probably be *most* helpful would be the JBF> traffic that lead up to this--by the time the client and server get JBF> into this loop the interesting problem may have already JBF> happened--but just seeing the loop may be useful too.

Yeah, there's basically no chance of capturing that, and I have no way to make it happen. I can't just snarf all of the NFS traffic, and once this starts it generates so many packets....

The best you could do is capture all traffic and throw away all but the last few seconds (see the ring buffer stuff in tshark) and write a script that kills the capture as soon as it notices you've hit this condition. Anyway, possibly still impractical and not worth the trouble at this point anyway.

Quoted 3 lines

Note that this doesn't appear to be caused by something like a kerberos ticket; the user last logged in well under the maximum ticket renewal time, and SSSD has been dutifully renewing them.

OK, thanks.

--b.

#4 lore raw
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line

"JBF" == J Bruce Fields <[email protected]> writes:

JBF> Argh, it's all encrypted, so we all we have to go on is the size of JBF> the request and reply:

Yeah, I'm not sure how to get around that. I know tshark can take a keytab, but the user's key is in the kernel keyring and I'm not at all sure how to dig it out (assuming I even can). But if there's something I can do, I can try.

I could switch to krb5i or plain krb for a while if that would be useful, except that the clients would prefer krb5p if it's exported, and if I stop exporting it then existing mounts break.... I'd have to schedule downtime and kick everyone off, which I could do if it would help.

JBF> The best you could do is capture all traffic and throw away all but JBF> the last few seconds (see the ring buffer stuff in tshark) and JBF> write a script that kills the capture as soon as it notices you've JBF> hit this condition.

If I knew how to detect the condition, though, I have a feeling that would be enough information to track down the bug anyway.

Also, I'd have to do this for a couple of hundred clients. Ugh.

- J<

#5 lore raw
Quoted 10 lines · Jason L Tibbitts III
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line

"JBF" == J Bruce Fields <[email protected]> writes:

JBF> Argh, it's all encrypted, so we all we have to go on is the size of JBF> the request and reply:

Yeah, I'm not sure how to get around that. I know tshark can take a keytab, but the user's key is in the kernel keyring and I'm not at all sure how to dig it out (assuming I even can). But if there's something I can do, I can try.

Quoted 5 lines

I could switch to krb5i or plain krb for a while if that would be useful, except that the clients would prefer krb5p if it's exported, and if I stop exporting it then existing mounts break.... I'd have to schedule downtime and kick everyone off, which I could do if it would help.

I believe the order of flavors in the sec= option is the order they're given to the client, so reversing it might cause new clients to make a different choice--but I'm not actually sure of the logic there.

Quoted 10 lines

JBF> The best you could do is capture all traffic and throw away all but JBF> the last few seconds (see the ring buffer stuff in tshark) and JBF> write a script that kills the capture as soon as it notices you've JBF> hit this condition.

If I knew how to detect the condition, though, I have a feeling that would be enough information to track down the bug anyway.

Also, I'd have to do this for a couple of hundred clients. Ugh.

Yeah, don't worry about it, I was just thinking aloud.

--b.

#6 lore raw
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line

"JBF" == J Bruce Fields <[email protected]> writes:

JBF> I believe the order of flavors in the sec= option is the order JBF> they're given to the client, so reversing it might cause new JBF> clients to make a different choice--but I'm not actually sure of JBF> the logic there.

I've found it not to actually be stable; different Linux versions will do different things. But then, almost all of the desktops are now running a single OS release so unless it's simply random, that should be good enough. I'll add krb5 to the exports and try to catch this again.

- J<

#7 lore raw

I'm replying to a rather old message, but the issue has just now popped back up again.

To recap, a client stops being able to access _any_ mount on a particular server, and "NFS: nfs4_reclaim_open_state: Lock reclaim failed!" appears several hundred times per second in the kernel log. The load goes up by one for ever process attempting to access any mount from that particular server. Mounts to other servers are fine, and other clients can mount things from that one server without problems.

When I kill every process keeping that particular mount active and then umount it, I see:

NFS: nfs4_reclaim_open_state: unhandled error -10068

The server in this case is running Centos 7: 3.10.0-327.36.3.el7.x86_64 The client is one of the last I have that's still running Fedora 23:
4.7.10-100.fc23.x86_64

The big difference now, besides the updated kernel versions, is that fact that no kerberos is involved. It's a sec=sys mount. There are kerberized exports on the same server, but the client wasn't accessing any of them. There were other kerberized mounts on the client, but they were to different servers and they remained accessible.

Here's ten frames from a packet capture. I think it's all repeating at that point so maybe it will be enough, but I can provide a more complete capture log on request.

- J<

Frame 1: 390 bytes on wire (3120 bits), 390 bytes captured (3120 bits) on interface 0 Ethernet II, Src: SuperMic_19:8e:6e (00:25:90:19:8e:6e), Dst: AsrockIn_84:34:e7 (d0:50:99:84:34:e7) Internet Protocol Version 4, Src: 172.21.86.74, Dst: 172.21.86.141
Transmission Control Protocol, Src Port: 2049, Dst Port: 997, Seq: 1, Ack: 1, Len: 324 Remote Procedure Call

Frame 2: 322 bytes on wire (2576 bits), 322 bytes captured (2576 bits) on interface 0 Ethernet II, Src: AsrockIn_84:34:e7 (d0:50:99:84:34:e7), Dst: SuperMic_19:8e:6e (00:25:90:19:8e:6e) Internet Protocol Version 4, Src: 172.21.86.141, Dst: 172.21.86.74
Transmission Control Protocol, Src Port: 997, Dst Port: 2049, Seq: 1, Ack: 325, Len: 256 Remote Procedure Call, Type:Call XID:0x29009a8c
Network File System, Ops(5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    minorversion: 1
    Operations (count: 5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR
        Opcode: SEQUENCE (53)
            sessionid: f0f40f58bd020000e002000000000000
            seqid: 0x002b3189
            slot id: 0
            high slot id: 0
            cache this?: Yes
        Opcode: PUTFH (22)
            filehandle
                length: 28
                [hash (CRC-32): 0xdcaec4f7]
                filehandle: 010006016aeda54305f66ede000000000000000096484800...
        Opcode: OPEN (18)
            seqid: 0x00000000
            share_access: OPEN4_SHARE_ACCESS_BOTH (3)
            share_deny: OPEN4_SHARE_DENY_NONE (0)
            clientid: 0xf0f40f58bd020000
            owner: <DATA>
                length: 24
                contents: <DATA>
            Open Type: OPEN4_NOCREATE (0)
            Claim Type: CLAIM_FH (4)
        Opcode: ACCESS (3), [Check: RD MD XT XE]
            Check access: 0x2d
                .... ...1 = 0x01 READ: allowed?
                .... .1.. = 0x04 MODIFY: allowed?
                .... 1... = 0x08 EXTEND: allowed?
                ..1. .... = 0x20 EXECUTE: allowed?
        Opcode: GETATTR (9)
            Attr mask[0]: 0x0010011a (Type, Change, Size, FSID, FileId)
                reqd_attr: Type (1)
                reqd_attr: Change (3)
                reqd_attr: Size (4)
                reqd_attr: FSID (8)
                reco_attr: FileId (20)
            Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
                reco_attr: Mode (33)
                reco_attr: NumLinks (35)
                reco_attr: Owner (36)
                reco_attr: Owner_Group (37)
                reco_attr: RawDev (41)
                reco_attr: Space_Used (45)
                reco_attr: Time_Access (47)
                reco_attr: Time_Metadata (52)
                reco_attr: Time_Modify (53)
                reco_attr: Mounted_on_FileId (55)
    [Main Opcode: OPEN (18)]

Frame 3: 390 bytes on wire (3120 bits), 390 bytes captured (3120 bits) on interface 0 Ethernet II, Src: SuperMic_19:8e:6e (00:25:90:19:8e:6e), Dst: AsrockIn_84:34:e7 (d0:50:99:84:34:e7) Internet Protocol Version 4, Src: 172.21.86.74, Dst: 172.21.86.141
Transmission Control Protocol, Src Port: 2049, Dst Port: 997, Seq: 325, Ack: 257, Len: 324 Remote Procedure Call, Type:Reply XID:0x29009a8c
Network File System, Ops(5): SEQUENCE PUTFH OPEN ACCESS GETATTR

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Status: NFS4_OK (0)
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    Operations (count: 5)
        Opcode: SEQUENCE (53)
            Status: NFS4_OK (0)
            sessionid: f0f40f58bd020000e002000000000000
            seqid: 0x002b3189
            slot id: 0
            high slot id: 30
            target high slot id: 30
            status flags: 0x00000040, SEQ4_STATUS_RECALLABLE_STATE_REVOKED
                .... .... .... .... .... .... .... ...0 = SEQ4_STATUS_CB_PATH_DOWN: Not set
                .... .... .... .... .... .... .... ..0. = SEQ4_STATUS_CB_GSS_CONTEXTS_EXPIRING: Not set
                .... .... .... .... .... .... .... .0.. = SEQ4_STATUS_CB_GSS_CONTEXTS_EXPIRED: Not set
                .... .... .... .... .... .... .... 0... = SEQ4_STATUS_EXPIRED_ALL_STATE_REVOKED: Not set
                .... .... .... .... .... .... ...0 .... = SEQ4_STATUS_EXPIRED_SOME_STATE_REVOKED: Not set
                .... .... .... .... .... .... ..0. .... = SEQ4_STATUS_ADMIN_STATE_REVOKED: Not set
                .... .... .... .... .... .... .1.. .... = SEQ4_STATUS_RECALLABLE_STATE_REVOKED: Set
                .... .... .... .... .... .... 0... .... = SEQ4_STATUS_LEASE_MOVED: Not set
                .... .... .... .... .... ...0 .... .... = SEQ4_STATUS_RESTART_RECLAIM_NEEDED: Not set
                .... .... .... .... .... ..0. .... .... = SEQ4_STATUS_CB_PATH_DOWN_SESSION: Not set
                .... .... .... .... .... .0.. .... .... = SEQ4_STATUS_BACKCHANNEL_FAULT: Not set
                .... .... .... .... .... 0... .... .... = SEQ4_STATUS_DEVID_CHANGED: Not set
                .... .... .... .... ...0 .... .... .... = SEQ4_STATUS_DEVID_DELETED: Not set
        Opcode: PUTFH (22)
            Status: NFS4_OK (0)
        Opcode: OPEN (18)
            Status: NFS4_OK (0)
            stateid
                [StateID Hash: 0xb207]
                seqid: 0x00158249
                Data: f0f40f58bd02000092000000
                [Data hash (CRC-32): 0xf3e67f06]
            change_info
                Atomic: No
                changeid (before): 0
                changeid (after): 0
            result flags: 0x00000004, locktype posix
                .... .... .... .... .... .... .... ..0. = confirm: False
                .... .... .... .... .... .... .... .1.. = locktype posix: True
                .... .... .... .... .... .... .... 0... = preserve unlinked: False
                .... .... .... .... .... .... ..0. .... = may notify lock: False
            Delegation Type: OPEN_DELEGATE_NONE (0)
        Opcode: ACCESS (3), [Access Denied: XE], [Allowed: RD MD XT]
            Status: NFS4_OK (0)
            Supported types (of requested): 0x2d
                .... ...1 = 0x01 READ: supported
                .... .1.. = 0x04 MODIFY: supported
                .... 1... = 0x08 EXTEND: supported
                ..1. .... = 0x20 EXECUTE: supported
            Access rights (of requested): 0x0d
                .... ...1 = 0x01 READ: allowed
                .... .1.. = 0x04 MODIFY: allowed
                .... 1... = 0x08 EXTEND: allowed
                ..0. .... = 0x20 EXECUTE: *Access Denied*
        Opcode: GETATTR (9)
            Status: NFS4_OK (0)
            Attr mask[0]: 0x0010011a (Type, Change, Size, FSID, FileId)
                reqd_attr: Type (1)
                    ftype4: NF4REG (1)
                reqd_attr: Change (3)
                    changeid: 6353654913397708009
                reqd_attr: Size (4)
                    size: 32768
                reqd_attr: FSID (8)
                    fattr4_fsid
                        fsid4.major: 7704996244782214878
                        fsid4.minor: 0
                reco_attr: FileId (20)
                    fileid: 4737174
            Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
                reco_attr: Mode (33)
                    mode: 0644, Name: Unknown, Read permission for owner, Write permission for owner, Read permission for group, Read permission for others
                        .... .... .... .... 000. .... .... .... = Name: Unknown (0)
                        .... .... .... .... .... 0... .... .... = Set user id on exec: No
                        .... .... .... .... .... .0.. .... .... = Set group id on exec: No
                        .... .... .... .... .... ..0. .... .... = Save swapped text even after use: No
                        .... .... .... .... .... ...1 .... .... = Read permission for owner: Yes
                        .... .... .... .... .... .... 1... .... = Write permission for owner: Yes
                        .... .... .... .... .... .... .0.. .... = Execute permission for owner: No
                        .... .... .... .... .... .... ..1. .... = Read permission for group: Yes
                        .... .... .... .... .... .... ...0 .... = Write permission for group: No
                        .... .... .... .... .... .... .... 0... = Execute permission for group: No
                        .... .... .... .... .... .... .... .1.. = Read permission for others: Yes
                        .... .... .... .... .... .... .... ..0. = Write permission for others: No
                        .... .... .... .... .... .... .... ...0 = Execute permission for others: No
                reco_attr: NumLinks (35)
                    numlinks: 1
                reco_attr: Owner (36)
                    fattr4_owner: 7143
                        length: 4
                        contents: 7143
                reco_attr: Owner_Group (37)
                    fattr4_owner_group: 1112
                        length: 4
                        contents: 1112
                reco_attr: RawDev (41)
                    specdata1: 0
                    specdata2: 0
                reco_attr: Space_Used (45)
                    space_used: 32768
                reco_attr: Time_Access (47)
                    seconds: 1479318517
                    nseconds: 593359867
                reco_attr: Time_Metadata (52)
                    seconds: 1479325563
                    nseconds: 175920361
                reco_attr: Time_Modify (53)
                    seconds: 1479325563
                    nseconds: 175920361
                reco_attr: Mounted_on_FileId (55)
                    fileid: 0x0000000000484896
    [Main Opcode: OPEN (18)]

Frame 4: 322 bytes on wire (2576 bits), 322 bytes captured (2576 bits) on interface 0 Ethernet II, Src: AsrockIn_84:34:e7 (d0:50:99:84:34:e7), Dst: SuperMic_19:8e:6e (00:25:90:19:8e:6e) Internet Protocol Version 4, Src: 172.21.86.141, Dst: 172.21.86.74
Transmission Control Protocol, Src Port: 997, Dst Port: 2049, Seq: 257, Ack: 649, Len: 256 Remote Procedure Call, Type:Call XID:0x2a009a8c
Network File System, Ops(5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    minorversion: 1
    Operations (count: 5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR
        Opcode: SEQUENCE (53)
            sessionid: f0f40f58bd020000e002000000000000
            seqid: 0x002b318a
            slot id: 0
            high slot id: 0
            cache this?: Yes
        Opcode: PUTFH (22)
            filehandle
                length: 28
                [hash (CRC-32): 0x26ab9d8d]
                filehandle: 010006016aeda54305f66ede00000000000000009a424800...
        Opcode: OPEN (18)
            seqid: 0x00000000
            share_access: OPEN4_SHARE_ACCESS_BOTH (3)
            share_deny: OPEN4_SHARE_DENY_NONE (0)
            clientid: 0xf0f40f58bd020000
            owner: <DATA>
                length: 24
                contents: <DATA>
            Open Type: OPEN4_NOCREATE (0)
            Claim Type: CLAIM_FH (4)
        Opcode: ACCESS (3), [Check: RD MD XT XE]
            Check access: 0x2d
                .... ...1 = 0x01 READ: allowed?
                .... .1.. = 0x04 MODIFY: allowed?
                .... 1... = 0x08 EXTEND: allowed?
                ..1. .... = 0x20 EXECUTE: allowed?
        Opcode: GETATTR (9)
            Attr mask[0]: 0x0010011a (Type, Change, Size, FSID, FileId)
                reqd_attr: Type (1)
                reqd_attr: Change (3)
                reqd_attr: Size (4)
                reqd_attr: FSID (8)
                reco_attr: FileId (20)
            Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
                reco_attr: Mode (33)
                reco_attr: NumLinks (35)
                reco_attr: Owner (36)
                reco_attr: Owner_Group (37)
                reco_attr: RawDev (41)
                reco_attr: Space_Used (45)
                reco_attr: Time_Access (47)
                reco_attr: Time_Metadata (52)
                reco_attr: Time_Modify (53)
                reco_attr: Mounted_on_FileId (55)
    [Main Opcode: OPEN (18)]

Frame 5: 322 bytes on wire (2576 bits), 322 bytes captured (2576 bits) on interface 0 Ethernet II, Src: AsrockIn_84:34:e7 (d0:50:99:84:34:e7), Dst: SuperMic_19:8e:6e (00:25:90:19:8e:6e) Internet Protocol Version 4, Src: 172.21.86.141, Dst: 172.21.86.74
Transmission Control Protocol, Src Port: 997, Dst Port: 2049, Seq: 769, Ack: 1297, Len: 256 Remote Procedure Call, Type:Call XID:0x2c009a8c
Network File System, Ops(5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    minorversion: 1
    Operations (count: 5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR
        Opcode: SEQUENCE (53)
            sessionid: f0f40f58bd020000e002000000000000
            seqid: 0x002b318c
            slot id: 0
            high slot id: 0
            cache this?: Yes
        Opcode: PUTFH (22)
            filehandle
                length: 28
                [hash (CRC-32): 0x26ab9d8d]
                filehandle: 010006016aeda54305f66ede00000000000000009a424800...
        Opcode: OPEN (18)
            seqid: 0x00000000
            share_access: OPEN4_SHARE_ACCESS_BOTH (3)
            share_deny: OPEN4_SHARE_DENY_NONE (0)
            clientid: 0xf0f40f58bd020000
            owner: <DATA>
                length: 24
                contents: <DATA>
            Open Type: OPEN4_NOCREATE (0)
            Claim Type: CLAIM_FH (4)
        Opcode: ACCESS (3), [Check: RD MD XT XE]
            Check access: 0x2d
                .... ...1 = 0x01 READ: allowed?
                .... .1.. = 0x04 MODIFY: allowed?
                .... 1... = 0x08 EXTEND: allowed?
                ..1. .... = 0x20 EXECUTE: allowed?
        Opcode: GETATTR (9)
            Attr mask[0]: 0x0010011a (Type, Change, Size, FSID, FileId)
                reqd_attr: Type (1)
                reqd_attr: Change (3)
                reqd_attr: Size (4)
                reqd_attr: FSID (8)
                reco_attr: FileId (20)
            Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
                reco_attr: Mode (33)
                reco_attr: NumLinks (35)
                reco_attr: Owner (36)
                reco_attr: Owner_Group (37)
                reco_attr: RawDev (41)
                reco_attr: Space_Used (45)
                reco_attr: Time_Access (47)
                reco_attr: Time_Metadata (52)
                reco_attr: Time_Modify (53)
                reco_attr: Mounted_on_FileId (55)
    [Main Opcode: OPEN (18)]

Frame 6: 390 bytes on wire (3120 bits), 390 bytes captured (3120 bits) on interface 0 Ethernet II, Src: SuperMic_19:8e:6e (00:25:90:19:8e:6e), Dst: AsrockIn_84:34:e7 (d0:50:99:84:34:e7) Internet Protocol Version 4, Src: 172.21.86.74, Dst: 172.21.86.141
Transmission Control Protocol, Src Port: 2049, Dst Port: 997, Seq: 1297, Ack: 1025, Len: 324 Remote Procedure Call, Type:Reply XID:0x2c009a8c
Network File System, Ops(5): SEQUENCE PUTFH OPEN ACCESS GETATTR

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Status: NFS4_OK (0)
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    Operations (count: 5)
        Opcode: SEQUENCE (53)
            Status: NFS4_OK (0)
            sessionid: f0f40f58bd020000e002000000000000
            seqid: 0x002b318c
            slot id: 0
            high slot id: 30
            target high slot id: 30
            status flags: 0x00000040, SEQ4_STATUS_RECALLABLE_STATE_REVOKED
                .... .... .... .... .... .... .... ...0 = SEQ4_STATUS_CB_PATH_DOWN: Not set
                .... .... .... .... .... .... .... ..0. = SEQ4_STATUS_CB_GSS_CONTEXTS_EXPIRING: Not set
                .... .... .... .... .... .... .... .0.. = SEQ4_STATUS_CB_GSS_CONTEXTS_EXPIRED: Not set
                .... .... .... .... .... .... .... 0... = SEQ4_STATUS_EXPIRED_ALL_STATE_REVOKED: Not set
                .... .... .... .... .... .... ...0 .... = SEQ4_STATUS_EXPIRED_SOME_STATE_REVOKED: Not set
                .... .... .... .... .... .... ..0. .... = SEQ4_STATUS_ADMIN_STATE_REVOKED: Not set
                .... .... .... .... .... .... .1.. .... = SEQ4_STATUS_RECALLABLE_STATE_REVOKED: Set
                .... .... .... .... .... .... 0... .... = SEQ4_STATUS_LEASE_MOVED: Not set
                .... .... .... .... .... ...0 .... .... = SEQ4_STATUS_RESTART_RECLAIM_NEEDED: Not set
                .... .... .... .... .... ..0. .... .... = SEQ4_STATUS_CB_PATH_DOWN_SESSION: Not set
                .... .... .... .... .... .0.. .... .... = SEQ4_STATUS_BACKCHANNEL_FAULT: Not set
                .... .... .... .... .... 0... .... .... = SEQ4_STATUS_DEVID_CHANGED: Not set
                .... .... .... .... ...0 .... .... .... = SEQ4_STATUS_DEVID_DELETED: Not set
        Opcode: PUTFH (22)
            Status: NFS4_OK (0)
        Opcode: OPEN (18)
            Status: NFS4_OK (0)
            stateid
                [StateID Hash: 0xb9c3]
                seqid: 0x0015824c
                Data: f0f40f58bd0200009e000000
                [Data hash (CRC-32): 0xb930c0be]
            change_info
                Atomic: No
                changeid (before): 0
                changeid (after): 0
            result flags: 0x00000004, locktype posix
                .... .... .... .... .... .... .... ..0. = confirm: False
                .... .... .... .... .... .... .... .1.. = locktype posix: True
                .... .... .... .... .... .... .... 0... = preserve unlinked: False
                .... .... .... .... .... .... ..0. .... = may notify lock: False
            Delegation Type: OPEN_DELEGATE_NONE (0)
        Opcode: ACCESS (3), [Access Denied: XE], [Allowed: RD MD XT]
            Status: NFS4_OK (0)
            Supported types (of requested): 0x2d
                .... ...1 = 0x01 READ: supported
                .... .1.. = 0x04 MODIFY: supported
                .... 1... = 0x08 EXTEND: supported
                ..1. .... = 0x20 EXECUTE: supported
            Access rights (of requested): 0x0d
                .... ...1 = 0x01 READ: allowed
                .... .1.. = 0x04 MODIFY: allowed
                .... 1... = 0x08 EXTEND: allowed
                ..0. .... = 0x20 EXECUTE: *Access Denied*
        Opcode: GETATTR (9)
            Status: NFS4_OK (0)
            Attr mask[0]: 0x0010011a (Type, Change, Size, FSID, FileId)
                reqd_attr: Type (1)
                    ftype4: NF4REG (1)
                reqd_attr: Change (3)
                    changeid: 6310935438380194724
                reqd_attr: Size (4)
                    size: 24576
                reqd_attr: FSID (8)
                    fattr4_fsid
                        fsid4.major: 7704996244782214878
                        fsid4.minor: 0
                reco_attr: FileId (20)
                    fileid: 4735642
            Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
                reco_attr: Mode (33)
                    mode: 0644, Name: Unknown, Read permission for owner, Write permission for owner, Read permission for group, Read permission for others
                        .... .... .... .... 000. .... .... .... = Name: Unknown (0)
                        .... .... .... .... .... 0... .... .... = Set user id on exec: No
                        .... .... .... .... .... .0.. .... .... = Set group id on exec: No
                        .... .... .... .... .... ..0. .... .... = Save swapped text even after use: No
                        .... .... .... .... .... ...1 .... .... = Read permission for owner: Yes
                        .... .... .... .... .... .... 1... .... = Write permission for owner: Yes
                        .... .... .... .... .... .... .0.. .... = Execute permission for owner: No
                        .... .... .... .... .... .... ..1. .... = Read permission for group: Yes
                        .... .... .... .... .... .... ...0 .... = Write permission for group: No
                        .... .... .... .... .... .... .... 0... = Execute permission for group: No
                        .... .... .... .... .... .... .... .1.. = Read permission for others: Yes
                        .... .... .... .... .... .... .... ..0. = Write permission for others: No
                        .... .... .... .... .... .... .... ...0 = Execute permission for others: No
                reco_attr: NumLinks (35)
                    numlinks: 1
                reco_attr: Owner (36)
                    fattr4_owner: 7143
                        length: 4
                        contents: 7143
                reco_attr: Owner_Group (37)
                    fattr4_owner_group: 1112
                        length: 4
                        contents: 1112
                reco_attr: RawDev (41)
                    specdata1: 0
                    specdata2: 0
                reco_attr: Space_Used (45)
                    space_used: 24576
                reco_attr: Time_Access (47)
                    seconds: 1479325563
                    nseconds: 305919836
                reco_attr: Time_Metadata (52)
                    seconds: 1469379160
                    nseconds: 756243364
                reco_attr: Time_Modify (53)
                    seconds: 1469379160
                    nseconds: 756243364
                reco_attr: Mounted_on_FileId (55)
                    fileid: 0x000000000048429a
    [Main Opcode: OPEN (18)]

Frame 7: 322 bytes on wire (2576 bits), 322 bytes captured (2576 bits) on interface 0 Ethernet II, Src: AsrockIn_84:34:e7 (d0:50:99:84:34:e7), Dst: SuperMic_19:8e:6e (00:25:90:19:8e:6e) Internet Protocol Version 4, Src: 172.21.86.141, Dst: 172.21.86.74
Transmission Control Protocol, Src Port: 997, Dst Port: 2049, Seq: 1025, Ack: 1621, Len: 256 Remote Procedure Call, Type:Call XID:0x2d009a8c
Network File System, Ops(5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    minorversion: 1
    Operations (count: 5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR
        Opcode: SEQUENCE (53)
            sessionid: f0f40f58bd020000e002000000000000
            seqid: 0x002b318d
            slot id: 0
            high slot id: 0
            cache this?: Yes
        Opcode: PUTFH (22)
            filehandle
                length: 28
                [hash (CRC-32): 0xdcaec4f7]
                filehandle: 010006016aeda54305f66ede000000000000000096484800...
        Opcode: OPEN (18)
            seqid: 0x00000000
            share_access: OPEN4_SHARE_ACCESS_BOTH (3)
            share_deny: OPEN4_SHARE_DENY_NONE (0)
            clientid: 0xf0f40f58bd020000
            owner: <DATA>
                length: 24
                contents: <DATA>
            Open Type: OPEN4_NOCREATE (0)
            Claim Type: CLAIM_FH (4)
        Opcode: ACCESS (3), [Check: RD MD XT XE]
            Check access: 0x2d
                .... ...1 = 0x01 READ: allowed?
                .... .1.. = 0x04 MODIFY: allowed?
                .... 1... = 0x08 EXTEND: allowed?
                ..1. .... = 0x20 EXECUTE: allowed?
        Opcode: GETATTR (9)
            Attr mask[0]: 0x0010011a (Type, Change, Size, FSID, FileId)
                reqd_attr: Type (1)
                reqd_attr: Change (3)
                reqd_attr: Size (4)
                reqd_attr: FSID (8)
                reco_attr: FileId (20)
            Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
                reco_attr: Mode (33)
                reco_attr: NumLinks (35)
                reco_attr: Owner (36)
                reco_attr: Owner_Group (37)
                reco_attr: RawDev (41)
                reco_attr: Space_Used (45)
                reco_attr: Time_Access (47)
                reco_attr: Time_Metadata (52)
                reco_attr: Time_Modify (53)
                reco_attr: Mounted_on_FileId (55)
    [Main Opcode: OPEN (18)]

Frame 8: 390 bytes on wire (3120 bits), 390 bytes captured (3120 bits) on interface 0 Ethernet II, Src: SuperMic_19:8e:6e (00:25:90:19:8e:6e), Dst: AsrockIn_84:34:e7 (d0:50:99:84:34:e7) Internet Protocol Version 4, Src: 172.21.86.74, Dst: 172.21.86.141
Transmission Control Protocol, Src Port: 2049, Dst Port: 997, Seq: 1621, Ack: 1281, Len: 324 Remote Procedure Call, Type:Reply XID:0x2d009a8c
Network File System, Ops(5): SEQUENCE PUTFH OPEN ACCESS GETATTR

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Status: NFS4_OK (0)
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    Operations (count: 5)
        Opcode: SEQUENCE (53)
            Status: NFS4_OK (0)
            sessionid: f0f40f58bd020000e002000000000000
            seqid: 0x002b318d
            slot id: 0
            high slot id: 30
            target high slot id: 30
            status flags: 0x00000040, SEQ4_STATUS_RECALLABLE_STATE_REVOKED
                .... .... .... .... .... .... .... ...0 = SEQ4_STATUS_CB_PATH_DOWN: Not set
                .... .... .... .... .... .... .... ..0. = SEQ4_STATUS_CB_GSS_CONTEXTS_EXPIRING: Not set
                .... .... .... .... .... .... .... .0.. = SEQ4_STATUS_CB_GSS_CONTEXTS_EXPIRED: Not set
                .... .... .... .... .... .... .... 0... = SEQ4_STATUS_EXPIRED_ALL_STATE_REVOKED: Not set
                .... .... .... .... .... .... ...0 .... = SEQ4_STATUS_EXPIRED_SOME_STATE_REVOKED: Not set
                .... .... .... .... .... .... ..0. .... = SEQ4_STATUS_ADMIN_STATE_REVOKED: Not set
                .... .... .... .... .... .... .1.. .... = SEQ4_STATUS_RECALLABLE_STATE_REVOKED: Set
                .... .... .... .... .... .... 0... .... = SEQ4_STATUS_LEASE_MOVED: Not set
                .... .... .... .... .... ...0 .... .... = SEQ4_STATUS_RESTART_RECLAIM_NEEDED: Not set
                .... .... .... .... .... ..0. .... .... = SEQ4_STATUS_CB_PATH_DOWN_SESSION: Not set
                .... .... .... .... .... .0.. .... .... = SEQ4_STATUS_BACKCHANNEL_FAULT: Not set
                .... .... .... .... .... 0... .... .... = SEQ4_STATUS_DEVID_CHANGED: Not set
                .... .... .... .... ...0 .... .... .... = SEQ4_STATUS_DEVID_DELETED: Not set
        Opcode: PUTFH (22)
            Status: NFS4_OK (0)
        Opcode: OPEN (18)
            Status: NFS4_OK (0)
            stateid
                [StateID Hash: 0x1925]
                seqid: 0x0015824b
                Data: f0f40f58bd02000092000000
                [Data hash (CRC-32): 0xf3e67f06]
            change_info
                Atomic: No
                changeid (before): 0
                changeid (after): 0
            result flags: 0x00000004, locktype posix
                .... .... .... .... .... .... .... ..0. = confirm: False
                .... .... .... .... .... .... .... .1.. = locktype posix: True
                .... .... .... .... .... .... .... 0... = preserve unlinked: False
                .... .... .... .... .... .... ..0. .... = may notify lock: False
            Delegation Type: OPEN_DELEGATE_NONE (0)
        Opcode: ACCESS (3), [Access Denied: XE], [Allowed: RD MD XT]
            Status: NFS4_OK (0)
            Supported types (of requested): 0x2d
                .... ...1 = 0x01 READ: supported
                .... .1.. = 0x04 MODIFY: supported
                .... 1... = 0x08 EXTEND: supported
                ..1. .... = 0x20 EXECUTE: supported
            Access rights (of requested): 0x0d
                .... ...1 = 0x01 READ: allowed
                .... .1.. = 0x04 MODIFY: allowed
                .... 1... = 0x08 EXTEND: allowed
                ..0. .... = 0x20 EXECUTE: *Access Denied*
        Opcode: GETATTR (9)
            Status: NFS4_OK (0)
            Attr mask[0]: 0x0010011a (Type, Change, Size, FSID, FileId)
                reqd_attr: Type (1)
                    ftype4: NF4REG (1)
                reqd_attr: Change (3)
                    changeid: 6353654913397708009
                reqd_attr: Size (4)
                    size: 32768
                reqd_attr: FSID (8)
                    fattr4_fsid
                        fsid4.major: 7704996244782214878
                        fsid4.minor: 0
                reco_attr: FileId (20)
                    fileid: 4737174
            Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
                reco_attr: Mode (33)
                    mode: 0644, Name: Unknown, Read permission for owner, Write permission for owner, Read permission for group, Read permission for others
                        .... .... .... .... 000. .... .... .... = Name: Unknown (0)
                        .... .... .... .... .... 0... .... .... = Set user id on exec: No
                        .... .... .... .... .... .0.. .... .... = Set group id on exec: No
                        .... .... .... .... .... ..0. .... .... = Save swapped text even after use: No
                        .... .... .... .... .... ...1 .... .... = Read permission for owner: Yes
                        .... .... .... .... .... .... 1... .... = Write permission for owner: Yes
                        .... .... .... .... .... .... .0.. .... = Execute permission for owner: No
                        .... .... .... .... .... .... ..1. .... = Read permission for group: Yes
                        .... .... .... .... .... .... ...0 .... = Write permission for group: No
                        .... .... .... .... .... .... .... 0... = Execute permission for group: No
                        .... .... .... .... .... .... .... .1.. = Read permission for others: Yes
                        .... .... .... .... .... .... .... ..0. = Write permission for others: No
                        .... .... .... .... .... .... .... ...0 = Execute permission for others: No
                reco_attr: NumLinks (35)
                    numlinks: 1
                reco_attr: Owner (36)
                    fattr4_owner: 7143
                        length: 4
                        contents: 7143
                reco_attr: Owner_Group (37)
                    fattr4_owner_group: 1112
                        length: 4
                        contents: 1112
                reco_attr: RawDev (41)
                    specdata1: 0
                    specdata2: 0
                reco_attr: Space_Used (45)
                    space_used: 32768
                reco_attr: Time_Access (47)
                    seconds: 1479318517
                    nseconds: 593359867
                reco_attr: Time_Metadata (52)
                    seconds: 1479325563
                    nseconds: 175920361
                reco_attr: Time_Modify (53)
                    seconds: 1479325563
                    nseconds: 175920361
                reco_attr: Mounted_on_FileId (55)
                    fileid: 0x0000000000484896
    [Main Opcode: OPEN (18)]

Frame 9: 322 bytes on wire (2576 bits), 322 bytes captured (2576 bits) on interface 0 Ethernet II, Src: AsrockIn_84:34:e7 (d0:50:99:84:34:e7), Dst: SuperMic_19:8e:6e (00:25:90:19:8e:6e) Internet Protocol Version 4, Src: 172.21.86.141, Dst: 172.21.86.74
Transmission Control Protocol, Src Port: 997, Dst Port: 2049, Seq: 1281, Ack: 1945, Len: 256 Remote Procedure Call, Type:Call XID:0x2e009a8c
Network File System, Ops(5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    minorversion: 1
    Operations (count: 5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR
        Opcode: SEQUENCE (53)
            sessionid: f0f40f58bd020000e002000000000000
            seqid: 0x002b318e
            slot id: 0
            high slot id: 0
            cache this?: Yes
        Opcode: PUTFH (22)
            filehandle
                length: 28
                [hash (CRC-32): 0x26ab9d8d]
                filehandle: 010006016aeda54305f66ede00000000000000009a424800...
        Opcode: OPEN (18)
            seqid: 0x00000000
            share_access: OPEN4_SHARE_ACCESS_BOTH (3)
            share_deny: OPEN4_SHARE_DENY_NONE (0)
            clientid: 0xf0f40f58bd020000
            owner: <DATA>
                length: 24
                contents: <DATA>
            Open Type: OPEN4_NOCREATE (0)
            Claim Type: CLAIM_FH (4)
        Opcode: ACCESS (3), [Check: RD MD XT XE]
            Check access: 0x2d
                .... ...1 = 0x01 READ: allowed?
                .... .1.. = 0x04 MODIFY: allowed?
                .... 1... = 0x08 EXTEND: allowed?
                ..1. .... = 0x20 EXECUTE: allowed?
        Opcode: GETATTR (9)
            Attr mask[0]: 0x0010011a (Type, Change, Size, FSID, FileId)
                reqd_attr: Type (1)
                reqd_attr: Change (3)
                reqd_attr: Size (4)
                reqd_attr: FSID (8)
                reco_attr: FileId (20)
            Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
                reco_attr: Mode (33)
                reco_attr: NumLinks (35)
                reco_attr: Owner (36)
                reco_attr: Owner_Group (37)
                reco_attr: RawDev (41)
                reco_attr: Space_Used (45)
                reco_attr: Time_Access (47)
                reco_attr: Time_Metadata (52)
                reco_attr: Time_Modify (53)
                reco_attr: Mounted_on_FileId (55)
    [Main Opcode: OPEN (18)]

Frame 10: 390 bytes on wire (3120 bits), 390 bytes captured (3120 bits) on interface 0 Ethernet II, Src: SuperMic_19:8e:6e (00:25:90:19:8e:6e), Dst: AsrockIn_84:34:e7 (d0:50:99:84:34:e7) Internet Protocol Version 4, Src: 172.21.86.74, Dst: 172.21.86.141
Transmission Control Protocol, Src Port: 2049, Dst Port: 997, Seq: 1945, Ack: 1537, Len: 324 Remote Procedure Call, Type:Reply XID:0x2e009a8c
Network File System, Ops(5): SEQUENCE PUTFH OPEN ACCESS GETATTR

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Status: NFS4_OK (0)
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    Operations (count: 5)
        Opcode: SEQUENCE (53)
            Status: NFS4_OK (0)
            sessionid: f0f40f58bd020000e002000000000000
            seqid: 0x002b318e
            slot id: 0
            high slot id: 30
            target high slot id: 30
            status flags: 0x00000040, SEQ4_STATUS_RECALLABLE_STATE_REVOKED
                .... .... .... .... .... .... .... ...0 = SEQ4_STATUS_CB_PATH_DOWN: Not set
                .... .... .... .... .... .... .... ..0. = SEQ4_STATUS_CB_GSS_CONTEXTS_EXPIRING: Not set
                .... .... .... .... .... .... .... .0.. = SEQ4_STATUS_CB_GSS_CONTEXTS_EXPIRED: Not set
                .... .... .... .... .... .... .... 0... = SEQ4_STATUS_EXPIRED_ALL_STATE_REVOKED: Not set
                .... .... .... .... .... .... ...0 .... = SEQ4_STATUS_EXPIRED_SOME_STATE_REVOKED: Not set
                .... .... .... .... .... .... ..0. .... = SEQ4_STATUS_ADMIN_STATE_REVOKED: Not set
                .... .... .... .... .... .... .1.. .... = SEQ4_STATUS_RECALLABLE_STATE_REVOKED: Set
                .... .... .... .... .... .... 0... .... = SEQ4_STATUS_LEASE_MOVED: Not set
                .... .... .... .... .... ...0 .... .... = SEQ4_STATUS_RESTART_RECLAIM_NEEDED: Not set
                .... .... .... .... .... ..0. .... .... = SEQ4_STATUS_CB_PATH_DOWN_SESSION: Not set
                .... .... .... .... .... .0.. .... .... = SEQ4_STATUS_BACKCHANNEL_FAULT: Not set
                .... .... .... .... .... 0... .... .... = SEQ4_STATUS_DEVID_CHANGED: Not set
                .... .... .... .... ...0 .... .... .... = SEQ4_STATUS_DEVID_DELETED: Not set
        Opcode: PUTFH (22)
            Status: NFS4_OK (0)
        Opcode: OPEN (18)
            Status: NFS4_OK (0)
            stateid
                [StateID Hash: 0xec52]
                seqid: 0x0015824d
                Data: f0f40f58bd0200009e000000
                [Data hash (CRC-32): 0xb930c0be]
            change_info
                Atomic: No
                changeid (before): 0
                changeid (after): 0
            result flags: 0x00000004, locktype posix
                .... .... .... .... .... .... .... ..0. = confirm: False
                .... .... .... .... .... .... .... .1.. = locktype posix: True
                .... .... .... .... .... .... .... 0... = preserve unlinked: False
                .... .... .... .... .... .... ..0. .... = may notify lock: False
            Delegation Type: OPEN_DELEGATE_NONE (0)
        Opcode: ACCESS (3), [Access Denied: XE], [Allowed: RD MD XT]
            Status: NFS4_OK (0)
            Supported types (of requested): 0x2d
                .... ...1 = 0x01 READ: supported
                .... .1.. = 0x04 MODIFY: supported
                .... 1... = 0x08 EXTEND: supported
                ..1. .... = 0x20 EXECUTE: supported
            Access rights (of requested): 0x0d
                .... ...1 = 0x01 READ: allowed
                .... .1.. = 0x04 MODIFY: allowed
                .... 1... = 0x08 EXTEND: allowed
                ..0. .... = 0x20 EXECUTE: *Access Denied*
        Opcode: GETATTR (9)
            Status: NFS4_OK (0)
            Attr mask[0]: 0x0010011a (Type, Change, Size, FSID, FileId)
                reqd_attr: Type (1)
                    ftype4: NF4REG (1)
                reqd_attr: Change (3)
                    changeid: 6310935438380194724
                reqd_attr: Size (4)
                    size: 24576
                reqd_attr: FSID (8)
                    fattr4_fsid
                        fsid4.major: 7704996244782214878
                        fsid4.minor: 0
                reco_attr: FileId (20)
                    fileid: 4735642
            Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
                reco_attr: Mode (33)
                    mode: 0644, Name: Unknown, Read permission for owner, Write permission for owner, Read permission for group, Read permission for others
                        .... .... .... .... 000. .... .... .... = Name: Unknown (0)
                        .... .... .... .... .... 0... .... .... = Set user id on exec: No
                        .... .... .... .... .... .0.. .... .... = Set group id on exec: No
                        .... .... .... .... .... ..0. .... .... = Save swapped text even after use: No
                        .... .... .... .... .... ...1 .... .... = Read permission for owner: Yes
                        .... .... .... .... .... .... 1... .... = Write permission for owner: Yes
                        .... .... .... .... .... .... .0.. .... = Execute permission for owner: No
                        .... .... .... .... .... .... ..1. .... = Read permission for group: Yes
                        .... .... .... .... .... .... ...0 .... = Write permission for group: No
                        .... .... .... .... .... .... .... 0... = Execute permission for group: No
                        .... .... .... .... .... .... .... .1.. = Read permission for others: Yes
                        .... .... .... .... .... .... .... ..0. = Write permission for others: No
                        .... .... .... .... .... .... .... ...0 = Execute permission for others: No
                reco_attr: NumLinks (35)
                    numlinks: 1
                reco_attr: Owner (36)
                    fattr4_owner: 7143
                        length: 4
                        contents: 7143
                reco_attr: Owner_Group (37)
                    fattr4_owner_group: 1112
                        length: 4
                        contents: 1112
                reco_attr: RawDev (41)
                    specdata1: 0
                    specdata2: 0
                reco_attr: Space_Used (45)
                    space_used: 24576
                reco_attr: Time_Access (47)
                    seconds: 1479325563
                    nseconds: 305919836
                reco_attr: Time_Metadata (52)
                    seconds: 1469379160
                    nseconds: 756243364
                reco_attr: Time_Modify (53)
                    seconds: 1469379160
                    nseconds: 756243364
                reco_attr: Mounted_on_FileId (55)
                    fileid: 0x000000000048429a
    [Main Opcode: OPEN (18)]
#8 lore raw
Quoted 10 lines · Jason L Tibbitts III

I'm replying to a rather old message, but the issue has just now popped back up again.

To recap, a client stops being able to access _any_ mount on a particular server, and "NFS: nfs4_reclaim_open_state: Lock reclaim failed!" appears several hundred times per second in the kernel log. The load goes up by one for ever process attempting to access any mount from that particular server. Mounts to other servers are fine, and other clients can mount things from that one server without problems.

Quoted 4 lines

When I kill every process keeping that particular mount active and then umount it, I see:

NFS: nfs4_reclaim_open_state: unhandled error -10068

NFS4ERR_RETRY_UNCACHED_REP.

So, you're using NFSv4.1 or 4.2, and the server thinks that the client has reused a (slot, sequence number) pair, but the server doesn't have a cached response to return.

Hard to know how that happened, and it's not shown in the below. Sounds like a bug, though.

Quoted 9 lines

The server in this case is running Centos 7: 3.10.0-327.36.3.el7.x86_64 The client is one of the last I have that's still running Fedora 23:
4.7.10-100.fc23.x86_64

The big difference now, besides the updated kernel versions, is that fact that no kerberos is involved. It's a sec=sys mount. There are kerberized exports on the same server, but the client wasn't accessing any of them. There were other kerberized mounts on the client, but they were to different servers and they remained accessible.

Recent clients will use sec=krb5 for certain state-related operations even if you mount with sec=sys, so it's still possible it could be involved here.

Quoted 3 lines

Here's ten frames from a packet capture. I think it's all repeating at that point so maybe it will be enough, but I can provide a more complete capture log on request.

The SEQ4_STATUS_RECALLABLE_STATE_REVOKED flag set in the OPEN replies is also a sign something's gone wrong. Apparently the server thinks the client has failed to return a delegation.

--b.

Quoted 809 lines

- J<

Frame 1: 390 bytes on wire (3120 bits), 390 bytes captured (3120 bits) on interface 0 Ethernet II, Src: SuperMic_19:8e:6e (00:25:90:19:8e:6e), Dst: AsrockIn_84:34:e7 (d0:50:99:84:34:e7) Internet Protocol Version 4, Src: 172.21.86.74, Dst: 172.21.86.141
Transmission Control Protocol, Src Port: 2049, Dst Port: 997, Seq: 1, Ack: 1, Len: 324 Remote Procedure Call

Frame 2: 322 bytes on wire (2576 bits), 322 bytes captured (2576 bits) on interface 0 Ethernet II, Src: AsrockIn_84:34:e7 (d0:50:99:84:34:e7), Dst: SuperMic_19:8e:6e (00:25:90:19:8e:6e) Internet Protocol Version 4, Src: 172.21.86.141, Dst: 172.21.86.74
Transmission Control Protocol, Src Port: 997, Dst Port: 2049, Seq: 1, Ack: 325, Len: 256 Remote Procedure Call, Type:Call XID:0x29009a8c
Network File System, Ops(5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    minorversion: 1
    Operations (count: 5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR
        Opcode: SEQUENCE (53)
            sessionid: f0f40f58bd020000e002000000000000
            seqid: 0x002b3189
            slot id: 0
            high slot id: 0
            cache this?: Yes
        Opcode: PUTFH (22)
            filehandle
                length: 28
                [hash (CRC-32): 0xdcaec4f7]
                filehandle: 010006016aeda54305f66ede000000000000000096484800...
        Opcode: OPEN (18)
            seqid: 0x00000000
            share_access: OPEN4_SHARE_ACCESS_BOTH (3)
            share_deny: OPEN4_SHARE_DENY_NONE (0)
            clientid: 0xf0f40f58bd020000
            owner: <DATA>
                length: 24
                contents: <DATA>
            Open Type: OPEN4_NOCREATE (0)
            Claim Type: CLAIM_FH (4)
        Opcode: ACCESS (3), [Check: RD MD XT XE]
            Check access: 0x2d
                .... ...1 = 0x01 READ: allowed?
                .... .1.. = 0x04 MODIFY: allowed?
                .... 1... = 0x08 EXTEND: allowed?
                ..1. .... = 0x20 EXECUTE: allowed?
        Opcode: GETATTR (9)
            Attr mask[0]: 0x0010011a (Type, Change, Size, FSID, FileId)
                reqd_attr: Type (1)
                reqd_attr: Change (3)
                reqd_attr: Size (4)
                reqd_attr: FSID (8)
                reco_attr: FileId (20)
            Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
                reco_attr: Mode (33)
                reco_attr: NumLinks (35)
                reco_attr: Owner (36)
                reco_attr: Owner_Group (37)
                reco_attr: RawDev (41)
                reco_attr: Space_Used (45)
                reco_attr: Time_Access (47)
                reco_attr: Time_Metadata (52)
                reco_attr: Time_Modify (53)
                reco_attr: Mounted_on_FileId (55)
    [Main Opcode: OPEN (18)]

Frame 3: 390 bytes on wire (3120 bits), 390 bytes captured (3120 bits) on interface 0 Ethernet II, Src: SuperMic_19:8e:6e (00:25:90:19:8e:6e), Dst: AsrockIn_84:34:e7 (d0:50:99:84:34:e7) Internet Protocol Version 4, Src: 172.21.86.74, Dst: 172.21.86.141
Transmission Control Protocol, Src Port: 2049, Dst Port: 997, Seq: 325, Ack: 257, Len: 324 Remote Procedure Call, Type:Reply XID:0x29009a8c
Network File System, Ops(5): SEQUENCE PUTFH OPEN ACCESS GETATTR

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Status: NFS4_OK (0)
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    Operations (count: 5)
        Opcode: SEQUENCE (53)
            Status: NFS4_OK (0)
            sessionid: f0f40f58bd020000e002000000000000
            seqid: 0x002b3189
            slot id: 0
            high slot id: 30
            target high slot id: 30
            status flags: 0x00000040, SEQ4_STATUS_RECALLABLE_STATE_REVOKED
                .... .... .... .... .... .... .... ...0 = SEQ4_STATUS_CB_PATH_DOWN: Not set
                .... .... .... .... .... .... .... ..0. = SEQ4_STATUS_CB_GSS_CONTEXTS_EXPIRING: Not set
                .... .... .... .... .... .... .... .0.. = SEQ4_STATUS_CB_GSS_CONTEXTS_EXPIRED: Not set
                .... .... .... .... .... .... .... 0... = SEQ4_STATUS_EXPIRED_ALL_STATE_REVOKED: Not set
                .... .... .... .... .... .... ...0 .... = SEQ4_STATUS_EXPIRED_SOME_STATE_REVOKED: Not set
                .... .... .... .... .... .... ..0. .... = SEQ4_STATUS_ADMIN_STATE_REVOKED: Not set
                .... .... .... .... .... .... .1.. .... = SEQ4_STATUS_RECALLABLE_STATE_REVOKED: Set
                .... .... .... .... .... .... 0... .... = SEQ4_STATUS_LEASE_MOVED: Not set
                .... .... .... .... .... ...0 .... .... = SEQ4_STATUS_RESTART_RECLAIM_NEEDED: Not set
                .... .... .... .... .... ..0. .... .... = SEQ4_STATUS_CB_PATH_DOWN_SESSION: Not set
                .... .... .... .... .... .0.. .... .... = SEQ4_STATUS_BACKCHANNEL_FAULT: Not set
                .... .... .... .... .... 0... .... .... = SEQ4_STATUS_DEVID_CHANGED: Not set
                .... .... .... .... ...0 .... .... .... = SEQ4_STATUS_DEVID_DELETED: Not set
        Opcode: PUTFH (22)
            Status: NFS4_OK (0)
        Opcode: OPEN (18)
            Status: NFS4_OK (0)
            stateid
                [StateID Hash: 0xb207]
                seqid: 0x00158249
                Data: f0f40f58bd02000092000000
                [Data hash (CRC-32): 0xf3e67f06]
            change_info
                Atomic: No
                changeid (before): 0
                changeid (after): 0
            result flags: 0x00000004, locktype posix
                .... .... .... .... .... .... .... ..0. = confirm: False
                .... .... .... .... .... .... .... .1.. = locktype posix: True
                .... .... .... .... .... .... .... 0... = preserve unlinked: False
                .... .... .... .... .... .... ..0. .... = may notify lock: False
            Delegation Type: OPEN_DELEGATE_NONE (0)
        Opcode: ACCESS (3), [Access Denied: XE], [Allowed: RD MD XT]
            Status: NFS4_OK (0)
            Supported types (of requested): 0x2d
                .... ...1 = 0x01 READ: supported
                .... .1.. = 0x04 MODIFY: supported
                .... 1... = 0x08 EXTEND: supported
                ..1. .... = 0x20 EXECUTE: supported
            Access rights (of requested): 0x0d
                .... ...1 = 0x01 READ: allowed
                .... .1.. = 0x04 MODIFY: allowed
                .... 1... = 0x08 EXTEND: allowed
                ..0. .... = 0x20 EXECUTE: *Access Denied*
        Opcode: GETATTR (9)
            Status: NFS4_OK (0)
            Attr mask[0]: 0x0010011a (Type, Change, Size, FSID, FileId)
                reqd_attr: Type (1)
                    ftype4: NF4REG (1)
                reqd_attr: Change (3)
                    changeid: 6353654913397708009
                reqd_attr: Size (4)
                    size: 32768
                reqd_attr: FSID (8)
                    fattr4_fsid
                        fsid4.major: 7704996244782214878
                        fsid4.minor: 0
                reco_attr: FileId (20)
                    fileid: 4737174
            Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
                reco_attr: Mode (33)
                    mode: 0644, Name: Unknown, Read permission for owner, Write permission for owner, Read permission for group, Read permission for others
                        .... .... .... .... 000. .... .... .... = Name: Unknown (0)
                        .... .... .... .... .... 0... .... .... = Set user id on exec: No
                        .... .... .... .... .... .0.. .... .... = Set group id on exec: No
                        .... .... .... .... .... ..0. .... .... = Save swapped text even after use: No
                        .... .... .... .... .... ...1 .... .... = Read permission for owner: Yes
                        .... .... .... .... .... .... 1... .... = Write permission for owner: Yes
                        .... .... .... .... .... .... .0.. .... = Execute permission for owner: No
                        .... .... .... .... .... .... ..1. .... = Read permission for group: Yes
                        .... .... .... .... .... .... ...0 .... = Write permission for group: No
                        .... .... .... .... .... .... .... 0... = Execute permission for group: No
                        .... .... .... .... .... .... .... .1.. = Read permission for others: Yes
                        .... .... .... .... .... .... .... ..0. = Write permission for others: No
                        .... .... .... .... .... .... .... ...0 = Execute permission for others: No
                reco_attr: NumLinks (35)
                    numlinks: 1
                reco_attr: Owner (36)
                    fattr4_owner: 7143
                        length: 4
                        contents: 7143
                reco_attr: Owner_Group (37)
                    fattr4_owner_group: 1112
                        length: 4
                        contents: 1112
                reco_attr: RawDev (41)
                    specdata1: 0
                    specdata2: 0
                reco_attr: Space_Used (45)
                    space_used: 32768
                reco_attr: Time_Access (47)
                    seconds: 1479318517
                    nseconds: 593359867
                reco_attr: Time_Metadata (52)
                    seconds: 1479325563
                    nseconds: 175920361
                reco_attr: Time_Modify (53)
                    seconds: 1479325563
                    nseconds: 175920361
                reco_attr: Mounted_on_FileId (55)
                    fileid: 0x0000000000484896
    [Main Opcode: OPEN (18)]

Frame 4: 322 bytes on wire (2576 bits), 322 bytes captured (2576 bits) on interface 0 Ethernet II, Src: AsrockIn_84:34:e7 (d0:50:99:84:34:e7), Dst: SuperMic_19:8e:6e (00:25:90:19:8e:6e) Internet Protocol Version 4, Src: 172.21.86.141, Dst: 172.21.86.74
Transmission Control Protocol, Src Port: 997, Dst Port: 2049, Seq: 257, Ack: 649, Len: 256 Remote Procedure Call, Type:Call XID:0x2a009a8c
Network File System, Ops(5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    minorversion: 1
    Operations (count: 5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR
        Opcode: SEQUENCE (53)
            sessionid: f0f40f58bd020000e002000000000000
            seqid: 0x002b318a
            slot id: 0
            high slot id: 0
            cache this?: Yes
        Opcode: PUTFH (22)
            filehandle
                length: 28
                [hash (CRC-32): 0x26ab9d8d]
                filehandle: 010006016aeda54305f66ede00000000000000009a424800...
        Opcode: OPEN (18)
            seqid: 0x00000000
            share_access: OPEN4_SHARE_ACCESS_BOTH (3)
            share_deny: OPEN4_SHARE_DENY_NONE (0)
            clientid: 0xf0f40f58bd020000
            owner: <DATA>
                length: 24
                contents: <DATA>
            Open Type: OPEN4_NOCREATE (0)
            Claim Type: CLAIM_FH (4)
        Opcode: ACCESS (3), [Check: RD MD XT XE]
            Check access: 0x2d
                .... ...1 = 0x01 READ: allowed?
                .... .1.. = 0x04 MODIFY: allowed?
                .... 1... = 0x08 EXTEND: allowed?
                ..1. .... = 0x20 EXECUTE: allowed?
        Opcode: GETATTR (9)
            Attr mask[0]: 0x0010011a (Type, Change, Size, FSID, FileId)
                reqd_attr: Type (1)
                reqd_attr: Change (3)
                reqd_attr: Size (4)
                reqd_attr: FSID (8)
                reco_attr: FileId (20)
            Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
                reco_attr: Mode (33)
                reco_attr: NumLinks (35)
                reco_attr: Owner (36)
                reco_attr: Owner_Group (37)
                reco_attr: RawDev (41)
                reco_attr: Space_Used (45)
                reco_attr: Time_Access (47)
                reco_attr: Time_Metadata (52)
                reco_attr: Time_Modify (53)
                reco_attr: Mounted_on_FileId (55)
    [Main Opcode: OPEN (18)]

Frame 5: 322 bytes on wire (2576 bits), 322 bytes captured (2576 bits) on interface 0 Ethernet II, Src: AsrockIn_84:34:e7 (d0:50:99:84:34:e7), Dst: SuperMic_19:8e:6e (00:25:90:19:8e:6e) Internet Protocol Version 4, Src: 172.21.86.141, Dst: 172.21.86.74
Transmission Control Protocol, Src Port: 997, Dst Port: 2049, Seq: 769, Ack: 1297, Len: 256 Remote Procedure Call, Type:Call XID:0x2c009a8c
Network File System, Ops(5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    minorversion: 1
    Operations (count: 5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR
        Opcode: SEQUENCE (53)
            sessionid: f0f40f58bd020000e002000000000000
            seqid: 0x002b318c
            slot id: 0
            high slot id: 0
            cache this?: Yes
        Opcode: PUTFH (22)
            filehandle
                length: 28
                [hash (CRC-32): 0x26ab9d8d]
                filehandle: 010006016aeda54305f66ede00000000000000009a424800...
        Opcode: OPEN (18)
            seqid: 0x00000000
            share_access: OPEN4_SHARE_ACCESS_BOTH (3)
            share_deny: OPEN4_SHARE_DENY_NONE (0)
            clientid: 0xf0f40f58bd020000
            owner: <DATA>
                length: 24
                contents: <DATA>
            Open Type: OPEN4_NOCREATE (0)
            Claim Type: CLAIM_FH (4)
        Opcode: ACCESS (3), [Check: RD MD XT XE]
            Check access: 0x2d
                .... ...1 = 0x01 READ: allowed?
                .... .1.. = 0x04 MODIFY: allowed?
                .... 1... = 0x08 EXTEND: allowed?
                ..1. .... = 0x20 EXECUTE: allowed?
        Opcode: GETATTR (9)
            Attr mask[0]: 0x0010011a (Type, Change, Size, FSID, FileId)
                reqd_attr: Type (1)
                reqd_attr: Change (3)
                reqd_attr: Size (4)
                reqd_attr: FSID (8)
                reco_attr: FileId (20)
            Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
                reco_attr: Mode (33)
                reco_attr: NumLinks (35)
                reco_attr: Owner (36)
                reco_attr: Owner_Group (37)
                reco_attr: RawDev (41)
                reco_attr: Space_Used (45)
                reco_attr: Time_Access (47)
                reco_attr: Time_Metadata (52)
                reco_attr: Time_Modify (53)
                reco_attr: Mounted_on_FileId (55)
    [Main Opcode: OPEN (18)]

Frame 6: 390 bytes on wire (3120 bits), 390 bytes captured (3120 bits) on interface 0 Ethernet II, Src: SuperMic_19:8e:6e (00:25:90:19:8e:6e), Dst: AsrockIn_84:34:e7 (d0:50:99:84:34:e7) Internet Protocol Version 4, Src: 172.21.86.74, Dst: 172.21.86.141
Transmission Control Protocol, Src Port: 2049, Dst Port: 997, Seq: 1297, Ack: 1025, Len: 324 Remote Procedure Call, Type:Reply XID:0x2c009a8c
Network File System, Ops(5): SEQUENCE PUTFH OPEN ACCESS GETATTR

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Status: NFS4_OK (0)
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    Operations (count: 5)
        Opcode: SEQUENCE (53)
            Status: NFS4_OK (0)
            sessionid: f0f40f58bd020000e002000000000000
            seqid: 0x002b318c
            slot id: 0
            high slot id: 30
            target high slot id: 30
            status flags: 0x00000040, SEQ4_STATUS_RECALLABLE_STATE_REVOKED
                .... .... .... .... .... .... .... ...0 = SEQ4_STATUS_CB_PATH_DOWN: Not set
                .... .... .... .... .... .... .... ..0. = SEQ4_STATUS_CB_GSS_CONTEXTS_EXPIRING: Not set
                .... .... .... .... .... .... .... .0.. = SEQ4_STATUS_CB_GSS_CONTEXTS_EXPIRED: Not set
                .... .... .... .... .... .... .... 0... = SEQ4_STATUS_EXPIRED_ALL_STATE_REVOKED: Not set
                .... .... .... .... .... .... ...0 .... = SEQ4_STATUS_EXPIRED_SOME_STATE_REVOKED: Not set
                .... .... .... .... .... .... ..0. .... = SEQ4_STATUS_ADMIN_STATE_REVOKED: Not set
                .... .... .... .... .... .... .1.. .... = SEQ4_STATUS_RECALLABLE_STATE_REVOKED: Set
                .... .... .... .... .... .... 0... .... = SEQ4_STATUS_LEASE_MOVED: Not set
                .... .... .... .... .... ...0 .... .... = SEQ4_STATUS_RESTART_RECLAIM_NEEDED: Not set
                .... .... .... .... .... ..0. .... .... = SEQ4_STATUS_CB_PATH_DOWN_SESSION: Not set
                .... .... .... .... .... .0.. .... .... = SEQ4_STATUS_BACKCHANNEL_FAULT: Not set
                .... .... .... .... .... 0... .... .... = SEQ4_STATUS_DEVID_CHANGED: Not set
                .... .... .... .... ...0 .... .... .... = SEQ4_STATUS_DEVID_DELETED: Not set
        Opcode: PUTFH (22)
            Status: NFS4_OK (0)
        Opcode: OPEN (18)
            Status: NFS4_OK (0)
            stateid
                [StateID Hash: 0xb9c3]
                seqid: 0x0015824c
                Data: f0f40f58bd0200009e000000
                [Data hash (CRC-32): 0xb930c0be]
            change_info
                Atomic: No
                changeid (before): 0
                changeid (after): 0
            result flags: 0x00000004, locktype posix
                .... .... .... .... .... .... .... ..0. = confirm: False
                .... .... .... .... .... .... .... .1.. = locktype posix: True
                .... .... .... .... .... .... .... 0... = preserve unlinked: False
                .... .... .... .... .... .... ..0. .... = may notify lock: False
            Delegation Type: OPEN_DELEGATE_NONE (0)
        Opcode: ACCESS (3), [Access Denied: XE], [Allowed: RD MD XT]
            Status: NFS4_OK (0)
            Supported types (of requested): 0x2d
                .... ...1 = 0x01 READ: supported
                .... .1.. = 0x04 MODIFY: supported
                .... 1... = 0x08 EXTEND: supported
                ..1. .... = 0x20 EXECUTE: supported
            Access rights (of requested): 0x0d
                .... ...1 = 0x01 READ: allowed
                .... .1.. = 0x04 MODIFY: allowed
                .... 1... = 0x08 EXTEND: allowed
                ..0. .... = 0x20 EXECUTE: *Access Denied*
        Opcode: GETATTR (9)
            Status: NFS4_OK (0)
            Attr mask[0]: 0x0010011a (Type, Change, Size, FSID, FileId)
                reqd_attr: Type (1)
                    ftype4: NF4REG (1)
                reqd_attr: Change (3)
                    changeid: 6310935438380194724
                reqd_attr: Size (4)
                    size: 24576
                reqd_attr: FSID (8)
                    fattr4_fsid
                        fsid4.major: 7704996244782214878
                        fsid4.minor: 0
                reco_attr: FileId (20)
                    fileid: 4735642
            Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
                reco_attr: Mode (33)
                    mode: 0644, Name: Unknown, Read permission for owner, Write permission for owner, Read permission for group, Read permission for others
                        .... .... .... .... 000. .... .... .... = Name: Unknown (0)
                        .... .... .... .... .... 0... .... .... = Set user id on exec: No
                        .... .... .... .... .... .0.. .... .... = Set group id on exec: No
                        .... .... .... .... .... ..0. .... .... = Save swapped text even after use: No
                        .... .... .... .... .... ...1 .... .... = Read permission for owner: Yes
                        .... .... .... .... .... .... 1... .... = Write permission for owner: Yes
                        .... .... .... .... .... .... .0.. .... = Execute permission for owner: No
                        .... .... .... .... .... .... ..1. .... = Read permission for group: Yes
                        .... .... .... .... .... .... ...0 .... = Write permission for group: No
                        .... .... .... .... .... .... .... 0... = Execute permission for group: No
                        .... .... .... .... .... .... .... .1.. = Read permission for others: Yes
                        .... .... .... .... .... .... .... ..0. = Write permission for others: No
                        .... .... .... .... .... .... .... ...0 = Execute permission for others: No
                reco_attr: NumLinks (35)
                    numlinks: 1
                reco_attr: Owner (36)
                    fattr4_owner: 7143
                        length: 4
                        contents: 7143
                reco_attr: Owner_Group (37)
                    fattr4_owner_group: 1112
                        length: 4
                        contents: 1112
                reco_attr: RawDev (41)
                    specdata1: 0
                    specdata2: 0
                reco_attr: Space_Used (45)
                    space_used: 24576
                reco_attr: Time_Access (47)
                    seconds: 1479325563
                    nseconds: 305919836
                reco_attr: Time_Metadata (52)
                    seconds: 1469379160
                    nseconds: 756243364
                reco_attr: Time_Modify (53)
                    seconds: 1469379160
                    nseconds: 756243364
                reco_attr: Mounted_on_FileId (55)
                    fileid: 0x000000000048429a
    [Main Opcode: OPEN (18)]

Frame 7: 322 bytes on wire (2576 bits), 322 bytes captured (2576 bits) on interface 0 Ethernet II, Src: AsrockIn_84:34:e7 (d0:50:99:84:34:e7), Dst: SuperMic_19:8e:6e (00:25:90:19:8e:6e) Internet Protocol Version 4, Src: 172.21.86.141, Dst: 172.21.86.74
Transmission Control Protocol, Src Port: 997, Dst Port: 2049, Seq: 1025, Ack: 1621, Len: 256 Remote Procedure Call, Type:Call XID:0x2d009a8c
Network File System, Ops(5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    minorversion: 1
    Operations (count: 5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR
        Opcode: SEQUENCE (53)
            sessionid: f0f40f58bd020000e002000000000000
            seqid: 0x002b318d
            slot id: 0
            high slot id: 0
            cache this?: Yes
        Opcode: PUTFH (22)
            filehandle
                length: 28
                [hash (CRC-32): 0xdcaec4f7]
                filehandle: 010006016aeda54305f66ede000000000000000096484800...
        Opcode: OPEN (18)
            seqid: 0x00000000
            share_access: OPEN4_SHARE_ACCESS_BOTH (3)
            share_deny: OPEN4_SHARE_DENY_NONE (0)
            clientid: 0xf0f40f58bd020000
            owner: <DATA>
                length: 24
                contents: <DATA>
            Open Type: OPEN4_NOCREATE (0)
            Claim Type: CLAIM_FH (4)
        Opcode: ACCESS (3), [Check: RD MD XT XE]
            Check access: 0x2d
                .... ...1 = 0x01 READ: allowed?
                .... .1.. = 0x04 MODIFY: allowed?
                .... 1... = 0x08 EXTEND: allowed?
                ..1. .... = 0x20 EXECUTE: allowed?
        Opcode: GETATTR (9)
            Attr mask[0]: 0x0010011a (Type, Change, Size, FSID, FileId)
                reqd_attr: Type (1)
                reqd_attr: Change (3)
                reqd_attr: Size (4)
                reqd_attr: FSID (8)
                reco_attr: FileId (20)
            Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
                reco_attr: Mode (33)
                reco_attr: NumLinks (35)
                reco_attr: Owner (36)
                reco_attr: Owner_Group (37)
                reco_attr: RawDev (41)
                reco_attr: Space_Used (45)
                reco_attr: Time_Access (47)
                reco_attr: Time_Metadata (52)
                reco_attr: Time_Modify (53)
                reco_attr: Mounted_on_FileId (55)
    [Main Opcode: OPEN (18)]

Frame 8: 390 bytes on wire (3120 bits), 390 bytes captured (3120 bits) on interface 0 Ethernet II, Src: SuperMic_19:8e:6e (00:25:90:19:8e:6e), Dst: AsrockIn_84:34:e7 (d0:50:99:84:34:e7) Internet Protocol Version 4, Src: 172.21.86.74, Dst: 172.21.86.141
Transmission Control Protocol, Src Port: 2049, Dst Port: 997, Seq: 1621, Ack: 1281, Len: 324 Remote Procedure Call, Type:Reply XID:0x2d009a8c
Network File System, Ops(5): SEQUENCE PUTFH OPEN ACCESS GETATTR

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Status: NFS4_OK (0)
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    Operations (count: 5)
        Opcode: SEQUENCE (53)
            Status: NFS4_OK (0)
            sessionid: f0f40f58bd020000e002000000000000
            seqid: 0x002b318d
            slot id: 0
            high slot id: 30
            target high slot id: 30
            status flags: 0x00000040, SEQ4_STATUS_RECALLABLE_STATE_REVOKED
                .... .... .... .... .... .... .... ...0 = SEQ4_STATUS_CB_PATH_DOWN: Not set
                .... .... .... .... .... .... .... ..0. = SEQ4_STATUS_CB_GSS_CONTEXTS_EXPIRING: Not set
                .... .... .... .... .... .... .... .0.. = SEQ4_STATUS_CB_GSS_CONTEXTS_EXPIRED: Not set
                .... .... .... .... .... .... .... 0... = SEQ4_STATUS_EXPIRED_ALL_STATE_REVOKED: Not set
                .... .... .... .... .... .... ...0 .... = SEQ4_STATUS_EXPIRED_SOME_STATE_REVOKED: Not set
                .... .... .... .... .... .... ..0. .... = SEQ4_STATUS_ADMIN_STATE_REVOKED: Not set
                .... .... .... .... .... .... .1.. .... = SEQ4_STATUS_RECALLABLE_STATE_REVOKED: Set
                .... .... .... .... .... .... 0... .... = SEQ4_STATUS_LEASE_MOVED: Not set
                .... .... .... .... .... ...0 .... .... = SEQ4_STATUS_RESTART_RECLAIM_NEEDED: Not set
                .... .... .... .... .... ..0. .... .... = SEQ4_STATUS_CB_PATH_DOWN_SESSION: Not set
                .... .... .... .... .... .0.. .... .... = SEQ4_STATUS_BACKCHANNEL_FAULT: Not set
                .... .... .... .... .... 0... .... .... = SEQ4_STATUS_DEVID_CHANGED: Not set
                .... .... .... .... ...0 .... .... .... = SEQ4_STATUS_DEVID_DELETED: Not set
        Opcode: PUTFH (22)
            Status: NFS4_OK (0)
        Opcode: OPEN (18)
            Status: NFS4_OK (0)
            stateid
                [StateID Hash: 0x1925]
                seqid: 0x0015824b
                Data: f0f40f58bd02000092000000
                [Data hash (CRC-32): 0xf3e67f06]
            change_info
                Atomic: No
                changeid (before): 0
                changeid (after): 0
            result flags: 0x00000004, locktype posix
                .... .... .... .... .... .... .... ..0. = confirm: False
                .... .... .... .... .... .... .... .1.. = locktype posix: True
                .... .... .... .... .... .... .... 0... = preserve unlinked: False
                .... .... .... .... .... .... ..0. .... = may notify lock: False
            Delegation Type: OPEN_DELEGATE_NONE (0)
        Opcode: ACCESS (3), [Access Denied: XE], [Allowed: RD MD XT]
            Status: NFS4_OK (0)
            Supported types (of requested): 0x2d
                .... ...1 = 0x01 READ: supported
                .... .1.. = 0x04 MODIFY: supported
                .... 1... = 0x08 EXTEND: supported
                ..1. .... = 0x20 EXECUTE: supported
            Access rights (of requested): 0x0d
                .... ...1 = 0x01 READ: allowed
                .... .1.. = 0x04 MODIFY: allowed
                .... 1... = 0x08 EXTEND: allowed
                ..0. .... = 0x20 EXECUTE: *Access Denied*
        Opcode: GETATTR (9)
            Status: NFS4_OK (0)
            Attr mask[0]: 0x0010011a (Type, Change, Size, FSID, FileId)
                reqd_attr: Type (1)
                    ftype4: NF4REG (1)
                reqd_attr: Change (3)
                    changeid: 6353654913397708009
                reqd_attr: Size (4)
                    size: 32768
                reqd_attr: FSID (8)
                    fattr4_fsid
                        fsid4.major: 7704996244782214878
                        fsid4.minor: 0
                reco_attr: FileId (20)
                    fileid: 4737174
            Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
                reco_attr: Mode (33)
                    mode: 0644, Name: Unknown, Read permission for owner, Write permission for owner, Read permission for group, Read permission for others
                        .... .... .... .... 000. .... .... .... = Name: Unknown (0)
                        .... .... .... .... .... 0... .... .... = Set user id on exec: No
                        .... .... .... .... .... .0.. .... .... = Set group id on exec: No
                        .... .... .... .... .... ..0. .... .... = Save swapped text even after use: No
                        .... .... .... .... .... ...1 .... .... = Read permission for owner: Yes
                        .... .... .... .... .... .... 1... .... = Write permission for owner: Yes
                        .... .... .... .... .... .... .0.. .... = Execute permission for owner: No
                        .... .... .... .... .... .... ..1. .... = Read permission for group: Yes
                        .... .... .... .... .... .... ...0 .... = Write permission for group: No
                        .... .... .... .... .... .... .... 0... = Execute permission for group: No
                        .... .... .... .... .... .... .... .1.. = Read permission for others: Yes
                        .... .... .... .... .... .... .... ..0. = Write permission for others: No
                        .... .... .... .... .... .... .... ...0 = Execute permission for others: No
                reco_attr: NumLinks (35)
                    numlinks: 1
                reco_attr: Owner (36)
                    fattr4_owner: 7143
                        length: 4
                        contents: 7143
                reco_attr: Owner_Group (37)
                    fattr4_owner_group: 1112
                        length: 4
                        contents: 1112
                reco_attr: RawDev (41)
                    specdata1: 0
                    specdata2: 0
                reco_attr: Space_Used (45)
                    space_used: 32768
                reco_attr: Time_Access (47)
                    seconds: 1479318517
                    nseconds: 593359867
                reco_attr: Time_Metadata (52)
                    seconds: 1479325563
                    nseconds: 175920361
                reco_attr: Time_Modify (53)
                    seconds: 1479325563
                    nseconds: 175920361
                reco_attr: Mounted_on_FileId (55)
                    fileid: 0x0000000000484896
    [Main Opcode: OPEN (18)]

Frame 9: 322 bytes on wire (2576 bits), 322 bytes captured (2576 bits) on interface 0 Ethernet II, Src: AsrockIn_84:34:e7 (d0:50:99:84:34:e7), Dst: SuperMic_19:8e:6e (00:25:90:19:8e:6e) Internet Protocol Version 4, Src: 172.21.86.141, Dst: 172.21.86.74
Transmission Control Protocol, Src Port: 997, Dst Port: 2049, Seq: 1281, Ack: 1945, Len: 256 Remote Procedure Call, Type:Call XID:0x2e009a8c
Network File System, Ops(5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    minorversion: 1
    Operations (count: 5): SEQUENCE, PUTFH, OPEN, ACCESS, GETATTR
        Opcode: SEQUENCE (53)
            sessionid: f0f40f58bd020000e002000000000000
            seqid: 0x002b318e
            slot id: 0
            high slot id: 0
            cache this?: Yes
        Opcode: PUTFH (22)
            filehandle
                length: 28
                [hash (CRC-32): 0x26ab9d8d]
                filehandle: 010006016aeda54305f66ede00000000000000009a424800...
        Opcode: OPEN (18)
            seqid: 0x00000000
            share_access: OPEN4_SHARE_ACCESS_BOTH (3)
            share_deny: OPEN4_SHARE_DENY_NONE (0)
            clientid: 0xf0f40f58bd020000
            owner: <DATA>
                length: 24
                contents: <DATA>
            Open Type: OPEN4_NOCREATE (0)
            Claim Type: CLAIM_FH (4)
        Opcode: ACCESS (3), [Check: RD MD XT XE]
            Check access: 0x2d
                .... ...1 = 0x01 READ: allowed?
                .... .1.. = 0x04 MODIFY: allowed?
                .... 1... = 0x08 EXTEND: allowed?
                ..1. .... = 0x20 EXECUTE: allowed?
        Opcode: GETATTR (9)
            Attr mask[0]: 0x0010011a (Type, Change, Size, FSID, FileId)
                reqd_attr: Type (1)
                reqd_attr: Change (3)
                reqd_attr: Size (4)
                reqd_attr: FSID (8)
                reco_attr: FileId (20)
            Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
                reco_attr: Mode (33)
                reco_attr: NumLinks (35)
                reco_attr: Owner (36)
                reco_attr: Owner_Group (37)
                reco_attr: RawDev (41)
                reco_attr: Space_Used (45)
                reco_attr: Time_Access (47)
                reco_attr: Time_Metadata (52)
                reco_attr: Time_Modify (53)
                reco_attr: Mounted_on_FileId (55)
    [Main Opcode: OPEN (18)]

Frame 10: 390 bytes on wire (3120 bits), 390 bytes captured (3120 bits) on interface 0 Ethernet II, Src: SuperMic_19:8e:6e (00:25:90:19:8e:6e), Dst: AsrockIn_84:34:e7 (d0:50:99:84:34:e7) Internet Protocol Version 4, Src: 172.21.86.74, Dst: 172.21.86.141
Transmission Control Protocol, Src Port: 2049, Dst Port: 997, Seq: 1945, Ack: 1537, Len: 324 Remote Procedure Call, Type:Reply XID:0x2e009a8c
Network File System, Ops(5): SEQUENCE PUTFH OPEN ACCESS GETATTR

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Status: NFS4_OK (0)
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    Operations (count: 5)
        Opcode: SEQUENCE (53)
            Status: NFS4_OK (0)
            sessionid: f0f40f58bd020000e002000000000000
            seqid: 0x002b318e
            slot id: 0
            high slot id: 30
            target high slot id: 30
            status flags: 0x00000040, SEQ4_STATUS_RECALLABLE_STATE_REVOKED
                .... .... .... .... .... .... .... ...0 = SEQ4_STATUS_CB_PATH_DOWN: Not set
                .... .... .... .... .... .... .... ..0. = SEQ4_STATUS_CB_GSS_CONTEXTS_EXPIRING: Not set
                .... .... .... .... .... .... .... .0.. = SEQ4_STATUS_CB_GSS_CONTEXTS_EXPIRED: Not set
                .... .... .... .... .... .... .... 0... = SEQ4_STATUS_EXPIRED_ALL_STATE_REVOKED: Not set
                .... .... .... .... .... .... ...0 .... = SEQ4_STATUS_EXPIRED_SOME_STATE_REVOKED: Not set
                .... .... .... .... .... .... ..0. .... = SEQ4_STATUS_ADMIN_STATE_REVOKED: Not set
                .... .... .... .... .... .... .1.. .... = SEQ4_STATUS_RECALLABLE_STATE_REVOKED: Set
                .... .... .... .... .... .... 0... .... = SEQ4_STATUS_LEASE_MOVED: Not set
                .... .... .... .... .... ...0 .... .... = SEQ4_STATUS_RESTART_RECLAIM_NEEDED: Not set
                .... .... .... .... .... ..0. .... .... = SEQ4_STATUS_CB_PATH_DOWN_SESSION: Not set
                .... .... .... .... .... .0.. .... .... = SEQ4_STATUS_BACKCHANNEL_FAULT: Not set
                .... .... .... .... .... 0... .... .... = SEQ4_STATUS_DEVID_CHANGED: Not set
                .... .... .... .... ...0 .... .... .... = SEQ4_STATUS_DEVID_DELETED: Not set
        Opcode: PUTFH (22)
            Status: NFS4_OK (0)
        Opcode: OPEN (18)
            Status: NFS4_OK (0)
            stateid
                [StateID Hash: 0xec52]
                seqid: 0x0015824d
                Data: f0f40f58bd0200009e000000
                [Data hash (CRC-32): 0xb930c0be]
            change_info
                Atomic: No
                changeid (before): 0
                changeid (after): 0
            result flags: 0x00000004, locktype posix
                .... .... .... .... .... .... .... ..0. = confirm: False
                .... .... .... .... .... .... .... .1.. = locktype posix: True
                .... .... .... .... .... .... .... 0... = preserve unlinked: False
                .... .... .... .... .... .... ..0. .... = may notify lock: False
            Delegation Type: OPEN_DELEGATE_NONE (0)
        Opcode: ACCESS (3), [Access Denied: XE], [Allowed: RD MD XT]
            Status: NFS4_OK (0)
            Supported types (of requested): 0x2d
                .... ...1 = 0x01 READ: supported
                .... .1.. = 0x04 MODIFY: supported
                .... 1... = 0x08 EXTEND: supported
                ..1. .... = 0x20 EXECUTE: supported
            Access rights (of requested): 0x0d
                .... ...1 = 0x01 READ: allowed
                .... .1.. = 0x04 MODIFY: allowed
                .... 1... = 0x08 EXTEND: allowed
                ..0. .... = 0x20 EXECUTE: *Access Denied*
        Opcode: GETATTR (9)
            Status: NFS4_OK (0)
            Attr mask[0]: 0x0010011a (Type, Change, Size, FSID, FileId)
                reqd_attr: Type (1)
                    ftype4: NF4REG (1)
                reqd_attr: Change (3)
                    changeid: 6310935438380194724
                reqd_attr: Size (4)
                    size: 24576
                reqd_attr: FSID (8)
                    fattr4_fsid
                        fsid4.major: 7704996244782214878
                        fsid4.minor: 0
                reco_attr: FileId (20)
                    fileid: 4735642
            Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
                reco_attr: Mode (33)
                    mode: 0644, Name: Unknown, Read permission for owner, Write permission for owner, Read permission for group, Read permission for others
                        .... .... .... .... 000. .... .... .... = Name: Unknown (0)
                        .... .... .... .... .... 0... .... .... = Set user id on exec: No
                        .... .... .... .... .... .0.. .... .... = Set group id on exec: No
                        .... .... .... .... .... ..0. .... .... = Save swapped text even after use: No
                        .... .... .... .... .... ...1 .... .... = Read permission for owner: Yes
                        .... .... .... .... .... .... 1... .... = Write permission for owner: Yes
                        .... .... .... .... .... .... .0.. .... = Execute permission for owner: No
                        .... .... .... .... .... .... ..1. .... = Read permission for group: Yes
                        .... .... .... .... .... .... ...0 .... = Write permission for group: No
                        .... .... .... .... .... .... .... 0... = Execute permission for group: No
                        .... .... .... .... .... .... .... .1.. = Read permission for others: Yes
                        .... .... .... .... .... .... .... ..0. = Write permission for others: No
                        .... .... .... .... .... .... .... ...0 = Execute permission for others: No
                reco_attr: NumLinks (35)
                    numlinks: 1
                reco_attr: Owner (36)
                    fattr4_owner: 7143
                        length: 4
                        contents: 7143
                reco_attr: Owner_Group (37)
                    fattr4_owner_group: 1112
                        length: 4
                        contents: 1112
                reco_attr: RawDev (41)
                    specdata1: 0
                    specdata2: 0
                reco_attr: Space_Used (45)
                    space_used: 24576
                reco_attr: Time_Access (47)
                    seconds: 1479325563
                    nseconds: 305919836
                reco_attr: Time_Metadata (52)
                    seconds: 1469379160
                    nseconds: 756243364
                reco_attr: Time_Modify (53)
                    seconds: 1469379160
                    nseconds: 756243364
                reco_attr: Mounted_on_FileId (55)
                    fileid: 0x000000000048429a
    [Main Opcode: OPEN (18)]

--
To unsubscribe from this list: send the line "unsubscribe linux-nfs" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

#9 lore raw
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line

"JBF" == J Bruce Fields <[email protected]> writes:

JBF> So, you're using NFSv4.1 or 4.2, and the server thinks that the JBF> client has reused a (slot, sequence number) pair, but the server JBF> doesn't have a cached response to return.

Thanks for the reply. Sadly I don't understand all of it, but...

JBF> Hard to know how that happened, and it's not shown in the below. JBF> Sounds like a bug, though.

Yeah, I only found the problem after it was already happening, so obviously the beginning of the process is missing. And sadly it's not something I can easily repeat, so short of running some continuous package capture (which would be hard since once this starts the traffic volume is huge) there's no easy way to see it.

Is there any state on either the client or server that I could inspect which might give any hints? I can add that to my notes in case this problem happens again.

JBF> Recent clients will use sec=krb5 for certain state-related JBF> operations even if you mount with sec=sys, so it's still possible JBF> it could be involved here.

On the server, the involved filesystem isn't exported with any sec= options, in case it matters.

JBF> The SEQ4_STATUS_RECALLABLE_STATE_REVOKED flag set in the OPEN JBF> replies is also a sign something's gone wrong. Apparently the JBF> server thinks the client has failed to return a delegation.

I can't imagine how that might have happened. There is nothing else NFS-related in the client's log besides the spew and that final line. There are some automount complaints about the user accessing directories that aren't in the map sources, and the usual random gssproxy noise which was fixed in Fedora 24.

Currently the system is stable; it hasn't been rebooted since the problem occurred. Everything cleared up once I was able to unmounted the problematic filesystem.

- J<

#10 lore raw

I've found this extremely useful on clients in tracking down 'lost' delegations.

echo "error != 0" | tee /sys/kernel/debug/tracing/events/nfs4/nfs4_delegreturn_exit/filter

...and then look in here:

cat /sys/kernel/debug/tracing/trace

(YMMV, not sure if this is going to work on your distro, debugfs etc)

There's still work to be done with nfsd4_delegreturn()
and revoked delegations serverside (as well as killing fh_verify() per Bruce's earlier suggestions)

We've recently seen the server recall a delegation, revoke it, and then have the client try to return it much later (because of an unknown slowness issue) -- after the file had been deleted at the server.

Quoted 48 lines · Jason L Tibbitts III
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line

"JBF" == J Bruce Fields <[email protected]> writes:

JBF> So, you're using NFSv4.1 or 4.2, and the server thinks that the JBF> client has reused a (slot, sequence number) pair, but the server JBF> doesn't have a cached response to return.

Thanks for the reply. Sadly I don't understand all of it, but...

JBF> Hard to know how that happened, and it's not shown in the below. JBF> Sounds like a bug, though.

Yeah, I only found the problem after it was already happening, so obviously the beginning of the process is missing. And sadly it's not something I can easily repeat, so short of running some continuous package capture (which would be hard since once this starts the traffic volume is huge) there's no easy way to see it.

Is there any state on either the client or server that I could inspect which might give any hints? I can add that to my notes in case this problem happens again.

JBF> Recent clients will use sec=krb5 for certain state-related JBF> operations even if you mount with sec=sys, so it's still possible JBF> it could be involved here.

On the server, the involved filesystem isn't exported with any sec= options, in case it matters.

JBF> The SEQ4_STATUS_RECALLABLE_STATE_REVOKED flag set in the OPEN JBF> replies is also a sign something's gone wrong. Apparently the JBF> server thinks the client has failed to return a delegation.

I can't imagine how that might have happened. There is nothing else NFS-related in the client's log besides the spew and that final line. There are some automount complaints about the user accessing directories that aren't in the map sources, and the usual random gssproxy noise which was fixed in Fedora 24.

Currently the system is stable; it hasn't been rebooted since the problem occurred. Everything cleared up once I was able to unmounted the problematic filesystem.

- J<
--
To unsubscribe from this list: send the line "unsubscribe linux-nfs" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Signature · 5 lines
Andrew W. Elble
[email protected]
Infrastructure Engineer, Communications Technical Lead
Rochester Institute of Technology
PGP: BFAD 8461 4CCF DC95 DA2C B0EB 965B 082E 863E C912
#11 lore raw
In reply to J. Bruce Fields

T24gVGh1LCAyMDE2LTExLTE3IGF0IDExOjMxIC0wNTAwLCBKLiBCcnVjZSBGaWVsZHMgd3JvdGU6 DQo+IE9uIFdlZCwgTm92IDE2LCAyMDE2IGF0IDAyOjU1OjA1UE0gLTA2MDAsIEphc29uIEwgVGli Yml0dHMgSUlJIHdyb3RlOg0KPiA+IA0KPiA+IEknbSByZXBseWluZyB0byBhIHJhdGhlciBvbGQg bWVzc2FnZSwgYnV0IHRoZSBpc3N1ZSBoYXMganVzdCBub3cNCj4gPiBwb3BwZWQNCj4gPiBiYWNr IHVwIGFnYWluLg0KPiA+IA0KPiA+IFRvIHJlY2FwLCBhIGNsaWVudCBzdG9wcyBiZWluZyBhYmxl IHRvIGFjY2VzcyBfYW55XyBtb3VudCBvbiBhDQo+ID4gcGFydGljdWxhciBzZXJ2ZXIsIGFuZCAi TkZTOiBuZnM0X3JlY2xhaW1fb3Blbl9zdGF0ZTogTG9jayByZWNsYWltDQo+ID4gZmFpbGVkISIg YXBwZWFycyBzZXZlcmFsIGh1bmRyZWQgdGltZXMgcGVyIHNlY29uZCBpbiB0aGUga2VybmVsDQo+ ID4gbG9nLg0KPiA+IFRoZSBsb2FkIGdvZXMgdXAgYnkgb25lIGZvciBldmVyIHByb2Nlc3MgYXR0 ZW1wdGluZyB0byBhY2Nlc3MgYW55DQo+ID4gbW91bnQNCj4gPiBmcm9tIHRoYXQgcGFydGljdWxh ciBzZXJ2ZXIuwqDCoE1vdW50cyB0byBvdGhlciBzZXJ2ZXJzIGFyZSBmaW5lLCBhbmQNCj4gPiBv dGhlciBjbGllbnRzIGNhbiBtb3VudCB0aGluZ3MgZnJvbSB0aGF0IG9uZSBzZXJ2ZXIgd2l0aG91 dA0KPiA+IHByb2JsZW1zLg0KPiA+IA0KPiA+IFdoZW4gSSBraWxsIGV2ZXJ5IHByb2Nlc3Mga2Vl cGluZyB0aGF0IHBhcnRpY3VsYXIgbW91bnQgYWN0aXZlIGFuZA0KPiA+IHRoZW4NCj4gPiB1bW91 bnQgaXQsIEkgc2VlOg0KPiA+IA0KPiA+IE5GUzogbmZzNF9yZWNsYWltX29wZW5fc3RhdGU6IHVu aGFuZGxlZCBlcnJvciAtMTAwNjgNCj4gDQo+IE5GUzRFUlJfUkVUUllfVU5DQUNIRURfUkVQLg0K PiANCj4gU28sIHlvdSdyZSB1c2luZyBORlN2NC4xIG9yIDQuMiwgYW5kIHRoZSBzZXJ2ZXIgdGhp bmtzIHRoYXQgdGhlDQo+IGNsaWVudA0KPiBoYXMgcmV1c2VkIGEgKHNsb3QsIHNlcXVlbmNlIG51 bWJlcikgcGFpciwgYnV0IHRoZSBzZXJ2ZXIgZG9lc24ndA0KPiBoYXZlIGENCj4gY2FjaGVkIHJl c3BvbnNlIHRvIHJldHVybi4NCj4gDQo+IEhhcmQgdG8ga25vdyBob3cgdGhhdCBoYXBwZW5lZCwg YW5kIGl0J3Mgbm90IHNob3duIGluIHRoZSBiZWxvdy4NCj4gU291bmRzIGxpa2UgYSBidWcsIHRo b3VnaC4NCg0KLi4ub3IgYSBDdHJsLUMuLi4uDQoNCg==

#12 lore raw
Quoted 31 lines · Trond Myklebust
Quoted 30 lines · J. Bruce Fields
Quoted 15 lines · Jason L Tibbitts III

I'm replying to a rather old message, but the issue has just now popped
back up again.

To recap, a client stops being able to access _any_ mount on a particular server, and "NFS: nfs4_reclaim_open_state: Lock reclaim failed!" appears several hundred times per second in the kernel log.
The load goes up by one for ever process attempting to access any mount
from that particular server.  Mounts to other servers are fine, and other clients can mount things from that one server without problems.

Quoted 5 lines

When I kill every process keeping that particular mount active and then
umount it, I see:

NFS: nfs4_reclaim_open_state: unhandled error -10068

NFS4ERR_RETRY_UNCACHED_REP.

So, you're using NFSv4.1 or 4.2, and the server thinks that the client
has reused a (slot, sequence number) pair, but the server doesn't have a
cached response to return.

Quoted 4 lines
Quoted 2 lines

Hard to know how that happened, and it's not shown in the below. Sounds like a bug, though.

...or a Ctrl-C....

How does that happen?

--b.

#13 lore raw
Quoted 32 lines · On Thu, Nov 17, 2016 at 2:32 PM, [email protected] <[email protected]>…
Quoted 31 lines · Trond Myklebust
Quoted 30 lines · J. Bruce Fields
Quoted 15 lines · Jason L Tibbitts III

I'm replying to a rather old message, but the issue has just now popped
back up again.

To recap, a client stops being able to access _any_ mount on a particular server, and "NFS: nfs4_reclaim_open_state: Lock reclaim failed!" appears several hundred times per second in the kernel log.
The load goes up by one for ever process attempting to access any mount
from that particular server. Mounts to other servers are fine, and other clients can mount things from that one server without problems.

Quoted 5 lines

When I kill every process keeping that particular mount active and then
umount it, I see:

NFS: nfs4_reclaim_open_state: unhandled error -10068

NFS4ERR_RETRY_UNCACHED_REP.

So, you're using NFSv4.1 or 4.2, and the server thinks that the client
has reused a (slot, sequence number) pair, but the server doesn't have a
cached response to return.

Quoted 7 lines
Quoted 4 lines
Quoted 2 lines

Hard to know how that happened, and it's not shown in the below. Sounds like a bug, though.

...or a Ctrl-C....

How does that happen?

If I may chime in...

Bruce, when an application sends a Ctrl-C and clients's session slot has sent out an RPC but didn't process the reply, the client doesn't know if the server processed that sequence id or not. In that case, the client doesn't increment the sequence number. Normally the client would handle getting such an error by retrying again (and resetting the slots) but I think during recovery operation the client handles errors differently (by just erroring). I believe the reasoning that we don't want to be stuck trying to recover from the recovery from the recovery etc...

Jason,

The UNCACHED_REP error is really not interesting as it's a consequence of you having a client that already failed with an error of "unable to reclaim the locks". I'm surprised that the application doesn't error at this point with EIO. But that aside, I think I've seen this kind of behavior due to client't callback channel going down (and not replying to the CB_RECALLs and then server revoking state).

Quoted 5 lines

--b.
--
To unsubscribe from this list: send the line "unsubscribe linux-nfs" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

#14 lore raw
Quoted 44 lines · Olga Kornievskaia
Quoted 32 lines · On Thu, Nov 17, 2016 at 2:32 PM, [email protected] <[email protected]>…
Quoted 31 lines · Trond Myklebust
Quoted 30 lines · J. Bruce Fields
Quoted 15 lines · Jason L Tibbitts III

I'm replying to a rather old message, but the issue has just now popped
back up again.

To recap, a client stops being able to access _any_ mount on a particular server, and "NFS: nfs4_reclaim_open_state: Lock reclaim failed!" appears several hundred times per second in the kernel log.
The load goes up by one for ever process attempting to access any mount
from that particular server. Mounts to other servers are fine, and other clients can mount things from that one server without problems.

Quoted 5 lines

When I kill every process keeping that particular mount active and then
umount it, I see:

NFS: nfs4_reclaim_open_state: unhandled error -10068

NFS4ERR_RETRY_UNCACHED_REP.

So, you're using NFSv4.1 or 4.2, and the server thinks that the client
has reused a (slot, sequence number) pair, but the server doesn't have a
cached response to return.

Quoted 7 lines
Quoted 4 lines
Quoted 2 lines

Hard to know how that happened, and it's not shown in the below. Sounds like a bug, though.

...or a Ctrl-C....

How does that happen?

If I may chime in...

Quoted 9 lines

Bruce, when an application sends a Ctrl-C and clients's session slot has sent out an RPC but didn't process the reply, the client doesn't know if the server processed that sequence id or not. In that case, the client doesn't increment the sequence number. Normally the client would handle getting such an error by retrying again (and resetting the slots) but I think during recovery operation the client handles errors differently (by just erroring). I believe the reasoning that we don't want to be stuck trying to recover from the recovery from the recovery etc...

So in that case the client can end up sending a different rpc reusing the old slot and sequence number?

--b.

Quoted 17 lines

Jason,

The UNCACHED_REP error is really not interesting as it's a consequence of you having a client that already failed with an error of "unable to reclaim the locks". I'm surprised that the application doesn't error at this point with EIO. But that aside, I think I've seen this kind of behavior due to client't callback channel going down (and not replying to the CB_RECALLs and then server revoking state).

Quoted 5 lines

--b.
--
To unsubscribe from this list: send the line "unsubscribe linux-nfs" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

#15 lore raw
Quoted 55 lines · On Thu, Nov 17, 2016 at 3:17 PM, [email protected] <[email protected]>…
Quoted 44 lines · Olga Kornievskaia
Quoted 32 lines · On Thu, Nov 17, 2016 at 2:32 PM, [email protected] <[email protected]>…
Quoted 31 lines · Trond Myklebust
Quoted 30 lines · J. Bruce Fields
Quoted 15 lines · Jason L Tibbitts III

I'm replying to a rather old message, but the issue has just now popped
back up again.

To recap, a client stops being able to access _any_ mount on a particular server, and "NFS: nfs4_reclaim_open_state: Lock reclaim failed!" appears several hundred times per second in the kernel log.
The load goes up by one for ever process attempting to access any mount
from that particular server. Mounts to other servers are fine, and other clients can mount things from that one server without problems.

Quoted 5 lines

When I kill every process keeping that particular mount active and then
umount it, I see:

NFS: nfs4_reclaim_open_state: unhandled error -10068

NFS4ERR_RETRY_UNCACHED_REP.

So, you're using NFSv4.1 or 4.2, and the server thinks that the client
has reused a (slot, sequence number) pair, but the server doesn't have a
cached response to return.

Quoted 7 lines
Quoted 4 lines
Quoted 2 lines

Hard to know how that happened, and it's not shown in the below. Sounds like a bug, though.

...or a Ctrl-C....

How does that happen?

If I may chime in...

Quoted 9 lines

Bruce, when an application sends a Ctrl-C and clients's session slot has sent out an RPC but didn't process the reply, the client doesn't know if the server processed that sequence id or not. In that case, the client doesn't increment the sequence number. Normally the client would handle getting such an error by retrying again (and resetting the slots) but I think during recovery operation the client handles errors differently (by just erroring). I believe the reasoning that we don't want to be stuck trying to recover from the recovery from the recovery etc...

Quoted 2 lines

So in that case the client can end up sending a different rpc reusing the old slot and sequence number?

Correct.

Quoted 17 lines
Quoted 17 lines

Jason,

The UNCACHED_REP error is really not interesting as it's a consequence of you having a client that already failed with an error of "unable to reclaim the locks". I'm surprised that the application doesn't error at this point with EIO. But that aside, I think I've seen this kind of behavior due to client't callback channel going down (and not replying to the CB_RECALLs and then server revoking state).

Quoted 5 lines

--b.
--
To unsubscribe from this list: send the line "unsubscribe linux-nfs" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

#16 lore raw
Quoted 57 lines · Olga Kornievskaia
Quoted 55 lines · On Thu, Nov 17, 2016 at 3:17 PM, [email protected] <[email protected]>…
Quoted 53 lines · Olga Kornievskaia
Quoted 32 lines · On Thu, Nov 17, 2016 at 2:32 PM, [email protected] <[email protected]>…
Quoted 31 lines · Trond Myklebust
Quoted 30 lines · J. Bruce Fields
Quoted 15 lines · Jason L Tibbitts III

I'm replying to a rather old message, but the issue has just now popped
back up again.

To recap, a client stops being able to access _any_ mount on a particular server, and "NFS: nfs4_reclaim_open_state: Lock reclaim failed!" appears several hundred times per second in the kernel log.
The load goes up by one for ever process attempting to access any mount
from that particular server. Mounts to other servers are fine, and other clients can mount things from that one server without problems.

Quoted 5 lines

When I kill every process keeping that particular mount active and then
umount it, I see:

NFS: nfs4_reclaim_open_state: unhandled error -10068

NFS4ERR_RETRY_UNCACHED_REP.

So, you're using NFSv4.1 or 4.2, and the server thinks that the client
has reused a (slot, sequence number) pair, but the server doesn't have a
cached response to return.

Quoted 7 lines
Quoted 4 lines
Quoted 2 lines

Hard to know how that happened, and it's not shown in the below. Sounds like a bug, though.

...or a Ctrl-C....

How does that happen?

If I may chime in...

Bruce, when an application sends a Ctrl-C and clients's session slot has sent out an RPC but didn't process the reply, the client doesn't know if the server processed that sequence id or not. In that case, the client doesn't increment the sequence number. Normally the client would handle getting such an error by retrying again (and resetting the slots) but I think during recovery operation the client handles errors differently (by just erroring). I believe the reasoning that we don't want to be stuck trying to recover from the recovery from the recovery etc...

Quoted 4 lines
Quoted 2 lines

So in that case the client can end up sending a different rpc reusing the old slot and sequence number?

Correct.

So that could get UNCACHED_REP as the response. But if you're very unlucky, couldn't this also happen?:

1) the compound previously sent on that slot was processed by the server and cached
2) the compound you're sending now happens to have the same set of operations

with the result that the client doesn't detect that the reply was actually to some other rpc, and instead it returns bad data to the application?

--b.

Quoted 18 lines
Quoted 18 lines
Quoted 18 lines

Jason,

The UNCACHED_REP error is really not interesting as it's a consequence of you having a client that already failed with an error of "unable to reclaim the locks". I'm surprised that the application doesn't error at this point with EIO. But that aside, I think I've seen this kind of behavior due to client't callback channel going down (and not replying to the CB_RECALLs and then server revoking state).

Quoted 5 lines

--b.
--
To unsubscribe from this list: send the line "unsubscribe linux-nfs" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

#17 lore raw
Quoted 66 lines · On Thu, Nov 17, 2016 at 3:46 PM, [email protected] <[email protected]>…
Quoted 57 lines · Olga Kornievskaia
Quoted 55 lines · On Thu, Nov 17, 2016 at 3:17 PM, [email protected] <[email protected]>…
Quoted 53 lines · Olga Kornievskaia
Quoted 32 lines · On Thu, Nov 17, 2016 at 2:32 PM, [email protected] <[email protected]>…
Quoted 31 lines · Trond Myklebust
Quoted 30 lines · J. Bruce Fields
Quoted 15 lines · Jason L Tibbitts III

I'm replying to a rather old message, but the issue has just now popped
back up again.

To recap, a client stops being able to access _any_ mount on a particular server, and "NFS: nfs4_reclaim_open_state: Lock reclaim failed!" appears several hundred times per second in the kernel log.
The load goes up by one for ever process attempting to access any mount
from that particular server. Mounts to other servers are fine, and other clients can mount things from that one server without problems.

Quoted 5 lines

When I kill every process keeping that particular mount active and then
umount it, I see:

NFS: nfs4_reclaim_open_state: unhandled error -10068

NFS4ERR_RETRY_UNCACHED_REP.

So, you're using NFSv4.1 or 4.2, and the server thinks that the client
has reused a (slot, sequence number) pair, but the server doesn't have a
cached response to return.

Quoted 7 lines
Quoted 4 lines
Quoted 2 lines

Hard to know how that happened, and it's not shown in the below. Sounds like a bug, though.

...or a Ctrl-C....

How does that happen?

If I may chime in...

Bruce, when an application sends a Ctrl-C and clients's session slot has sent out an RPC but didn't process the reply, the client doesn't know if the server processed that sequence id or not. In that case, the client doesn't increment the sequence number. Normally the client would handle getting such an error by retrying again (and resetting the slots) but I think during recovery operation the client handles errors differently (by just erroring). I believe the reasoning that we don't want to be stuck trying to recover from the recovery from the recovery etc...

Quoted 4 lines
Quoted 2 lines

So in that case the client can end up sending a different rpc reusing the old slot and sequence number?

Correct.

So that could get UNCACHED_REP as the response. But if you're very unlucky, couldn't this also happen?:

Quoted 8 lines

1) the compound previously sent on that slot was processed by the server and cached
2) the compound you're sending now happens to have the same set of operations

with the result that the client doesn't detect that the reply was actually to some other rpc, and instead it returns bad data to the application?

If you are sending exactly the same operations and arguments, then why is a reply from the cache would lead to bad data?

Quoted 21 lines

--b.

Quoted 18 lines
Quoted 18 lines
Quoted 18 lines

Jason,

The UNCACHED_REP error is really not interesting as it's a consequence of you having a client that already failed with an error of "unable to reclaim the locks". I'm surprised that the application doesn't error at this point with EIO. But that aside, I think I've seen this kind of behavior due to client't callback channel going down (and not replying to the CB_RECALLs and then server revoking state).

Quoted 5 lines

--b.
--
To unsubscribe from this list: send the line "unsubscribe linux-nfs" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

#18 lore raw
Quoted 73 lines · Olga Kornievskaia
Quoted 71 lines · On Thu, Nov 17, 2016 at 3:46 PM, [email protected] <[email protected]>…
Quoted 57 lines · Olga Kornievskaia
Quoted 55 lines · On Thu, Nov 17, 2016 at 3:17 PM, [email protected] <[email protected]>…
Quoted 53 lines · Olga Kornievskaia
Quoted 32 lines · On Thu, Nov 17, 2016 at 2:32 PM, [email protected] <[email protected]>…
Quoted 31 lines · Trond Myklebust
Quoted 30 lines · J. Bruce Fields
Quoted 15 lines · Jason L Tibbitts III

I'm replying to a rather old message, but the issue has just now popped
back up again.

To recap, a client stops being able to access _any_ mount on a particular server, and "NFS: nfs4_reclaim_open_state: Lock reclaim failed!" appears several hundred times per second in the kernel log.
The load goes up by one for ever process attempting to access any mount
from that particular server. Mounts to other servers are fine, and other clients can mount things from that one server without problems.

Quoted 5 lines

When I kill every process keeping that particular mount active and then
umount it, I see:

NFS: nfs4_reclaim_open_state: unhandled error -10068

NFS4ERR_RETRY_UNCACHED_REP.

So, you're using NFSv4.1 or 4.2, and the server thinks that the client
has reused a (slot, sequence number) pair, but the server doesn't have a
cached response to return.

Quoted 7 lines
Quoted 4 lines
Quoted 2 lines

Hard to know how that happened, and it's not shown in the below. Sounds like a bug, though.

...or a Ctrl-C....

How does that happen?

If I may chime in...

Bruce, when an application sends a Ctrl-C and clients's session slot has sent out an RPC but didn't process the reply, the client doesn't know if the server processed that sequence id or not. In that case, the client doesn't increment the sequence number. Normally the client would handle getting such an error by retrying again (and resetting the slots) but I think during recovery operation the client handles errors differently (by just erroring). I believe the reasoning that we don't want to be stuck trying to recover from the recovery from the recovery etc...

Quoted 4 lines
Quoted 2 lines

So in that case the client can end up sending a different rpc reusing the old slot and sequence number?

Correct.

So that could get UNCACHED_REP as the response. But if you're very unlucky, couldn't this also happen?:

1) the compound previously sent on that slot was processed by the server and cached
2) the compound you're sending now happens to have the same set of operations

Quoted 6 lines
Quoted 3 lines

with the result that the client doesn't detect that the reply was actually to some other rpc, and instead it returns bad data to the application?

If you are sending exactly the same operations and arguments, then why is a reply from the cache would lead to bad data?

That would probably be fine, I was wondering what would happen if you sent the same operation but different arguments.

So the original cancelled operation is something like PUTFH(fh1)+OPEN("foo")+GETFH, and the new one is PUTFH(fh2)+OPEN("bar")+GETFH. In theory couldn't the second one succeed and leave the client thinking it had opened (fh2, bar) when the filehandle it got back was really for (fh1, foo)?

--b.

#19 lore raw

T24gVGh1LCAyMDE2LTExLTE3IGF0IDE2OjI2IC0wNTAwLCBiZmllbGRzQGZpZWxkc2VzLm9yZyB3 cm90ZToNCj4gT24gVGh1LCBOb3YgMTcsIDIwMTYgYXQgMDQ6MDU6MzJQTSAtMDUwMCwgT2xnYSBL b3JuaWV2c2thaWEgd3JvdGU6DQo+ID4gDQo+ID4gT24gVGh1LCBOb3YgMTcsIDIwMTYgYXQgMzo0 NiBQTSwgYmZpZWxkc0BmaWVsZHNlcy5vcmcNCj4gPiA8YmZpZWxkc0BmaWVsZHNlcy5vcmc+IHdy b3RlOg0KPiA+ID4gDQo+ID4gPiBPbiBUaHUsIE5vdiAxNywgMjAxNiBhdCAwMzoyOToxMVBNIC0w NTAwLCBPbGdhIEtvcm5pZXZza2FpYQ0KPiA+ID4gd3JvdGU6DQo+ID4gPiA+IA0KPiA+ID4gPiBP biBUaHUsIE5vdiAxNywgMjAxNiBhdCAzOjE3IFBNLCBiZmllbGRzQGZpZWxkc2VzLm9yZw0KPiA+ ID4gPiA8YmZpZWxkc0BmaWVsZHNlcy5vcmc+IHdyb3RlOg0KPiA+ID4gPiA+IA0KPiA+ID4gPiA+ IE9uIFRodSwgTm92IDE3LCAyMDE2IGF0IDAyOjU4OjEyUE0gLTA1MDAsIE9sZ2EgS29ybmlldnNr YWlhDQo+ID4gPiA+ID4gd3JvdGU6DQo+ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+IE9uIFRodSwg Tm92IDE3LCAyMDE2IGF0IDI6MzIgUE0sIGJmaWVsZHNAZmllbGRzZXMub3JnDQo+ID4gPiA+ID4g PiA8YmZpZWxkc0BmaWVsZHNlcy5vcmc+IHdyb3RlOg0KPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4g PiA+ID4gT24gVGh1LCBOb3YgMTcsIDIwMTYgYXQgMDU6NDU6NTJQTSArMDAwMCwgVHJvbmQgTXlr bGVidXN0DQo+ID4gPiA+ID4gPiA+IHdyb3RlOg0KPiA+ID4gPiA+ID4gPiA+IA0KPiA+ID4gPiA+ ID4gPiA+IE9uIFRodSwgMjAxNi0xMS0xNyBhdCAxMTozMSAtMDUwMCwgSi4gQnJ1Y2UgRmllbGRz DQo+ID4gPiA+ID4gPiA+ID4gd3JvdGU6DQo+ID4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ ID4gPiA+IE9uIFdlZCwgTm92IDE2LCAyMDE2IGF0IDAyOjU1OjA1UE0gLTA2MDAsIEphc29uIEwN Cj4gPiA+ID4gPiA+ID4gPiA+IFRpYmJpdHRzIElJSSB3cm90ZToNCj4gPiA+ID4gPiA+ID4gPiA+ ID4gDQo+ID4gPiA+ID4gPiA+ID4gPiA+IA0KPiA+ID4gPiA+ID4gPiA+ID4gPiBJJ20gcmVwbHlp bmcgdG8gYSByYXRoZXIgb2xkIG1lc3NhZ2UsIGJ1dCB0aGUgaXNzdWUNCj4gPiA+ID4gPiA+ID4g PiA+ID4gaGFzIGp1c3Qgbm93DQo+ID4gPiA+ID4gPiA+ID4gPiA+IHBvcHBlZA0KPiA+ID4gPiA+ ID4gPiA+ID4gPiBiYWNrIHVwIGFnYWluLg0KPiA+ID4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4g PiA+ID4gPiA+ID4gVG8gcmVjYXAsIGEgY2xpZW50IHN0b3BzIGJlaW5nIGFibGUgdG8gYWNjZXNz IF9hbnlfDQo+ID4gPiA+ID4gPiA+ID4gPiA+IG1vdW50IG9uIGENCj4gPiA+ID4gPiA+ID4gPiA+ ID4gcGFydGljdWxhciBzZXJ2ZXIsIGFuZCAiTkZTOg0KPiA+ID4gPiA+ID4gPiA+ID4gPiBuZnM0 X3JlY2xhaW1fb3Blbl9zdGF0ZTogTG9jayByZWNsYWltDQo+ID4gPiA+ID4gPiA+ID4gPiA+IGZh aWxlZCEiIGFwcGVhcnMgc2V2ZXJhbCBodW5kcmVkIHRpbWVzIHBlciBzZWNvbmQNCj4gPiA+ID4g PiA+ID4gPiA+ID4gaW4gdGhlIGtlcm5lbA0KPiA+ID4gPiA+ID4gPiA+ID4gPiBsb2cuDQo+ID4g PiA+ID4gPiA+ID4gPiA+IFRoZSBsb2FkIGdvZXMgdXAgYnkgb25lIGZvciBldmVyIHByb2Nlc3Mg YXR0ZW1wdGluZw0KPiA+ID4gPiA+ID4gPiA+ID4gPiB0byBhY2Nlc3MgYW55DQo+ID4gPiA+ID4g PiA+ID4gPiA+IG1vdW50DQo+ID4gPiA+ID4gPiA+ID4gPiA+IGZyb20gdGhhdCBwYXJ0aWN1bGFy IHNlcnZlci7CoMKgTW91bnRzIHRvIG90aGVyDQo+ID4gPiA+ID4gPiA+ID4gPiA+IHNlcnZlcnMg YXJlIGZpbmUsIGFuZA0KPiA+ID4gPiA+ID4gPiA+ID4gPiBvdGhlciBjbGllbnRzIGNhbiBtb3Vu dCB0aGluZ3MgZnJvbSB0aGF0IG9uZSBzZXJ2ZXINCj4gPiA+ID4gPiA+ID4gPiA+ID4gd2l0aG91 dA0KPiA+ID4gPiA+ID4gPiA+ID4gPiBwcm9ibGVtcy4NCj4gPiA+ID4gPiA+ID4gPiA+ID4gDQo+ ID4gPiA+ID4gPiA+ID4gPiA+IFdoZW4gSSBraWxsIGV2ZXJ5IHByb2Nlc3Mga2VlcGluZyB0aGF0 IHBhcnRpY3VsYXINCj4gPiA+ID4gPiA+ID4gPiA+ID4gbW91bnQgYWN0aXZlIGFuZA0KPiA+ID4g PiA+ID4gPiA+ID4gPiB0aGVuDQo+ID4gPiA+ID4gPiA+ID4gPiA+IHVtb3VudCBpdCwgSSBzZWU6 DQo+ID4gPiA+ID4gPiA+ID4gPiA+IA0KPiA+ID4gPiA+ID4gPiA+ID4gPiBORlM6IG5mczRfcmVj bGFpbV9vcGVuX3N0YXRlOiB1bmhhbmRsZWQgZXJyb3INCj4gPiA+ID4gPiA+ID4gPiA+ID4gLTEw MDY4DQo+ID4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gPiA+IE5GUzRFUlJfUkVUUllf VU5DQUNIRURfUkVQLg0KPiA+ID4gPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiA+ID4gPiBTbywg eW91J3JlIHVzaW5nIE5GU3Y0LjEgb3IgNC4yLCBhbmQgdGhlIHNlcnZlcg0KPiA+ID4gPiA+ID4g PiA+ID4gdGhpbmtzIHRoYXQgdGhlDQo+ID4gPiA+ID4gPiA+ID4gPiBjbGllbnQNCj4gPiA+ID4g PiA+ID4gPiA+IGhhcyByZXVzZWQgYSAoc2xvdCwgc2VxdWVuY2UgbnVtYmVyKSBwYWlyLCBidXQg dGhlDQo+ID4gPiA+ID4gPiA+ID4gPiBzZXJ2ZXIgZG9lc24ndA0KPiA+ID4gPiA+ID4gPiA+ID4g aGF2ZSBhDQo+ID4gPiA+ID4gPiA+ID4gPiBjYWNoZWQgcmVzcG9uc2UgdG8gcmV0dXJuLg0KPiA+ ID4gPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiA+ID4gPiBIYXJkIHRvIGtub3cgaG93IHRoYXQg aGFwcGVuZWQsIGFuZCBpdCdzIG5vdCBzaG93biBpbg0KPiA+ID4gPiA+ID4gPiA+ID4gdGhlIGJl bG93Lg0KPiA+ID4gPiA+ID4gPiA+ID4gU291bmRzIGxpa2UgYSBidWcsIHRob3VnaC4NCj4gPiA+ ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gPiAuLi5vciBhIEN0cmwtQy4uLi4NCj4gPiA+ID4g PiA+ID4gDQo+ID4gPiA+ID4gPiA+IEhvdyBkb2VzIHRoYXQgaGFwcGVuPw0KPiA+ID4gPiA+ID4g PiANCj4gPiA+ID4gPiA+IA0KPiA+ID4gPiA+ID4gSWYgSSBtYXkgY2hpbWUgaW4uLi4NCj4gPiA+ ID4gPiA+IA0KPiA+ID4gPiA+ID4gQnJ1Y2UsIHdoZW4gYW4gYXBwbGljYXRpb24gc2VuZHMgYSBD dHJsLUMgYW5kIGNsaWVudHMncw0KPiA+ID4gPiA+ID4gc2Vzc2lvbiBzbG90DQo+ID4gPiA+ID4g PiBoYXMgc2VudCBvdXQgYW4gUlBDIGJ1dCBkaWRuJ3QgcHJvY2VzcyB0aGUgcmVwbHksIHRoZQ0K PiA+ID4gPiA+ID4gY2xpZW50IGRvZXNuJ3QNCj4gPiA+ID4gPiA+IGtub3cgaWYgdGhlIHNlcnZl ciBwcm9jZXNzZWQgdGhhdCBzZXF1ZW5jZSBpZCBvciBub3QuIEluDQo+ID4gPiA+ID4gPiB0aGF0 IGNhc2UsDQo+ID4gPiA+ID4gPiB0aGUgY2xpZW50IGRvZXNuJ3QgaW5jcmVtZW50IHRoZSBzZXF1 ZW5jZSBudW1iZXIuIE5vcm1hbGx5DQo+ID4gPiA+ID4gPiB0aGUgY2xpZW50DQo+ID4gPiA+ID4g PiB3b3VsZCBoYW5kbGUgZ2V0dGluZyBzdWNoIGFuIGVycm9yIGJ5IHJldHJ5aW5nIGFnYWluIChh bmQNCj4gPiA+ID4gPiA+IHJlc2V0dGluZw0KPiA+ID4gPiA+ID4gdGhlIHNsb3RzKSBidXQgSSB0 aGluayBkdXJpbmcgcmVjb3Zlcnkgb3BlcmF0aW9uIHRoZSBjbGllbnQNCj4gPiA+ID4gPiA+IGhh bmRsZXMNCj4gPiA+ID4gPiA+IGVycm9ycyBkaWZmZXJlbnRseSAoYnkganVzdCBlcnJvcmluZyku IEkgYmVsaWV2ZSB0aGUNCj4gPiA+ID4gPiA+IHJlYXNvbmluZyB0aGF0IHdlDQo+ID4gPiA+ID4g PiBkb24ndCB3YW50IHRvIGJlIHN0dWNrIHRyeWluZyB0byByZWNvdmVyIGZyb20gdGhlIHJlY292 ZXJ5DQo+ID4gPiA+ID4gPiBmcm9tIHRoZQ0KPiA+ID4gPiA+ID4gcmVjb3ZlcnkgZXRjLi4uDQo+ ID4gPiA+ID4gDQo+ID4gPiA+ID4gU28gaW4gdGhhdCBjYXNlIHRoZSBjbGllbnQgY2FuIGVuZCB1 cCBzZW5kaW5nIGEgZGlmZmVyZW50IHJwYw0KPiA+ID4gPiA+IHJldXNpbmcNCj4gPiA+ID4gPiB0 aGUgb2xkIHNsb3QgYW5kIHNlcXVlbmNlIG51bWJlcj8NCj4gPiA+ID4gDQo+ID4gPiA+IENvcnJl Y3QuDQo+ID4gPiANCj4gPiA+IFNvIHRoYXQgY291bGQgZ2V0IFVOQ0FDSEVEX1JFUCBhcyB0aGUg cmVzcG9uc2UuwqDCoEJ1dCBpZiB5b3UncmUNCj4gPiA+IHZlcnkNCj4gPiA+IHVubHVja3ksIGNv dWxkbid0IHRoaXMgYWxzbyBoYXBwZW4/Og0KPiA+ID4gDQo+ID4gPiDCoMKgwqDCoMKgwqDCoMKg MSkgdGhlIGNvbXBvdW5kIHByZXZpb3VzbHkgc2VudCBvbiB0aGF0IHNsb3Qgd2FzDQo+ID4gPiBw cm9jZXNzZWQgYnkNCj4gPiA+IMKgwqDCoMKgwqDCoMKgwqB0aGUgc2VydmVyIGFuZCBjYWNoZWQN Cj4gPiA+IMKgwqDCoMKgwqDCoMKgwqAyKSB0aGUgY29tcG91bmQgeW91J3JlIHNlbmRpbmcgbm93 IGhhcHBlbnMgdG8gaGF2ZSB0aGUNCj4gPiA+IHNhbWUgc2V0DQo+ID4gPiDCoMKgwqDCoMKgwqDC oMKgb2Ygb3BlcmF0aW9ucw0KPiA+ID4gDQo+ID4gPiB3aXRoIHRoZSByZXN1bHQgdGhhdCB0aGUg Y2xpZW50IGRvZXNuJ3QgZGV0ZWN0IHRoYXQgdGhlIHJlcGx5IHdhcw0KPiA+ID4gYWN0dWFsbHkg dG8gc29tZSBvdGhlciBycGMsIGFuZCBpbnN0ZWFkIGl0IHJldHVybnMgYmFkIGRhdGEgdG8NCj4g PiA+IHRoZQ0KPiA+ID4gYXBwbGljYXRpb24/DQo+ID4gDQo+ID4gSWYgeW91IGFyZSBzZW5kaW5n IGV4YWN0bHkgdGhlIHNhbWUgb3BlcmF0aW9ucyBhbmQgYXJndW1lbnRzLCB0aGVuDQo+ID4gd2h5 DQo+ID4gaXMgYSByZXBseSBmcm9tIHRoZSBjYWNoZSB3b3VsZCBsZWFkIHRvIGJhZCBkYXRhPw0K PiANCj4gVGhhdCB3b3VsZCBwcm9iYWJseSBiZSBmaW5lLCBJIHdhcyB3b25kZXJpbmcgd2hhdCB3 b3VsZCBoYXBwZW4gaWYgeW91DQo+IHNlbnQgdGhlIHNhbWUgb3BlcmF0aW9uIGJ1dCBkaWZmZXJl bnQgYXJndW1lbnRzLg0KDQo+IFNvIHRoZSBvcmlnaW5hbCBjYW5jZWxsZWQgb3BlcmF0aW9uIGlz IHNvbWV0aGluZyBsaWtlDQo+IFBVVEZIKGZoMSkrT1BFTigiZm9vIikrR0VURkgsIGFuZCB0aGUg bmV3IG9uZSBpcw0KPiBQVVRGSChmaDIpK09QRU4oImJhciIpK0dFVEZILsKgwqBJbiB0aGVvcnkg Y291bGRuJ3QgdGhlIHNlY29uZCBvbmUNCj4gc3VjY2VlZA0KPiBhbmQgbGVhdmUgdGhlIGNsaWVu dCB0aGlua2luZyBpdCBoYWQgb3BlbmVkIChmaDIsIGJhcikgd2hlbiB0aGUNCj4gZmlsZWhhbmRs ZSBpdCBnb3QgYmFjayB3YXMgcmVhbGx5IGZvciAoZmgxLCBmb28pPw0KPsKgDQoNClRoZSBjbGll bnQgd291bGQgcmVjZWl2ZSBhIGZpbGVoYW5kbGUgZm9yIGZoMS8iZm9vIiwgc28gaXQgd291bGQg YXBwbHkNCmFueSBzdGF0ZSBpdCB0aG91Z2h0IGl0IGhhZCByZWNlaXZlZCB0byB0aGF0IGZpbGUu IEhvd2V2ZXIsIG5vcm1hbGx5LA0KSSdkIGV4cGVjdCB0byBzZWUgYSBORlM0RVJSX0ZBTFNFX1JF VFJZIGluIHRoaXMgY2FzZS4=

#20 lore raw
Quoted 133 lines · Trond Myklebust
Quoted 124 lines · On Thu, 2016-11-17 at 16:26 -0500, [email protected] wrote:
Quoted 111 lines · Olga Kornievskaia
Quoted 108 lines · On Thu, Nov 17, 2016 at 3:46 PM, [email protected] <[email protected]>…
Quoted 88 lines · Olga Kornievskaia
Quoted 85 lines · On Thu, Nov 17, 2016 at 3:17 PM, [email protected] <[email protected]>…
Quoted 81 lines · Olga Kornievskaia
Quoted 50 lines · On Thu, Nov 17, 2016 at 2:32 PM, [email protected] <[email protected]>…
Quoted 47 lines · Trond Myklebust
Quoted 44 lines · J. Bruce Fields
Quoted 23 lines · Jason L Tibbitts III

I'm replying to a rather old message, but the issue has just now
popped
back up again.

To recap, a client stops being able to access _any_ mount on a
particular server, and "NFS:
nfs4_reclaim_open_state: Lock reclaim failed!" appears several hundred times per second in the kernel
log.
The load goes up by one for ever process attempting to access any
mount
from that particular server. Mounts to other servers are fine, and
other clients can mount things from that one server without
problems.

Quoted 7 lines

When I kill every process keeping that particular
mount active and
then
umount it, I see:

NFS: nfs4_reclaim_open_state: unhandled error
-10068

NFS4ERR_RETRY_UNCACHED_REP.

So, you're using NFSv4.1 or 4.2, and the server thinks that the
client
has reused a (slot, sequence number) pair, but the server doesn't
have a
cached response to return.

Quoted 8 lines
Quoted 5 lines
Quoted 3 lines

Hard to know how that happened, and it's not shown in the below.
Sounds like a bug, though.

...or a Ctrl-C....

How does that happen?

If I may chime in...

Bruce, when an application sends a Ctrl-C and clients's session slot
has sent out an RPC but didn't process the reply, the client doesn't
know if the server processed that sequence id or not. In that case,
the client doesn't increment the sequence number. Normally the client
would handle getting such an error by retrying again (and resetting
the slots) but I think during recovery operation the client handles
errors differently (by just erroring). I believe the reasoning that we
don't want to be stuck trying to recover from the recovery from the
recovery etc...

Quoted 5 lines
Quoted 3 lines

So in that case the client can end up sending a different rpc reusing
the old slot and sequence number?

Correct.

So that could get UNCACHED_REP as the response. But if you're very
unlucky, couldn't this also happen?:

1) the compound previously sent on that slot was
processed by
the server and cached
2) the compound you're sending now happens to have the
same set
of operations

Quoted 8 lines
Quoted 4 lines

with the result that the client doesn't detect that the reply was actually to some other rpc, and instead it returns bad data to the
application?

If you are sending exactly the same operations and arguments, then why
is a reply from the cache would lead to bad data?

That would probably be fine, I was wondering what would happen if you sent the same operation but different arguments.

Quoted 7 lines

So the original cancelled operation is something like PUTFH(fh1)+OPEN("foo")+GETFH, and the new one is PUTFH(fh2)+OPEN("bar")+GETFH. In theory couldn't the second one succeed
and leave the client thinking it had opened (fh2, bar) when the filehandle it got back was really for (fh1, foo)?

Quoted 3 lines

The client would receive a filehandle for fh1/"foo", so it would apply any state it thought it had received to that file. However, normally, I'd expect to see a NFS4ERR_FALSE_RETRY in this case.

I see Bruce's point that if the server only looks up the cache based on the seqid and slot# and doesn't have like a hash of the content which I could see is expensive, then the client in this case would get into trouble of thinking it opened "bar" but really it's "foo". Spec says:

Section 18.46.3
If the client reuses a slot ID and sequence ID for a completely
different request, the server MAY treat the request as if it is a retry of what it has already executed. The server MAY however detect the client's illegal reuse and return NFS4ERR_SEQ_FALSE_RETRY.

What is "a completely different request". From the client's point of view sending different args would constitute a different request. But in any case it's a "MAY" so client can't depend on this being implemented.

#21 lore raw

T24gVGh1LCAyMDE2LTExLTE3IGF0IDE2OjUzIC0wNTAwLCBPbGdhIEtvcm5pZXZza2FpYSB3cm90 ZToNCj4gT24gVGh1LCBOb3YgMTcsIDIwMTYgYXQgNDo0NSBQTSwgVHJvbmQgTXlrbGVidXN0DQo+ IDx0cm9uZG15QHByaW1hcnlkYXRhLmNvbT4gd3JvdGU6DQo+ID4gDQo+ID4gT24gVGh1LCAyMDE2 LTExLTE3IGF0IDE2OjI2IC0wNTAwLCBiZmllbGRzQGZpZWxkc2VzLm9yZyB3cm90ZToNCj4gPiA+ IA0KPiA+ID4gT24gVGh1LCBOb3YgMTcsIDIwMTYgYXQgMDQ6MDU6MzJQTSAtMDUwMCwgT2xnYSBL b3JuaWV2c2thaWENCj4gPiA+IHdyb3RlOg0KPiA+ID4gPiANCj4gPiA+ID4gDQo+ID4gPiA+IE9u IFRodSwgTm92IDE3LCAyMDE2IGF0IDM6NDYgUE0sIGJmaWVsZHNAZmllbGRzZXMub3JnDQo+ID4g PiA+IDxiZmllbGRzQGZpZWxkc2VzLm9yZz4gd3JvdGU6DQo+ID4gPiA+ID4gDQo+ID4gPiA+ID4g DQo+ID4gPiA+ID4gT24gVGh1LCBOb3YgMTcsIDIwMTYgYXQgMDM6Mjk6MTFQTSAtMDUwMCwgT2xn YSBLb3JuaWV2c2thaWENCj4gPiA+ID4gPiB3cm90ZToNCj4gPiA+ID4gPiA+IA0KPiA+ID4gPiA+ ID4gDQo+ID4gPiA+ID4gPiBPbiBUaHUsIE5vdiAxNywgMjAxNiBhdCAzOjE3IFBNLCBiZmllbGRz QGZpZWxkc2VzLm9yZw0KPiA+ID4gPiA+ID4gPGJmaWVsZHNAZmllbGRzZXMub3JnPiB3cm90ZToN Cj4gPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiA+IA0KPiA+ID4gPiA+ID4gPiBPbiBUaHUsIE5v diAxNywgMjAxNiBhdCAwMjo1ODoxMlBNIC0wNTAwLCBPbGdhDQo+ID4gPiA+ID4gPiA+IEtvcm5p ZXZza2FpYQ0KPiA+ID4gPiA+ID4gPiB3cm90ZToNCj4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4g PiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gPiBPbiBUaHUsIE5vdiAxNywgMjAxNiBhdCAyOjMyIFBN LCBiZmllbGRzQGZpZWxkc2VzLm9yZw0KPiA+ID4gPiA+ID4gPiA+IDxiZmllbGRzQGZpZWxkc2Vz Lm9yZz4gd3JvdGU6DQo+ID4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gPiA+IA0KPiA+ ID4gPiA+ID4gPiA+ID4gT24gVGh1LCBOb3YgMTcsIDIwMTYgYXQgMDU6NDU6NTJQTSArMDAwMCwg VHJvbmQNCj4gPiA+ID4gPiA+ID4gPiA+IE15a2xlYnVzdA0KPiA+ID4gPiA+ID4gPiA+ID4gd3Jv dGU6DQo+ID4gPiA+ID4gPiA+ID4gPiA+IA0KPiA+ID4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4g PiA+ID4gPiA+ID4gT24gVGh1LCAyMDE2LTExLTE3IGF0IDExOjMxIC0wNTAwLCBKLiBCcnVjZSBG aWVsZHMNCj4gPiA+ID4gPiA+ID4gPiA+ID4gd3JvdGU6DQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4g DQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gT24gV2VkLCBO b3YgMTYsIDIwMTYgYXQgMDI6NTU6MDVQTSAtMDYwMCwgSmFzb24gTA0KPiA+ID4gPiA+ID4gPiA+ ID4gPiA+IFRpYmJpdHRzIElJSSB3cm90ZToNCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+IA0KPiA+ ID4gPiA+ID4gPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4g PiA+ID4gPiA+ID4gPiA+IEknbSByZXBseWluZyB0byBhIHJhdGhlciBvbGQgbWVzc2FnZSwgYnV0 IHRoZQ0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gaXNzdWUNCj4gPiA+ID4gPiA+ID4gPiA+ID4g PiA+IGhhcyBqdXN0IG5vdw0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gcG9wcGVkDQo+ID4gPiA+ ID4gPiA+ID4gPiA+ID4gPiBiYWNrIHVwIGFnYWluLg0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4g DQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiBUbyByZWNhcCwgYSBjbGllbnQgc3RvcHMgYmVpbmcg YWJsZSB0byBhY2Nlc3MNCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+IF9hbnlfDQo+ID4gPiA+ID4g PiA+ID4gPiA+ID4gPiBtb3VudCBvbiBhDQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiBwYXJ0aWN1 bGFyIHNlcnZlciwgYW5kICJORlM6DQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiBuZnM0X3JlY2xh aW1fb3Blbl9zdGF0ZTogTG9jayByZWNsYWltDQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiBmYWls ZWQhIiBhcHBlYXJzIHNldmVyYWwgaHVuZHJlZCB0aW1lcyBwZXINCj4gPiA+ID4gPiA+ID4gPiA+ ID4gPiA+IHNlY29uZA0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gaW4gdGhlIGtlcm5lbA0KPiA+ ID4gPiA+ID4gPiA+ID4gPiA+ID4gbG9nLg0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gVGhlIGxv YWQgZ29lcyB1cCBieSBvbmUgZm9yIGV2ZXIgcHJvY2Vzcw0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ ID4gYXR0ZW1wdGluZw0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gdG8gYWNjZXNzIGFueQ0KPiA+ ID4gPiA+ID4gPiA+ID4gPiA+ID4gbW91bnQNCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+IGZyb20g dGhhdCBwYXJ0aWN1bGFyIHNlcnZlci7CoMKgTW91bnRzIHRvIG90aGVyDQo+ID4gPiA+ID4gPiA+ ID4gPiA+ID4gPiBzZXJ2ZXJzIGFyZSBmaW5lLCBhbmQNCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ IG90aGVyIGNsaWVudHMgY2FuIG1vdW50IHRoaW5ncyBmcm9tIHRoYXQgb25lDQo+ID4gPiA+ID4g PiA+ID4gPiA+ID4gPiBzZXJ2ZXINCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+IHdpdGhvdXQNCj4g PiA+ID4gPiA+ID4gPiA+ID4gPiA+IHByb2JsZW1zLg0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4g DQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiBXaGVuIEkga2lsbCBldmVyeSBwcm9jZXNzIGtlZXBp bmcgdGhhdA0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gcGFydGljdWxhcg0KPiA+ID4gPiA+ID4g PiA+ID4gPiA+ID4gbW91bnQgYWN0aXZlIGFuZA0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gdGhl bg0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gdW1vdW50IGl0LCBJIHNlZToNCj4gPiA+ID4gPiA+ ID4gPiA+ID4gPiA+IA0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gTkZTOiBuZnM0X3JlY2xhaW1f b3Blbl9zdGF0ZTogdW5oYW5kbGVkIGVycm9yDQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiAtMTAw NjgNCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiBORlM0RVJS X1JFVFJZX1VOQ0FDSEVEX1JFUC4NCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ ID4gPiA+ID4gPiBTbywgeW91J3JlIHVzaW5nIE5GU3Y0LjEgb3IgNC4yLCBhbmQgdGhlIHNlcnZl cg0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+IHRoaW5rcyB0aGF0IHRoZQ0KPiA+ID4gPiA+ID4gPiA+ ID4gPiA+IGNsaWVudA0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+IGhhcyByZXVzZWQgYSAoc2xvdCwg c2VxdWVuY2UgbnVtYmVyKSBwYWlyLCBidXQNCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiB0aGUNCj4g PiA+ID4gPiA+ID4gPiA+ID4gPiBzZXJ2ZXIgZG9lc24ndA0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ IGhhdmUgYQ0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+IGNhY2hlZCByZXNwb25zZSB0byByZXR1cm4u DQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gSGFyZCB0byBr bm93IGhvdyB0aGF0IGhhcHBlbmVkLCBhbmQgaXQncyBub3QNCj4gPiA+ID4gPiA+ID4gPiA+ID4g PiBzaG93biBpbg0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+IHRoZSBiZWxvdy4NCj4gPiA+ID4gPiA+ ID4gPiA+ID4gPiBTb3VuZHMgbGlrZSBhIGJ1ZywgdGhvdWdoLg0KPiA+ID4gPiA+ID4gPiA+ID4g PiANCj4gPiA+ID4gPiA+ID4gPiA+ID4gLi4ub3IgYSBDdHJsLUMuLi4uDQo+ID4gPiA+ID4gPiA+ ID4gPiANCj4gPiA+ID4gPiA+ID4gPiA+IEhvdyBkb2VzIHRoYXQgaGFwcGVuPw0KPiA+ID4gPiA+ ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiA+ID4gSWYgSSBtYXkgY2hp bWUgaW4uLi4NCj4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gPiBCcnVjZSwgd2hlbiBh biBhcHBsaWNhdGlvbiBzZW5kcyBhIEN0cmwtQyBhbmQgY2xpZW50cydzDQo+ID4gPiA+ID4gPiA+ ID4gc2Vzc2lvbiBzbG90DQo+ID4gPiA+ID4gPiA+ID4gaGFzIHNlbnQgb3V0IGFuIFJQQyBidXQg ZGlkbid0IHByb2Nlc3MgdGhlIHJlcGx5LCB0aGUNCj4gPiA+ID4gPiA+ID4gPiBjbGllbnQgZG9l c24ndA0KPiA+ID4gPiA+ID4gPiA+IGtub3cgaWYgdGhlIHNlcnZlciBwcm9jZXNzZWQgdGhhdCBz ZXF1ZW5jZSBpZCBvciBub3QuDQo+ID4gPiA+ID4gPiA+ID4gSW4NCj4gPiA+ID4gPiA+ID4gPiB0 aGF0IGNhc2UsDQo+ID4gPiA+ID4gPiA+ID4gdGhlIGNsaWVudCBkb2Vzbid0IGluY3JlbWVudCB0 aGUgc2VxdWVuY2UgbnVtYmVyLg0KPiA+ID4gPiA+ID4gPiA+IE5vcm1hbGx5DQo+ID4gPiA+ID4g PiA+ID4gdGhlIGNsaWVudA0KPiA+ID4gPiA+ID4gPiA+IHdvdWxkIGhhbmRsZSBnZXR0aW5nIHN1 Y2ggYW4gZXJyb3IgYnkgcmV0cnlpbmcgYWdhaW4NCj4gPiA+ID4gPiA+ID4gPiAoYW5kDQo+ID4g PiA+ID4gPiA+ID4gcmVzZXR0aW5nDQo+ID4gPiA+ID4gPiA+ID4gdGhlIHNsb3RzKSBidXQgSSB0 aGluayBkdXJpbmcgcmVjb3Zlcnkgb3BlcmF0aW9uIHRoZQ0KPiA+ID4gPiA+ID4gPiA+IGNsaWVu dA0KPiA+ID4gPiA+ID4gPiA+IGhhbmRsZXMNCj4gPiA+ID4gPiA+ID4gPiBlcnJvcnMgZGlmZmVy ZW50bHkgKGJ5IGp1c3QgZXJyb3JpbmcpLiBJIGJlbGlldmUgdGhlDQo+ID4gPiA+ID4gPiA+ID4g cmVhc29uaW5nIHRoYXQgd2UNCj4gPiA+ID4gPiA+ID4gPiBkb24ndCB3YW50IHRvIGJlIHN0dWNr IHRyeWluZyB0byByZWNvdmVyIGZyb20gdGhlDQo+ID4gPiA+ID4gPiA+ID4gcmVjb3ZlcnkNCj4g PiA+ID4gPiA+ID4gPiBmcm9tIHRoZQ0KPiA+ID4gPiA+ID4gPiA+IHJlY292ZXJ5IGV0Yy4uLg0K PiA+ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gU28gaW4gdGhhdCBjYXNlIHRoZSBjbGllbnQg Y2FuIGVuZCB1cCBzZW5kaW5nIGEgZGlmZmVyZW50DQo+ID4gPiA+ID4gPiA+IHJwYw0KPiA+ID4g PiA+ID4gPiByZXVzaW5nDQo+ID4gPiA+ID4gPiA+IHRoZSBvbGQgc2xvdCBhbmQgc2VxdWVuY2Ug bnVtYmVyPw0KPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiBDb3JyZWN0Lg0KPiA+ID4gPiA+IA0K PiA+ID4gPiA+IFNvIHRoYXQgY291bGQgZ2V0IFVOQ0FDSEVEX1JFUCBhcyB0aGUgcmVzcG9uc2Uu wqDCoEJ1dCBpZg0KPiA+ID4gPiA+IHlvdSdyZQ0KPiA+ID4gPiA+IHZlcnkNCj4gPiA+ID4gPiB1 bmx1Y2t5LCBjb3VsZG4ndCB0aGlzIGFsc28gaGFwcGVuPzoNCj4gPiA+ID4gPiANCj4gPiA+ID4g PiDCoMKgwqDCoMKgwqDCoMKgMSkgdGhlIGNvbXBvdW5kIHByZXZpb3VzbHkgc2VudCBvbiB0aGF0 IHNsb3Qgd2FzDQo+ID4gPiA+ID4gcHJvY2Vzc2VkIGJ5DQo+ID4gPiA+ID4gwqDCoMKgwqDCoMKg wqDCoHRoZSBzZXJ2ZXIgYW5kIGNhY2hlZA0KPiA+ID4gPiA+IMKgwqDCoMKgwqDCoMKgwqAyKSB0 aGUgY29tcG91bmQgeW91J3JlIHNlbmRpbmcgbm93IGhhcHBlbnMgdG8gaGF2ZQ0KPiA+ID4gPiA+ IHRoZQ0KPiA+ID4gPiA+IHNhbWUgc2V0DQo+ID4gPiA+ID4gwqDCoMKgwqDCoMKgwqDCoG9mIG9w ZXJhdGlvbnMNCj4gPiA+ID4gPiANCj4gPiA+ID4gPiB3aXRoIHRoZSByZXN1bHQgdGhhdCB0aGUg Y2xpZW50IGRvZXNuJ3QgZGV0ZWN0IHRoYXQgdGhlIHJlcGx5DQo+ID4gPiA+ID4gd2FzDQo+ID4g PiA+ID4gYWN0dWFsbHkgdG8gc29tZSBvdGhlciBycGMsIGFuZCBpbnN0ZWFkIGl0IHJldHVybnMg YmFkIGRhdGENCj4gPiA+ID4gPiB0bw0KPiA+ID4gPiA+IHRoZQ0KPiA+ID4gPiA+IGFwcGxpY2F0 aW9uPw0KPiA+ID4gPiANCj4gPiA+ID4gSWYgeW91IGFyZSBzZW5kaW5nIGV4YWN0bHkgdGhlIHNh bWUgb3BlcmF0aW9ucyBhbmQgYXJndW1lbnRzLA0KPiA+ID4gPiB0aGVuDQo+ID4gPiA+IHdoeQ0K PiA+ID4gPiBpcyBhIHJlcGx5IGZyb20gdGhlIGNhY2hlIHdvdWxkIGxlYWQgdG8gYmFkIGRhdGE/ DQo+ID4gPiANCj4gPiA+IFRoYXQgd291bGQgcHJvYmFibHkgYmUgZmluZSwgSSB3YXMgd29uZGVy aW5nIHdoYXQgd291bGQgaGFwcGVuIGlmDQo+ID4gPiB5b3UNCj4gPiA+IHNlbnQgdGhlIHNhbWUg b3BlcmF0aW9uIGJ1dCBkaWZmZXJlbnQgYXJndW1lbnRzLg0KPiA+IA0KPiA+ID4gDQo+ID4gPiBT byB0aGUgb3JpZ2luYWwgY2FuY2VsbGVkIG9wZXJhdGlvbiBpcyBzb21ldGhpbmcgbGlrZQ0KPiA+ ID4gUFVURkgoZmgxKStPUEVOKCJmb28iKStHRVRGSCwgYW5kIHRoZSBuZXcgb25lIGlzDQo+ID4g PiBQVVRGSChmaDIpK09QRU4oImJhciIpK0dFVEZILsKgwqBJbiB0aGVvcnkgY291bGRuJ3QgdGhl IHNlY29uZCBvbmUNCj4gPiA+IHN1Y2NlZWQNCj4gPiA+IGFuZCBsZWF2ZSB0aGUgY2xpZW50IHRo aW5raW5nIGl0IGhhZCBvcGVuZWQgKGZoMiwgYmFyKSB3aGVuIHRoZQ0KPiA+ID4gZmlsZWhhbmRs ZSBpdCBnb3QgYmFjayB3YXMgcmVhbGx5IGZvciAoZmgxLCBmb28pPw0KPiA+ID4gDQo+ID4gDQo+ ID4gVGhlIGNsaWVudCB3b3VsZCByZWNlaXZlIGEgZmlsZWhhbmRsZSBmb3IgZmgxLyJmb28iLCBz byBpdCB3b3VsZA0KPiA+IGFwcGx5DQo+ID4gYW55IHN0YXRlIGl0IHRob3VnaHQgaXQgaGFkIHJl Y2VpdmVkIHRvIHRoYXQgZmlsZS4gSG93ZXZlciwNCj4gPiBub3JtYWxseSwNCj4gPiBJJ2QgZXhw ZWN0IHRvIHNlZSBhIE5GUzRFUlJfRkFMU0VfUkVUUlkgaW4gdGhpcyBjYXNlLg0KPiANCj4gSSBz ZWUgQnJ1Y2UncyBwb2ludCB0aGF0IGlmIHRoZSBzZXJ2ZXIgb25seSBsb29rcyB1cCB0aGUgY2Fj aGUgYmFzZWQNCj4gb24gdGhlIHNlcWlkIGFuZCBzbG90IyBhbmQgZG9lc24ndCBoYXZlIGxpa2Ug YSBoYXNoIG9mIHRoZSBjb250ZW50DQo+IHdoaWNoIEkgY291bGQgc2VlIGlzIGV4cGVuc2l2ZSwg dGhlbiB0aGUgY2xpZW50IGluIHRoaXMgY2FzZSB3b3VsZA0KPiBnZXQNCj4gaW50byB0cm91Ymxl IG9mIHRoaW5raW5nIGl0IG9wZW5lZCAiYmFyIiBidXQgcmVhbGx5IGl0J3MgImZvbyIuIFNwZWMN Cj4gc2F5czoNCj4gDQo+IFNlY3Rpb24gMTguNDYuMw0KPiBJZiB0aGUgY2xpZW50IHJldXNlcyBh IHNsb3QgSUQgYW5kIHNlcXVlbmNlIElEIGZvciBhIGNvbXBsZXRlbHkNCj4gwqDCoMKgZGlmZmVy ZW50IHJlcXVlc3QsIHRoZSBzZXJ2ZXIgTUFZIHRyZWF0IHRoZSByZXF1ZXN0IGFzIGlmIGl0IGlz IGENCj4gwqDCoMKgcmV0cnkgb2Ygd2hhdCBpdCBoYXMgYWxyZWFkeSBleGVjdXRlZC7CoMKgVGhl IHNlcnZlciBNQVkgaG93ZXZlcg0KPiBkZXRlY3QNCj4gwqDCoMKgdGhlIGNsaWVudCdzIGlsbGVn YWwgcmV1c2UgYW5kIHJldHVybiBORlM0RVJSX1NFUV9GQUxTRV9SRVRSWS4NCj4gDQo+IFdoYXQg aXMgImEgY29tcGxldGVseSBkaWZmZXJlbnQgcmVxdWVzdCIuIEZyb20gdGhlIGNsaWVudCdzIHBv aW50IG9mDQo+IHZpZXcgc2VuZGluZyBkaWZmZXJlbnQgYXJncyB3b3VsZCBjb25zdGl0dXRlIGEg ZGlmZmVyZW50IHJlcXVlc3QuIEJ1dA0KPiBpbiBhbnkgY2FzZSBpdCdzIGEgIk1BWSIgc28gY2xp ZW50IGNhbid0IGRlcGVuZCBvbiB0aGlzIGJlaW5nDQo+IGltcGxlbWVudGVkLg0KPiANCg0KV2hh dCdzIHRoZSBhbHRlcm5hdGl2ZT8gQXNzdW1lIHRoZSBjbGllbnQgcHJlLWVtcHRpdmVseSBidW1w cyB0aGUgc2VxaWQNCmluc3RlYWQgb2YgcmV0cnlpbmcsIHRoZW4gdGhlIHVzZXIgcHJlc3NlcyBD dHJsLUMgYWdhaW4uIFJlcGVhdCBhIGZldw0KbW9yZSB0aW1lcy4gSG93IGRvIEkgbm93IHJlc3lu YyB0aGUgc2VxaWRzIGJldHdlZW4gdGhlIGNsaWVudCBhbmQNCnNlcnZlciBvdGhlciB0aGFuIGJ5 IHRyYXNoaW5nIHRoZSBzZXNzaW9uPw==

#22 lore raw
Quoted 197 lines · Trond Myklebust
Quoted 190 lines · Olga Kornievskaia
Quoted 168 lines · Trond Myklebust
Quoted 158 lines · On Thu, 2016-11-17 at 16:26 -0500, [email protected] wrote:
Quoted 145 lines · Olga Kornievskaia
Quoted 134 lines · On Thu, Nov 17, 2016 at 3:46 PM, [email protected] <[email protected]>…
Quoted 110 lines · Olga Kornievskaia
Quoted 106 lines · On Thu, Nov 17, 2016 at 3:17 PM, [email protected] <[email protected]>…
Quoted 100 lines · Olga Kornievskaia
Quoted 62 lines · On Thu, Nov 17, 2016 at 2:32 PM, [email protected] <[email protected]>…
Quoted 57 lines · Trond Myklebust
Quoted 53 lines · J. Bruce Fields
Quoted 37 lines · Jason L Tibbitts III

I'm replying to a rather old message, but the
issue
has just now
popped
back up again.

To recap, a client stops being able to access
_any_
mount on a
particular server, and "NFS:
nfs4_reclaim_open_state: Lock reclaim
failed!" appears several hundred times per
second
in the kernel
log.
The load goes up by one for ever process
attempting
to access any
mount
from that particular server. Mounts to other
servers are fine, and
other clients can mount things from that one
server
without
problems.

When I kill every process keeping that
particular
mount active and
then
umount it, I see:

NFS: nfs4_reclaim_open_state: unhandled error
-10068

NFS4ERR_RETRY_UNCACHED_REP.

So, you're using NFSv4.1 or 4.2, and the server
thinks that the
client
has reused a (slot, sequence number) pair, but
the
server doesn't
have a
cached response to return.

Quoted 9 lines
Quoted 6 lines
Quoted 4 lines

Hard to know how that happened, and it's not
shown in
the below.
Sounds like a bug, though.

...or a Ctrl-C....

How does that happen?

If I may chime in...

Bruce, when an application sends a Ctrl-C and clients's session slot
has sent out an RPC but didn't process the reply, the client doesn't
know if the server processed that sequence id or not. In
that case,
the client doesn't increment the sequence number. Normally
the client
would handle getting such an error by retrying again (and
resetting
the slots) but I think during recovery operation the client
handles
errors differently (by just erroring). I believe the reasoning that we
don't want to be stuck trying to recover from the recovery
from the
recovery etc...

Quoted 6 lines
Quoted 4 lines

So in that case the client can end up sending a different rpc
reusing
the old slot and sequence number?

Correct.

So that could get UNCACHED_REP as the response. But if you're
very
unlucky, couldn't this also happen?:

1) the compound previously sent on that slot was
processed by
the server and cached
2) the compound you're sending now happens to have
the
same set
of operations

Quoted 6 lines

with the result that the client doesn't detect that the reply was
actually to some other rpc, and instead it returns bad data to
the
application?

Quoted 4 lines

If you are sending exactly the same operations and arguments, then
why
is a reply from the cache would lead to bad data?

That would probably be fine, I was wondering what would happen if you
sent the same operation but different arguments.

Quoted 7 lines

So the original cancelled operation is something like PUTFH(fh1)+OPEN("foo")+GETFH, and the new one is PUTFH(fh2)+OPEN("bar")+GETFH. In theory couldn't the second one succeed
and leave the client thinking it had opened (fh2, bar) when the filehandle it got back was really for (fh1, foo)?

Quoted 5 lines

The client would receive a filehandle for fh1/"foo", so it would apply
any state it thought it had received to that file. However, normally,
I'd expect to see a NFS4ERR_FALSE_RETRY in this case.

I see Bruce's point that if the server only looks up the cache based on the seqid and slot# and doesn't have like a hash of the content which I could see is expensive, then the client in this case would get
into trouble of thinking it opened "bar" but really it's "foo". Spec says:

Section 18.46.3
If the client reuses a slot ID and sequence ID for a completely
different request, the server MAY treat the request as if it is a retry of what it has already executed. The server MAY however
detect
the client's illegal reuse and return NFS4ERR_SEQ_FALSE_RETRY.

Quoted 5 lines

What is "a completely different request". From the client's point of view sending different args would constitute a different request. But in any case it's a "MAY" so client can't depend on this being implemented.

Quoted 4 lines

What's the alternative? Assume the client pre-emptively bumps the seqid instead of retrying, then the user presses Ctrl-C again. Repeat a few more times. How do I now resync the seqids between the client and server other than by trashing the session?

I don't see any alternatives than to reset in that case. But I think it's better then the possibility of accidentally opening a wrong file?

#23 lore raw

T24gVGh1LCAyMDE2LTExLTE3IGF0IDE3OjI3IC0wNTAwLCBPbGdhIEtvcm5pZXZza2FpYSB3cm90 ZToNCj4gT24gVGh1LCBOb3YgMTcsIDIwMTYgYXQgNToxNSBQTSwgVHJvbmQgTXlrbGVidXN0DQo+ IDx0cm9uZG15QHByaW1hcnlkYXRhLmNvbT4gd3JvdGU6DQo+ID4gDQo+ID4gT24gVGh1LCAyMDE2 LTExLTE3IGF0IDE2OjUzIC0wNTAwLCBPbGdhIEtvcm5pZXZza2FpYSB3cm90ZToNCj4gPiA+IA0K PiA+ID4gT24gVGh1LCBOb3YgMTcsIDIwMTYgYXQgNDo0NSBQTSwgVHJvbmQgTXlrbGVidXN0DQo+ ID4gPiA8dHJvbmRteUBwcmltYXJ5ZGF0YS5jb20+IHdyb3RlOg0KPiA+ID4gPiANCj4gPiA+ID4g DQo+ID4gPiA+IE9uIFRodSwgMjAxNi0xMS0xNyBhdCAxNjoyNiAtMDUwMCwgYmZpZWxkc0BmaWVs ZHNlcy5vcmcgd3JvdGU6DQo+ID4gPiA+ID4gDQo+ID4gPiA+ID4gDQo+ID4gPiA+ID4gT24gVGh1 LCBOb3YgMTcsIDIwMTYgYXQgMDQ6MDU6MzJQTSAtMDUwMCwgT2xnYSBLb3JuaWV2c2thaWENCj4g PiA+ID4gPiB3cm90ZToNCj4gPiA+ID4gPiA+IA0KPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiAN Cj4gPiA+ID4gPiA+IE9uIFRodSwgTm92IDE3LCAyMDE2IGF0IDM6NDYgUE0sIGJmaWVsZHNAZmll bGRzZXMub3JnDQo+ID4gPiA+ID4gPiA8YmZpZWxkc0BmaWVsZHNlcy5vcmc+IHdyb3RlOg0KPiA+ ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiA+IA0KPiA+ID4gPiA+ID4g PiBPbiBUaHUsIE5vdiAxNywgMjAxNiBhdCAwMzoyOToxMVBNIC0wNTAwLCBPbGdhDQo+ID4gPiA+ ID4gPiA+IEtvcm5pZXZza2FpYQ0KPiA+ID4gPiA+ID4gPiB3cm90ZToNCj4gPiA+ID4gPiA+ID4g PiANCj4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gPiBP biBUaHUsIE5vdiAxNywgMjAxNiBhdCAzOjE3IFBNLCBiZmllbGRzQGZpZWxkc2VzLm9yZw0KPiA+ ID4gPiA+ID4gPiA+IDxiZmllbGRzQGZpZWxkc2VzLm9yZz4gd3JvdGU6DQo+ID4gPiA+ID4gPiA+ ID4gPiANCj4gPiA+ID4gPiA+ID4gPiA+IA0KPiA+ID4gPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4g PiA+ID4gPiBPbiBUaHUsIE5vdiAxNywgMjAxNiBhdCAwMjo1ODoxMlBNIC0wNTAwLCBPbGdhDQo+ ID4gPiA+ID4gPiA+ID4gPiBLb3JuaWV2c2thaWENCj4gPiA+ID4gPiA+ID4gPiA+IHdyb3RlOg0K PiA+ID4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiA+ ID4gPiA+IA0KPiA+ID4gPiA+ID4gPiA+ID4gPiBPbiBUaHUsIE5vdiAxNywgMjAxNiBhdCAyOjMy IFBNLCBiZmllbGRzQGZpZWxkc2VzLm8NCj4gPiA+ID4gPiA+ID4gPiA+ID4gcmcNCj4gPiA+ID4g PiA+ID4gPiA+ID4gPGJmaWVsZHNAZmllbGRzZXMub3JnPiB3cm90ZToNCj4gPiA+ID4gPiA+ID4g PiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiAN Cj4gPiA+ID4gPiA+ID4gPiA+ID4gPiBPbiBUaHUsIE5vdiAxNywgMjAxNiBhdCAwNTo0NTo1MlBN ICswMDAwLCBUcm9uZA0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+IE15a2xlYnVzdA0KPiA+ID4gPiA+ ID4gPiA+ID4gPiA+IHdyb3RlOg0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4g PiA+ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+IA0KPiA+ID4gPiA+ID4gPiA+ ID4gPiA+ID4gT24gVGh1LCAyMDE2LTExLTE3IGF0IDExOjMxIC0wNTAwLCBKLiBCcnVjZQ0KPiA+ ID4gPiA+ID4gPiA+ID4gPiA+ID4gRmllbGRzDQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiB3cm90 ZToNCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ IA0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4g T24gV2VkLCBOb3YgMTYsIDIwMTYgYXQgMDI6NTU6MDVQTSAtMDYwMCwNCj4gPiA+ID4gPiA+ID4g PiA+ID4gPiA+ID4gSmFzb24gTA0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiBUaWJiaXR0cyBJ SUkgd3JvdGU6DQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiA+ID4g PiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiA+ ID4gPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gSSdtIHJlcGx5aW5n IHRvIGEgcmF0aGVyIG9sZCBtZXNzYWdlLCBidXQNCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4g PiB0aGUNCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiBpc3N1ZQ0KPiA+ID4gPiA+ID4gPiA+ ID4gPiA+ID4gPiA+IGhhcyBqdXN0IG5vdw0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+IHBv cHBlZA0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+IGJhY2sgdXAgYWdhaW4uDQo+ID4gPiA+ ID4gPiA+ID4gPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gVG8gcmVj YXAsIGEgY2xpZW50IHN0b3BzIGJlaW5nIGFibGUgdG8NCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ ID4gPiBhY2Nlc3MNCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiBfYW55Xw0KPiA+ID4gPiA+ ID4gPiA+ID4gPiA+ID4gPiA+IG1vdW50IG9uIGENCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4g PiBwYXJ0aWN1bGFyIHNlcnZlciwgYW5kICJORlM6DQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ ID4gbmZzNF9yZWNsYWltX29wZW5fc3RhdGU6IExvY2sgcmVjbGFpbQ0KPiA+ID4gPiA+ID4gPiA+ ID4gPiA+ID4gPiA+IGZhaWxlZCEiIGFwcGVhcnMgc2V2ZXJhbCBodW5kcmVkIHRpbWVzIHBlcg0K PiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+IHNlY29uZA0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ ID4gPiA+IGluIHRoZSBrZXJuZWwNCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiBsb2cuDQo+ ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gVGhlIGxvYWQgZ29lcyB1cCBieSBvbmUgZm9yIGV2 ZXIgcHJvY2Vzcw0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+IGF0dGVtcHRpbmcNCj4gPiA+ ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiB0byBhY2Nlc3MgYW55DQo+ID4gPiA+ID4gPiA+ID4gPiA+ ID4gPiA+ID4gbW91bnQNCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiBmcm9tIHRoYXQgcGFy dGljdWxhciBzZXJ2ZXIuwqDCoE1vdW50cyB0bw0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ IG90aGVyDQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gc2VydmVycyBhcmUgZmluZSwgYW5k DQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gb3RoZXIgY2xpZW50cyBjYW4gbW91bnQgdGhp bmdzIGZyb20gdGhhdA0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+IG9uZQ0KPiA+ID4gPiA+ ID4gPiA+ID4gPiA+ID4gPiA+IHNlcnZlcg0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+IHdp dGhvdXQNCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiBwcm9ibGVtcy4NCj4gPiA+ID4gPiA+ ID4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiBXaGVuIEkga2ls bCBldmVyeSBwcm9jZXNzIGtlZXBpbmcgdGhhdA0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ IHBhcnRpY3VsYXINCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiBtb3VudCBhY3RpdmUgYW5k DQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gdGhlbg0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ ID4gPiA+IHVtb3VudCBpdCwgSSBzZWU6DQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gDQo+ ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gTkZTOiBuZnM0X3JlY2xhaW1fb3Blbl9zdGF0ZTog dW5oYW5kbGVkDQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gZXJyb3INCj4gPiA+ID4gPiA+ ID4gPiA+ID4gPiA+ID4gPiAtMTAwNjgNCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gDQo+ID4g PiA+ID4gPiA+ID4gPiA+ID4gPiA+IE5GUzRFUlJfUkVUUllfVU5DQUNIRURfUkVQLg0KPiA+ID4g PiA+ID4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gU28sIHlvdSdy ZSB1c2luZyBORlN2NC4xIG9yIDQuMiwgYW5kIHRoZQ0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4g PiBzZXJ2ZXINCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gdGhpbmtzIHRoYXQgdGhlDQo+ID4g PiA+ID4gPiA+ID4gPiA+ID4gPiA+IGNsaWVudA0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiBo YXMgcmV1c2VkIGEgKHNsb3QsIHNlcXVlbmNlIG51bWJlcikgcGFpciwNCj4gPiA+ID4gPiA+ID4g PiA+ID4gPiA+ID4gYnV0DQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+IHRoZQ0KPiA+ID4gPiA+ ID4gPiA+ID4gPiA+ID4gPiBzZXJ2ZXIgZG9lc24ndA0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4g PiBoYXZlIGENCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gY2FjaGVkIHJlc3BvbnNlIHRvIHJl dHVybi4NCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4g PiA+IEhhcmQgdG8ga25vdyBob3cgdGhhdCBoYXBwZW5lZCwgYW5kIGl0J3Mgbm90DQo+ID4gPiA+ ID4gPiA+ID4gPiA+ID4gPiA+IHNob3duIGluDQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+IHRo ZSBiZWxvdy4NCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4gU291bmRzIGxpa2UgYSBidWcsIHRo b3VnaC4NCj4gPiA+ID4gPiA+ID4gPiA+ID4gPiA+IA0KPiA+ID4gPiA+ID4gPiA+ID4gPiA+ID4g Li4ub3IgYSBDdHJsLUMuLi4uDQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gDQo+ID4gPiA+ID4gPiA+ ID4gPiA+ID4gSG93IGRvZXMgdGhhdCBoYXBwZW4/DQo+ID4gPiA+ID4gPiA+ID4gPiA+ID4gDQo+ ID4gPiA+ID4gPiA+ID4gPiA+IA0KPiA+ID4gPiA+ID4gPiA+ID4gPiBJZiBJIG1heSBjaGltZSBp bi4uLg0KPiA+ID4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gPiA+ID4gQnJ1Y2UsIHdo ZW4gYW4gYXBwbGljYXRpb24gc2VuZHMgYSBDdHJsLUMgYW5kDQo+ID4gPiA+ID4gPiA+ID4gPiA+ IGNsaWVudHMncw0KPiA+ID4gPiA+ID4gPiA+ID4gPiBzZXNzaW9uIHNsb3QNCj4gPiA+ID4gPiA+ ID4gPiA+ID4gaGFzIHNlbnQgb3V0IGFuIFJQQyBidXQgZGlkbid0IHByb2Nlc3MgdGhlIHJlcGx5 LA0KPiA+ID4gPiA+ID4gPiA+ID4gPiB0aGUNCj4gPiA+ID4gPiA+ID4gPiA+ID4gY2xpZW50IGRv ZXNuJ3QNCj4gPiA+ID4gPiA+ID4gPiA+ID4ga25vdyBpZiB0aGUgc2VydmVyIHByb2Nlc3NlZCB0 aGF0IHNlcXVlbmNlIGlkIG9yDQo+ID4gPiA+ID4gPiA+ID4gPiA+IG5vdC4NCj4gPiA+ID4gPiA+ ID4gPiA+ID4gSW4NCj4gPiA+ID4gPiA+ID4gPiA+ID4gdGhhdCBjYXNlLA0KPiA+ID4gPiA+ID4g PiA+ID4gPiB0aGUgY2xpZW50IGRvZXNuJ3QgaW5jcmVtZW50IHRoZSBzZXF1ZW5jZSBudW1iZXIu DQo+ID4gPiA+ID4gPiA+ID4gPiA+IE5vcm1hbGx5DQo+ID4gPiA+ID4gPiA+ID4gPiA+IHRoZSBj bGllbnQNCj4gPiA+ID4gPiA+ID4gPiA+ID4gd291bGQgaGFuZGxlIGdldHRpbmcgc3VjaCBhbiBl cnJvciBieSByZXRyeWluZw0KPiA+ID4gPiA+ID4gPiA+ID4gPiBhZ2Fpbg0KPiA+ID4gPiA+ID4g PiA+ID4gPiAoYW5kDQo+ID4gPiA+ID4gPiA+ID4gPiA+IHJlc2V0dGluZw0KPiA+ID4gPiA+ID4g PiA+ID4gPiB0aGUgc2xvdHMpIGJ1dCBJIHRoaW5rIGR1cmluZyByZWNvdmVyeSBvcGVyYXRpb24N Cj4gPiA+ID4gPiA+ID4gPiA+ID4gdGhlDQo+ID4gPiA+ID4gPiA+ID4gPiA+IGNsaWVudA0KPiA+ ID4gPiA+ID4gPiA+ID4gPiBoYW5kbGVzDQo+ID4gPiA+ID4gPiA+ID4gPiA+IGVycm9ycyBkaWZm ZXJlbnRseSAoYnkganVzdCBlcnJvcmluZykuIEkgYmVsaWV2ZQ0KPiA+ID4gPiA+ID4gPiA+ID4g PiB0aGUNCj4gPiA+ID4gPiA+ID4gPiA+ID4gcmVhc29uaW5nIHRoYXQgd2UNCj4gPiA+ID4gPiA+ ID4gPiA+ID4gZG9uJ3Qgd2FudCB0byBiZSBzdHVjayB0cnlpbmcgdG8gcmVjb3ZlciBmcm9tIHRo ZQ0KPiA+ID4gPiA+ID4gPiA+ID4gPiByZWNvdmVyeQ0KPiA+ID4gPiA+ID4gPiA+ID4gPiBmcm9t IHRoZQ0KPiA+ID4gPiA+ID4gPiA+ID4gPiByZWNvdmVyeSBldGMuLi4NCj4gPiA+ID4gPiA+ID4g PiA+IA0KPiA+ID4gPiA+ID4gPiA+ID4gU28gaW4gdGhhdCBjYXNlIHRoZSBjbGllbnQgY2FuIGVu ZCB1cCBzZW5kaW5nIGENCj4gPiA+ID4gPiA+ID4gPiA+IGRpZmZlcmVudA0KPiA+ID4gPiA+ID4g PiA+ID4gcnBjDQo+ID4gPiA+ID4gPiA+ID4gPiByZXVzaW5nDQo+ID4gPiA+ID4gPiA+ID4gPiB0 aGUgb2xkIHNsb3QgYW5kIHNlcXVlbmNlIG51bWJlcj8NCj4gPiA+ID4gPiA+ID4gPiANCj4gPiA+ ID4gPiA+ID4gPiBDb3JyZWN0Lg0KPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4gPiA+ID4gU28gdGhh dCBjb3VsZCBnZXQgVU5DQUNIRURfUkVQIGFzIHRoZSByZXNwb25zZS7CoMKgQnV0IGlmDQo+ID4g PiA+ID4gPiA+IHlvdSdyZQ0KPiA+ID4gPiA+ID4gPiB2ZXJ5DQo+ID4gPiA+ID4gPiA+IHVubHVj a3ksIGNvdWxkbid0IHRoaXMgYWxzbyBoYXBwZW4/Og0KPiA+ID4gPiA+ID4gPiANCj4gPiA+ID4g PiA+ID4gwqDCoMKgwqDCoMKgwqDCoDEpIHRoZSBjb21wb3VuZCBwcmV2aW91c2x5IHNlbnQgb24g dGhhdCBzbG90IHdhcw0KPiA+ID4gPiA+ID4gPiBwcm9jZXNzZWQgYnkNCj4gPiA+ID4gPiA+ID4g wqDCoMKgwqDCoMKgwqDCoHRoZSBzZXJ2ZXIgYW5kIGNhY2hlZA0KPiA+ID4gPiA+ID4gPiDCoMKg wqDCoMKgwqDCoMKgMikgdGhlIGNvbXBvdW5kIHlvdSdyZSBzZW5kaW5nIG5vdyBoYXBwZW5zIHRv DQo+ID4gPiA+ID4gPiA+IGhhdmUNCj4gPiA+ID4gPiA+ID4gdGhlDQo+ID4gPiA+ID4gPiA+IHNh bWUgc2V0DQo+ID4gPiA+ID4gPiA+IMKgwqDCoMKgwqDCoMKgwqBvZiBvcGVyYXRpb25zDQo+ID4g PiA+ID4gPiA+IA0KPiA+ID4gPiA+ID4gPiB3aXRoIHRoZSByZXN1bHQgdGhhdCB0aGUgY2xpZW50 IGRvZXNuJ3QgZGV0ZWN0IHRoYXQgdGhlDQo+ID4gPiA+ID4gPiA+IHJlcGx5DQo+ID4gPiA+ID4g PiA+IHdhcw0KPiA+ID4gPiA+ID4gPiBhY3R1YWxseSB0byBzb21lIG90aGVyIHJwYywgYW5kIGlu c3RlYWQgaXQgcmV0dXJucyBiYWQNCj4gPiA+ID4gPiA+ID4gZGF0YQ0KPiA+ID4gPiA+ID4gPiB0 bw0KPiA+ID4gPiA+ID4gPiB0aGUNCj4gPiA+ID4gPiA+ID4gYXBwbGljYXRpb24/DQo+ID4gPiA+ ID4gPiANCj4gPiA+ID4gPiA+IElmIHlvdSBhcmUgc2VuZGluZyBleGFjdGx5IHRoZSBzYW1lIG9w ZXJhdGlvbnMgYW5kDQo+ID4gPiA+ID4gPiBhcmd1bWVudHMsDQo+ID4gPiA+ID4gPiB0aGVuDQo+ ID4gPiA+ID4gPiB3aHkNCj4gPiA+ID4gPiA+IGlzIGEgcmVwbHkgZnJvbSB0aGUgY2FjaGUgd291 bGQgbGVhZCB0byBiYWQgZGF0YT8NCj4gPiA+ID4gPiANCj4gPiA+ID4gPiBUaGF0IHdvdWxkIHBy b2JhYmx5IGJlIGZpbmUsIEkgd2FzIHdvbmRlcmluZyB3aGF0IHdvdWxkDQo+ID4gPiA+ID4gaGFw cGVuIGlmDQo+ID4gPiA+ID4geW91DQo+ID4gPiA+ID4gc2VudCB0aGUgc2FtZSBvcGVyYXRpb24g YnV0IGRpZmZlcmVudCBhcmd1bWVudHMuDQo+ID4gPiA+IA0KPiA+ID4gPiA+IA0KPiA+ID4gPiA+ IA0KPiA+ID4gPiA+IFNvIHRoZSBvcmlnaW5hbCBjYW5jZWxsZWQgb3BlcmF0aW9uIGlzIHNvbWV0 aGluZyBsaWtlDQo+ID4gPiA+ID4gUFVURkgoZmgxKStPUEVOKCJmb28iKStHRVRGSCwgYW5kIHRo ZSBuZXcgb25lIGlzDQo+ID4gPiA+ID4gUFVURkgoZmgyKStPUEVOKCJiYXIiKStHRVRGSC7CoMKg SW4gdGhlb3J5IGNvdWxkbid0IHRoZSBzZWNvbmQNCj4gPiA+ID4gPiBvbmUNCj4gPiA+ID4gPiBz dWNjZWVkDQo+ID4gPiA+ID4gYW5kIGxlYXZlIHRoZSBjbGllbnQgdGhpbmtpbmcgaXQgaGFkIG9w ZW5lZCAoZmgyLCBiYXIpIHdoZW4NCj4gPiA+ID4gPiB0aGUNCj4gPiA+ID4gPiBmaWxlaGFuZGxl IGl0IGdvdCBiYWNrIHdhcyByZWFsbHkgZm9yIChmaDEsIGZvbyk/DQo+ID4gPiA+ID4gDQo+ID4g PiA+IA0KPiA+ID4gPiBUaGUgY2xpZW50IHdvdWxkIHJlY2VpdmUgYSBmaWxlaGFuZGxlIGZvciBm aDEvImZvbyIsIHNvIGl0DQo+ID4gPiA+IHdvdWxkDQo+ID4gPiA+IGFwcGx5DQo+ID4gPiA+IGFu eSBzdGF0ZSBpdCB0aG91Z2h0IGl0IGhhZCByZWNlaXZlZCB0byB0aGF0IGZpbGUuIEhvd2V2ZXIs DQo+ID4gPiA+IG5vcm1hbGx5LA0KPiA+ID4gPiBJJ2QgZXhwZWN0IHRvIHNlZSBhIE5GUzRFUlJf RkFMU0VfUkVUUlkgaW4gdGhpcyBjYXNlLg0KPiA+ID4gDQo+ID4gPiBJIHNlZSBCcnVjZSdzIHBv aW50IHRoYXQgaWYgdGhlIHNlcnZlciBvbmx5IGxvb2tzIHVwIHRoZSBjYWNoZQ0KPiA+ID4gYmFz ZWQNCj4gPiA+IG9uIHRoZSBzZXFpZCBhbmQgc2xvdCMgYW5kIGRvZXNuJ3QgaGF2ZSBsaWtlIGEg aGFzaCBvZiB0aGUNCj4gPiA+IGNvbnRlbnQNCj4gPiA+IHdoaWNoIEkgY291bGQgc2VlIGlzIGV4 cGVuc2l2ZSwgdGhlbiB0aGUgY2xpZW50IGluIHRoaXMgY2FzZQ0KPiA+ID4gd291bGQNCj4gPiA+ IGdldA0KPiA+ID4gaW50byB0cm91YmxlIG9mIHRoaW5raW5nIGl0IG9wZW5lZCAiYmFyIiBidXQg cmVhbGx5IGl0J3MgImZvbyIuDQo+ID4gPiBTcGVjDQo+ID4gPiBzYXlzOg0KPiA+ID4gDQo+ID4g PiBTZWN0aW9uIDE4LjQ2LjMNCj4gPiA+IElmIHRoZSBjbGllbnQgcmV1c2VzIGEgc2xvdCBJRCBh bmQgc2VxdWVuY2UgSUQgZm9yIGEgY29tcGxldGVseQ0KPiA+ID4gwqDCoMKgZGlmZmVyZW50IHJl cXVlc3QsIHRoZSBzZXJ2ZXIgTUFZIHRyZWF0IHRoZSByZXF1ZXN0IGFzIGlmIGl0DQo+ID4gPiBp cyBhDQo+ID4gPiDCoMKgwqByZXRyeSBvZiB3aGF0IGl0IGhhcyBhbHJlYWR5IGV4ZWN1dGVkLsKg wqBUaGUgc2VydmVyIE1BWSBob3dldmVyDQo+ID4gPiBkZXRlY3QNCj4gPiA+IMKgwqDCoHRoZSBj bGllbnQncyBpbGxlZ2FsIHJldXNlIGFuZCByZXR1cm4gTkZTNEVSUl9TRVFfRkFMU0VfUkVUUlku DQo+ID4gPiANCj4gPiA+IFdoYXQgaXMgImEgY29tcGxldGVseSBkaWZmZXJlbnQgcmVxdWVzdCIu IEZyb20gdGhlIGNsaWVudCdzIHBvaW50DQo+ID4gPiBvZg0KPiA+ID4gdmlldyBzZW5kaW5nIGRp ZmZlcmVudCBhcmdzIHdvdWxkIGNvbnN0aXR1dGUgYSBkaWZmZXJlbnQgcmVxdWVzdC4NCj4gPiA+ IEJ1dA0KPiA+ID4gaW4gYW55IGNhc2UgaXQncyBhICJNQVkiIHNvIGNsaWVudCBjYW4ndCBkZXBl bmQgb24gdGhpcyBiZWluZw0KPiA+ID4gaW1wbGVtZW50ZWQuDQo+ID4gPiANCj4gPiANCj4gPiBX aGF0J3MgdGhlIGFsdGVybmF0aXZlPyBBc3N1bWUgdGhlIGNsaWVudCBwcmUtZW1wdGl2ZWx5IGJ1 bXBzIHRoZQ0KPiA+IHNlcWlkDQo+ID4gaW5zdGVhZCBvZiByZXRyeWluZywgdGhlbiB0aGUgdXNl ciBwcmVzc2VzIEN0cmwtQyBhZ2Fpbi4gUmVwZWF0IGENCj4gPiBmZXcNCj4gPiBtb3JlIHRpbWVz LiBIb3cgZG8gSSBub3cgcmVzeW5jIHRoZSBzZXFpZHMgYmV0d2VlbiB0aGUgY2xpZW50IGFuZA0K PiA+IHNlcnZlciBvdGhlciB0aGFuIGJ5IHRyYXNoaW5nIHRoZSBzZXNzaW9uPw0KPiANCj4gSSBk b24ndCBzZWUgYW55IGFsdGVybmF0aXZlcyB0aGFuIHRvIHJlc2V0IGluIHRoYXQgY2FzZS4gQnV0 IEkgdGhpbmsNCj4gaXQncyBiZXR0ZXIgdGhlbiB0aGUgcG9zc2liaWxpdHkgb2YgYWNjaWRlbnRh bGx5IG9wZW5pbmcgYSB3cm9uZw0KPiBmaWxlPw0KDQpUaGV5IHNvdW5kIGVxdWFsbHkgYmFkIHRv IG1lIHdoaWNoIGlzIHdoeSBJJ20gbm90IHVuZGVyc3RhbmRpbmcgaG93IGENCnNlcnZlciB3b3Vs ZCBmYWlsIHRvIGltcGxlbWVudCBzb21lIG1pbmltYWwgZm9ybSBvZiBmYWxzZSByZXRyeQ0KY2hl Y2tpbmcuDQpUaGUgTGludXggTkZTdjMgRFJDIHdpbGwsIGZvciBpbnN0YW5jZSwgY2hlY2tzdW0g YXQgbGVhc3Qgc29tZSBwYXJ0IG9mDQp0aGUgUlBDIGFyZ3VtZW50cyBmb3IgX2FsbF8gUlBDIGNh bGxzLiBNb3N0IE5GU3Y0LnggY2xpZW50cyB3aWxsIG9ubHkNCmFzayB0aGF0IHlvdSBjaGVja3N1 bSB0aGUgbm9uLWlkZW1wb3RlbnQgUlBDIGNhbGxzLCB3aGljaCBzaWduaWZpY2FudGx5DQpjdXRz IGRvd24gb24gdGhlIGNhbGN1bGF0aW9uIG92ZXJoZWFkLg0K

#24 lore raw
Quoted 10 lines · Trond Myklebust
Quoted 9 lines · Olga Kornievskaia
Quoted 6 lines · Trond Myklebust

What's the alternative? Assume the client pre-emptively bumps the seqid
instead of retrying, then the user presses Ctrl-C again. Repeat a few
more times. How do I now resync the seqids between the client and server other than by trashing the session?

Quoted 3 lines
Quoted 3 lines

I don't see any alternatives than to reset in that case. But I think it's better then the possibility of accidentally opening a wrong file?

Remind me why you can't continue resending after the Ctrl-C? (I thought this was already done for some lock and other cases?)

Quoted 7 lines

They sound equally bad to me which is why I'm not understanding how a server would fail to implement some minimal form of false retry checking.
The Linux NFSv3 DRC will, for instance, checksum at least some part of the RPC arguments for _all_ RPC calls. Most NFSv4.x clients will only ask that you checksum the non-idempotent RPC calls, which significantly cuts down on the calculation overhead.

I'll look at adding checksumming, it shouldn't be hard.

--b.

#25 lore raw

DQo+IE9uIE5vdiAxOCwgMjAxNiwgYXQgMTU6NTIsIGJmaWVsZHNAZmllbGRzZXMub3JnIHdyb3Rl Og0KPiANCj4gT24gVGh1LCBOb3YgMTcsIDIwMTYgYXQgMTA6NDM6NThQTSArMDAwMCwgVHJvbmQg TXlrbGVidXN0IHdyb3RlOg0KPj4gT24gVGh1LCAyMDE2LTExLTE3IGF0IDE3OjI3IC0wNTAwLCBP bGdhIEtvcm5pZXZza2FpYSB3cm90ZToNCj4+PiBPbiBUaHUsIE5vdiAxNywgMjAxNiBhdCA1OjE1 IFBNLCBUcm9uZCBNeWtsZWJ1c3QNCj4+PiA8dHJvbmRteUBwcmltYXJ5ZGF0YS5jb20+IHdyb3Rl Og0KPj4+PiBXaGF0J3MgdGhlIGFsdGVybmF0aXZlPyBBc3N1bWUgdGhlIGNsaWVudCBwcmUtZW1w dGl2ZWx5IGJ1bXBzIHRoZQ0KPj4+PiBzZXFpZA0KPj4+PiBpbnN0ZWFkIG9mIHJldHJ5aW5nLCB0 aGVuIHRoZSB1c2VyIHByZXNzZXMgQ3RybC1DIGFnYWluLiBSZXBlYXQgYQ0KPj4+PiBmZXcNCj4+ Pj4gbW9yZSB0aW1lcy4gSG93IGRvIEkgbm93IHJlc3luYyB0aGUgc2VxaWRzIGJldHdlZW4gdGhl IGNsaWVudCBhbmQNCj4+Pj4gc2VydmVyIG90aGVyIHRoYW4gYnkgdHJhc2hpbmcgdGhlIHNlc3Np b24/DQo+Pj4gDQo+Pj4gSSBkb24ndCBzZWUgYW55IGFsdGVybmF0aXZlcyB0aGFuIHRvIHJlc2V0 IGluIHRoYXQgY2FzZS4gQnV0IEkgdGhpbmsNCj4+PiBpdCdzIGJldHRlciB0aGVuIHRoZSBwb3Nz aWJpbGl0eSBvZiBhY2NpZGVudGFsbHkgb3BlbmluZyBhIHdyb25nDQo+Pj4gZmlsZT8NCj4gDQo+ IFJlbWluZCBtZSB3aHkgeW91IGNhbid0IGNvbnRpbnVlIHJlc2VuZGluZyBhZnRlciB0aGUgQ3Ry bC1DPyAgKEkgdGhvdWdodA0KPiB0aGlzIHdhcyBhbHJlYWR5IGRvbmUgZm9yIHNvbWUgbG9jayBh bmQgb3RoZXIgY2FzZXM/KQ0KDQpXZeKAmWQgaGF2ZSB0byBkbyBpdCBmb3IgYWxsIFJQQyBjYWxs cywgd2hpY2ggbWVhbnMgdGhleSB3b3VsZCBhbGwgaGF2ZSB0byBiZSBjb252ZXJ0ZWQgdG8gbm90 IHVzZSB0aGUgc3RhY2suIFRoZSByZXN1bHRpbmcgYmVoYXZpb3VyIHdvdWxkIGFsc28gYmUgY29u ZnVzaW5nLCBhcyBvcGVyYXRpb25zIHdvdWxkIGNvbXBsZXRlIG91dHNpZGUgb2YgbG9ja2luZyBy dWxlcyBldGMuIFNvLCBmb3IgaW5zdGFuY2UsIHlvdSB3b3VsZCBiZSBzZWVpbmcgc3VjY2Vzc2Z1 bGx5IGxvb2tlZCB1cCBmaWxlcyBteXN0ZXJpb3VzbHkgZGlzYXBwZWFyaW5nIGFzIHRoZSBhc3lu Y2hyb25vdXMgdW5saW5rKCkgb3BlcmF0aW9uIHRoYXQgd2FzIGludGVycnVwdGVkIGNvbXBsZXRl cywgb3IgZGlyZWN0b3JpZXMgbXlzdGVyaW91c2x5IGdldHRpbmcgcmVuYW1lZC4NCg0KPiANCj4+ IFRoZXkgc291bmQgZXF1YWxseSBiYWQgdG8gbWUgd2hpY2ggaXMgd2h5IEknbSBub3QgdW5kZXJz dGFuZGluZyBob3cgYQ0KPj4gc2VydmVyIHdvdWxkIGZhaWwgdG8gaW1wbGVtZW50IHNvbWUgbWlu aW1hbCBmb3JtIG9mIGZhbHNlIHJldHJ5DQo+PiBjaGVja2luZy4NCj4+IFRoZSBMaW51eCBORlN2 MyBEUkMgd2lsbCwgZm9yIGluc3RhbmNlLCBjaGVja3N1bSBhdCBsZWFzdCBzb21lIHBhcnQgb2YN Cj4+IHRoZSBSUEMgYXJndW1lbnRzIGZvciBfYWxsXyBSUEMgY2FsbHMuIE1vc3QgTkZTdjQueCBj bGllbnRzIHdpbGwgb25seQ0KPj4gYXNrIHRoYXQgeW91IGNoZWNrc3VtIHRoZSBub24taWRlbXBv dGVudCBSUEMgY2FsbHMsIHdoaWNoIHNpZ25pZmljYW50bHkNCj4+IGN1dHMgZG93biBvbiB0aGUg Y2FsY3VsYXRpb24gb3ZlcmhlYWQuDQo+IA0KPiBJJ2xsIGxvb2sgYXQgYWRkaW5nIGNoZWNrc3Vt bWluZywgaXQgc2hvdWxkbid0IGJlIGhhcmQuDQoNClRoYW5rcy4NCg0K

#26 lore raw
Quoted 14 lines · Trond Myklebust
Quoted 14 lines · On Nov 18, 2016, at 15:52, [email protected] wrote:
Quoted 10 lines · Trond Myklebust
Quoted 9 lines · Olga Kornievskaia
Quoted 6 lines · Trond Myklebust

What's the alternative? Assume the client pre-emptively bumps the seqid
instead of retrying, then the user presses Ctrl-C again. Repeat a few
more times. How do I now resync the seqids between the client and server other than by trashing the session?

Quoted 8 lines
Quoted 6 lines
Quoted 3 lines
Quoted 3 lines

I don't see any alternatives than to reset in that case. But I think it's better then the possibility of accidentally opening a wrong file?

Remind me why you can't continue resending after the Ctrl-C? (I thought this was already done for some lock and other cases?)

We’d have to do it for all RPC calls, which means they would all have to be converted to not use the stack. The resulting behaviour would also be confusing, as operations would complete outside of locking rules etc. So, for instance, you would be seeing successfully looked up files mysteriously disappearing as the asynchronous unlink() operation that was interrupted completes, or directories mysteriously getting renamed.

We get that anyway, since the server may already be processing the rpc.

I'll admit it sounds complicated.

Quoted 11 lines
Quoted 9 lines
Quoted 7 lines

They sound equally bad to me which is why I'm not understanding how a server would fail to implement some minimal form of false retry checking.
The Linux NFSv3 DRC will, for instance, checksum at least some part of the RPC arguments for _all_ RPC calls. Most NFSv4.x clients will only ask that you checksum the non-idempotent RPC calls, which significantly cuts down on the calculation overhead.

I'll look at adding checksumming, it shouldn't be hard.

Thanks.

I doubt it's a complete fix, though. Two calls with the same arguments aren't necessarily the same call either, and it's the sequence id that's supposed to distinguish the "same call" and "different call with same argument" cases.

--b.