Re: [Nfs-ganesha-devel] Ganesh 2.3 : NFSv4 client gets error NFS4ERR_OLD_STATEID

2018-04-10 Thread Jeff Layton 
On Mon, 2018-04-09 at 10:26 -0400, Daniel Gryniewicz wrote:
> 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


More or less.

A stateid represents the open/lock/delegation/layout state of a
filehandle at a particular point in time. The sequence ID is how we
distinguish the period of time for that state.

In this case, the client presented a stateid that was older than the one
the server had. So we have a situation where the server's idea of the
state of the file is newer than the client's.

A single OLD_STATEID error is generally not a problem, and usually
indicates a benign race between an OPEN/LOCK and a READ/WRITE. Once the
client gets the new stateid, things should start chugging along again.
If it keeps going then that usually means that the client didn't get the
new stateid for some reason.

A wire capture of the event would be ideal, if only to narrow down
whether the server sent the wrong seqid here or the client ignored it
for some reason. Testing more recent ganesha code might also be helpful
if that's an option.

Good luck!
-- 
Jeff Layton 

--
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

Re: [Nfs-ganesha-devel] Ganesh 2.3 : NFSv4 client gets error NFS4ERR_OLD_STATEID

2018-04-09 Thread Daniel Gryniewicz 
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 = 00f0 req = 0010
2018-03-13 14:37:28 : epoch 00050087 : nfs02 : 
ganesha.nfsd-10335[work-77] nfs4_Is_Fh_Invalid :FH :F_DBG :NFS4 Handle 
(53:0x43000800303a00010028000a8026ca59d277870202d7b3f900f6a7110ade460100)
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=0x010087000500f201 {{CLIENTID Epoch=0x00050087 
Counter=0x0001} StateIdCounter=0x01f2}} vs 
{OTHER=0x010087000500f201 {{CLIENTID Epoch=0x00050087 
Counter=0x0001} StateIdCounter=0x01f2}}
2018-03-13 14:37:28 : epoch 00050087 : nfs02 : 
ganesha.nfsd-10335[work-77] display_stateid :RW LOCK :F_DBG :Acquired 
mutex 0x7f33fc002330 (>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_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=0x010087000500f201 {{CLIENTID Epoch=0x00050087 
Counter=0x0001} StateIdCounter=0x01f2} entry=0x7f343c001280 
type=SHARE seqid=2 owner={STATE_OPEN_OWNER_NFSV4 0x7f34200012d0: 
clientid={0x7f3428000cb0 ClientID={Epoch=0x00050087 Counter=0x0001} 
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:0x6f70656e2069643a002e00028f32d4178918) 
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 (>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_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

[Nfs-ganesha-devel] Ganesh 2.3 : NFSv4 client gets error NFS4ERR_OLD_STATEID

2018-04-09 Thread Sachin Punadikar 
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 =
00f0 req = 0010
2018-03-13 14:37:28 : epoch 00050087 : nfs02 : ganesha.nfsd-10335[work-77]
nfs4_Is_Fh_Invalid :FH :F_DBG :NFS4 Handle
(53:0x43000800303a00010028000a8026ca59d277870202d7b3f900f6a7110ade460100)
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=0x010087000500f201
{{CLIENTID Epoch=0x00050087 Counter=0x0001} StateIdCounter=0x01f2}}
vs {OTHER=0x010087000500f201 {{CLIENTID Epoch=0x00050087
Counter=0x0001} StateIdCounter=0x01f2}}
2018-03-13 14:37:28 : epoch 00050087 : nfs02 : ganesha.nfsd-10335[work-77]
display_stateid :RW LOCK :F_DBG :Acquired mutex 0x7f33fc002330
(>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_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=0x010087000500f201 {{CLIENTID
Epoch=0x00050087 Counter=0x0001} StateIdCounter=0x01f2}
entry=0x7f343c001280 type=SHARE seqid=2 owner={STATE_OPEN_OWNER_NFSV4
0x7f34200012d0: clientid={0x7f3428000cb0 ClientID={Epoch=0x00050087
Counter=0x0001} 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:0x6f70656e2069643a002e00028f32d4178918) 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
(>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_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 :