My server unit tests for Sync Gateway REST API produces a high-speed call sequence that seems to break bucket shadowing, requiring Sync Gateway to be restarted. Upon preliminary investigation, I am seeing the following WARNING buried in the Sync Gateway console, but unsure if it’s related or not.
WARNING
2015-12-03T05:22:48.732Z WARNING: Error pushing rev of "TESTKEY:1B" to external bucket: MCResponse status=KEY_ENOENT, opcode=DELETE, opaque=0, msg: Not found -- db.(*Shadower).PushRevision() at shadower.go:162
Pseudo Code / Sequence
Simulating the (approximate) sequence produced by go unit test that causes the anomaly is:
Loop high-speed for 50 - 100 cycles:
GET doc_id // Get doc (and acquire latest _rev)
DELETE doc_id, _rev // Use _rev returned by Get, above
POST doc_id // Insert a doc with same key as just deleted
Question
Q1: What causes this error, how can it be avoided in a high-load situation, and should bucket shadowing recover?
Q2: Is it possible to DELETE or PUT a document without knowing the latest _rev ( for brute force doc deletes or overwrite situations where the _rev is not initially available )? In other words, force a doc delete or replace without first querying for the latest known _rev.
Note
Client vs. Server speed may be a factor, influencing cycles required to overload the server.
It appears the _rev may become stale ( behind the latest POST _rev ) as the Sync Gateway has not caught up resolving the cache / queue. The problem that concerns me is this approximate scenario could happen in a deployed high-load situation.
.
.
.
.
More from the console:
2015-12-03T05:22:48.622Z HTTP: #4306: GET /test_store_sg/TESTKEY:1B (ADMIN)
2015-12-03T05:22:48.653Z HTTP: #4306: --> 404 deleted (31.0 ms)
2015-12-03T05:22:48.658Z HTTP: #4307: GET /test_store_sg/ (ADMIN)
2015-12-03T05:22:48.659Z HTTP+: #4307: --> 200 (0.6 ms)
2015-12-03T05:22:48.661Z HTTP: #4308: GET /test_store_sg/TESTKEY:1B (ADMIN)
2015-12-03T05:22:48.711Z Cache: Received deduplicated #3245 for ("TESTKEY:1B" / "1762-bc72a185f288c31aee1176de268b518e")
2015-12-03T05:22:48.711Z Cache: Received deduplicated #3246 for ("TESTKEY:1B" / "1762-bc72a185f288c31aee1176de268b518e")
2015-12-03T05:22:48.711Z Cache: Received deduplicated #3247 for ("TESTKEY:1B" / "1762-bc72a185f288c31aee1176de268b518e")
2015-12-03T05:22:48.711Z Cache: Received #3248 after 414ms ("TESTKEY:1B" / "1762-bc72a185f288c31aee1176de268b518e")
2015-12-03T05:22:48.711Z Cache: #3248 ==> channel "public"
2015-12-03T05:22:48.712Z Cache: #3248 ==> channel "*"
2015-12-03T05:22:48.712Z Changes+: Notifying that "test_store_sync_gateway" changed (keys="{*, public}") count=141
2015-12-03T05:22:48.711Z HTTP: #4308: --> 404 deleted (49.7 ms)
2015-12-03T05:22:48.722Z Cache: Received #3248 after 391ms ("TESTKEY:1B" / "1762-bc72a185f288c31aee1176de268b518e")
2015-12-03T05:22:48.724Z HTTP: #4309: GET /test_store_sg/ (ADMIN)
2015-12-03T05:22:48.725Z HTTP+: #4309: --> 200 (1.2 ms)
2015-12-03T05:22:48.726Z Shadow: Pushing "TESTKEY:1B", rev "1762-bc72a185f288c31aee1176de268b518e" [deletion]
2015-12-03T05:22:48.732Z HTTP: #4310: GET /test_store_sg/TESTKEY:1B (ADMIN)
2015-12-03T05:22:48.732Z WARNING: Error pushing rev of "TESTKEY:1B" to external bucket: MCResponse status=KEY_ENOENT, opcode=DELETE, opaque=0, msg: Not found -- db.(*Shadower).PushRevision() at shadower.go:162
2015-12-03T05:22:48.772Z Shadow: Pushing "TESTKEY:1B", rev "1762-bc72a185f288c31aee1176de268b518e" [deletion]
2015-12-03T05:22:48.784Z WARNING: Error pushing rev of "TESTKEY:1B" to external bucket: MCResponse status=KEY_ENOENT, opcode=DELETE, opaque=0, msg: Not found -- db.(*Shadower).PushRevision() at shadower.go:162
2015-12-03T05:22:48.793Z HTTP: #4310: --> 404 deleted (61.0 ms)