12:02 a.m.
+ Frank
From: Sriram Patil <sriramp(a)vmware.com>
Date: Friday, May 24, 2019 at 10:32 AM
To: "devel(a)lists.nfs-ganesha.org" <devel(a)lists.nfs-ganesha.org>
Cc: "Frank Filz (GerritHub)" <gerrit(a)gerrithub.io>,
"dang(a)redhat.com" <dang(a)redhat.com>
Subject: Re: Seeing out of order logs
CCing Frank and Daniel because I don’t see the email on the mailing list.
- Sriram
From: Sriram Patil <sriramp(a)vmware.com>
Date: Friday, May 24, 2019 at 1:00 AM
To: "devel(a)lists.nfs-ganesha.org" <devel(a)lists.nfs-ganesha.org>
Subject: Seeing out of order logs
Hi,
I am observing a weird out of order logs. As seen from the logs below, for threads svc_5,
svc_7 and svc_14, only the first log messages appears with a timestamp which is about 2
minutes old. When those threads are actually processing the compound operations, the
timestamp seems fine. In fact the timestamps for for the reaper thread after svc_5 are
also out of order. I am using v2.7.2. Is there any known scenario when we can get these
out of order logs?
The following log is continuous, I have added blanks lines in between so that they are a
bit easier to read.
2019-05-22T20:19:02Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[none] [svc_5] 1332
:nfs_rpc_decode_request :DISP :0x7fa674000a90 fd 21 context 0x7fa670001ac0
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[::ffff:10.192.78.96]
[svc_5] 839 :nfs_rpc_process_request :DISP :Request from ::ffff:10.192.78.96 for Program
100003, Version 4, Function 1 has xid=3831317466
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[::ffff:10.192.78.96]
[svc_5] 687 :nfs4_Compound :NFS4 :COMPOUND: There are 3 operations, res = 0x7fa670001f70,
tag = NO TAG
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[::ffff:10.192.78.96]
[svc_5] 798 :nfs4_Compound :NFS4 :Request 0: opcode 53 is OP_SEQUENCE
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[::ffff:10.192.78.96]
[svc_5] 81 :nfs4_op_sequence :SESSIONS :SEQUENCE session=0x7fa670049dd0
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[::ffff:10.192.78.96]
[svc_5] 93 :nfs4_op_sequence :SESSIONS :SESSIONS: DEBUG: SEQUENCE returning status
NFS4ERR_EXPIRED
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[::ffff:10.192.78.96]
[svc_5] 977 :nfs4_Compound :NFS4 :Status of OP_SEQUENCE in position 0 = NFS4ERR_EXPIRED,
op response size is 4 total response size is 40
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[::ffff:10.192.78.96]
[svc_5] 1107 :nfs4_Compound :NFS4 :End status = NFS4ERR_EXPIRED lastindex = 0
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[none] [svc_5] 1381
:nfs_rpc_decode_request :DISP :SVC_DECODE on 0x7fa674000a90 fd 21
(::ffff:10.192.78.96:1013) xid=3831317466 returned XPRT_IDLE
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[none] [svc_5] 1294
:free_nfs_request :DISP :free_nfs_request: 0x7fa674000a90 fd 21 xp_refcnt 6 rq_refcnt 0
2019-05-22T20:19:08Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[none] [reaper] 219
:reaper_run :CLIENT ID :Now checking NFS4 clients for expiration2019-05-22T20:21:01Z :
epoch 5ce5ab1d : localhost : ganesha.nfsd-38[none] [reaper] 906 :nfs_client_id_expire
:CLIENT ID :Expiring {0x7fa664004c10 ClientID={Epoch=0x5ce5ab1d Counter=0x00000003}
CONFIRMED Client={0x7fa6700019d0 name=(27:Linux NFSv4.1 h10-192-78-96) refcount=2}
t_delta=124 reservations=0 refcount=3}
2019-05-22T20:19:16Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[none] [svc_7] 1332
:nfs_rpc_decode_request :DISP :0x7fa664000b20 fd 31 context 0x7fa6680082e0 <---
XXX
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[::ffff:10.192.73.159]
[svc_7] 839 :nfs_rpc_process_request :DISP :Request from ::ffff:10.192.73.159 for Program
100003, Version 4, Function 1 has xid=1048477897
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[::ffff:10.192.73.159]
[svc_7] 687 :nfs4_Compound :NFS4 :COMPOUND: There are 1 operations, res = 0x7fa668008da0,
tag = NO TAG
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[::ffff:10.192.73.159]
[svc_7] 798 :nfs4_Compound :NFS4 :Request 0: opcode 53 is OP_SEQUENCE
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[::ffff:10.192.73.159]
[svc_7] 81 :nfs4_op_sequence :SESSIONS :SEQUENCE session=0x7fa664001ca0
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[::ffff:10.192.73.159]
[svc_7] 977 :nfs4_Compound :NFS4 :Status of OP_SEQUENCE in position 0 = NFS4_OK, op
response size is 40 total response size is 76
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[none] [svc_7] 1381
:nfs_rpc_decode_request :DISP :SVC_DECODE on 0x7fa664000b20 fd 31
(::ffff:10.192.73.159:908) xid=1048477897 returned XPRT_IDLE
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[none] [svc_7] 1294
:free_nfs_request :DISP :free_nfs_request: 0x7fa664000b20 fd 31 xp_refcnt 11 rq_refcnt 0
2019-05-22T20:19:17Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[none] [svc_14] 1332
:nfs_rpc_decode_request :DISP :0x7fa674000a90 fd 21 context 0x7fa64403a150 <---
XXX
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[::ffff:10.192.78.96]
[svc_14] 839 :nfs_rpc_process_request :DISP :Request from ::ffff:10.192.78.96 for Program
100003, Version 4, Function 1 has xid=3848094682
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[::ffff:10.192.78.96]
[svc_14] 687 :nfs4_Compound :NFS4 :COMPOUND: There are 1 operations, res = 0x7fa64403ab90,
tag = NO TAG
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[::ffff:10.192.78.96]
[svc_14] 798 :nfs4_Compound :NFS4 :Request 0: opcode 53 is OP_SEQUENCE
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[::ffff:10.192.78.96]
[svc_14] 74 :nfs4_op_sequence :SESSIONS :SESSIONS: DEBUG: SEQUENCE returning status
NFS4ERR_BADSESSION
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[::ffff:10.192.78.96]
[svc_14] 977 :nfs4_Compound :NFS4 :Status of OP_SEQUENCE in position 0 =
NFS4ERR_BADSESSION, op response size is 4 total response size is 40
2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost : ganesha.nfsd-38[::ffff:10.192.78.96]
[svc_14] 1107 :nfs4_Compound :NFS4 :End status = NFS4ERR_BADSESSION lastindex = 0
Thanks,
Sriram