couchbase/sync_gateway

changes response randomly empty

olivierboudet opened this issue · 3 comments

olivierboudet commented

Sync Gateway version

Couchbase Sync Gateway/2.7.2(2;583d2dc) CE

Operating system

Ubuntu 16.04 on kubernetes 1.15 (GKE)

Config file

The server in bucket configuration is a kubernetes service to reach one of our 3 pods in round robin.

{
	"adminInterface":"0.0.0.0:4985",
	"interface":"0.0.0.0:4984",
	"logging": {
		"console": {
			"log_level": "debug",
			"log_keys": [ "Changes" ]
		}
	},
	"databases": {
		"porc": {
			"unsupported": {
				"user_views": {
					"enabled": true
				}
			},
			"server": "http://couchbase-service:8091",
			"allow_empty_password": false,
			"bucket": "porc",
      		"username":"syncgateway",
			"password":"syncgateway",
			"use_views": false,
			"num_index_replicas": 0,
			"enable_shared_bucket_access": true, 
            "import_docs": true,
			"sync": "function(doc, oldDoc) {channel(doc.model+'_'+doc.identifiantSite)};",
			"users": {
				"GUEST": {
					"disabled": true,
					"admin_channels": [
						"*"
					],
					"all_channels": [
						"*"
					]
				}
			}
		}
	}
}

Log output

2020-06-26T14:41:46.497Z [INF] HTTP:  #384: GET / (as ADMIN)
2020-06-26T14:41:51.702Z [INF] HTTP:  #385: GET /porc/_changes?limit=5&style=main_only&active_only=false&include_docs=false&filter=&channels=[_admin]&doc_ids=[ANIMAL:222EM:3400000000000000001800149027:20181226]&feed=normal&since=&heartbeat=0&timeout=300000 (as ADMIN)
2020-06-26T14:41:51.702Z [DBG] Changes+: c:#385 Int sequence multi changes feed...
2020-06-26T14:41:51.702Z [INF] Changes: c:#385 MultiChangesFeed(channels: {*}, options: {Since: 0, Limit: 5, Conflicts: false, IncludeDocs: false, Wait: false, Continuous: false, HeartbeatMs: 0, TimeoutMs: 300000, ActiveOnly: false}) ... 
2020-06-26T14:41:51.702Z [DBG] Changes+: c:#385 MultiChangesFeed: channels expand to "" ... 
2020-06-26T14:41:51.704Z [WRN] Error when querying index using statement: [SELECT meta(`porc`).xattrs._sync.sequence AS seq, meta(`porc`).xattrs._sync.rev AS rev, meta(`porc`).xattrs._sync.flags AS flags, META(`porc`).id AS id FROM `porc` USE INDEX (sg_allDocs_x1) WHERE meta(`porc`).xattrs._sync.sequence >= $startSeq AND meta(`porc`).xattrs._sync.sequence < $endSeq AND META().id NOT LIKE '\\_sync:%' LIMIT 5] parameters: [map[channelName:* endSeq:3043164 startSeq:1]] error:[4040] No such prepared statement: fbbd176c-59fe-57dc-a4ec-e76f602a377b -- base.(*CouchbaseBucketGoCB).Query() at bucket_n1ql.go:76
2020-06-26T14:41:51.704Z [DBG] Changes+: c:#385 [changesFeed] Found 0 changes for channel "*"
2020-06-26T14:41:51.704Z [WRN] c:#385 MultiChangesFeed got error reading changes feed "*": [4040] No such prepared statement: fbbd176c-59fe-57dc-a4ec-e76f602a377b -- db.(*Database).SimpleMultiChangesFeed.func1() at changes.go:548
2020-06-26T14:41:51.704Z [INF] Changes: c:#385 MultiChangesFeed done 
2020-06-26T14:41:57.082Z [INF] HTTP:  #386: GET /porc/_changes?limit=5&style=main_only&active_only=false&include_docs=false&filter=&channels=[_admin]&doc_ids=[ANIMAL:222EM:3400000000000000001800149027:20181226]&feed=normal&since=&heartbeat=0&timeout=300000 (as ADMIN)
2020-06-26T14:41:57.083Z [DBG] Changes+: c:#386 Int sequence multi changes feed...
2020-06-26T14:41:57.083Z [INF] Changes: c:#386 MultiChangesFeed(channels: {*}, options: {Since: 0, Limit: 5, Conflicts: false, IncludeDocs: false, Wait: false, Continuous: false, HeartbeatMs: 0, TimeoutMs: 300000, ActiveOnly: false}) ... 
2020-06-26T14:41:57.083Z [DBG] Changes+: c:#386 MultiChangesFeed: channels expand to "" ... 
2020-06-26T14:41:57.083Z [WRN] Error when querying index using statement: [SELECT meta(`porc`).xattrs._sync.sequence AS seq, meta(`porc`).xattrs._sync.rev AS rev, meta(`porc`).xattrs._sync.flags AS flags, META(`porc`).id AS id FROM `porc` USE INDEX (sg_allDocs_x1) WHERE meta(`porc`).xattrs._sync.sequence >= $startSeq AND meta(`porc`).xattrs._sync.sequence < $endSeq AND META().id NOT LIKE '\\_sync:%' LIMIT 5] parameters: [map[channelName:* endSeq:3043164 startSeq:1]] error:[4040] No such prepared statement: fbbd176c-59fe-57dc-a4ec-e76f602a377b -- base.(*CouchbaseBucketGoCB).Query() at bucket_n1ql.go:76
2020-06-26T14:41:57.083Z [DBG] Changes+: c:#386 [changesFeed] Found 0 changes for channel "*"
2020-06-26T14:41:57.084Z [WRN] c:#386 MultiChangesFeed got error reading changes feed "*": [4040] No such prepared statement: fbbd176c-59fe-57dc-a4ec-e76f602a377b -- db.(*Database).SimpleMultiChangesFeed.func1() at changes.go:548
2020-06-26T14:41:57.084Z [INF] Changes: c:#386 MultiChangesFeed done 
2020-06-26T14:42:02.405Z [INF] HTTP:  #387: GET /porc/_changes?limit=5&style=main_only&active_only=false&include_docs=false&filter=&channels=[_admin]&doc_ids=[ANIMAL:222EM:3400000000000000001800149027:20181226]&feed=normal&since=&heartbeat=0&timeout=300000 (as ADMIN)
2020-06-26T14:42:02.405Z [DBG] Changes+: c:#387 Int sequence multi changes feed...
2020-06-26T14:42:02.405Z [INF] Changes: c:#387 MultiChangesFeed(channels: {*}, options: {Since: 0, Limit: 5, Conflicts: false, IncludeDocs: false, Wait: false, Continuous: false, HeartbeatMs: 0, TimeoutMs: 300000, ActiveOnly: false}) ... 
2020-06-26T14:42:02.405Z [DBG] Changes+: c:#387 MultiChangesFeed: channels expand to "" ... 
2020-06-26T14:42:02.411Z [DBG] Changes+: c:#387 [changesFeed] Found 5 changes for channel "*"
2020-06-26T14:42:02.412Z [DBG] Changes+: c:#387 Channel feed processing seq:97 in channel * 
2020-06-26T14:42:02.412Z [DBG] Changes+: c:#387 Channel feed processing seq:98 in channel * 
2020-06-26T14:42:02.412Z [DBG] Changes+: c:#387 Channel feed processing seq:99 in channel * 
2020-06-26T14:42:02.412Z [DBG] Changes+: c:#387 MultiChangesFeed sending {Seq:97, ID:BANDE:29TF3:201916, Changes:[map[rev:1-187957886efe31194776af437cf8cbbd]]} 
2020-06-26T14:42:02.412Z [DBG] Changes+: c:#387 MultiChangesFeed sending {Seq:98, ID:BANDE:29TF3:201919, Changes:[map[rev:1-c9f632a0460c6f162cbb431b41404452]]} 
2020-06-26T14:42:02.412Z [DBG] Changes+: c:#387 MultiChangesFeed sending {Seq:99, ID:BANDE:29TF3:201922, Changes:[map[rev:1-8b10193004ea4593161524ca5218f098]]} 
2020-06-26T14:42:02.412Z [DBG] Changes+: c:#387 Channel feed processing seq:106 in channel * 
2020-06-26T14:42:02.412Z [DBG] Changes+: c:#387 Channel feed processing seq:110 in channel * 
2020-06-26T14:42:02.412Z [DBG] Changes+: c:#387 MultiChangesFeed sending {Seq:106, ID:BANDE:29TF3:201913, Changes:[map[rev:2-02c29e89a76b84140701ab9ccb602a64]]} 
2020-06-26T14:42:02.412Z [DBG] Changes+: c:#387 MultiChangesFeed sending {Seq:110, ID:BANDE:29TF3:201925, Changes:[map[rev:5-3c780696a6315b289f20a4f38edfae00]]} 
2020-06-26T14:42:02.412Z [INF] Changes: c:#387 MultiChangesFeed done 
2020-06-26T14:42:05.797Z [INF] HTTP:  #388: GET / (as ADMIN)

Expected behavior

We have 3 pods in kubernetes with couchbase server 6.5.0 community edition.
We are running a script with a loop to fetch changes on a document from a bucket (curl --location --request GET ‘http://localhost:4985/porc/_changes?limit=5&style=main_only&active_only=false&include_docs=false&filter=&channels=[_admin]&doc_ids=[ANIMAL:222EM:3400000000000000001800149027:20181226]&feed=normal&since=&heartbeat=0&timeout=300000’ --header ‘Accept: application/json’ --header ‘Content-Type: application/json’ --globoff
We expect to always have the same results.

This a test cluster, there is no other traffic than the one generated by the script.

Actual behavior

Randomly, the output of the query is empty. As shown below, 4 calls are returning my documents and 3 calls are returning an empty response :

{“results”:[
{“seq”:97,“id”:“BANDE:29TF3:201916",“changes”:[{“rev”:“1-187957886efe31194776af437cf8cbbd”}]}
,{“seq”:98,“id”:“BANDE:29TF3:201919",“changes”:[{“rev”:“1-c9f632a0460c6f162cbb431b41404452”}]}
,{“seq”:99,“id”:“BANDE:29TF3:201922",“changes”:[{“rev”:“1-8b10193004ea4593161524ca5218f098”}]}
,{“seq”:106,“id”:“BANDE:29TF3:201913",“changes”:[{“rev”:“2-02c29e89a76b84140701ab9ccb602a64”}]}
,{“seq”:110,“id”:“BANDE:29TF3:201925",“changes”:[{“rev”:“5-3c780696a6315b289f20a4f38edfae00”}]}
],
“last_seq”:“110”}
{“results”:[
],
“last_seq”:“0"}
{“results”:[
{“seq”:97,“id”:“BANDE:29TF3:201916",“changes”:[{“rev”:“1-187957886efe31194776af437cf8cbbd”}]}
,{“seq”:98,“id”:“BANDE:29TF3:201919",“changes”:[{“rev”:“1-c9f632a0460c6f162cbb431b41404452”}]}
,{“seq”:99,“id”:“BANDE:29TF3:201922",“changes”:[{“rev”:“1-8b10193004ea4593161524ca5218f098”}]}
,{“seq”:106,“id”:“BANDE:29TF3:201913",“changes”:[{“rev”:“2-02c29e89a76b84140701ab9ccb602a64”}]}
,{“seq”:110,“id”:“BANDE:29TF3:201925",“changes”:[{“rev”:“5-3c780696a6315b289f20a4f38edfae00”}]}
],
“last_seq”:“110”}
{“results”:[
],
“last_seq”:“0"}
{“results”:[
{“seq”:97,“id”:“BANDE:29TF3:201916",“changes”:[{“rev”:“1-187957886efe31194776af437cf8cbbd”}]}
,{“seq”:98,“id”:“BANDE:29TF3:201919",“changes”:[{“rev”:“1-c9f632a0460c6f162cbb431b41404452”}]}
,{“seq”:99,“id”:“BANDE:29TF3:201922",“changes”:[{“rev”:“1-8b10193004ea4593161524ca5218f098”}]}
,{“seq”:106,“id”:“BANDE:29TF3:201913",“changes”:[{“rev”:“2-02c29e89a76b84140701ab9ccb602a64”}]}
,{“seq”:110,“id”:“BANDE:29TF3:201925",“changes”:[{“rev”:“5-3c780696a6315b289f20a4f38edfae00”}]}
],
“last_seq”:“110”}
{“results”:[
{“seq”:97,“id”:“BANDE:29TF3:201916”,“changes”:[{“rev”:“1-187957886efe31194776af437cf8cbbd”}]}
,{“seq”:98,“id”:“BANDE:29TF3:201919”,“changes”:[{“rev”:“1-c9f632a0460c6f162cbb431b41404452"}]}
,{“seq”:99,“id”:“BANDE:29TF3:201922”,“changes”:[{“rev”:“1-8b10193004ea4593161524ca5218f098"}]}
,{“seq”:106,“id”:“BANDE:29TF3:201913”,“changes”:[{“rev”:“2-02c29e89a76b84140701ab9ccb602a64"}]}
,{“seq”:110,“id”:“BANDE:29TF3:201925”,“changes”:[{“rev”:“5-3c780696a6315b289f20a4f38edfae00"}]}
],
“last_seq”:“110"}
{“results”:[
],
“last_seq”:“0”}

In the log, we can see the following error :
2020-06-26T14:41:57.084Z [WRN] c:#386 MultiChangesFeed got error reading changes feed "*": [4040] No such prepared statement: fbbd176c-59fe-57dc-a4ec-e76f602a377b -- db.(*Database).SimpleMultiChangesFeed.func1() at changes.go:548

We had tested the same reproduction steps on couchbase server 6.0.0 (and SG 2.7.2) and we did not reproduce it.

bbrks commented

I believe there may be some compatibility issues with SDKs and Couchbase Server 6.5.0

You can try applying the server-side workaround here to see if this resolves your issue:
https://docs.couchbase.com/server/6.5/install/upgrade-strategy-for-features.html#prepared-statements

Previous discussion:
https://forums.couchbase.com/t/syncgateway-error-4040-no-such-prepared-statement/25163

olivierboudet commented

Thank you, we tried with the server-side workaround you linked but it does not help. We have the exact same error.
By the way, we also opened an issue because we can not apply the workaround when only one couchbase node is upgraded, so are forced to have a downtime... (https://issues.couchbase.com/browse/MB-40202)

bbrks commented

There's now a client-side fix available for the Go SDK, and we're planning on including the fix in upcoming releases 2.7.4, and 2.8.0

You can track the 2.7.4 backport here: https://issues.couchbase.com/browse/CBG-979

  • 👍1