[NFS-Ganesha-Devel] Re: Seeing out of order logs

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&gt; 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&gt; > *Date: *Friday, May 24, 2019 at 1:00 AM > *To: *&quot;devel(a)lists.nfs-ganesha.org&quot; <devel(a)lists.nfs-ganesha.org&gt; > *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 >