+ Frank
From: Sriram Patil <sriramp@vmware.com>
Date: Friday, May 24, 2019 at 10:32 AM
To: "devel@lists.nfs-ganesha.org" <devel@lists.nfs-ganesha.org>
Cc: "Frank Filz (GerritHub)" <gerrit@gerrithub.io>, "dang@redhat.com" <dang@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@vmware.com>
Date: Friday, May 24, 2019 at 1:00 AM
To: "devel@lists.nfs-ganesha.org" <devel@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