Strange sync. issue.... - what could have happened?

I have a mobile app that uses sync gateway to exchange info. User can see all public documents - and can only create/update/delete own documents (also if public).

Now, I have one document that appears to be “empty”:

The meta data looks like this:

{
  "meta": {
    "id": "Catch:1589131910328DB006C50A0",
    "rev": "266-16489bf3205d00000000000000000000",
    "expiration": 0,
    "flags": 0,
    "type": "json"
  },
  "xattrs": {
    "_sync": {
      "rev": "4-4bc4cab710d2760daec66b58082f1f83334fc021",
      "flags": 1,
      "sequence": 1371320,
      "recent_sequences": [
        1371320
      ],
      "history": {
        "revs": [
          "2-235fbb104124321602f25c5afaea02f121eda824",
          "3-aab9f1093a5a80c3d80c3915a9b6bea578f62a9c",
          "4-4bc4cab710d2760daec66b58082f1f83334fc021",
          "1-015c0b2168d217e3032e7e85ecfe4418"
        ],
        "parents": [
          3,
          0,
          1,
          -1
        ],
        "deleted": [
          2
        ],
        "channels": [
          null,
          null,
          null,
          null
        ]
      },
      "cas": "0x00005d20f39b4816",
      "value_crc32c": "0x297bd0aa",
      "tombstoned_at": 1605704752,
      "time_saved": "2020-11-18T14:05:52.503273506+01:00"
    }
  }
}

I went to the Sync gateway server and looked for that key in the sg_info.log and found a lot of communication (left out similar entries in between start and end):

2020-11-16T22:56:56.534+01:00 [INF] Javascript: Sync doc id: Catch:1589131910328DB006C50A0, ispublic: true, userkey=EF9E7F3513256C88C12583DB006C50A0,  creation
2020-11-16T22:56:56.534+01:00 [INF] Javascript: Sync public, id: Catch:1589131910328DB006C50A0
2020-11-16T22:56:56.534+01:00 [INF] Javascript: Sync User owned, id: Catch:1589131910328DB006C50A0, type: Catch, user: EF9E7F3513256C88C12583DB006C50A0
2020-11-16T22:56:56.534+01:00 [INF] c:[7c785598] Sync fn rejected doc "Catch:1589131910328DB006C50A0" / "" --> 403 sg wrong user
2020-11-16T22:56:57.153+01:00 [INF] Javascript: Sync doc id: Catch:1589131910328DB006C50A0, ispublic: true, userkey=EF9E7F3513256C88C12583DB006C50A0,  creation
2020-11-16T22:56:57.153+01:00 [INF] Javascript: Sync public, id: Catch:1589131910328DB006C50A0
2020-11-16T22:56:57.153+01:00 [INF] Javascript: Sync User owned, id: Catch:1589131910328DB006C50A0, type: Catch, user: EF9E7F3513256C88C12583DB006C50A0
2020-11-16T22:56:57.154+01:00 [INF] c:[51198d8c] Sync fn rejected doc "Catch:1589131910328DB006C50A0" / "" --> 403 sg wrong user
2020-11-16T22:57:01.440+01:00 [INF] Javascript: Sync doc id: Catch:1589131910328DB006C50A0, ispublic: true, userkey=EF9E7F3513256C88C12583DB006C50A0,  creation
2020-11-16T22:57:01.440+01:00 [INF] Javascript: Sync public, id: Catch:1589131910328DB006C50A0
2020-11-16T22:57:01.440+01:00 [INF] Javascript: Sync User owned, id: Catch:1589131910328DB006C50A0, type: Catch, user: EF9E7F3513256C88C12583DB006C50A0
2020-11-16T22:57:01.440+01:00 [INF] c:[7c785598] Sync fn rejected doc "Catch:1589131910328DB006C50A0" / "" --> 403 sg wrong user
2020-11-16T22:57:01.672+01:00 [INF] Javascript: Sync doc id: Catch:1589131910328DB006C50A0, ispublic: true, userkey=EF9E7F3513256C88C12583DB006C50A0,  creation
2020-11-16T22:57:01.672+01:00 [INF] Javascript: Sync public, id: Catch:1589131910328DB006C50A0
2020-11-16T22:57:01.672+01:00 [INF] Javascript: Sync User owned, id: Catch:1589131910328DB006C50A0, type: Catch, user: EF9E7F3513256C88C12583DB006C50A0
2020-11-16T22:57:01.672+01:00 [INF] c:[51198d8c] Sync fn rejected doc "Catch:1589131910328DB006C50A0" / "" --> 403 sg wrong user
2020-11-16T23:29:19.936+01:00 [INF] Javascript: Sync doc id: Catch:1589131910328DB006C50A0, ispublic: true, userkey=EF9E7F3513256C88C12583DB006C50A0,  creation
2020-11-16T23:29:19.936+01:00 [INF] Javascript: Sync public, id: Catch:1589131910328DB006C50A0
2020-11-16T23:29:19.936+01:00 [INF] Javascript: Sync User owned, id: Catch:1589131910328DB006C50A0, type: Catch, user: EF9E7F3513256C88C12583DB006C50A0
2020-11-16T23:29:19.936+01:00 [INF] c:[791688d1] Sync fn rejected doc "Catch:1589131910328DB006C50A0" / "" --> 403 sg wrong user
:
:
2020-11-18T10:58:16.222+01:00 [INF] Javascript: Sync doc id: Catch:1589131910328DB006C50A0, ispublic: true, userkey=EF9E7F3513256C88C12583DB006C50A0,  creation
2020-11-18T10:58:16.222+01:00 [INF] Javascript: Sync public, id: Catch:1589131910328DB006C50A0
2020-11-18T10:58:16.222+01:00 [INF] Javascript: Sync User owned, id: Catch:1589131910328DB006C50A0, type: Catch, user: EF9E7F3513256C88C12583DB006C50A0
2020-11-18T10:58:16.222+01:00 [INF] c:[5a5c723a] Sync fn rejected doc "Catch:1589131910328DB006C50A0" / "" --> 403 sg wrong user
2020-11-18T11:56:40.044+01:00 [INF] Javascript: Sync doc id: Catch:1589131910328DB006C50A0, ispublic: true, userkey=EF9E7F3513256C88C12583DB006C50A0,  creation
2020-11-18T11:56:40.044+01:00 [INF] Javascript: Sync public, id: Catch:1589131910328DB006C50A0
2020-11-18T11:56:40.044+01:00 [INF] Javascript: Sync User owned, id: Catch:1589131910328DB006C50A0, type: Catch, user: EF9E7F3513256C88C12583DB006C50A0
2020-11-18T11:56:40.044+01:00 [INF] c:[5b4cacad] Sync fn rejected doc "Catch:1589131910328DB006C50A0" / "" --> 403 sg wrong user
2020-11-18T11:56:46.084+01:00 [INF] Javascript: Sync doc id: Catch:1589131910328DB006C50A0, ispublic: true, userkey=EF9E7F3513256C88C12583DB006C50A0,  creation
2020-11-18T11:56:46.084+01:00 [INF] Javascript: Sync public, id: Catch:1589131910328DB006C50A0
2020-11-18T11:56:46.084+01:00 [INF] Javascript: Sync User owned, id: Catch:1589131910328DB006C50A0, type: Catch, user: EF9E7F3513256C88C12583DB006C50A0
2020-11-18T11:56:46.084+01:00 [INF] c:[5b4cacad] Sync fn rejected doc "Catch:1589131910328DB006C50A0" / "" --> 403 sg wrong user
2020-11-18T14:05:52.502+01:00 [INF] Javascript: Sync doc deleted, id: Catch:1589131910328DB006C50A0, no oldDoc

It seems like the document was created on 2020-11-16 - but that confuses me a bit as the fishing trip that this catch document belongs to was last edited on 2020-10-05… (and those should align up unless some logic is broken or the app crashed in the middle of the work). Could creation mean that the user uninstalled the app and reinstalled it - so creation comes from the server?

The sync function (where some of the messages come from) looks like this:

			function (doc, oldDoc) {
                function _log(t) {
                    // Write to sg_info.log
                    console.log('' + t);
                }
                function _getUserKey(d) {
                    var key = null;
                    if (d) {
                        if (d.type == 'User') {
                            key = d.key;
                        } else {
                            key = d.userkey;
                        }
                    }
                    return key;
                }
            
				if (doc && doc._deleted) {
                    // Doc. deleted -> if public then require
					if(oldDoc){
	                    var userkey = _getUserKey(oldDoc);
	                    _log('delete doc id: ' + doc._id + ', userkey=' + userkey);
    	                if (userkey != null) {
		                    requireUser(userkey);
            	        } else {
                    	    requireAdmin();
						}
                    }
                    _log('doc deleted, id: ' + (doc._id || 'no id!') + ', ' + (oldDoc ? ('old key=' + oldDoc.key + ', userkey=' + userkey) : 'no oldDoc'));
                    return;
                }
                _log('doc id: ' + (doc._id || 'no id!') + ', ispublic: ' + doc.ispublic + ', userkey=' + doc.userkey + ', ' + (oldDoc ? (oldDoc._deleted ? 'oldDoc is deleted' : ('old key=' + oldDoc.key + ', oldDoc.userkey=' + oldDoc.userkey + ' update')) : ' creation'));
                // Document type is mandatory
                if (typeof doc.type === 'undefined') {
                    _log('Document type missing: ' + JSON.stringify(doc));
                    throw ({ forbidden: "Document type is required. id=" + doc._id });
                }
				if (doc.type == 'EnvLake' || doc.type == 'EnvMeasurement') {
                    throw ({ forbidden: "Document type '" + doc.type + "' not allowed on mobile. id=" + doc._id });
                }
				// Document key is mandatory
                if (typeof doc.key === 'undefined') {
                    _log('Document key missing: ' + JSON.stringify(doc));
                    throw ({ forbidden: "Document key is required. id=" + doc._id });
                }
                // Update: Cannot allow change of type or key
                if (oldDoc != null && !oldDoc._deleted) {
                    // Update
                    if (oldDoc.type != doc.type) {
                        throw ({ forbidden: "Can't change doc type" });
                    }
                    if (oldDoc.key != doc.key) {
                        throw ({ forbidden: "Can't change doc key" });
                    }
                }
                // Document sync is disabled (used for type Image - but generic implementation)
                if (doc.issyncdisabled) {
                    throw ({ forbidden: "Sync. disabled for id=" + doc._id });
                }
				var includeForStats = false;
                var userkey = _getUserKey(doc);
                // All public docs (not deleted) are available in the app
                if (doc.ispublic && doc.deleted != true) {
                    _log('public, id: ' + (doc._id || 'no id!'));
                    channel('!');
                } else if (doc.type == 'FishingTrip' || doc.type == 'Catch') {
                    // All fishing trips and catches are available (for stats and quotas)
					includeForStats = (userkey == null);
                    _log('Trip/catch for user: ' + (doc.userkey || "<external>") + ', id: ' + (doc._id || 'no id!'));
                    channel('!');
                 }
                // All users are available (for stats)
                if (doc.type == 'User' && doc.deleted != true) {
                    _log('User doc, id: ' + (doc._id || 'no id!'));
                    channel('!');
                 }

                // Allow anyone to create a Feedback or Observation on the server
                if (oldDoc == null && userkey == null && (doc.type == 'Feedback' || doc.type == 'Observation')) {
                    _log('Created ' + doc.type + ': ' + (doc._id || 'no id!') + ', key: ' + doc.key + ' as anonymous user ');
                    return;
                }
                // Allow app user  to create an ActivityLog on the server
                if (oldDoc == null && doc.type == 'ActivityLog') {
                    _log('Created ' + doc.type + ': ' + (doc._id || 'no id!') + ', key: ' + doc.key + ' for user: ' + doc.userkey);
                    return;
                }

                // Only non-public docs "owned" by user can be created/updated (and replicated)
                if (userkey != null) {
                    if (oldDoc != null && ! oldDoc._deleted) {
                        // Update
                        if (oldDoc.userkey && oldDoc.userkey != doc.userkey) {
                            throw ({ forbidden: "Can't change user key" });
                        }
                    }
                    _log('User owned, id: ' + (doc._id || 'no id!') + ', type: ' + doc.type + ', user: ' + userkey);
					if(doc.type != 'Image'){	// Do not send images TO mobile
	                    channel('channel.' + userkey);
					}
                    access(userkey, 'channel.' + userkey);
					requireUser(userkey);
                } else if (doc.ispublic || includeForStats) {
	                requireAdmin();
                } else {
                    // Creation/update without user
                    _log('Document type cannot be created without user key: ' + (doc.type === 'Image' ? doc._id : JSON.stringify(doc)));
                    throw ({ forbidden: "This document type cannot be created without user key. id=" + doc._id });
                }
             }

I find it very difficult to try and find out what happened. Any suggestions as to how best to troubleshoot problems like this?
And if the document is deleted should it then not be “gone” from the database instead of being there as an “empty” document? - or do I just see that as I point at it with the id?
Thanks for any insights!

Environment:
Running CB Community edition 6.6, sync. gateway 2.8.0 and CB Lite 2.7.1 (for the user in question)

You are right. If a document is deleted, assuming you have shared bucket access enabled, a tombstone is created and it should have no body. We are currently tracking an issue wherein deleting a non-existent document (such as via REST API) does in fact create a document with an empty body. So it is possible that in your specific case, the document in question didn’t exist (perhaps failed to be created in the first place) and a delete is causing this empty body document.

Based on the messages on the sync. gateway I guess it did exist… - but just trying to figure out based on the messages I see in the log.

The way I get the document is via a direct lookup - and that’s where the problems started as all items were empty (but the document wasn’t null). Is it normal that a deleted document will return the tombstone as an “empty” document if it is deleted? It hasn’t been a problem before but that could just have been plain luck. When getting a document (via the Java API on the server) then I only check for the document not being null…

As mentioned earlier - No. Based on what we know, deleting a document that doesn’t exist could result in this state. But you say that the document existed, - how was the documented deleted ?

Hmmmm… I was just looking at these messages:

2020-11-18T11:56:46.084+01:00 [INF] Javascript: Sync User owned, id: Catch:1589131910328DB006C50A0, type: Catch, user: EF9E7F3513256C88C12583DB006C50A0
2020-11-18T11:56:46.084+01:00 [INF] c:[5b4cacad] Sync fn rejected doc "Catch:1589131910328DB006C50A0" / "" --> 403 sg wrong user
2020-11-18T14:05:52.502+01:00 [INF] Javascript: Sync doc deleted, id: Catch:1589131910328DB006C50A0, no oldDoc

But that is all that I have…
And I don’t really understand the c:[5b4cacad] Sync fn rejected doc "Catch:1589131910328DB006C50A0" / "" --> 403 sg wrong user message… I have a userkey on each document that corresponds to the user’s id when logged into sync.gateway. So perhaps the “empty” document was created back at the beginning???
I have not heard from the user - I reacted on the “null” reference in the document on the server side.

Just to say that user can create, update and delete documents (with userkey the same as their user id). And that is what the app should do - and does in normal circumstances. But you never know what happens if for some reason the app crashed or whatever… And I have no evidence of any issues for this particular user - and we have very few crashes.