Serious Delete issue

Hi,
we are using sync gateway v.1.4.1-3 with Couchbase server v.4.6.2.
We are having some troubles to solve a problem that we cannot fully understand.

It happens randomly that the client doesn’t capture some changes of delete calls made by the server (through API).
In particular this is the situation. We have a web server that makes a HTTP call to delete a specific id (through the delete rest API). Client side we have implemented the replication in this way:

this.http.post(${this.urlLocalDb}_replicate, {source: ‘db’, target: ‘http://192.168.22.23:4984/db/’, websocket:true, continuous: true}).subscribe((data)=>{
this.http.post(${this.urlLocalDb}_replicate, {source: ‘http://192.168.22.23:4984/db/’, target: ‘db’, websocket:true, continuous: true}).subscribe((data)=>{
});
});

Every operation made by the server, except the delete, is instantly synchronized and we find it in the “_changes” endpoint. This is our client-side function:

checkChanged(){
let params: any = {
include_docs: true,
since: this.last_seq
};
let url = this.urlLocalDb +“db/_changes?” + this.serializeQueryParameters(params);

this.http.get(url).subscribe((data)=>{
const _data = data.json();
if(!this.ready || !_data.results.length){
setTimeout(()=>{
this.checkChanged();
}, 1000);
return;
}
this.last_seq = _data.last_seq;
window.localStorage.setItem(‘last_seq’, this.last_seq);
this.subject.next(_data);
setTimeout(()=>{
this.checkChanged();
}, 1000);
});
}

The issue cannot be in this method as it’s invoked every second and doesn’t capture any change meanwhile in the “_changes” endpoint. Moreover the replication still works because new documents or updated documents find their way to the client through this method. We also noticed that the delete change isn’t captured in a totally random way, without logic.
We also thought about a possible workaround, i.e. making a PUT call with a custom delete parameter set to true but we don’t want to do this because the DELETE API itself SHOULD work.
With this presupposition it’s impossible to move the application in production environment. It is necessary that someone of the Couchbase team enlighten us, please.

It’s possible you’ve got conflicts where one actor updates a document and another deletes it (‘simultaneously’, i.e. both acting on the same revision.) The result will be that the deletion is ignored.

How are you deleting the document?

When the client fails to see a delete, is the delete still visible on the server if you do a GET to the SG REST API?

The fact is that there was only one actor involved (a single device) that was already displaying the document. Then we made a delete with the DELETE api (Calling ‘url/db/id?rev=xxx’ with the DELETE method) from our backend panel but the ‘_changes’ on the device isn’t triggered (we were inspecting the network http requests on the device in the meanwhile) and it happens randomly. Sometimes it is triggered some others don’t but only for the delete api. Otherwise in case of new or updated document it never fails.
Then on the backend panel when we launch the ‘all_docs’ api again we see that the deleted document is correctly deleted. Just the ‘_changes’ api seems not aware of this and the device doesn’t know that a document is deleted.

Sounds like a SG issue; any ideas, @adamf / @andy / @traun ?

I’ve seen a similar scenario when the document being deleted is the one granting the client user access to the channel - since they no longer have access to the channel, they aren’t notified of the deleted document in that channel.

I can’t tell whether that’s the case here. How is the client user being granted access to the deleted document?

I’m glad that I finally got the attention of the team because I’m stuck with this issue.
I attach my SG code here.

{
“log”: [“HTTP+”, “Changes”, “CRUD”, “Replicate”],
“adminInterface”: “127.0.0.1:4985”,
“interface”: “0.0.0.0:4984”,
“databases”: {
“db”: {
“import_docs”: true,
“server”: “http://192.168.22.23:8091”,
“bucket”: “storeapp”,
“users”: {
“GUEST”: {“disabled”: false, “admin_channels”: ["*"] }
},
“sync”: function(doc, oldDoc){ channel('testfinale_'); }
}
}
}

As you can see we haven’t blocked any user in particular and also the problem happens randomly and not all the times a document is deleted.

Here’s the code of the delete function:

deleteProduct(id, rev) {
return this.http.delete(http://192.168.22.23:4984/db/${id}?rev=${rev})
.map(res => {
return res.json();
})
.catch(error => {
return Observable.throw(error.json());
});
}

Any ideas?
Thx

Can you post a gist with your Sync Gateway logs showing both the delete operation, and a subsequent changes request that doesn’t get the delete? Running with “log”:"*" would be ideal.

I tried to replicate both cases (working and not working DELETE).
This is the successful one and I correctly get the change from the device. This is the SG log:

2017-08-02T12:06:05.898+02:00 HTTP: #019: OPTIONS /db/6e1febf7905e46a2053d96276d3ffa86?rev=1-315fc58c41f9154eb389f727346b28a3
2017-08-02T12:06:05.899+02:00 HTTP+: #019: --> 204 (0.2 ms)
2017-08-02T12:06:05.909+02:00 HTTP: #020: DELETE /db/6e1febf7905e46a2053d96276d3ffa86?rev=1-315fc58c41f9154eb389f727346b28a3
2017-08-02T12:06:05.909+02:00 CRUD+: Invoking sync on doc “6e1febf7905e46a2053d96276d3ffa86” rev 2-a64614d789fa173ce3ade42606628fa5
2017-08-02T12:06:05.909+02:00 CRUD+: Saving old revision “6e1febf7905e46a2053d96276d3ffa86” / “1-315fc58c41f9154eb389f727346b28a3” (36 bytes)
2017-08-02T12:06:05.910+02:00 CRUD+: Backed up obsolete rev “6e1febf7905e46a2053d96276d3ffa86”/"1-315fc58c41f9154eb389f727346b28a3"
2017-08-02T12:06:05.910+02:00 CRUD+: SAVING #3
2017-08-02T12:06:05.911+02:00 CRUD: Stored doc “6e1febf7905e46a2053d96276d3ffa86” / "2-a64614d789fa173ce3ade42606628fa5"
2017-08-02T12:06:05.912+02:00 HTTP+: #020: --> 200 (2.9 ms)
2017-08-02T12:06:07.808+02:00 Cache: Received #3 after 1897ms (“6e1febf7905e46a2053d96276d3ffa86” / “2-a64614d789fa173ce3ade42606628fa5”)
2017-08-02T12:06:07.808+02:00 Cache: #3 ==> channel “testfinale_“
2017-08-02T12:06:07.808+02:00 Cache: #3 ==> channel “
2017-08-02T12:06:07.808+02:00 Changes+: Notifying that “storeapp” changed (keys=”{
, testfinale_}”) count=6
2017-08-02T12:06:07.808+02:00 Changes+: MultiChangesFeed: channels expand to “!:1,:1" …
2017-08-02T12:06:07.808+02:00 Changes+: MultiChangesFeed: channels expand to "!:1,
:1” …
2017-08-02T12:06:07.808+02:00 Cache: getCachedChanges(”", 2) --> 1 changes valid from #2
2017-08-02T12:06:07.808+02:00 Changes+: [changesFeed] Found 1 changes for channel *
2017-08-02T12:06:07.808+02:00 Cache: getCachedChanges("!", 2) --> 0 changes valid from #1
2017-08-02T12:06:07.808+02:00 Cache: getCachedChanges("!", 2) --> 0 changes valid from #1
2017-08-02T12:06:07.808+02:00 Changes+: [changesFeed] Found 0 changes for channel !
2017-08-02T12:06:07.808+02:00 Changes+: [changesFeed] Found 0 changes for channel !
2017-08-02T12:06:07.808+02:00 Cache: getCachedChanges("
”, 2) --> 1 changes valid from #2
2017-08-02T12:06:07.808+02:00 Changes+: [changesFeed] Found 1 changes for channel *
2017-08-02T12:06:07.808+02:00 Changes+: Channel feed processing seq:3 in channel *
2017-08-02T12:06:07.808+02:00 Changes+: MultiChangesFeed waiting…
2017-08-02T12:06:07.808+02:00 Changes+: Waiting for “storeapp”'s count to pass 6
2017-08-02T12:06:07.808+02:00 Changes+: Channel feed processing seq:3 in channel *
2017-08-02T12:06:07.808+02:00 Changes+: MultiChangesFeed sending {Seq:3, ID:6e1febf7905e46a2053d96276d3ffa86, Changes:[map[rev:2-a64614d789fa173ce3ade42606628fa5]], Deleted:true}
2017-08-02T12:06:07.808+02:00 Changes+: MultiChangesFeed waiting…
2017-08-02T12:06:07.808+02:00 Changes+: Waiting for “storeapp”'s count to pass 6
2017-08-02T12:06:07.808+02:00 Changes: sending 1 change(s)
2017-08-02T12:06:07.808+02:00 HTTP+: #007: --> WebSocket closed
2017-08-02T12:06:07.817+02:00 HTTP: #021: GET /db/6e1febf7905e46a2053d96276d3ffa86?rev=2-a64614d789fa173ce3ade42606628fa5&revs=true&attachments=true&atts_since=%5B%221-315fc58c41f9154eb389f727346b28a3%22%5D
2017-08-02T12:06:07.818+02:00 HTTP+: #021: --> 200 (0.7 ms)
2017-08-02T12:06:07.824+02:00 HTTP: #022: PUT /db/_local/c413c13bdab28b8f34987202c1bea69e0c2718f8
2017-08-02T12:06:07.825+02:00 HTTP+: #022: --> 201 (1.2 ms)
2017-08-02T12:06:12.860+02:00 HTTP: #023: PUT /db/_local/481af35637d3374373048afc6e3d3c92676d536f
2017-08-02T12:06:12.861+02:00 HTTP+: #023: --> 201 (1.9 ms)

This is the one not received by the device:

2017-08-02T11:29:38.094+02:00 Heartbeat: heartbeat written to changes feed for request received (as GUEST)
2017-08-02T11:32:45.754+02:00 HTTP: #356: OPTIONS /db/0495070f0ab922748b487dc9db6ea524?rev=1-7480cb3ed0bf31a9970e0878347a5042
2017-08-02T11:32:45.754+02:00 HTTP+: #356: --> 204 (0.2 ms)
2017-08-02T11:32:56.112+02:00 HTTP: #357: DELETE /db/0495070f0ab922748b487dc9db6ea524?rev=1-7480cb3ed0bf31a9970e0878347a5042
2017-08-02T11:32:56.112+02:00 CRUD+: Invoking sync on doc “0495070f0ab922748b487dc9db6ea524” rev 2-6574e0fe322e7ed8349cb64793300957
2017-08-02T11:32:56.113+02:00 CRUD+: Saving old revision “0495070f0ab922748b487dc9db6ea524” / “1-7480cb3ed0bf31a9970e0878347a5042” (159 bytes)
2017-08-02T11:32:56.113+02:00 CRUD+: Backed up obsolete rev “0495070f0ab922748b487dc9db6ea524”/"1-7480cb3ed0bf31a9970e0878347a5042"
2017-08-02T11:32:56.114+02:00 CRUD+: SAVING #17101
2017-08-02T11:32:56.115+02:00 CRUD: Stored doc “0495070f0ab922748b487dc9db6ea524” / "2-6574e0fe322e7ed8349cb64793300957"
2017-08-02T11:32:56.116+02:00 HTTP+: #357: --> 200 (4.5 ms)
2017-08-02T11:32:57.530+02:00 Cache: Received #17101 after 1416ms (“0495070f0ab922748b487dc9db6ea524” / “2-6574e0fe322e7ed8349cb64793300957”)
2017-08-02T11:32:57.530+02:00 Cache: #17101 ==> channel "testfinale
"
2017-08-02T11:32:57.530+02:00 Cache+: Pruned 1 old entries from channel “"
2017-08-02T11:32:57.530+02:00 Cache: #17101 ==> channel "

2017-08-02T11:32:57.530+02:00 Changes+: Notifying that “storeapp” changed (keys=”{, testfinale_}") count=3
2017-08-02T11:32:57.531+02:00 Changes+: MultiChangesFeed: channels expand to "!:1,
:1” …
2017-08-02T11:32:57.531+02:00 Cache: getCachedChanges("*", 17099) --> 2 changes valid from #17100
2017-08-02T11:32:57.531+02:00 Changes+: [changesFeed] Found 2 changes for channel *
2017-08-02T11:32:57.531+02:00 Cache: getCachedChanges("!", 17099) --> 0 changes valid from #1
2017-08-02T11:32:57.531+02:00 Changes+: [changesFeed] Found 0 changes for channel !
2017-08-02T11:32:57.531+02:00 Changes+: Channel feed processing seq:17100 in channel *
2017-08-02T11:32:57.531+02:00 Changes+: Channel feed processing seq:17101 in channel *
2017-08-02T11:32:57.531+02:00 Changes+: MultiChangesFeed waiting…
2017-08-02T11:32:57.531+02:00 Changes+: Waiting for “storeapp”'s count to pass 3

@albalb45 I can’t tell what’s going on from those log excerpts - I’d need a more complete log that includes the initial changes requests to dig into this further. I’ve filed https://github.com/couchbase/sync_gateway/issues/2767 to track the issue. If you can post a link to a gist (gist.github.com) with the full logs on that ticket, we can follow up.