Details
-
Bug
-
Resolution: Fixed
-
Critical
-
7.1.0
-
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.