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

24 May 2019

      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@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@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
    >