[MB-45053] [System Test] Eventing Rebalance failed - Couchbase database

XML

Word

Printable

Details

Type: Bug
Status: Closed
Priority: Critical
Resolution: Fixed
Affects Version/s: Cheshire-Cat
Fix Version/s: 7.0.0
Component/s: clients
Labels:

Triage:
Untriaged
Operating System:
Centos 64-bit
Link to Log File, atop/blg, CBCollectInfo, Core dump:

Hide
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.104.15.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.104.165.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.104.214.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.104.232.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.104.244.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.104.245.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.102.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.109.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.112.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.118.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.164.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.183.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.206.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.210.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.25.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.29.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.61.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.62.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.86.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.90.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.93.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.106.117.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.106.191.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.106.207.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.106.209.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.106.225.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.106.32.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.106.54.zip
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.106.70.zip

Show
url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.104.15.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.104.165.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.104.214.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.104.232.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.104.244.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.104.245.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.102.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.109.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.112.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.118.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.164.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.183.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.206.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.210.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.25.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.29.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.61.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.62.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.86.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.90.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.105.93.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.106.117.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.106.191.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.106.207.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.106.209.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.106.225.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.106.32.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.106.54.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616043372/collectinfo-2021-03-18T045613-ns_1%40172.23.106.70.zip
Story Points:
1
Is this a Regression?:
Yes

Description

System Test:

Eventing handlers deployment{

[2021-03-17T16:06:53-07:00, sequoiatools/eventing:7.0:a87aaf] eventing_helper.py -i 172.23.105.183 -u Administrator -p password -s default.event_0.coll0 -m ITEM.event_0.coll0 -d dst_bucket.NEW_ORDER.event_0.coll0.rw -t timers -o create --name timers

[2021-03-17T16:07:01-07:00, sequoiatools/eventing:7.0:dfee66] eventing_helper.py -i 172.23.105.183 -u Administrator -p password -s default.event_0.coll0 -m ITEM.event_0.coll1 -d dst_bucket.NEW_ORDER.event_0.coll1.rw -t n1ql -o create --name n1ql

[2021-03-17T16:07:08-07:00, sequoiatools/eventing:7.0:dd9a54] eventing_helper.py -i 172.23.105.183 -u Administrator -p password -s WAREHOUSE.event_0.coll0 -m ITEM.event_0.coll2 -d dst_bucket.WAREHOUSE.event_0.coll0.rw -t sbm -o create --name sbm

[2021-03-17T16:07:17-07:00, sequoiatools/eventing:7.0:ef5686] eventing_helper.py -i 172.23.105.183 -u Administrator -p password -s WAREHOUSE.event_0.coll0 -m ITEM.event_0.coll3 -d dst_bucket.NEW_ORDER.event_0.coll2.rw -t curl -o create --name curl

[2021-03-17T16:07:25-07:00, sequoiatools/eventing:7.0:b3959c] eventing_helper.py -i 172.23.105.183 -u Administrator -p password -o deploy

[2021-03-17T16:07:30-07:00, sequoiatools/eventing:7.0:d2d34d] eventing_helper.py -i 172.23.105.183 -u Administrator -p password -o wait_for_state --state deployed

– At this point of time there should be not data in collections.

Current step

[2021-03-17T21:13:59-07:00, sequoiatools/couchbase-cli:7.0:e63846] server-add -c 172.23.104.232:8091 --server-add https://172.23.104.244 -u Administrator -p password --server-add-username Administrator --server-add-password password --services data

[2021-03-17T21:14:11-07:00, sequoiatools/couchbase-cli:7.0:d5525c] rebalance -c 172.23.104.232:8091 --server-remove 172.23.105.25 -u Administrator -p password

→

Error occurred on container - sequoiatools/couchbase-cli:7.0:[rebalance -c 172.23.104.232:8091 --server-remove 172.23.105.25 -u Administrator -p password]

docker logs d5525c

docker start d5525c

*Unable to display progress bar on this os

JERROR: Rebalance failed. See logs for detailed reason. You can try again.

Rebalance Failed -

Rebalance exited with reason {service_rebalance_failed,eventing,

{worker_died,

{'EXIT',<0.1247.496>,

{{badmatch,

{error,

{bad_nodes,eventing,prepare_rebalance,

[{'ns_1@172.23.104.214',

{error,

{unknown_error,

<<"Some apps are deploying or resuming on nodeId: d0c98164b79fbb3e57b4808d7c71ef3b Apps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]">>}}}]}}},

[{service_rebalancer,rebalance_worker,1,

[{file,"src/service_rebalancer.erl"},

{line,164}]},

{proc_lib,init_p,3,

[{file,"proc_lib.erl"},{line,234}]}]}}}}.

Rebalance Operation Id = 6c309e9434208e5789108f241ad43a4b

– All 4 handlers above are undeployed.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

eventing_pprof.log
58 kB
17/Mar/21 11:58 PM
goroutine5.out
57 kB
17/Mar/21 11:58 PM

Issue Links

relates to

MB-45722 Remove the 'replace' directives for gocb/gocbcore in go.mod

Closed

Gerrit Reviews

- Issue Only
- Show All Reviews
- Show Open Reviews
- Show All Issues
- Show Open Issues

No reviews matched the request. Check your Options in the drop-down menu of this sections header.

Activity

Ascending order - Click to sort in descending order

Ritam Sharma created issue - 17/Mar/21 10:33 PM

Ritam Sharma made changes - 17/Mar/21 10:36 PM

Field	Original Value	New Value
Description	System Test: Current step {noformat} [2021-03-17T21:13:59-07:00, sequoiatools/couchbase-cli:7.0:e63846] server-add -c 172.23.104.232:8091 --server-add https://172.23.104.244 -u Administrator -p password --server-add-username Administrator --server-add-password password --services data [2021-03-17T21:14:11-07:00, sequoiatools/couchbase-cli:7.0:d5525c] rebalance -c 172.23.104.232:8091 --server-remove 172.23.105.25 -u Administrator -p password → Error occurred on container - sequoiatools/couchbase-cli:7.0:[rebalance -c 172.23.104.232:8091 --server-remove 172.23.105.25 -u Administrator -p password] docker logs d5525c docker start d5525c *Unable to display progress bar on this os JERROR: Rebalance failed. See logs for detailed reason. You can try again. {noformat} Rebalance Failed - {noformat} Rebalance exited with reason {service_rebalance_failed,eventing, {worker_died, {'EXIT',<0.1247.496>, {{badmatch, {error, {bad_nodes,eventing,prepare_rebalance, [{'ns_1@172.23.104.214', {error, {unknown_error, <<"Some apps are deploying or resuming on nodeId: d0c98164b79fbb3e57b4808d7c71ef3b Apps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]">>}}}]}}}, [{service_rebalancer,rebalance_worker,1, [{file,"src/service_rebalancer.erl"}, {line,164}]}, {proc_lib,init_p,3, [{file,"proc_lib.erl"},{line,234}]}]}}}}. Rebalance Operation Id = 6c309e9434208e5789108f241ad43a4b {noformat}	System Test: Eventing handlers deployment{ {noformat} [2021-03-17T16:06:53-07:00, sequoiatools/eventing:7.0:a87aaf] eventing_helper.py -i 172.23.105.183 -u Administrator -p password -s default.event_0.coll0 -m ITEM.event_0.coll0 -d dst_bucket.NEW_ORDER.event_0.coll0.rw -t timers -o create --name timers [2021-03-17T16:07:01-07:00, sequoiatools/eventing:7.0:dfee66] eventing_helper.py -i 172.23.105.183 -u Administrator -p password -s default.event_0.coll0 -m ITEM.event_0.coll1 -d dst_bucket.NEW_ORDER.event_0.coll1.rw -t n1ql -o create --name n1ql [2021-03-17T16:07:08-07:00, sequoiatools/eventing:7.0:dd9a54] eventing_helper.py -i 172.23.105.183 -u Administrator -p password -s WAREHOUSE.event_0.coll0 -m ITEM.event_0.coll2 -d dst_bucket.WAREHOUSE.event_0.coll0.rw -t sbm -o create --name sbm [2021-03-17T16:07:17-07:00, sequoiatools/eventing:7.0:ef5686] eventing_helper.py -i 172.23.105.183 -u Administrator -p password -s WAREHOUSE.event_0.coll0 -m ITEM.event_0.coll3 -d dst_bucket.NEW_ORDER.event_0.coll2.rw -t curl -o create --name curl [2021-03-17T16:07:25-07:00, sequoiatools/eventing:7.0:b3959c] eventing_helper.py -i 172.23.105.183 -u Administrator -p password -o deploy [2021-03-17T16:07:30-07:00, sequoiatools/eventing:7.0:d2d34d] eventing_helper.py -i 172.23.105.183 -u Administrator -p password -o wait_for_state --state deployed {noformat} -- At this point of time there should be not data in collections. Current step {noformat} [2021-03-17T21:13:59-07:00, sequoiatools/couchbase-cli:7.0:e63846] server-add -c 172.23.104.232:8091 --server-add https://172.23.104.244 -u Administrator -p password --server-add-username Administrator --server-add-password password --services data [2021-03-17T21:14:11-07:00, sequoiatools/couchbase-cli:7.0:d5525c] rebalance -c 172.23.104.232:8091 --server-remove 172.23.105.25 -u Administrator -p password → Error occurred on container - sequoiatools/couchbase-cli:7.0:[rebalance -c 172.23.104.232:8091 --server-remove 172.23.105.25 -u Administrator -p password] docker logs d5525c docker start d5525c *Unable to display progress bar on this os JERROR: Rebalance failed. See logs for detailed reason. You can try again. {noformat} Rebalance Failed - {noformat} Rebalance exited with reason {service_rebalance_failed,eventing, {worker_died, {'EXIT',<0.1247.496>, {{badmatch, {error, {bad_nodes,eventing,prepare_rebalance, [{'ns_1@172.23.104.214', {error, {unknown_error, <<"Some apps are deploying or resuming on nodeId: d0c98164b79fbb3e57b4808d7c71ef3b Apps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]">>}}}]}}}, [{service_rebalancer,rebalance_worker,1, [{file,"src/service_rebalancer.erl"}, {line,164}]}, {proc_lib,init_p,3, [{file,"proc_lib.erl"},{line,234}]}]}}}}. Rebalance Operation Id = 6c309e9434208e5789108f241ad43a4b {noformat} -- All 4 handlers above are not undeployed.

Ritam Sharma made changes - 17/Mar/21 10:36 PM

Description

System Test:

Eventing handlers deployment{
{noformat}
[2021-03-17T16:06:53-07:00, sequoiatools/eventing:7.0:a87aaf] eventing_helper.py -i 172.23.105.183 -u Administrator -p password -s default.event_0.coll0 -m ITEM.event_0.coll0 -d dst_bucket.NEW_ORDER.event_0.coll0.rw -t timers -o create --name timers
[2021-03-17T16:07:01-07:00, sequoiatools/eventing:7.0:dfee66] eventing_helper.py -i 172.23.105.183 -u Administrator -p password -s default.event_0.coll0 -m ITEM.event_0.coll1 -d dst_bucket.NEW_ORDER.event_0.coll1.rw -t n1ql -o create --name n1ql
[2021-03-17T16:07:08-07:00, sequoiatools/eventing:7.0:dd9a54] eventing_helper.py -i 172.23.105.183 -u Administrator -p password -s WAREHOUSE.event_0.coll0 -m ITEM.event_0.coll2 -d dst_bucket.WAREHOUSE.event_0.coll0.rw -t sbm -o create --name sbm
[2021-03-17T16:07:17-07:00, sequoiatools/eventing:7.0:ef5686] eventing_helper.py -i 172.23.105.183 -u Administrator -p password -s WAREHOUSE.event_0.coll0 -m ITEM.event_0.coll3 -d dst_bucket.NEW_ORDER.event_0.coll2.rw -t curl -o create --name curl
[2021-03-17T16:07:25-07:00, sequoiatools/eventing:7.0:b3959c] eventing_helper.py -i 172.23.105.183 -u Administrator -p password -o deploy
[2021-03-17T16:07:30-07:00, sequoiatools/eventing:7.0:d2d34d] eventing_helper.py -i 172.23.105.183 -u Administrator -p password -o wait_for_state --state deployed
{noformat}
-- At this point of time there should be not data in collections.

Current step
{noformat}
[2021-03-17T21:13:59-07:00, sequoiatools/couchbase-cli:7.0:e63846] server-add -c 172.23.104.232:8091 --server-add https://172.23.104.244 -u Administrator -p password --server-add-username Administrator --server-add-password password --services data
[2021-03-17T21:14:11-07:00, sequoiatools/couchbase-cli:7.0:d5525c] rebalance -c 172.23.104.232:8091 --server-remove 172.23.105.25 -u Administrator -p password
→

Error occurred on container - sequoiatools/couchbase-cli:7.0:[rebalance -c 172.23.104.232:8091 --server-remove 172.23.105.25 -u Administrator -p password]

docker logs d5525c
docker start d5525c

*Unable to display progress bar on this os
JERROR: Rebalance failed. See logs for detailed reason. You can try again.
{noformat}

Rebalance Failed -

{noformat}
Rebalance exited with reason {service_rebalance_failed,eventing,
{worker_died,
{'EXIT',<0.1247.496>,
{{badmatch,
{error,
{bad_nodes,eventing,prepare_rebalance,
[{'ns_1@172.23.104.214',
{error,
{unknown_error,
<<"Some apps are deploying or resuming on nodeId: d0c98164b79fbb3e57b4808d7c71ef3b Apps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]">>}}}]}}},
[{service_rebalancer,rebalance_worker,1,
[{file,"src/service_rebalancer.erl"},
{line,164}]},
{proc_lib,init_p,3,
[{file,"proc_lib.erl"},{line,234}]}]}}}}.
Rebalance Operation Id = 6c309e9434208e5789108f241ad43a4b
{noformat}

-- All 4 handlers above are not undeployed.

Jeelan Poola made changes - 17/Mar/21 11:26 PM

Assignee

Jeelan Poola [ jeelan.poola ]

Ankit Prabhu [ ankit.prabhu ]

Ankit Prabhu made changes - 17/Mar/21 11:58 PM

Attachment		eventing_pprof.log [ 131500 ]
Attachment		goroutine5.out [ 131501 ]

Ankit Prabhu added a comment - 17/Mar/21 11:59 PM

timer_0 function is stuck in bootstrapping.
Looking at eventing logs it is trying to open the connection with the metadata bucket using gocb but its receiving timeout in WaitUntilReady operation.

1793:2021-03-17T16:08:38.945-07:00 [Error] Consumer::gocbConnectMetaBucketCallback [worker_timers_0_0:1] Failed to connect to metadata bucket ITEM (bucket got deleted?) , err: unambiguous timeout | {"InnerError":{"InnerError":{"InnerError":{},"Message":"unambiguous timeout"}},"OperationID":"WaitUntilReady","Opaque":"","TimeObserved":5000155810,"RetryReasons":["NOT_READY"],"RetryAttempts":10,"LastDispatchedTo":"","LastDispatchedFrom":"","LastConnectionID":""}

Looking at the pprof looks like its stuck in closing the connection which blocked deployment of the function.

1 @ 0x93b320 0x90fb48 0x90fb1e 0x90f80b 0xd5ad86 0xd60d4b 0xdd5f42 0xdd75f4 0x1142c06 0xe412ba 0x11312f6 0xe656e3 0x969351

#       0xd5ad85        github.com/couchbase/gocbcore/v9.(*Agent).Close+0xc5                            /tmp/workspace/toy-unix-simple/godeps/src/github.com/couchbase/gocbcore/v9/agent.go:495

#       0xd60d4a        github.com/couchbase/gocbcore/v9.(*AgentGroup).Close+0x11a                      /tmp/workspace/toy-unix-simple/godeps/src/github.com/couchbase/gocbcore/v9/agentgroup.go:115

#       0xdd5f41        github.com/couchbase/gocb/v2.(*stdConnectionMgr).close+0x141                    /tmp/workspace/toy-unix-simple/godeps/src/github.com/couchbase/gocb/v2/client.go:262

#       0xdd75f3        github.com/couchbase/gocb/v2.(*Cluster).Close+0xf3                              /tmp/workspace/toy-unix-simple/godeps/src/github.com/couchbase/gocb/v2/cluster.go:379

#       0x1142c05       github.com/couchbase/eventing/consumer.glob..func2+0x4d5                        /tmp/workspace/toy-unix-simple/goproj/src/github.com/couchbase/eventing/consumer/bucket_ops.go:89

#       0xe412b9        github.com/couchbase/eventing/util.Retry+0x129                                  /tmp/workspace/toy-unix-simple/goproj/src/github.com/couchbase/eventing/util/retry.go:65

#       0x11312f5       github.com/couchbase/eventing/consumer.(*Consumer).Serve+0x5d5                  /tmp/workspace/toy-unix-simple/goproj/src/github.com/couchbase/eventing/consumer/v8_consumer.go:196

#       0xe656e2        github.com/couchbase/eventing/suptree.(*Supervisor).runService.func1+0x72       /tmp/workspace/toy-unix-simple/goproj/src/github.com/couchbase/eventing/suptree/supervisor.go:413

There is no more message after 16:08:38 so it looks like its stuck from that period.
https://github.com/couchbase/gocbcore/blob/e48d03a40861100a01753e1277952abaa0bce343/agent.go#L495
Could someone from gocb team take a look and check why its stuck in closing the connection and also the timeout?
goroutine dump: eventing_pprof.log goroutine5.out

Ankit Prabhu added a comment - 17/Mar/21 11:59 PM timer_0 function is stuck in bootstrapping. Looking at eventing logs it is trying to open the connection with the metadata bucket using gocb but its receiving timeout in WaitUntilReady operation. 1793:2021-03-17T16:08:38.945-07:00 [Error] Consumer::gocbConnectMetaBucketCallback [worker_timers_0_0:1] Failed to connect to metadata bucket ITEM (bucket got deleted?) , err: unambiguous timeout | {"InnerError":{"InnerError":{"InnerError":{},"Message":"unambiguous timeout"}},"OperationID":"WaitUntilReady","Opaque":"","TimeObserved":5000155810,"RetryReasons":["NOT_READY"],"RetryAttempts":10,"LastDispatchedTo":"","LastDispatchedFrom":"","LastConnectionID":""} Looking at the pprof looks like its stuck in closing the connection which blocked deployment of the function. 1 @ 0x93b320 0x90fb48 0x90fb1e 0x90f80b 0xd5ad86 0xd60d4b 0xdd5f42 0xdd75f4 0x1142c06 0xe412ba 0x11312f6 0xe656e3 0x969351 # 0xd5ad85 github.com/couchbase/gocbcore/v9.(*Agent).Close+0xc5 /tmp/workspace/toy-unix-simple/godeps/src/github.com/couchbase/gocbcore/v9/agent.go:495 # 0xd60d4a github.com/couchbase/gocbcore/v9.(*AgentGroup).Close+0x11a /tmp/workspace/toy-unix-simple/godeps/src/github.com/couchbase/gocbcore/v9/agentgroup.go:115 # 0xdd5f41 github.com/couchbase/gocb/v2.(*stdConnectionMgr).close+0x141 /tmp/workspace/toy-unix-simple/godeps/src/github.com/couchbase/gocb/v2/client.go:262 # 0xdd75f3 github.com/couchbase/gocb/v2.(*Cluster).Close+0xf3 /tmp/workspace/toy-unix-simple/godeps/src/github.com/couchbase/gocb/v2/cluster.go:379 # 0x1142c05 github.com/couchbase/eventing/consumer.glob..func2+0x4d5 /tmp/workspace/toy-unix-simple/goproj/src/github.com/couchbase/eventing/consumer/bucket_ops.go:89 # 0xe412b9 github.com/couchbase/eventing/util.Retry+0x129 /tmp/workspace/toy-unix-simple/goproj/src/github.com/couchbase/eventing/util/retry.go:65 # 0x11312f5 github.com/couchbase/eventing/consumer.(*Consumer).Serve+0x5d5 /tmp/workspace/toy-unix-simple/goproj/src/github.com/couchbase/eventing/consumer/v8_consumer.go:196 # 0xe656e2 github.com/couchbase/eventing/suptree.(*Supervisor).runService.func1+0x72 /tmp/workspace/toy-unix-simple/goproj/src/github.com/couchbase/eventing/suptree/supervisor.go:413 There is no more message after 16:08:38 so it looks like its stuck from that period. https://github.com/couchbase/gocbcore/blob/e48d03a40861100a01753e1277952abaa0bce343/agent.go#L495 Could someone from gocb team take a look and check why its stuck in closing the connection and also the timeout? goroutine dump: eventing_pprof.log goroutine5.out

Ritam Sharma added a comment - 18/Mar/21 12:10 AM

seeing this is on another cluster - none of the handlers are deployed - Ankit Prabhu - Can you please review these set of logs too

Ritam Sharma added a comment - 18/Mar/21 12:10 AM seeing this is on another cluster - none of the handlers are deployed - Ankit Prabhu - Can you please review these set of logs too https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.106.134.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.120.58.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.120.73.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.120.74.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.120.75.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.120.77.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.120.81.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.120.86.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.121.77.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.123.24.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.123.25.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.123.26.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.123.31.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.123.32.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.123.33.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.96.122.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.96.243.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.96.254.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.96.48.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.97.105.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.97.110.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.97.112.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.97.148.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.97.149.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.97.150.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.97.151.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.97.241.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053/collectinfo-2021-03-18T070059-ns_1%40172.23.97.74.zip

Ankit Prabhu made changes - 18/Mar/21 12:10 AM

Assignee

Ankit Prabhu [ ankit.prabhu ]

Brett Lawson [ brett19 ]

Ankit Prabhu added a comment - 18/Mar/21 12:28 AM

Its a same issue. On node 172.23.120.58 eventing received unambiguous timeout from gocb.

2021-03-17T22:08:20.327-07:00 [Error] util::IsSyncGatewayEnabled OpenBucket failed for bucket: WAREHOUSE, err: unambiguous timeout | {"InnerError":{"InnerError":{"InnerError":{},"Message":"unambiguous timeout"}},"OperationID":"WaitUntilReady","Opaque":"","TimeObserved":5000193958,"RetryReasons":["NOT_READY"],"RetryAttempts":10,"LastDispatchedTo":"","LastDispatchedFrom":"","LastConnectionID":""}2021-03-17T22:08:42.181-07:00 [Error] util::IsSyncGatewayEnabled OpenBucket failed for bucket: WAREHOUSE, err: unambiguous timeout | {"InnerError":{"InnerError":{"InnerError":{},"Message":"unambiguous timeout"}},"OperationID":"WaitUntilReady","Opaque":"","TimeObserved":5000186176,"RetryReasons":["NOT_READY"],"RetryAttempts":10,"LastDispatchedTo":"","LastDispatchedFrom":"","LastConnectionID":""}

And from goroutine dump gocb is stuck in closing the cluster agent.

1 @ 0x93b320 0x90fb48 0x90fb1e 0x90f80b 0xd5ae66 0xd60e2b 0xdd6022 0xdd76d4 0xe37d3c 0x11b2015 0x11a7d04 0x11be0dd 0xc00ac4 0xc0299d 0xc03f14 0xbff8b5 0x969351

#       0xd5ae65        github.com/couchbase/gocbcore/v9.(*Agent).Close+0xc5                                    /home/couchbase/jenkins/workspace/couchbase-server-unix/godeps/src/github.com/couchbase/gocbcore/v9/agent.go:495

#       0xd60e2a        github.com/couchbase/gocbcore/v9.(*AgentGroup).Close+0x11a                              /home/couchbase/jenkins/workspace/couchbase-server-unix/godeps/src/github.com/couchbase/gocbcore/v9/agentgroup.go:115

#       0xdd6021        github.com/couchbase/gocb/v2.(*stdConnectionMgr).close+0x141                            /home/couchbase/jenkins/workspace/couchbase-server-unix/godeps/src/github.com/couchbase/gocb/v2/client.go:262

#       0xdd76d3        github.com/couchbase/gocb/v2.(*Cluster).Close+0xf3                                      /home/couchbase/jenkins/workspace/couchbase-server-unix/godeps/src/github.com/couchbase/gocb/v2/cluster.go:379

#       0xe37d3b        github.com/couchbase/eventing/util.IsSyncGatewayEnabled+0x74b                           /home/couchbase/jenkins/workspace/couchbase-server-unix/goproj/src/github.com/couchbase/eventing/util/bucket_ops.go:205

#       0x11b2014       github.com/couchbase/eventing/service_manager.(*ServiceMgr).savePrimaryStore+0x2144     /home/couchbase/jenkins/workspace/couchbase-server-unix/goproj/src/github.com/couchbase/eventing/service_manager/http_handlers.go:1912

#       0x11a7d03       github.com/couchbase/eventing/service_manager.(*ServiceMgr).setSettings+0x1a13          /home/couchbase/jenkins/workspace/couchbase-server-unix/goproj/src/github.com/couchbase/eventing/service_manager/http_handlers.go:1415

#       0x11be0dc       github.com/couchbase/eventing/service_manager.(*ServiceMgr).functionsHandler+0x533c     /home/couchbase/jenkins/workspace/couchbase-server-unix/goproj/src/github.com/couchbase/eventing/service_manager/http_handlers.go:2963

#       0xc00ac3        net/http.HandlerFunc.ServeHTTP+0x43                                                     /home/couchbase/.cbdepscache/exploded/x86_64/go-1.13.7/go/src/net/http/server.go:2007

#       0xc0299c        net/http.(*ServeMux).ServeHTTP+0x1bc                                                    /home/couchbase/.cbdepscache/exploded/x86_64/go-1.13.7/go/src/net/http/server.go:2387

#       0xc03f13        net/http.serverHandler.ServeHTTP+0xa3                                                   /home/couchbase/.cbdepscache/exploded/x86_64/go-1.13.7/go/src/net/http/server.go:2802

#       0xbff8b4        net/http.(*conn).serve+0x874                                                            /home/couchbase/.cbdepscache/exploded/x86_64/go-1.13.7/go/src/net/http/server.go:1890

Recently gocb moved to 2.2.2 from 2.1.5 and gocbcore to 9.1.3 from 9.0.7
https://github.com/couchbase/manifest/commit/db19fbd7bd7d389213ff82fd026ff55d62dcdeb9

Ankit Prabhu added a comment - 18/Mar/21 12:28 AM Its a same issue. On node 172.23.120.58 eventing received unambiguous timeout from gocb. 2021-03-17T22:08:20.327-07:00 [Error] util::IsSyncGatewayEnabled OpenBucket failed for bucket: WAREHOUSE, err: unambiguous timeout | {"InnerError":{"InnerError":{"InnerError":{},"Message":"unambiguous timeout"}},"OperationID":"WaitUntilReady","Opaque":"","TimeObserved":5000193958,"RetryReasons":["NOT_READY"],"RetryAttempts":10,"LastDispatchedTo":"","LastDispatchedFrom":"","LastConnectionID":""}2021-03-17T22:08:42.181-07:00 [Error] util::IsSyncGatewayEnabled OpenBucket failed for bucket: WAREHOUSE, err: unambiguous timeout | {"InnerError":{"InnerError":{"InnerError":{},"Message":"unambiguous timeout"}},"OperationID":"WaitUntilReady","Opaque":"","TimeObserved":5000186176,"RetryReasons":["NOT_READY"],"RetryAttempts":10,"LastDispatchedTo":"","LastDispatchedFrom":"","LastConnectionID":""} And from goroutine dump gocb is stuck in closing the cluster agent. 1 @ 0x93b320 0x90fb48 0x90fb1e 0x90f80b 0xd5ae66 0xd60e2b 0xdd6022 0xdd76d4 0xe37d3c 0x11b2015 0x11a7d04 0x11be0dd 0xc00ac4 0xc0299d 0xc03f14 0xbff8b5 0x969351 # 0xd5ae65 github.com/couchbase/gocbcore/v9.(*Agent).Close+0xc5 /home/couchbase/jenkins/workspace/couchbase-server-unix/godeps/src/github.com/couchbase/gocbcore/v9/agent.go:495 # 0xd60e2a github.com/couchbase/gocbcore/v9.(*AgentGroup).Close+0x11a /home/couchbase/jenkins/workspace/couchbase-server-unix/godeps/src/github.com/couchbase/gocbcore/v9/agentgroup.go:115 # 0xdd6021 github.com/couchbase/gocb/v2.(*stdConnectionMgr).close+0x141 /home/couchbase/jenkins/workspace/couchbase-server-unix/godeps/src/github.com/couchbase/gocb/v2/client.go:262 # 0xdd76d3 github.com/couchbase/gocb/v2.(*Cluster).Close+0xf3 /home/couchbase/jenkins/workspace/couchbase-server-unix/godeps/src/github.com/couchbase/gocb/v2/cluster.go:379 # 0xe37d3b github.com/couchbase/eventing/util.IsSyncGatewayEnabled+0x74b /home/couchbase/jenkins/workspace/couchbase-server-unix/goproj/src/github.com/couchbase/eventing/util/bucket_ops.go:205 # 0x11b2014 github.com/couchbase/eventing/service_manager.(*ServiceMgr).savePrimaryStore+0x2144 /home/couchbase/jenkins/workspace/couchbase-server-unix/goproj/src/github.com/couchbase/eventing/service_manager/http_handlers.go:1912 # 0x11a7d03 github.com/couchbase/eventing/service_manager.(*ServiceMgr).setSettings+0x1a13 /home/couchbase/jenkins/workspace/couchbase-server-unix/goproj/src/github.com/couchbase/eventing/service_manager/http_handlers.go:1415 # 0x11be0dc github.com/couchbase/eventing/service_manager.(*ServiceMgr).functionsHandler+0x533c /home/couchbase/jenkins/workspace/couchbase-server-unix/goproj/src/github.com/couchbase/eventing/service_manager/http_handlers.go:2963 # 0xc00ac3 net/http.HandlerFunc.ServeHTTP+0x43 /home/couchbase/.cbdepscache/exploded/x86_64/go-1.13.7/go/src/net/http/server.go:2007 # 0xc0299c net/http.(*ServeMux).ServeHTTP+0x1bc /home/couchbase/.cbdepscache/exploded/x86_64/go-1.13.7/go/src/net/http/server.go:2387 # 0xc03f13 net/http.serverHandler.ServeHTTP+0xa3 /home/couchbase/.cbdepscache/exploded/x86_64/go-1.13.7/go/src/net/http/server.go:2802 # 0xbff8b4 net/http.(*conn).serve+0x874 /home/couchbase/.cbdepscache/exploded/x86_64/go-1.13.7/go/src/net/http/server.go:1890 Recently gocb moved to 2.2.2 from 2.1.5 and gocbcore to 9.1.3 from 9.0.7 https://github.com/couchbase/manifest/commit/db19fbd7bd7d389213ff82fd026ff55d62dcdeb9

Jeelan Poola made changes - 18/Mar/21 2:32 AM

Component/s		clients [ 10042 ]
Component/s	eventing [ 14026 ]

Charles Dixon added a comment - 18/Mar/21 3:05 AM

I'm trying to piece together what is happening here. Is eventing seeing the WaitUntilReady call fail and then closing the gocb cluster object? The Close call is then blocking eventing from making any further progress? It's hard to say why the WaitUntilReady call is timing out as there aren't any logs to see what gocbcore is doing (unless i'm looking in the wrong place). Is it at all possible to run with gocb/gocbcore logging set to debug level?

Regardless of why WaitUntilReady is timing out the cluster Close call should not be blocking indefinitely, the goroutine dump helps but again logs would likely be useful to work out what gocbcore is doing.

Charles Dixon added a comment - 18/Mar/21 3:05 AM I'm trying to piece together what is happening here. Is eventing seeing the WaitUntilReady call fail and then closing the gocb cluster object? The Close call is then blocking eventing from making any further progress? It's hard to say why the WaitUntilReady call is timing out as there aren't any logs to see what gocbcore is doing (unless i'm looking in the wrong place). Is it at all possible to run with gocb/gocbcore logging set to debug level? Regardless of why WaitUntilReady is timing out the cluster Close call should not be blocking indefinitely, the goroutine dump helps but again logs would likely be useful to work out what gocbcore is doing.

Ankit Prabhu added a comment - 18/Mar/21 3:20 AM

Charles Dixon, Yes WaitUntilReady calls failed which resulted in eventing closing the cluster object(which will be retried). But this close called blocked which resulted in eventing not making any further progress(in this case stuck in bootstrap state of eventing function)

1800:2021-03-17T16:08:41.244-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]

1801:2021-03-17T16:08:41.261-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]

1802:2021-03-17T16:08:41.271-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]

1803:2021-03-17T16:08:41.280-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]

1804:2021-03-17T16:08:41.289-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]

1806:2021-03-17T16:08:46.307-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]

1807:2021-03-17T16:08:46.320-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]

1808:2021-03-17T16:08:46.328-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]

1809:2021-03-17T16:08:46.335-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]

1810:2021-03-17T16:08:46.342-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]

1814:2021-03-17T16:08:51.361-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]

1815:2021-03-17T16:08:51.373-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]

1816:2021-03-17T16:08:51.382-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]

1817:2021-03-17T16:08:51.390-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]

1818:2021-03-17T16:08:51.399-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]

1824:2021-03-17T16:08:56.418-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]

1825:2021-03-17T16:08:56.431-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591]

2021-03-17T16:08:27.888-07:00 [Info] [gocb] SDK Version: gocbcore/v9.1.3

2021-03-17T16:08:27.888-07:00 [Info] [gocb] Creating new agent: &{MemdAddrs:[172.23.104.245:11210 172.23.105.102:11210 172.23.105.93:11210 172.23.104.232:11210 172.23.105.86:11210 172.23.105.25:11210 172.23.105.29:11210 172.23.105.90:11210 172.23.105.112:11210 172.23.105.109:11210 172.23.104.165:11210] HTTPAddrs:[172.23.104.245:8091 172.23.105.102:8091 172.23.105.93:8091 172.23.104.232:8091 172.23.105.86:8091 172.23.105.25:8091 172.23.105.29:8091 172.23.105.90:8091 172.23.105.112:8091 172.23.105.109:8091 172.23.104.165:8091] BucketName:ITEM UserAgent:gocb/v2.2.2 UseTLS:false NetworkType: Auth:0xc009a9d5e0 TLSRootCAProvider:0xe1c190 UseMutationTokens:true UseCompression:false UseDurations:true DisableDecompression:false UseOutOfOrderResponses:true DisableXErrors:false DisableJSONHello:false DisableSyncReplicationHello:false UseCollections:true CompressionMinSize:0 CompressionMinRatio:0 HTTPRedialPeriod:0s HTTPRetryDelay:0s CccpMaxWait:0s CccpPollPeriod:0s ConnectTimeout:10s KVConnectTimeout:7s KvPoolSize:0 MaxQueueSize:0 HTTPMaxIdleConns:0 HTTPMaxIdleConnsPerHost:0 HTTPIdleConnectionTimeout:0s Tracer:0xc009a9d2d0 NoRootTraceSpans:true DefaultRetryStrategy:0xc009a9d2b0 CircuitBreakerConfig:{Enabled:true VolumeThreshold:0 ErrorThresholdPercentage:0 SleepWindow:0s RollingWindow:0s CompletionCallback:<nil> CanaryTimeout:0s} UseZombieLogger:true ZombieLoggerInterval:0s ZombieLoggerSampleSize:0 AuthMechanisms:[]}

2021-03-17T16:08:32.942-07:00 [Error] Consumer::gocbConnectMetaBucketCallback [worker_timers_0_0:1] Failed to connect to metadata bucket ITEM (bucket got deleted?) , err: unambiguous timeout | {"InnerError":{"InnerError":{"InnerError":{},"Message":"unambiguous timeout"}},"OperationID":"WaitUntilReady","Opaque":"","TimeObserved":5000133580,"RetryReasons":["NOT_READY"],"RetryAttempts":10,"LastDispatchedTo":"","LastDispatchedFrom":"","LastConnectionID":""}

Ankit Prabhu added a comment - 18/Mar/21 3:20 AM Charles Dixon , Yes WaitUntilReady calls failed which resulted in eventing closing the cluster object(which will be retried). But this close called blocked which resulted in eventing not making any further progress(in this case stuck in bootstrap state of eventing function) 1800:2021-03-17T16:08:41.244-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591] 1801:2021-03-17T16:08:41.261-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591] 1802:2021-03-17T16:08:41.271-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591] 1803:2021-03-17T16:08:41.280-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591] 1804:2021-03-17T16:08:41.289-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591] 1806:2021-03-17T16:08:46.307-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591] 1807:2021-03-17T16:08:46.320-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591] 1808:2021-03-17T16:08:46.328-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591] 1809:2021-03-17T16:08:46.335-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591] 1810:2021-03-17T16:08:46.342-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591] 1814:2021-03-17T16:08:51.361-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591] 1815:2021-03-17T16:08:51.373-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591] 1816:2021-03-17T16:08:51.382-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591] 1817:2021-03-17T16:08:51.390-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591] 1818:2021-03-17T16:08:51.399-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591] 1824:2021-03-17T16:08:56.418-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591] 1825:2021-03-17T16:08:56.431-07:00 [Info] SuperSupervisor::BootstrapAppList [1] bootstrappingApps: map[timers_0:2021-03-17 16:07:27.988668711 -0700 PDT m=+2440.940195591] 2021-03-17T16:08:27.888-07:00 [Info] [gocb] SDK Version: gocbcore/v9.1.3 2021-03-17T16:08:27.888-07:00 [Info] [gocb] Creating new agent: &{MemdAddrs:[172.23.104.245:11210 172.23.105.102:11210 172.23.105.93:11210 172.23.104.232:11210 172.23.105.86:11210 172.23.105.25:11210 172.23.105.29:11210 172.23.105.90:11210 172.23.105.112:11210 172.23.105.109:11210 172.23.104.165:11210] HTTPAddrs:[172.23.104.245:8091 172.23.105.102:8091 172.23.105.93:8091 172.23.104.232:8091 172.23.105.86:8091 172.23.105.25:8091 172.23.105.29:8091 172.23.105.90:8091 172.23.105.112:8091 172.23.105.109:8091 172.23.104.165:8091] BucketName:ITEM UserAgent:gocb/v2.2.2 UseTLS:false NetworkType: Auth:0xc009a9d5e0 TLSRootCAProvider:0xe1c190 UseMutationTokens:true UseCompression:false UseDurations:true DisableDecompression:false UseOutOfOrderResponses:true DisableXErrors:false DisableJSONHello:false DisableSyncReplicationHello:false UseCollections:true CompressionMinSize:0 CompressionMinRatio:0 HTTPRedialPeriod:0s HTTPRetryDelay:0s CccpMaxWait:0s CccpPollPeriod:0s ConnectTimeout:10s KVConnectTimeout:7s KvPoolSize:0 MaxQueueSize:0 HTTPMaxIdleConns:0 HTTPMaxIdleConnsPerHost:0 HTTPIdleConnectionTimeout:0s Tracer:0xc009a9d2d0 NoRootTraceSpans:true DefaultRetryStrategy:0xc009a9d2b0 CircuitBreakerConfig:{Enabled:true VolumeThreshold:0 ErrorThresholdPercentage:0 SleepWindow:0s RollingWindow:0s CompletionCallback:<nil> CanaryTimeout:0s} UseZombieLogger:true ZombieLoggerInterval:0s ZombieLoggerSampleSize:0 AuthMechanisms:[]} 2021-03-17T16:08:32.942-07:00 [Error] Consumer::gocbConnectMetaBucketCallback [worker_timers_0_0:1] Failed to connect to metadata bucket ITEM (bucket got deleted?) , err: unambiguous timeout | {"InnerError":{"InnerError":{"InnerError":{},"Message":"unambiguous timeout"}},"OperationID":"WaitUntilReady","Opaque":"","TimeObserved":5000133580,"RetryReasons":["NOT_READY"],"RetryAttempts":10,"LastDispatchedTo":"","LastDispatchedFrom":"","LastConnectionID":""}

Charles Dixon added a comment - 18/Mar/21 4:08 AM

Looking at the goroutine dump it looks like one of the connections has failed to auth and has reattempted the auth request (probably with a different method) and the connection is then waiting for that request to complete, which in turn is preventing the entire agent from shutting down (this could be that the goroutine dump has just caught the SDK at this precise moment too I think). Without more detailed logs I can't say if the response has somehow got lost in gocbcore or if it's got lost on the network (it should have timed out if it was lost on the network anyway).

The WaitUntilReady timing out with retry reason of only [NOT_READY] and not [NOT_READY,CONNECTION_ERROR] suggests that at least one connection has failed to contact the relevant node or has somehow become blocked during bootstrap. If the connection was able to contact the node but failed to complete bootstrap (for example if the bucket doesn't exist at all) then we'd see the CONNECTION_ERROR reason. WaitUntilReady by default will wait for every connection to become available.

Charles Dixon added a comment - 18/Mar/21 4:08 AM Looking at the goroutine dump it looks like one of the connections has failed to auth and has reattempted the auth request (probably with a different method) and the connection is then waiting for that request to complete, which in turn is preventing the entire agent from shutting down (this could be that the goroutine dump has just caught the SDK at this precise moment too I think). Without more detailed logs I can't say if the response has somehow got lost in gocbcore or if it's got lost on the network (it should have timed out if it was lost on the network anyway). The WaitUntilReady timing out with retry reason of only [NOT_READY] and not [NOT_READY,CONNECTION_ERROR] suggests that at least one connection has failed to contact the relevant node or has somehow become blocked during bootstrap. If the connection was able to contact the node but failed to complete bootstrap (for example if the bucket doesn't exist at all) then we'd see the CONNECTION_ERROR reason. WaitUntilReady by default will wait for every connection to become available.

Charles Dixon added a comment - 18/Mar/21 4:43 AM

Vikas Chaudhary could you rerun this debug logging enabled please?

Charles Dixon added a comment - 18/Mar/21 4:43 AM Vikas Chaudhary could you rerun this debug logging enabled please?

Charles Dixon made changes - 18/Mar/21 4:44 AM

Assignee

Brett Lawson [ brett19 ]

Vikas Chaudhary [ vikas.chaudhary ]

Ritam Sharma added a comment - 18/Mar/21 7:38 AM

Charles Dixon- Can you please help with debugging steps, this is a system test env that works on dockers.

Ritam Sharma added a comment - 18/Mar/21 7:38 AM Charles Dixon - Can you please help with debugging steps, this is a system test env that works on dockers.

Ritam Sharma made changes - 18/Mar/21 7:38 AM

Assignee

Vikas Chaudhary [ vikas.chaudhary ]

Charles Dixon [ charles.dixon ]

Charles Dixon added a comment - 18/Mar/21 8:21 AM

Ritam Sharma I'm not aware of how to adjust debug levels of server components. Gocb does not provide an environment option for setting debug levels so it would have to be done from eventing. Ankit Prabhu can you assist with how to do this?

Charles Dixon added a comment - 18/Mar/21 8:21 AM Ritam Sharma I'm not aware of how to adjust debug levels of server components. Gocb does not provide an environment option for setting debug levels so it would have to be done from eventing. Ankit Prabhu can you assist with how to do this?

Charles Dixon made changes - 18/Mar/21 8:21 AM

Assignee

Charles Dixon [ charles.dixon ]

Ankit Prabhu [ ankit.prabhu ]

Mihir Kamdar (Inactive) made changes - 18/Mar/21 11:51 AM

Priority

Critical [ 2 ]

Blocker [ 1 ]

Mihir Kamdar (Inactive) made changes - 18/Mar/21 11:51 AM

Priority

Blocker [ 1 ]

Test Blocker [ 6 ]

Mihir Kamdar (Inactive) made changes - 18/Mar/21 11:51 AM

Labels

system-test

affects-cc-testing system-test

Mihir Kamdar (Inactive) added a comment - 18/Mar/21 11:52 AM

Marking this as a test blocker, as it prevents the test from proceeding further without a manual intervention.

Mihir Kamdar (Inactive) added a comment - 18/Mar/21 11:52 AM Marking this as a test blocker, as it prevents the test from proceeding further without a manual intervention.

Ankit Prabhu added a comment - 18/Mar/21 9:35 PM

Vikas Chaudhary Ritam Sharma changing function log level in setting will change the logs levels of the SDK.

Ankit Prabhu added a comment - 18/Mar/21 9:35 PM Vikas Chaudhary Ritam Sharma changing function log level in setting will change the logs levels of the SDK.

Ankit Prabhu made changes - 18/Mar/21 9:35 PM

Assignee

Ankit Prabhu [ ankit.prabhu ]

Vikas Chaudhary [ vikas.chaudhary ]

Ritam Sharma added a comment - 20/Mar/21 7:27 PM

Log levels are debug now:

Ritam Sharma added a comment - 20/Mar/21 7:27 PM Log levels are debug now: https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.106.134.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.120.58.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.120.73.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.120.74.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.120.75.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.120.77.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.120.81.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.120.86.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.121.77.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.123.24.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.123.25.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.123.26.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.123.31.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.123.32.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.123.33.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.96.122.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.96.14.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.96.243.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.96.254.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.96.48.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.97.105.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.97.110.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.97.112.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.97.148.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.97.149.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.97.150.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.97.151.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.97.241.zip https://cb-jira.s3.us-east-2.amazonaws.com/logs/MB-45053-01/collectinfo-2021-03-21T021758-ns_1%40172.23.97.74.zip

Ritam Sharma made changes - 20/Mar/21 7:28 PM

Assignee

Vikas Chaudhary [ vikas.chaudhary ]

Ankit Prabhu [ ankit.prabhu ]

Arunkumar Senthilnathan (Inactive) added a comment - 22/Mar/21 8:57 AM

Latest logs from 7.0.0-4735 run:

Arunkumar Senthilnathan (Inactive) added a comment - 22/Mar/21 8:57 AM Latest logs from 7.0.0-4735 run: url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.106.134.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.106.136.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.120.58.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.120.73.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.120.74.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.120.75.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.120.77.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.120.81.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.120.86.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.123.24.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.123.25.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.123.26.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.123.31.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.123.32.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.123.33.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.96.254.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.96.48.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.97.110.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.97.112.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.97.148.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.97.149.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.97.150.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.97.151.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.97.241.zip url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1616411900/collectinfo-2021-03-22T111822-ns_1%40172.23.97.74.zip

Matt Ingenthron added a comment - 22/Mar/21 10:22 PM

Ankit Prabhu: did you discover anything in looking at the logs to pass along?

Charles Dixon can you have a look at this with some priority? Per your request, they've re-run this with more detailed logging.

Matt Ingenthron added a comment - 22/Mar/21 10:22 PM Ankit Prabhu : did you discover anything in looking at the logs to pass along? Charles Dixon can you have a look at this with some priority? Per your request, they've re-run this with more detailed logging.

Matt Ingenthron made changes - 22/Mar/21 10:22 PM

Assignee

Ankit Prabhu [ ankit.prabhu ]

Charles Dixon [ charles.dixon ]

Ankit Prabhu added a comment - 22/Mar/21 10:30 PM

Matt Ingenthron, i looked at the logs. Logs rolled over and there is no logs when it actually got stuck. I am making some changes to eventing logger so that logs won't roll over.

Ankit Prabhu added a comment - 22/Mar/21 10:30 PM Matt Ingenthron , i looked at the logs. Logs rolled over and there is no logs when it actually got stuck. I am making some changes to eventing logger so that logs won't roll over.

Charles Dixon added a comment - 23/Mar/21 12:57 AM

Ankit Prabhu are you also able to move the gocbcore version being used to the latest gocbcore SHA? (https://github.com/couchbase/gocbcore/commit/341fc70dc8ba195416b4dc8f6d8599e391de686b) there were a couple of bugs introduced in 9.1.3 which are now fixed and may have an impact on this, such as https://issues.couchbase.com/browse/GOCBC-1073 .

Charles Dixon added a comment - 23/Mar/21 12:57 AM Ankit Prabhu are you also able to move the gocbcore version being used to the latest gocbcore SHA? ( https://github.com/couchbase/gocbcore/commit/341fc70dc8ba195416b4dc8f6d8599e391de686b) there were a couple of bugs introduced in 9.1.3 which are now fixed and may have an impact on this, such as https://issues.couchbase.com/browse/GOCBC-1073 .

Vikas Chaudhary added a comment - 23/Mar/21 1:26 AM

Seeing the same issue with functional tests as well. Weekly run is impacted due to this

Vikas Chaudhary added a comment - 23/Mar/21 1:26 AM Seeing the same issue with functional tests as well. Weekly run is impacted due to this

Vikas Chaudhary made changes - 23/Mar/21 1:26 AM

Labels

affects-cc-testing system-test

affects-cc-testing functional-test system-test

Prajwal‌ Kiran Kumar‌ (Inactive) added a comment - 23/Mar/21 1:50 AM

Many perf tests have failed, perf degradation has been observed and function deployment has hung due to this issue.

Prajwal‌ Kiran Kumar‌ (Inactive) added a comment - 23/Mar/21 1:50 AM Many perf tests have failed, perf degradation has been observed and function deployment has hung due to this issue.

Prajwal‌ Kiran Kumar‌ (Inactive) made changes - 23/Mar/21 1:50 AM

Labels

affects-cc-testing functional-test system-test

affects-cc-testing functional-test performance system-test

Charles Dixon added a comment - 23/Mar/21 2:44 AM - edited

I have just raised https://issues.couchbase.com/browse/GOCBC-1075 which MIGHT lead to this behaviour. I'm not sure of the mechanism involved for the GOCBC to lead to this issue but the resulting behaviour of the bug possibly leading to waiting on a channel indefinitely does appear to match.

Charles Dixon added a comment - 23/Mar/21 2:44 AM - edited I have just raised https://issues.couchbase.com/browse/GOCBC-1075 which MIGHT lead to this behaviour. I'm not sure of the mechanism involved for the GOCBC to lead to this issue but the resulting behaviour of the bug possibly leading to waiting on a channel indefinitely does appear to match.

Charles Dixon added a comment - 23/Mar/21 7:08 AM

I chatted with Ankit Prabhu and he said that he will create a toy build with the latest gocbcore fixes (including the above) and run the system test.

Charles Dixon added a comment - 23/Mar/21 7:08 AM I chatted with Ankit Prabhu and he said that he will create a toy build with the latest gocbcore fixes (including the above) and run the system test.

Charles Dixon made changes - 23/Mar/21 7:08 AM

Assignee

Charles Dixon [ charles.dixon ]

Ankit Prabhu [ ankit.prabhu ]

Raju Suravarjjala added a comment - 26/Mar/21 9:19 AM

Ankit Prabhu Any update?
cc Jeelan Poola and Ritam Sharma

Raju Suravarjjala added a comment - 26/Mar/21 9:19 AM Ankit Prabhu Any update? cc Jeelan Poola and Ritam Sharma

Couchbase Build Team added a comment - 29/Mar/21 2:32 AM

Build Couchbase Server-7.0.0-4807 contains eventing commit 83aa8bf with commit message:
~~MB-45053~~: Upgrade gocb@2.2.2 + fixes

Couchbase Build Team added a comment - 29/Mar/21 2:32 AM Build Couchbase Server-7.0.0-4807 contains eventing commit 83aa8bf with commit message: MB-45053 : Upgrade gocb@2.2.2 + fixes

Couchbase Build Team added a comment - 29/Mar/21 2:32 AM

Build Couchbase Server-7.0.0-4807 contains eventing commit 50bf671 with commit message:
~~MB-45053~~: Signal bootstrap finish when scope/collection gets deleted during bootstraping

Couchbase Build Team added a comment - 29/Mar/21 2:32 AM Build Couchbase Server-7.0.0-4807 contains eventing commit 50bf671 with commit message: MB-45053 : Signal bootstrap finish when scope/collection gets deleted during bootstraping

Jeelan Poola added a comment - 29/Mar/21 2:36 AM - edited

Temporary fixes (which are not yet released in any official gocb release) have been merged to master which should help unblock QE. But we can not resolve the ticket yet because we need to move gocb version used by eventing to a released version. Waiting for the same from SDK Team. Lowering the severity to Critical. Please raise it to blocker if the issue is still not fixed with build 4807.

Jeelan Poola added a comment - 29/Mar/21 2:36 AM - edited Temporary fixes (which are not yet released in any official gocb release) have been merged to master which should help unblock QE. But we can not resolve the ticket yet because we need to move gocb version used by eventing to a released version. Waiting for the same from SDK Team. Lowering the severity to Critical. Please raise it to blocker if the issue is still not fixed with build 4807.

Jeelan Poola made changes - 29/Mar/21 2:37 AM

Priority

Test Blocker [ 6 ]

Critical [ 2 ]

Jeelan Poola made changes - 29/Mar/21 2:39 AM

Assignee

Ankit Prabhu [ ankit.prabhu ]

Charles Dixon [ charles.dixon ]

Vikas Chaudhary added a comment - 29/Mar/21 10:55 AM

Jeelan Poola No EE builds are available http://172.23.126.166/builds/latestbuilds/couchbase-server/cheshire-cat/4807/couchbase-server-enterprise-7.0.0-4807-centos7.x86_64.rpm

Vikas Chaudhary added a comment - 29/Mar/21 10:55 AM Jeelan Poola No EE builds are available http://172.23.126.166/builds/latestbuilds/couchbase-server/cheshire-cat/4807/couchbase-server-enterprise-7.0.0-4807-centos7.x86_64.rpm

Couchbase Build Team added a comment - 29/Mar/21 4:34 PM

Build couchbase-server-7.0.0-4813 contains eventing commit 83aa8bf with commit message:
~~MB-45053~~: Upgrade gocb@2.2.2 + fixes

Couchbase Build Team added a comment - 29/Mar/21 4:34 PM Build couchbase-server-7.0.0-4813 contains eventing commit 83aa8bf with commit message: MB-45053 : Upgrade gocb@2.2.2 + fixes

Couchbase Build Team added a comment - 29/Mar/21 4:34 PM

Build couchbase-server-7.0.0-4813 contains eventing commit 50bf671 with commit message:
~~MB-45053~~: Signal bootstrap finish when scope/collection gets deleted during bootstraping

Couchbase Build Team added a comment - 29/Mar/21 4:34 PM Build couchbase-server-7.0.0-4813 contains eventing commit 50bf671 with commit message: MB-45053 : Signal bootstrap finish when scope/collection gets deleted during bootstraping

Brett Lawson made changes - 29/Mar/21 4:39 PM

Assignee

Charles Dixon [ charles.dixon ]

Jeelan Poola [ jeelan.poola ]

Jeelan Poola added a comment - 29/Mar/21 5:51 PM - edited

Brett Lawson Any particular reason why this is assigned to me? Do we have a released version of gocb with fixes in it? Intent is to leave this ticket assigned to SDK team until we have a released version of gocb with the necessary fixes. Once we have it, you may please update the same in eventing gomods files and resolve it.

Jeelan Poola added a comment - 29/Mar/21 5:51 PM - edited Brett Lawson Any particular reason why this is assigned to me? Do we have a released version of gocb with fixes in it? Intent is to leave this ticket assigned to SDK team until we have a released version of gocb with the necessary fixes. Once we have it, you may please update the same in eventing gomods files and resolve it.

Jeelan Poola made changes - 29/Mar/21 6:08 PM

Assignee

Jeelan Poola [ jeelan.poola ]

Brett Lawson [ brett19 ]

Brett Lawson added a comment - 30/Mar/21 11:23 AM

Hey Jeelan Poola,

We are waiting on validation from Ankit Prabhu that the fixes Charlie provided have resolve the issue. I accidentally assigned to you rather than them.

Cheers, Brett

Brett Lawson added a comment - 30/Mar/21 11:23 AM Hey Jeelan Poola , We are waiting on validation from Ankit Prabhu that the fixes Charlie provided have resolve the issue. I accidentally assigned to you rather than them. Cheers, Brett

Brett Lawson made changes - 30/Mar/21 11:24 AM

Assignee

Brett Lawson [ brett19 ]

Ankit Prabhu [ ankit.prabhu ]

Ankit Prabhu added a comment - 31/Mar/21 9:16 PM

Vikas Chaudhary, could you please confirm whether the issue is seen on latest build or not?

Ankit Prabhu added a comment - 31/Mar/21 9:16 PM Vikas Chaudhary , could you please confirm whether the issue is seen on latest build or not?

Ankit Prabhu made changes - 31/Mar/21 9:16 PM

Assignee

Ankit Prabhu [ ankit.prabhu ]

Vikas Chaudhary [ vikas.chaudhary ]

Ritam Sharma added a comment - 01/Apr/21 6:02 AM

Ankit Prabhu - Cannot confirm on latest build, since there are blocker issues with eventing.

Ritam Sharma added a comment - 01/Apr/21 6:02 AM Ankit Prabhu - Cannot confirm on latest build, since there are blocker issues with eventing.

Ritam Sharma made changes - 01/Apr/21 6:02 AM

Assignee

Vikas Chaudhary [ vikas.chaudhary ]

Ankit Prabhu [ ankit.prabhu ]

Couchbase Build Team added a comment - 01/Apr/21 12:51 PM