So, NFS4ERR_OLD_STATEID can only happen in one circumstance: when the
State presented by the client doesn't match the State that Ganesha
expects. In this case, it's the sequence number that's off-by-one.
This could be the result of a replay, but the code checks for this, and
the owners must be different in this case.
So, what seams to have happened is that the old state was destroyed, and
a new owner got a new state, and then the client presented the old state
again.
I'm not an expert in this code, so maybe I'm missing something?
(Note, the code is the same in 2.7, so no bugs have been fixed in this code)
Daniel
On 04/09/2018 05:09 AM, Sachin Punadikar wrote:
Hi All,
As reported by customer, NFSv4 client, if left open the session
overnight, gets nothing for command "pwd". Customer is rebooting the
client to overcome this issue in the next morning.
Is this expected to happen ? If not is it related to any configuration
setting ? Ganesha bug / Client bug ?
This is related to Ganesha 2.3. The related logs indicates
error NFS4ERR_OLD_STATEID. Below is the FULL_DEBUG log:
-------------------------
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] nfs4_Compound :NFS4 :DEBUG :Request 1:
opcode 25 is OP_READ
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] nfs4_Compound :NFS4 :M_DBG :NFS4: MID DEBUG:
Check export perms export = 000000f0 req = 00000010
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] nfs4_Is_Fh_Invalid :FH :F_DBG :NFS4 Handle
(53:0x430008003030000a00010028000a8026ca59d277870200000200000000d7b3f9000000000000000000f6a7110ade46010000000000)
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] nfs4_Is_Fh_Invalid :FH :F_DBG :NFS4 Handle
0x0 export id 8
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] nfs4_Check_Stateid :STATE :F_DBG :Check READ
stateid flags ALL_0 ALL_1 CURRENT
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] state_id_value_hash_func :STATE :F_DBG :val = 4
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] state_id_rbt_hash_func :STATE :F_DBG :rbt =
328053
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] hashtable_getlatch :RW LOCK :F_DBG :Got
write lock on 0xaf11a8 (&(ht->partitions[index].lock)) at
/home/ppsbld/ttn423.171127.111356/ttn423.ganesha-rpmdir/BUILD/nfs-ganesha-2.3.2-ibm53-0.1.1-Source/hashtable/hashtable.c:477
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] key_locate :HT CACHE :F_DBG :hash hit index
4 slot 383
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] compare_state_id :STATE :F_DBG
:{OTHER=0x0100000087000500f2010000 {{CLIENTID Epoch=0x00050087
Counter=0x00000001} StateIdCounter=0x000001f2}} vs
{OTHER=0x0100000087000500f2010000 {{CLIENTID Epoch=0x00050087
Counter=0x00000001} StateIdCounter=0x000001f2}}
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] display_stateid :RW LOCK :F_DBG :Acquired
mutex 0x7f33fc002330 (&state->state_mutex) at
/home/ppsbld/ttn423.171127.111356/ttn423.ganesha-rpmdir/BUILD/nfs-ganesha-2.3.2-ibm53-0.1.1-Source/SAL/nfs4_state_id.c:190
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] display_stateid :RW LOCK :F_DBG :Released
mutex 0x7f33fc002330 (&state->state_mutex) at
/home/ppsbld/ttn423.171127.111356/ttn423.ganesha-rpmdir/BUILD/nfs-ganesha-2.3.2-ibm53-0.1.1-Source/SAL/nfs4_state_id.c:192
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] hashtable_getlatch :STATE :F_DBG :Get (null)
returning Value=0x7f33fc002300 {STATE 0x7f33fc002300
OTHER=0x0100000087000500f2010000 {{CLIENTID Epoch=0x00050087
Counter=0x00000001} StateIdCounter=0x000001f2} entry=0x7f343c001280
type=SHARE seqid=2 owner={STATE_OPEN_OWNER_NFSV4 0x7f34200012d0:
clientid={0x7f3428000cb0 ClientID={Epoch=0x00050087 Counter=0x00000001}
CONFIRMED Client={0x7f3428000bb0 name=(44:Linux NFSv4.0 x.x.x.x/x.x.x.x
tcp) refcount=1} t_delta=0 reservations=0 refcount=13 cb_prog=1073741824
r_addr=x.x.x.x.x.x r_netid=tcp}
owner=(24:0x6f70656e2069643a0000002e0000000000028f32d4178918)
confirmed=1 seqid=470159 refcount=37} refccount=1}
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] hashtable_releaselatched :RW LOCK :F_DBG
:Unlocked 0xaf11a8 (&ht->partitions[latch->index].lock) at
/home/ppsbld/ttn423.171127.111356/ttn423.ganesha-rpmdir/BUILD/nfs-ganesha-2.3.2-ibm53-0.1.1-Source/hashtable/hashtable.c:543
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] get_state_entry_export_owner_refs :RW LOCK
:F_DBG :Acquired mutex 0x7f33fc002330 (&state->state_mutex) at
/home/ppsbld/ttn423.171127.111356/ttn423.ganesha-rpmdir/BUILD/nfs-ganesha-2.3.2-ibm53-0.1.1-Source/SAL/nfs4_state.c:538
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] get_state_entry_export_owner_refs :STATE
:F_DBG :state 0x7f33fc002300 state_entry 0x7f343c001280 state_export
0xab7b18 state_owner 0x7f34200012d0
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] cache_inode_lru_ref :RW LOCK :F_DBG
:Acquired mutex 0x7fc880 (&(qlane)->mtx) at
/home/ppsbld/ttn423.171127.111356/ttn423.ganesha-rpmdir/BUILD/nfs-ganesha-2.3.2-ibm53-0.1.1-Source/cache_inode/cache_inode_lru.c:1375
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] cache_inode_lru_ref :RW LOCK :F_DBG
:Released mutex 0x7fc880 (&(qlane)->mtx) at
/home/ppsbld/ttn423.171127.111356/ttn423.ganesha-rpmdir/BUILD/nfs-ganesha-2.3.2-ibm53-0.1.1-Source/cache_inode/cache_inode_lru.c:1380
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] inc_state_owner_ref :STATE :F_DBG :Increment
refcount now=38 {STATE_OPEN_OWNER_NFSV4 0x7f34200012d0:
clientid={0x7f3428000cb0 ClientID={Epoch=0x00050087 Counter=0x00000001}
CONFIRMED Client={0x7f3428000bb0 name=(44:Linux NFSv4.0 x.x.x.x/x.x.x.x
tcp) refcount=1} t_delta=0 reservations=0 refcount=13 cb_prog=1073741824
r_addr=x.x.x.x.x.x r_netid=tcp}
owner=(24:0x6f70656e2069643a0000002e0000000000028f32d4178918)
confirmed=1 seqid=470159 refcount=37}
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] get_state_entry_export_owner_refs :RW LOCK
:F_DBG :Released mutex 0x7f33fc002330 (&state->state_mutex) at
/home/ppsbld/ttn423.171127.111356/ttn423.ganesha-rpmdir/BUILD/nfs-ganesha-2.3.2-ibm53-0.1.1-Source/SAL/nfs4_state.c:572
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] nfs4_Check_Stateid :RW LOCK :F_DBG :Acquired
mutex 0x7f3428000d40
(&owner2->so_owner.so_nfs4_owner.so_clientrec->cid_mutex) at
/home/ppsbld/ttn423.171127.111356/ttn423.ganesha-rpmdir/BUILD/nfs-ganesha-2.3.2-ibm53-0.1.1-Source/SAL/nfs4_state_id.c:1030
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] reserve_lease :CLIENT ID :F_DBG :Reserve
Lease 0x7f3428000cb0 ClientID={Epoch=0x00050087 Counter=0x00000001}
CONFIRMED Client={0x7f3428000bb0 name=(44:Linux NFSv4.0 X.X.X.X/X.X.X.X
tcp) refcount=1} t_delta=0 reservations=1 refcount=13 cb_prog=1073741824
r_addr=X.X.X.X.X.X r_netid=tcp (Valid=YES 60 seconds left)
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] nfs4_Check_Stateid :RW LOCK :F_DBG :Released
mutex 0x7f3428000d40
(&owner2->so_owner.so_nfs4_owner.so_clientrec->cid_mutex) at
/home/ppsbld/ttn423.171127.111356/ttn423.ganesha-rpmdir/BUILD/nfs-ganesha-2.3.2-ibm53-0.1.1-Source/SAL/nfs4_state_id.c:1047
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] nfs4_Check_Stateid :STATE :DEBUG :Check READ
stateid found OLD stateid OTHER=0x0100000087000500f2010000 {{CLIENTID
Epoch=0x00050087 Counter=0x00000001} StateIdCounter=0x000001f2} seqid=1,
expected seqid 2
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] display_stateid :RW LOCK :F_DBG :Acquired
mutex 0x7f33fc002330 (&state->state_mutex) at
/home/ppsbld/ttn423.171127.111356/ttn423.ganesha-rpmdir/BUILD/nfs-ganesha-2.3.2-ibm53-0.1.1-Source/SAL/nfs4_state_id.c:190
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] display_stateid :RW LOCK :F_DBG :Released
mutex 0x7f33fc002330 (&state->state_mutex) at
/home/ppsbld/ttn423.171127.111356/ttn423.ganesha-rpmdir/BUILD/nfs-ganesha-2.3.2-ibm53-0.1.1-Source/SAL/nfs4_state_id.c:192
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] dec_nfs4_state_ref :STATE :F_DBG :Decrement
refcount now=1 {STATE 0x7f33fc002300 OTHER=0x0100000087000500f2010000
{{CLIENTID Epoch=0x00050087 Counter=0x00000001}
StateIdCounter=0x000001f2} entry=0x7f343c001280 type=SHARE seqid=2
owner={STATE_OPEN_OWNER_NFSV4 0x7f34200012d0: clientid={0x7f3428000cb0
ClientID={Epoch=0x00050087 Counter=0x00000001} CONFIRMED
Client={0x7f3428000bb0 name=(44:Linux NFSv4.0 X.X.X.X/X.X.X.X tcp)
refcount=1} t_delta=0 reservations=1 refcount=13 cb_prog=1073741824
r_addr=X.X.X.X.X.X r_netid=tcp}
owner=(24:0x6f70656e2069643a0000002e0000000000028f32d4178918)
confirmed=1 seqid=470159 refcount=38} refccount=2}
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] cache_inode_lru_unref :RW LOCK :F_DBG
:Acquired mutex 0x7fc880 (&(qlane)->mtx) at
/home/ppsbld/ttn423.171127.111356/ttn423.ganesha-rpmdir/BUILD/nfs-ganesha-2.3.2-ibm53-0.1.1-Source/cache_inode/cache_inode_lru.c:1459
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] cache_inode_lru_unref :RW LOCK :F_DBG
:Released mutex 0x7fc880 (&(qlane)->mtx) at
/home/ppsbld/ttn423.171127.111356/ttn423.ganesha-rpmdir/BUILD/nfs-ganesha-2.3.2-ibm53-0.1.1-Source/cache_inode/cache_inode_lru.c:1465
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] dec_state_owner_ref :STATE :F_DBG :Decrement
refcount now=37 {STATE_OPEN_OWNER_NFSV4 0x7f34200012d0:
clientid={0x7f3428000cb0 ClientID={Epoch=0x00050087 Counter=0x00000001}
CONFIRMED Client={0x7f3428000bb0 name=(44:Linux NFSv4.0 X.X.X.X/X.X.X.X
tcp) refcount=1} t_delta=0 reservations=1 refcount=13 cb_prog=1073741824
r_addr=10.128.48.24.132.47 r_netid=tcp}
owner=(24:0x6f70656e2069643a0000002e0000000000028f32d4178918)
confirmed=1 seqid=470159 refcount=38}
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] LogCompoundFH :FH :F_DBG :Current FH File
Handle V4: Len=53
430008003030000a00010028000a8026ca59d277870200000200000000d7b3f9000000000000000000f6a7110ade46010000000000
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] LogCompoundFH :FH :F_DBG :Saved FH File
Handle V4: Len=0 <null>
2018-03-13 14:37:28 : epoch 00050087 : nfs02 :
ganesha.nfsd-10335[work-77] nfs4_Compound :NFS4 :DEBUG :Status of
OP_READ in position 1 = NFS4ERR_OLD_STATEID
-------------------------
--
with regards,
Sachin Punadikar
------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
_______________________________________________
Nfs-ganesha-devel mailing list
Nfs-ganesha-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/nfs-ganesha-devel
------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
_______________________________________________
Nfs-ganesha-devel mailing list
Nfs-ganesha-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/nfs-ganesha-devel
