* nfs4 state manager loop on recallable state revoked
@ 2015-02-18 16:22 Benjamin Coddington
2015-02-18 17:00 ` Trond Myklebust
0 siblings, 1 reply; 4+ messages in thread
From: Benjamin Coddington @ 2015-02-18 16:22 UTC (permalink / raw)
To: linux-nfs
While playing with callback channel failures, I noticed the state manager
get stuck looping trying to check a lease when the server responds with
SEQ4_STATUS_RECALLABLE_STATE_REVOKED set.
Does this look familiar to anyone?
[67732.348087] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
[67732.369726] nfs4_free_slot: slotid 2 highest_used_slotid 1
[67732.372881] nfs4_free_slot: slotid 0 highest_used_slotid 1
[67732.375337] nfs4_schedule_state_renewal: requeueing work. Lease period = 5
[67732.394736] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
[67732.401010] nfs4_free_slot: slotid 0 highest_used_slotid 1
[67732.402910] nfs4_free_slot: slotid 1 highest_used_slotid 4294967295
[67732.404659] nfs4_schedule_stateid_recovery: scheduling stateid recovery for server fedora
[67732.422848] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
[67732.426257] nfs4_free_slot: slotid 1 highest_used_slotid 0
[67732.427250] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[67732.428291] nfs41_handle_sequence_flag_errors: "fedora" (client ID f49be45401000000) flags=0x00000041
[67732.429596] nfs41_handle_recallable_state_revoked: Recallable state revoked on server fedora!
[67732.430746] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
[67732.431817] nfs4_recovery_handle_error: handled error 0 for server fedora
[67732.439132] nfs4_bind_conn_to_session: bind_conn_to_session was successful for server fedora!
[67732.451098] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
[67732.454522] nfs4_free_slot: slotid 1 highest_used_slotid 0
[67732.455557] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[67732.456647] nfs41_handle_sequence_flag_errors: "fedora" (client ID f49be45401000000) flags=0x00000040
[67732.457986] nfs41_handle_recallable_state_revoked: Recallable state revoked on server fedora!
[67732.459215] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
[67732.460350] nfs4_recovery_handle_error: handled error 0 for server fedora
[67732.472138] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
[67732.475707] nfs4_free_slot: slotid 1 highest_used_slotid 0
[67732.476779] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[67732.477917] nfs41_handle_sequence_flag_errors: "fedora" (client ID f49be45401000000) flags=0x00000040
[67732.479294] nfs41_handle_recallable_state_revoked: Recallable state revoked on server fedora!
[67732.480572] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
[67732.481753] nfs4_recovery_handle_error: handled error 0 for server fedora
[67732.493666] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
[67732.497269] nfs4_free_slot: slotid 1 highest_used_slotid 0
[67732.498402] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[67732.499563] nfs41_handle_sequence_flag_errors: "fedora" (client ID f49be45401000000) flags=0x00000040
[67732.500894] nfs41_handle_recallable_state_revoked: Recallable state revoked on server fedora!
[67732.502159] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
I think what's happening is that we never get to reclaim_lease() because
NFS4CLNT_LEASE_EXPIRED is never flagged. Should we set
NFS4CLNT_LEASE_EXPIRED in nfs41_handle_cb_path_down()? I think that would
have avoided this.
Ben
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: nfs4 state manager loop on recallable state revoked
2015-02-18 16:22 nfs4 state manager loop on recallable state revoked Benjamin Coddington
@ 2015-02-18 17:00 ` Trond Myklebust
2015-02-18 19:28 ` Benjamin Coddington
0 siblings, 1 reply; 4+ messages in thread
From: Trond Myklebust @ 2015-02-18 17:00 UTC (permalink / raw)
To: Benjamin Coddington; +Cc: Linux NFS Mailing List
On Wed, Feb 18, 2015 at 8:22 AM, Benjamin Coddington
<bcodding@redhat.com> wrote:
> While playing with callback channel failures, I noticed the state manager
> get stuck looping trying to check a lease when the server responds with
> SEQ4_STATUS_RECALLABLE_STATE_REVOKED set.
>
> Does this look familiar to anyone?
>
> [67732.348087] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
> [67732.369726] nfs4_free_slot: slotid 2 highest_used_slotid 1
> [67732.372881] nfs4_free_slot: slotid 0 highest_used_slotid 1
> [67732.375337] nfs4_schedule_state_renewal: requeueing work. Lease period = 5
> [67732.394736] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
> [67732.401010] nfs4_free_slot: slotid 0 highest_used_slotid 1
> [67732.402910] nfs4_free_slot: slotid 1 highest_used_slotid 4294967295
> [67732.404659] nfs4_schedule_stateid_recovery: scheduling stateid recovery for server fedora
> [67732.422848] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
> [67732.426257] nfs4_free_slot: slotid 1 highest_used_slotid 0
> [67732.427250] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> [67732.428291] nfs41_handle_sequence_flag_errors: "fedora" (client ID f49be45401000000) flags=0x00000041
> [67732.429596] nfs41_handle_recallable_state_revoked: Recallable state revoked on server fedora!
> [67732.430746] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
> [67732.431817] nfs4_recovery_handle_error: handled error 0 for server fedora
> [67732.439132] nfs4_bind_conn_to_session: bind_conn_to_session was successful for server fedora!
> [67732.451098] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
> [67732.454522] nfs4_free_slot: slotid 1 highest_used_slotid 0
> [67732.455557] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> [67732.456647] nfs41_handle_sequence_flag_errors: "fedora" (client ID f49be45401000000) flags=0x00000040
> [67732.457986] nfs41_handle_recallable_state_revoked: Recallable state revoked on server fedora!
> [67732.459215] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
> [67732.460350] nfs4_recovery_handle_error: handled error 0 for server fedora
> [67732.472138] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
> [67732.475707] nfs4_free_slot: slotid 1 highest_used_slotid 0
> [67732.476779] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> [67732.477917] nfs41_handle_sequence_flag_errors: "fedora" (client ID f49be45401000000) flags=0x00000040
> [67732.479294] nfs41_handle_recallable_state_revoked: Recallable state revoked on server fedora!
> [67732.480572] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
> [67732.481753] nfs4_recovery_handle_error: handled error 0 for server fedora
> [67732.493666] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
> [67732.497269] nfs4_free_slot: slotid 1 highest_used_slotid 0
> [67732.498402] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> [67732.499563] nfs41_handle_sequence_flag_errors: "fedora" (client ID f49be45401000000) flags=0x00000040
> [67732.500894] nfs41_handle_recallable_state_revoked: Recallable state revoked on server fedora!
> [67732.502159] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
>
> I think what's happening is that we never get to reclaim_lease() because
> NFS4CLNT_LEASE_EXPIRED is never flagged. Should we set
> NFS4CLNT_LEASE_EXPIRED in nfs41_handle_cb_path_down()? I think that would
> have avoided this.
I don't understand Why would the server reply NFS4ERR_OK to the
sequence operation if the lease has expired?
Right now, we assume that the server is doing the right thing w.r.t.
the lease, so instead, we call BIND_CONN_TO_SESSION with a request
that the fore and back channel be associated to this TCP connection.
--
Trond Myklebust
Linux NFS client maintainer, PrimaryData
trond.myklebust@primarydata.com
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: nfs4 state manager loop on recallable state revoked
2015-02-18 17:00 ` Trond Myklebust
@ 2015-02-18 19:28 ` Benjamin Coddington
2015-03-27 17:43 ` Benjamin Coddington
0 siblings, 1 reply; 4+ messages in thread
From: Benjamin Coddington @ 2015-02-18 19:28 UTC (permalink / raw)
To: Trond Myklebust; +Cc: Linux NFS Mailing List
[-- Attachment #1: Type: text/plain, Size: 15712 bytes --]
On Wed, 18 Feb 2015, Trond Myklebust wrote:
> On Wed, Feb 18, 2015 at 8:22 AM, Benjamin Coddington
> <bcodding@redhat.com> wrote:
> > While playing with callback channel failures, I noticed the state manager
> > get stuck looping trying to check a lease when the server responds with
> > SEQ4_STATUS_RECALLABLE_STATE_REVOKED set.
> >
> > Does this look familiar to anyone?
> >
> > [67732.348087] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
> > [67732.369726] nfs4_free_slot: slotid 2 highest_used_slotid 1
> > [67732.372881] nfs4_free_slot: slotid 0 highest_used_slotid 1
> > [67732.375337] nfs4_schedule_state_renewal: requeueing work. Lease period = 5
> > [67732.394736] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
> > [67732.401010] nfs4_free_slot: slotid 0 highest_used_slotid 1
> > [67732.402910] nfs4_free_slot: slotid 1 highest_used_slotid 4294967295
> > [67732.404659] nfs4_schedule_stateid_recovery: scheduling stateid recovery for server fedora
> > [67732.422848] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
> > [67732.426257] nfs4_free_slot: slotid 1 highest_used_slotid 0
> > [67732.427250] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> > [67732.428291] nfs41_handle_sequence_flag_errors: "fedora" (client ID f49be45401000000) flags=0x00000041
> > [67732.429596] nfs41_handle_recallable_state_revoked: Recallable state revoked on server fedora!
> > [67732.430746] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
> > [67732.431817] nfs4_recovery_handle_error: handled error 0 for server fedora
> > [67732.439132] nfs4_bind_conn_to_session: bind_conn_to_session was successful for server fedora!
> > [67732.451098] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
> > [67732.454522] nfs4_free_slot: slotid 1 highest_used_slotid 0
> > [67732.455557] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> > [67732.456647] nfs41_handle_sequence_flag_errors: "fedora" (client ID f49be45401000000) flags=0x00000040
> > [67732.457986] nfs41_handle_recallable_state_revoked: Recallable state revoked on server fedora!
> > [67732.459215] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
> > [67732.460350] nfs4_recovery_handle_error: handled error 0 for server fedora
> > [67732.472138] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
> > [67732.475707] nfs4_free_slot: slotid 1 highest_used_slotid 0
> > [67732.476779] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> > [67732.477917] nfs41_handle_sequence_flag_errors: "fedora" (client ID f49be45401000000) flags=0x00000040
> > [67732.479294] nfs41_handle_recallable_state_revoked: Recallable state revoked on server fedora!
> > [67732.480572] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
> > [67732.481753] nfs4_recovery_handle_error: handled error 0 for server fedora
> > [67732.493666] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
> > [67732.497269] nfs4_free_slot: slotid 1 highest_used_slotid 0
> > [67732.498402] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> > [67732.499563] nfs41_handle_sequence_flag_errors: "fedora" (client ID f49be45401000000) flags=0x00000040
> > [67732.500894] nfs41_handle_recallable_state_revoked: Recallable state revoked on server fedora!
> > [67732.502159] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
> >
> > I think what's happening is that we never get to reclaim_lease() because
> > NFS4CLNT_LEASE_EXPIRED is never flagged. Should we set
> > NFS4CLNT_LEASE_EXPIRED in nfs41_handle_cb_path_down()? I think that would
> > have avoided this.
>
> I don't understand Why would the server reply NFS4ERR_OK to the
> sequence operation if the lease has expired?
> Right now, we assume that the server is doing the right thing w.r.t.
> the lease, so instead, we call BIND_CONN_TO_SESSION with a request
> that the fore and back channel be associated to this TCP connection.
I may have oversimplified.. let me see if I can explain.
There's netfilter rules using ESTABLISHED,RELATED on the client, and I've
tuned down nf_conntrack's established and time_wait timeouts to 10 seconds.
echo 10 > /proc/sys/net/netfilter/nf_conntrack_tcp_timeout_established
echo 10 > /proc/sys/net/netfilter/nf_conntrack_tcp_timeout_time_wait
That causes netfilter to prune the connection tracking so that callbacks
fail if the client has been idle for 10 seconds or more. It also means that
as soon as the client transmits, the callback channel is "repaired".
So the client gets a delegation, and after 10 seconds the server tries to
call it back (because I wrote to the file), only to find the callback channel
is down.
Then, the client tries to renew the lease, and a retransmit of the callback
makes it through, but this is after the server has decided the callback
channel is down. This is the point where I get lost in the state manager
code.
I think that the client tries to recover the delegation, gets BAD_STATEID,
which should cause us to reclaim open state, eventually leading to freeing
of the stateid.. but that doesn't happen. I think because
NFS4CLNT_CHECK_LEASE is already set without NFS4CLNT_LEASE_EXPIRED, so we
cannot get to nfs4_do_reclaim(). Since the server never gets a
FREE_STATEID, it will always set SEQ4_STATUS_RECALLABLE_STATE_REVOKED.
Here's the network cap overview.. let me know if you'd like the whole thing.
The interesting bit is around frame 193.
156 137.857403000 10.0.1.82 -> 10.0.1.85 NFS 278 V4 Reply (Call In 153) EXCHANGE_ID
157 137.857506000 10.0.1.85 -> 10.0.1.82 TCP 66 895→2049 [ACK] Seq=405 Ack=241 Win=30336 Len=0 TSval=67302510 TSecr=11923
158 137.858980000 10.0.1.85 -> 10.0.1.82 NFS 338 V4 Call CREATE_SESSION
159 137.864535000 10.0.1.82 -> 10.0.1.85 NFS 150 V1 CB_NULL Call
160 137.864628000 10.0.1.85 -> 10.0.1.82 NFS 94 V1 CB_NULL Reply (Call In 159)
161 137.867513000 10.0.1.82 -> 10.0.1.85 NFS 262 V4 Reply (Call In 158) CREATE_SESSION
162 137.879044000 10.0.1.85 -> 10.0.1.82 NFS 262 V4 Call RECLAIM_COMPLETE
163 137.904896000 10.0.1.82 -> 10.0.1.85 NFS 226 V4 Reply (Call In 162) RECLAIM_COMPLETE
164 137.912835000 10.0.1.85 -> 10.0.1.82 NFS 222 V4 Call PUTROOTFH | GETATTR
165 137.927247000 10.0.1.82 -> 10.0.1.85 NFS 322 V4 Reply (Call In 164) PUTROOTFH | GETATTR
166 137.933836000 10.0.1.85 -> 10.0.1.82 NFS 226 V4 Call GETATTR FH: 0x62d40c52
167 137.945763000 10.0.1.82 -> 10.0.1.85 NFS 210 V4 Reply (Call In 166) GETATTR
168 137.952221000 10.0.1.85 -> 10.0.1.82 NFS 230 V4 Call GETATTR FH: 0x62d40c52
169 137.964209000 10.0.1.82 -> 10.0.1.85 NFS 222 V4 Reply (Call In 168) GETATTR
170 137.970844000 10.0.1.85 -> 10.0.1.82 NFS 226 V4 Call GETATTR FH: 0x62d40c52
171 137.982775000 10.0.1.82 -> 10.0.1.85 NFS 210 V4 Reply (Call In 170) GETATTR
172 137.989276000 10.0.1.85 -> 10.0.1.82 NFS 230 V4 Call GETATTR FH: 0x62d40c52
173 138.001042000 10.0.1.82 -> 10.0.1.85 NFS 222 V4 Reply (Call In 172) GETATTR
174 138.007406000 10.0.1.85 -> 10.0.1.82 NFS 226 V4 Call GETATTR FH: 0x62d40c52
175 138.019286000 10.0.1.82 -> 10.0.1.85 NFS 186 V4 Reply (Call In 174) GETATTR
176 138.025406000 10.0.1.85 -> 10.0.1.82 NFS 226 V4 Call GETATTR FH: 0x62d40c52
177 138.037430000 10.0.1.82 -> 10.0.1.85 NFS 210 V4 Reply (Call In 176) GETATTR
178 138.043344000 10.0.1.85 -> 10.0.1.82 NFS 234 V4 Call GETATTR FH: 0x62d40c52
179 138.055168000 10.0.1.82 -> 10.0.1.85 NFS 354 V4 Reply (Call In 178) GETATTR
180 138.061072000 10.0.1.85 -> 10.0.1.82 NFS 238 V4 Call ACCESS FH: 0x62d40c52, [Check: RD LU MD XT DL]
181 138.074921000 10.0.1.82 -> 10.0.1.85 NFS 238 V4 Reply (Call In 180) ACCESS, [Access Denied: MD XT DL], [Allowed: RD LU]
182 138.084987000 10.0.1.85 -> 10.0.1.82 NFS 230 V4 Call GETATTR FH: 0x62d40c52
183 138.098533000 10.0.1.82 -> 10.0.1.85 NFS 230 V4 Reply (Call In 182) GETATTR
184 138.105253000 10.0.1.85 -> 10.0.1.82 NFS 242 V4 Call ACCESS FH: 0x62d40c52, [Check: RD LU MD XT DL]
185 138.119543000 10.0.1.82 -> 10.0.1.85 NFS 238 V4 Reply (Call In 184) ACCESS, [Access Denied: MD XT DL], [Allowed: RD LU]
186 138.125581000 10.0.1.85 -> 10.0.1.82 NFS 258 V4 Call LOOKUP DH: 0x62d40c52/bcodding
187 138.142873000 10.0.1.82 -> 10.0.1.85 NFS 406 V4 Reply (Call In 186) LOOKUP
188 138.148820000 10.0.1.85 -> 10.0.1.82 NFS 250 V4 Call ACCESS FH: 0x5a3a896a, [Check: RD LU MD XT DL]
189 138.162711000 10.0.1.82 -> 10.0.1.85 NFS 238 V4 Reply (Call In 188) ACCESS, [Allowed: RD LU MD XT DL]
190 138.168768000 10.0.1.85 -> 10.0.1.82 NFS 326 V4 Call OPEN DH: 0x5a3a896a/foo
191 138.190654000 10.0.1.82 -> 10.0.1.85 NFS 514 V4 Reply (Call In 190) OPEN StateID: 0xf6b5
192 138.230847000 10.0.1.85 -> 10.0.1.82 TCP 66 895→2049 [ACK] Seq=3341 Ack=3557 Win=46464 Len=0 TSval=67302883 TSecr=12256
193 159.403954000 10.0.1.82 -> 10.0.1.85 NFS 250 V1 CB_COMPOUND Call <EMPTY> CB_SEQUENCE;CB_RECALL
194 159.404102000 10.0.1.85 -> 10.0.1.82 ICMP 278 Destination unreachable (Host administratively prohibited)
195 159.615010000 10.0.1.82 -> 10.0.1.85 NFS 250 [RPC retransmission of #193][TCP Retransmission] V1 CB_COMPOUND Call <EMPTY> CB_SEQUENCE;CB_RECALL
196 159.615217000 10.0.1.85 -> 10.0.1.82 ICMP 278 Destination unreachable (Host administratively prohibited)
197 159.826080000 10.0.1.82 -> 10.0.1.85 NFS 250 [RPC retransmission of #193][TCP Retransmission] V1 CB_COMPOUND Call <EMPTY> CB_SEQUENCE;CB_RECALL
198 159.826285000 10.0.1.85 -> 10.0.1.82 ICMP 278 Destination unreachable (Host administratively prohibited)
199 160.249069000 10.0.1.82 -> 10.0.1.85 NFS 250 [RPC retransmission of #193][TCP Retransmission] V1 CB_COMPOUND Call <EMPTY> CB_SEQUENCE;CB_RECALL
200 160.249304000 10.0.1.85 -> 10.0.1.82 ICMP 278 Destination unreachable (Host administratively prohibited)
201 161.094138000 10.0.1.82 -> 10.0.1.85 NFS 250 [RPC retransmission of #193][TCP Retransmission] V1 CB_COMPOUND Call <EMPTY> CB_SEQUENCE;CB_RECALL
202 161.094655000 10.0.1.85 -> 10.0.1.82 ICMP 278 Destination unreachable (Host administratively prohibited)
203 162.786081000 10.0.1.82 -> 10.0.1.85 NFS 250 [RPC retransmission of #193][TCP Retransmission] V1 CB_COMPOUND Call <EMPTY> CB_SEQUENCE;CB_RECALL
204 162.786329000 10.0.1.85 -> 10.0.1.82 ICMP 278 Destination unreachable (Host administratively prohibited)
205 166.174148000 10.0.1.82 -> 10.0.1.85 NFS 250 [RPC retransmission of #193][TCP Retransmission] V1 CB_COMPOUND Call <EMPTY> CB_SEQUENCE;CB_RECALL
206 166.174679000 10.0.1.85 -> 10.0.1.82 ICMP 278 Destination unreachable (Host administratively prohibited)
207 172.942070000 10.0.1.82 -> 10.0.1.85 NFS 250 [RPC retransmission of #193][TCP Retransmission] V1 CB_COMPOUND Call <EMPTY> CB_SEQUENCE;CB_RECALL
208 172.942310000 10.0.1.85 -> 10.0.1.82 ICMP 278 Destination unreachable (Host administratively prohibited)
209 186.478053000 10.0.1.82 -> 10.0.1.85 NFS 250 [RPC retransmission of #193][TCP Retransmission] V1 CB_COMPOUND Call <EMPTY> CB_SEQUENCE;CB_RECALL
210 186.478341000 10.0.1.85 -> 10.0.1.82 ICMP 278 Destination unreachable (Host administratively prohibited)
211 198.221376000 10.0.1.85 -> 10.0.1.82 TCP 66 [TCP Keep-Alive] 895→2049 [ACK] Seq=3340 Ack=3557 Win=46464 Len=0 TSval=67362844 TSecr=12256
212 198.221443000 10.0.1.82 -> 10.0.1.85 TCP 66 [TCP Keep-Alive ACK] 2049→895 [ACK] Seq=3741 Ack=3341 Win=47232 Len=0 TSval=72287 TSecr=67302883
213 198.341623000 10.0.1.85 -> 10.0.1.82 NFS 254 V4 Call SEQUENCE
214 198.381099000 10.0.1.82 -> 10.0.1.85 TCP 66 2049→895 [ACK] Seq=3741 Ack=3529 Win=48256 Len=0 TSval=72447 TSecr=67362964
215 213.550073000 10.0.1.82 -> 10.0.1.85 NFS 250 [RPC retransmission of #193][TCP Retransmission] V1 CB_COMPOUND Call <EMPTY> CB_SEQUENCE;CB_RECALL
216 213.550305000 10.0.1.85 -> 10.0.1.82 ICMP 278 Destination unreachable (Host administratively prohibited)
217 258.410816000 10.0.1.85 -> 10.0.1.82 TCP 66 [TCP Keep-Alive] 895→2049 [ACK] Seq=3528 Ack=3557 Win=46464 Len=0 TSval=67423004 TSecr=12256
218 258.410899000 10.0.1.82 -> 10.0.1.85 TCP 66 [TCP Keep-Alive ACK] 2049→895 [ACK] Seq=3741 Ack=3529 Win=48256 Len=0 TSval=132476 TSecr=67362964
219 263.422122000 RealtekU_30:a6:48 -> RealtekU_f2:45:f7 ARP 42 Who has 10.0.1.85? Tell 10.0.1.82
220 263.422560000 RealtekU_f2:45:f7 -> RealtekU_30:a6:48 ARP 42 10.0.1.85 is at 52:54:00:f2:45:f7
221 267.758096000 10.0.1.82 -> 10.0.1.85 NFS 250 [RPC retransmission of #193][TCP Retransmission] V1 CB_COMPOUND Call <EMPTY> CB_SEQUENCE;CB_RECALL
222 267.758576000 10.0.1.85 -> 10.0.1.82 TCP 66 895→2049 [ACK] Seq=3529 Ack=3741 Win=47488 Len=0 TSval=67432347 TSecr=141824
223 267.758646000 10.0.1.82 -> 10.0.1.85 NFS 218 V4 Reply (Call In 213) SEQUENCE
224 267.758740000 10.0.1.85 -> 10.0.1.82 NFS 154 V1 CB_COMPOUND Reply (Call In 193) <EMPTY> CB_SEQUENCE;CB_RECALL
225 267.758762000 10.0.1.82 -> 10.0.1.85 TCP 66 2049→895 [ACK] Seq=3893 Ack=3617 Win=48256 Len=0 TSval=141824 TSecr=67432347
226 267.774018000 10.0.1.85 -> 10.0.1.82 NFS 322 V4 Call OPEN DH: 0x2aa3b5f8/
227 267.774075000 10.0.1.82 -> 10.0.1.85 TCP 66 2049→895 [ACK] Seq=3893 Ack=3873 Win=49408 Len=0 TSval=141840 TSecr=67432361
228 267.805457000 10.0.1.82 -> 10.0.1.85 NFS 166 V4 Reply (Call In 226) OPEN Status: NFS4ERR_BAD_STATEID
229 267.821189000 10.0.1.85 -> 10.0.1.82 NFS 254 V4 Call SEQUENCE
230 267.833606000 10.0.1.82 -> 10.0.1.85 NFS 218 V4 Reply (Call In 229) SEQUENCE
231 267.844159000 10.0.1.85 -> 10.0.1.82 NFS 246 V4 Call BIND_CONN_TO_SESSION
232 267.846580000 10.0.1.82 -> 10.0.1.85 NFS 150 V1 CB_NULL Call
233 267.848899000 10.0.1.85 -> 10.0.1.82 NFS 94 V1 CB_NULL Reply (Call In 232)
234 267.849888000 10.0.1.82 -> 10.0.1.85 NFS 206 V4 Reply (Call In 231) BIND_CONN_TO_SESSION
235 267.853635000 10.0.1.85 -> 10.0.1.82 NFS 254 V4 Call SEQUENCE
236 267.861895000 10.0.1.82 -> 10.0.1.85 NFS 218 V4 Reply (Call In 235) SEQUENCE
237 267.874848000 10.0.1.85 -> 10.0.1.82 NFS 254 V4 Call SEQUENCE
238 267.882922000 10.0.1.82 -> 10.0.1.85 NFS 218 V4 Reply (Call In 237) SEQUENCE
239 267.896322000 10.0.1.85 -> 10.0.1.82 NFS 254 V4 Call SEQUENCE
240 267.904455000 10.0.1.82 -> 10.0.1.85 NFS 218 V4 Reply (Call In 239) SEQUENCE
241 267.918109000 10.0.1.85 -> 10.0.1.82 NFS 254 V4 Call SEQUENCE
242 267.926220000 10.0.1.82 -> 10.0.1.85 NFS 218 V4 Reply (Call In 241) SEQUENCE
243 267.940334000 10.0.1.85 -> 10.0.1.82 NFS 254 V4 Call SEQUENCE
244 267.948684000 10.0.1.82 -> 10.0.1.85 NFS 218 V4 Reply (Call In 243) SEQUENCE
245 267.962701000 10.0.1.85 -> 10.0.1.82 NFS 254 V4 Call SEQUENCE
246 267.970790000 10.0.1.82 -> 10.0.1.85 NFS 218 V4 Reply (Call In 245) SEQUENCE
247 267.984855000 10.0.1.85 -> 10.0.1.82 NFS 254 V4 Call SEQUENCE
248 267.992957000 10.0.1.82 -> 10.0.1.85 NFS 218 V4 Reply (Call In 247) SEQUENCE
249 268.006746000 10.0.1.85 -> 10.0.1.82 NFS 254 V4 Call SEQUENCE
250 268.014828000 10.0.1.82 -> 10.0.1.85 NFS 218 V4 Reply (Call In 249) SEQUENCE
251 268.028895000 10.0.1.85 -> 10.0.1.82 NFS 254 V4 Call SEQUENCE
252 268.037021000 10.0.1.82 -> 10.0.1.85 NFS 218 V4 Reply (Call In 251) SEQUENCE
253 268.052380000 10.0.1.85 -> 10.0.1.82 NFS 254 V4 Call SEQUENCE
254 268.060971000 10.0.1.82 -> 10.0.1.85 NFS 218 V4 Reply (Call In 253) SEQUENCE
...
Ben
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: nfs4 state manager loop on recallable state revoked
2015-02-18 19:28 ` Benjamin Coddington
@ 2015-03-27 17:43 ` Benjamin Coddington
0 siblings, 0 replies; 4+ messages in thread
From: Benjamin Coddington @ 2015-03-27 17:43 UTC (permalink / raw)
To: Trond Myklebust; +Cc: Linux NFS Mailing List
On Wed, 18 Feb 2015, Benjamin Coddington wrote:
> On Wed, 18 Feb 2015, Trond Myklebust wrote:
> > On Wed, Feb 18, 2015 at 8:22 AM, Benjamin Coddington
> > <bcodding@redhat.com> wrote:
> > > While playing with callback channel failures, I noticed the state manager
> > > get stuck looping trying to check a lease when the server responds with
> > > SEQ4_STATUS_RECALLABLE_STATE_REVOKED set.
> > >
> > > Does this look familiar to anyone?
> > >
> > > [67732.348087] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
> > > [67732.369726] nfs4_free_slot: slotid 2 highest_used_slotid 1
> > > [67732.372881] nfs4_free_slot: slotid 0 highest_used_slotid 1
> > > [67732.375337] nfs4_schedule_state_renewal: requeueing work. Lease period = 5
> > > [67732.394736] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
> > > [67732.401010] nfs4_free_slot: slotid 0 highest_used_slotid 1
> > > [67732.402910] nfs4_free_slot: slotid 1 highest_used_slotid 4294967295
> > > [67732.404659] nfs4_schedule_stateid_recovery: scheduling stateid recovery for server fedora
> > > [67732.422848] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
> > > [67732.426257] nfs4_free_slot: slotid 1 highest_used_slotid 0
> > > [67732.427250] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> > > [67732.428291] nfs41_handle_sequence_flag_errors: "fedora" (client ID f49be45401000000) flags=0x00000041
> > > [67732.429596] nfs41_handle_recallable_state_revoked: Recallable state revoked on server fedora!
> > > [67732.430746] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
> > > [67732.431817] nfs4_recovery_handle_error: handled error 0 for server fedora
> > > [67732.439132] nfs4_bind_conn_to_session: bind_conn_to_session was successful for server fedora!
> > > [67732.451098] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
> > > [67732.454522] nfs4_free_slot: slotid 1 highest_used_slotid 0
> > > [67732.455557] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> > > [67732.456647] nfs41_handle_sequence_flag_errors: "fedora" (client ID f49be45401000000) flags=0x00000040
> > > [67732.457986] nfs41_handle_recallable_state_revoked: Recallable state revoked on server fedora!
> > > [67732.459215] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
> > > [67732.460350] nfs4_recovery_handle_error: handled error 0 for server fedora
> > > [67732.472138] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
> > > [67732.475707] nfs4_free_slot: slotid 1 highest_used_slotid 0
> > > [67732.476779] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> > > [67732.477917] nfs41_handle_sequence_flag_errors: "fedora" (client ID f49be45401000000) flags=0x00000040
> > > [67732.479294] nfs41_handle_recallable_state_revoked: Recallable state revoked on server fedora!
> > > [67732.480572] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
> > > [67732.481753] nfs4_recovery_handle_error: handled error 0 for server fedora
> > > [67732.493666] nfs4_schedule_lease_recovery: scheduling lease recovery for server fedora
> > > [67732.497269] nfs4_free_slot: slotid 1 highest_used_slotid 0
> > > [67732.498402] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
> > > [67732.499563] nfs41_handle_sequence_flag_errors: "fedora" (client ID f49be45401000000) flags=0x00000040
> > > [67732.500894] nfs41_handle_recallable_state_revoked: Recallable state revoked on server fedora!
> > > [67732.502159] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
> > >
> > > I think what's happening is that we never get to reclaim_lease() because
> > > NFS4CLNT_LEASE_EXPIRED is never flagged. Should we set
> > > NFS4CLNT_LEASE_EXPIRED in nfs41_handle_cb_path_down()? I think that would
> > > have avoided this.
> >
> > I don't understand Why would the server reply NFS4ERR_OK to the
> > sequence operation if the lease has expired?
> > Right now, we assume that the server is doing the right thing w.r.t.
> > the lease, so instead, we call BIND_CONN_TO_SESSION with a request
> > that the fore and back channel be associated to this TCP connection.
>
> I may have oversimplified.. let me see if I can explain.
>
> There's netfilter rules using ESTABLISHED,RELATED on the client, and I've
> tuned down nf_conntrack's established and time_wait timeouts to 10 seconds.
>
> echo 10 > /proc/sys/net/netfilter/nf_conntrack_tcp_timeout_established
> echo 10 > /proc/sys/net/netfilter/nf_conntrack_tcp_timeout_time_wait
>
> That causes netfilter to prune the connection tracking so that callbacks
> fail if the client has been idle for 10 seconds or more. It also means that
> as soon as the client transmits, the callback channel is "repaired".
>
> So the client gets a delegation, and after 10 seconds the server tries to
> call it back (because I wrote to the file), only to find the callback channel
> is down.
>
> Then, the client tries to renew the lease, and a retransmit of the callback
> makes it through, but this is after the server has decided the callback
> channel is down. This is the point where I get lost in the state manager
> code.
>
> I think that the client tries to recover the delegation, gets BAD_STATEID,
> which should cause us to reclaim open state, eventually leading to freeing
> of the stateid.. but that doesn't happen. I think because
> NFS4CLNT_CHECK_LEASE is already set without NFS4CLNT_LEASE_EXPIRED, so we
> cannot get to nfs4_do_reclaim(). Since the server never gets a
> FREE_STATEID, it will always set SEQ4_STATUS_RECALLABLE_STATE_REVOKED.
>
> Here's the network cap overview.. let me know if you'd like the whole thing.
> The interesting bit is around frame 193.
Hi Trond,
b04b22f NFSv4: Ensure that we don't reap a delegation that is being returned
ade0464 NFSv4: Ensure we honour NFS_DELEGATION_RETURNING in nfs_inode_set_delegation()
9f0f8e1 NFSv4: Pin the superblock while we're returning the delegation
ec3ca4e NFSv4: Ensure we skip delegations that are already being returned
These fix things up so that it seems I can no longer reproduce this problem. Thanks!
Ben
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2015-03-27 17:43 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2015-02-18 16:22 nfs4 state manager loop on recallable state revoked Benjamin Coddington
2015-02-18 17:00 ` Trond Myklebust
2015-02-18 19:28 ` Benjamin Coddington
2015-03-27 17:43 ` Benjamin Coddington
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.