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