Uploaded image for project: 'Couchbase Server'
  1. Couchbase Server
  2. MB-51418

eventing.log covers less than 6 hours

    XMLWordPrintable

Details

    • Bug
    • Resolution: Fixed
    • Critical
    • 7.1.0
    • 7.1.0
    • eventing
    • Enterprise Edition 7.1.0 build 2440
      Enterprise Edition 7.1.0 build 2469
    • Untriaged
    • Centos 64-bit
    • 1
    • No

    Description

      Problem
      This issue was seen for last 2 runs of eventing component system test on builds 7.1.0-2440 (MB-51336) and 7.1.0-2469 (MB-51417). Eventing.log covered duration of 2-4 hours on all eventing nodes involved.

      For eg -
      Eventing component system test run on 7.1.0-2469
      172.23.96.31

      ~/Downloads/cbcollect_info_ns_1@172.23.96.31_20220311-224023                                                                                                     
      ▶ head ns_server.eventing.log                        
      ==============================================================================
      couchbase logs (eventing.log)
      cbbrowse_logs eventing.log
      ==============================================================================
      2022-03-11T11:16:31.267-08:00 [Info] eventing-consumer [worker_n1ql2_0_0:/tmp/127.0.0.1:8091_0_295878424.sock:3790] Received update processed seq_no event from Go {"seq":115325,"skip_ack":0,"vb":447}
      2022-03-11T11:16:31.267-08:00 [Info] Consumer::doVbTakeover [worker_n1ql0_0_0:/tmp/127.0.0.1:8091_0_4235439992.sock:17044] vb: 623 dcp stream status: running curr owner: 172.23.96.31:8096 worker: worker_n1ql0_0_0 UUID consumer: b9d623e533693228b2a053dffa465f52 from metadata: b9d623e533693228b2a053dffa465f52 check if current node should own vb: true
      2022-03-11T11:16:31.267-08:00 [Info] Consumer::doVbTakeover [worker_n1ql0_0_0:/tmp/127.0.0.1:8091_0_4235439992.sock:17044] vb: 623 current consumer and eventing node has already opened dcp stream. Stream status: running, skipping
      2022-03-11T11:16:31.267-08:00 [Info] Consumer::checkIfAlreadyEnqueued [worker_n1ql0_0_0:/tmp/127.0.0.1:8091_0_4235439992.sock:17044] vb: 626 enqueuing
      2022-03-11T11:16:31.268-08:00 [Info] Consumer::doVbTakeover [worker_n1ql2_0_0:/tmp/127.0.0.1:8091_0_295878424.sock:3790] vb: 348 dcp stream status: running curr owner: 172.23.96.31:8096 worker: worker_n1ql2_0_0 UUID consumer: b9d623e533693228b2a053dffa465f52 from metadata: b9d623e533693228b2a053dffa465f52 check if current node should own vb: true
      2022-03-11T11:16:31.268-08:00 [Info] Consumer::doVbTakeover [worker_n1ql2_0_0:/tmp/127.0.0.1:8091_0_295878424.sock:3790] vb: 348 current consumer and eventing node has already opened dcp stream. Stream status: running, skipping
       
      ~/Downloads/cbcollect_info_ns_1@172.23.96.31_20220311-224023                                                                                                     
      ▶ tail ns_server.eventing.log                        
      2022-03-11T14:44:17.762-08:00 [Info] DCPT[eventing:mzMeVckq-10061:eventing:mzMeVckq-10060:2229215679_172.23.97.77:11210_worker_n1ql_nw3_0_0_172.23.96.31:8096/0] DCP-socket -> eventing blocked 995.657629ms (0.955637%)
      2022-03-11T14:44:17.768-08:00 [Info] eventing-consumer [worker_n1ql_nw3_0_0:/tmp/127.0.0.1:8091_0_2229215679.sock:1875] [lcb,confmon L:172 I:1166079682] Setting new configuration. Received via CCCP (bucket="n1ql_op", rev=1:109200, address="172.23.104.16"). Old config was from CCCP (bucket="n1ql_op", rev=1:109196, address="172.23.104.16"). Changes: servers=no, map=yes, replicas=no
      2022-03-11T14:44:17.768-08:00 [Info] eventing-consumer [worker_n1ql_nw3_0_0:/tmp/127.0.0.1:8091_0_2229215679.sock:1875] [lcb,bootstrap L:157 I:1166079682] Got new config (source=CCCP, bucket=n1ql_op, epoch=1, rev=109200). Will refresh asynchronously
      2022-03-11T14:44:17.768-08:00 [Info] eventing-consumer [worker_n1ql_nw3_0_0:/tmp/127.0.0.1:8091_0_2229215679.sock:1875] [lcb,newconfig L:163 I:1166079682] Config Diff: [ vBuckets Modified=6 ], [Sequence Changed=0]
      2022-03-11T14:44:17.768-08:00 [Info] eventing-consumer [worker_n1ql_nw3_0_0:/tmp/127.0.0.1:8091_0_2229215679.sock:1875] [lcb,newconfig L:264 I:1166079682] Reusing server 172.23.104.16:11210 (0x7efe98011b30). OldIndex=0. NewIndex=0
      2022-03-11T14:44:17.768-08:00 [Info] eventing-consumer [worker_n1ql_nw3_0_0:/tmp/127.0.0.1:8091_0_2229215679.sock:1875] [lcb,newconfig L:264 I:1166079682] Reusing server 172.23.104.18:11210 (0x7efe7004b7f0). OldIndex=1. NewIndex=1
      2022-03-11T14:44:17.768-08:00 [Info] eventing-consumer [worker_n1ql_nw3_0_0:/tmp/127.0.0.1:8091_0_2229215679.sock:1875] [lcb,newconfig L:264 I:1166079682] Reusing server 172.23.104.19:11210 (0x7efe98017bf0). OldIndex=2. NewIndex=2
      2022-03-11T14:44:17.768-08:00 [Info] eventing-consumer [worker_n1ql_nw3_0_0:/tmp/127.0.0.1:8091_0_2229215679.sock:1875] [lcb,newconfig L:264 I:1166079682] Reusing server 172.23.97.77:11210 (0x7efe980189e0). OldIndex=3. NewIndex=3
      2022-03-11T14:44:18.048-08:00 [Info] serviceChangeNotifier: received CollectionManifestChangeNotification for bucket: n1ql_op
      2022-03-11T14:44:18.763-08:00 [Info] DCPT[eventing:mzMeVckq-10119:eventing:mzMeVckq-10118:724985045_172.23.104.16:11210_worker_n1ql_nw4_0_0_172.23.96.31:8096/0] ##20a DCP_STREAMEND for vb 522
      

      Marking this issue as critical as it affects the ability to debug problems.

      NOTE
      Logs are available at MB-51417 and MB-51336.

      Attachments

        Activity

          People

            sujay.gad Sujay Gad
            sujay.gad Sujay Gad
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              PagerDuty