2:30 p.m.
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
12:02 a.m.
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
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
8:23 a.m.
I'm not aware of any issues, nor has anything changed in 3 years. It's
clear to me from your logs that you've set time_format and/or
date_format, but likely haven't set it to "syslog_usec", right? This
means it's just calling time() to get the datestamp, and it's doing it
during each log message. (If you set "syslog_usec" it calls gettimeofday())
This means, to me, that the first time a thread calls time() in a while,
it's getting back an older timestamp, but that something kicks the
timestamp back to normal after that.
I haven't seen anything like this before; time can drift, especially in
virtual machines (which is why CLOCK_MONOTONIC exists), but this doesn't
seem to be that.
Are you running in a virtual machine? If so, which type (ie, vmware,
kvm, etc.)
Daniel
On 5/24/19 1:02 AM, Sriram Patil wrote:
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
9:59 a.m.
Hi Daniel,
Yes I have set a date format and I was running ganesha inside a container on a VMWare
VM.
But I fail to understand how come the time is different only for the first log message of
every request?
Thanks,
Sriram
On 5/24/19, 6:53 PM, "Daniel Gryniewicz" <dang(a)redhat.com> wrote:
I'm not aware of any issues, nor has anything changed in 3 years. It's
clear to me from your logs that you've set time_format and/or
date_format, but likely haven't set it to "syslog_usec", right? This
means it's just calling time() to get the datestamp, and it's doing it
during each log message. (If you set "syslog_usec" it calls
gettimeofday())
This means, to me, that the first time a thread calls time() in a while,
it's getting back an older timestamp, but that something kicks the
timestamp back to normal after that.
I haven't seen anything like this before; time can drift, especially in
virtual machines (which is why CLOCK_MONOTONIC exists), but this doesn't
seem to be that.
Are you running in a virtual machine? If so, which type (ie, vmware,
kvm, etc.)
Daniel
On 5/24/19 1:02 AM, Sriram Patil wrote:
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
10:34 a.m.
My guess is that something related to waking up the thread triggers a
system clock update from the VM host to the VM, but that this is done
asynchronously, and that it takes some time. This means that the first
call to time() in the thread is likely to get an out-of-date timestamp.
I don't know that this is the case; but VMWare, in particular, has some
really strange operation with-respect-to the system clock inside a VM.
When I last looked at this (~10 years ago, admittedly), there were some
settings you could change that would make it better, but we couldn't get
good, accurate time inside a VM no matter what we did. Note that we
needed sub-second accuracy, so you can likely make it good enough for
Ganesha timestamps.
Note: I'm blaming virtualization (and VMWare in particular) here, but I
don't know that this is the problem; I've just never seen this issue in
Ganesha before, and I have seen clock issues in VMs, so it's my best
guess. It may turn out to be something else entirely.
Daniel
On 5/24/19 10:59 AM, Sriram Patil wrote:
Hi Daniel,
Yes I have set a date format and I was running ganesha inside a container on a VMWare
VM.
But I fail to understand how come the time is different only for the first log message of
every request?
Thanks,
Sriram
On 5/24/19, 6:53 PM, "Daniel Gryniewicz" <dang(a)redhat.com> wrote:
I'm not aware of any issues, nor has anything changed in 3 years. It's
clear to me from your logs that you've set time_format and/or
date_format, but likely haven't set it to "syslog_usec", right? This
means it's just calling time() to get the datestamp, and it's doing it
during each log message. (If you set "syslog_usec" it calls
gettimeofday())
This means, to me, that the first time a thread calls time() in a while,
it's getting back an older timestamp, but that something kicks the
timestamp back to normal after that.
I haven't seen anything like this before; time can drift, especially in
virtual machines (which is why CLOCK_MONOTONIC exists), but this doesn't
seem to be that.
Are you running in a virtual machine? If so, which type (ie, vmware,
kvm, etc.)
Daniel
On 5/24/19 1:02 AM, Sriram Patil wrote:
> 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
>
12:50 p.m.
Ohh okay. I agree that this is very unusual behavior in a normal case because ganesha
calls time every time when logging. Also, it opens and closes file for every log
message.
I will investigate further on similar lines. Thanks for the help.
- Sriram
On 5/24/19, 9:04 PM, "Daniel Gryniewicz" <dang(a)redhat.com> wrote:
My guess is that something related to waking up the thread triggers a
system clock update from the VM host to the VM, but that this is done
asynchronously, and that it takes some time. This means that the first
call to time() in the thread is likely to get an out-of-date timestamp.
I don't know that this is the case; but VMWare, in particular, has some
really strange operation with-respect-to the system clock inside a VM.
When I last looked at this (~10 years ago, admittedly), there were some
settings you could change that would make it better, but we couldn't get
good, accurate time inside a VM no matter what we did. Note that we
needed sub-second accuracy, so you can likely make it good enough for
Ganesha timestamps.
Note: I'm blaming virtualization (and VMWare in particular) here, but I
don't know that this is the problem; I've just never seen this issue in
Ganesha before, and I have seen clock issues in VMs, so it's my best
guess. It may turn out to be something else entirely.
Daniel
On 5/24/19 10:59 AM, Sriram Patil wrote:
Hi Daniel,
Yes I have set a date format and I was running ganesha inside a container on a VMWare
VM.
But I fail to understand how come the time is different only for the first log message of
every request?
Thanks,
Sriram
On 5/24/19, 6:53 PM, "Daniel Gryniewicz" <dang(a)redhat.com> wrote:
I'm not aware of any issues, nor has anything changed in 3 years. It's
clear to me from your logs that you've set time_format and/or
date_format, but likely haven't set it to "syslog_usec", right?
This
means it's just calling time() to get the datestamp, and it's doing it
during each log message. (If you set "syslog_usec" it calls
gettimeofday())
This means, to me, that the first time a thread calls time() in a while,
it's getting back an older timestamp, but that something kicks the
timestamp back to normal after that.
I haven't seen anything like this before; time can drift, especially in
virtual machines (which is why CLOCK_MONOTONIC exists), but this doesn't
seem to be that.
Are you running in a virtual machine? If so, which type (ie, vmware,
kvm, etc.)
Daniel
On 5/24/19 1:02 AM, Sriram Patil wrote:
> 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
>
2582
days inactive
2583
days old
6 comments
2 participants
participants (2)
-
Daniel Gryniewicz -
Sriram Patil