Replication Push is failing when attachments are involved

[reyalpsirc]

I was trying to change a document on the couchDB server and found out that the replication is failing when pushing the data:

Replication.AsyncTaskStarted: asyncTaskCount: 1
Replication.AsyncTaskStarted: updated to 2
Replication: Sending async POST request to: http://192.168.1.10:5984/beatstream/_bulk_docs
[Mono] GC_OLD_BRIDGE num-objects 31 num_hash_entries 6478 sccs size 3634 init 0.00ms df1 2.50ms sort 0.47ms dfs2 0.65ms setup-cb 0.08ms free-data 0.64ms links 10942/10942/3603/1 dfs passes 17451/14576
[Mono] GC_MINOR: (Nursery full) pause 4.20ms, total 4.26ms, bridge 7.41ms promoted 288K major 2816K los 14732K
Pusher: processInbox() calling AsyncTaskFinished()
Replication.AsyncTaskFinished: AsyncTaskCount: 2 > 1
SingleTaskThreadpoolScheduler:  --> Exiting runloop: 0/0
Thread finished: <Thread Pool> #19
Thread finished: <Thread Pool> #19
Thread started: <Thread Pool> #29
SingleTaskThreadpoolScheduler:  --> Queued a task: 1/0
SingleTaskThreadpoolScheduler:  --> Dequeued a task: 0/1
SingleTaskThreadpoolScheduler:  --> Exiting runloop: 0/0
SingleTaskThreadpoolScheduler:  --> Queued a task: 1/0
SingleTaskThreadpoolScheduler:  --> Dequeued a task: 0/1
Replication: Server Version: CouchDB/1.6.0
Replication:  Progress: set error = 
    [HttpResponseException: StatusCode = PreconditionFailed]
Replication: Firing NotifyChangeListeners event! [SingleTaskThreadpoolScheduler -> SynchronizationContextTaskScheduler]

And later, when it retries the push, it also gives this:

Replication: RETRYING, to transfer missed revisions...
Replication
     Progress: set error = 
SingleTaskThreadpoolScheduler: Scheduled task faulted
    System.NullReferenceException: Object reference not set to an instance of an object
      at Couchbase.Lite.Util.CustomLogger.E (System.String tag, System.String msg, System.Exception tr) [0x0006b] in <filename unknown>:0 
      at Couchbase.Lite.Util.Log.E (System.String tag, System.String msg, System.Exception tr) [0x00011] in <filename unknown>:0 
      at Couchbase.Lite.Replication.set_LastError (System.Exception value) [0x0000e] in <filename unknown>:0 
      at Couchbase.Lite.Replication.Retry () [0x00001] in <filename unknown>:0 
      at Couchbase.Lite.Replication.RetryIfReady () [0x0003d] in <filename unknown>:0 
      at Couchbase.Lite.Replication.<ScheduleRetryIfReady>m__9 (System.Threading.Tasks.Task task) [0x0001c] in <filename unknown>:0 
      at System.Threading.Tasks.ContinuationTaskFromTask.InnerInvoke () [0x00027] in <filename unknown>:0 
      at System.Threading.Tasks.Task.Execute () [0x00016] in <filename unknown>:0 
SingleTaskThreadpoolScheduler:  --> Exiting runloop: 0/0

But since that was a retry and in order to check what was happening, I've used Wireshark on the background to inspect the data sent to the server and found out that it was giving this error:

{"error":"missing_stub","reason":"id:1d317ef4d2e579658427c6273d0017c4, name:event_top_img.png"}

So, given that I inspected what was being sent to the request and found out that everything was being sent less some parts of the attachments. This is what is getting sent in relation to the attachments:

POST /beatstream/_bulk_docs HTTP/1.1
Accept: multipart/related,application/json
Content-Type: application/json
Content-Length: 574
Host: 192.168.1.10:5984
Cookie: AuthSession=Y3Jpczo1NTlCQURCNzrMw0U8yv_TqhKwtygRLweopmx3Yg

{
  "docs": [
    {
      [...]
      "_attachments": {
        "event_top_img.png": {
          "stub": true,
          "revpos": 89
        },
        "venue_top_img.png": {
          "stub": true,
          "revpos": 89
        }
      },
      [...]
  ],
  "new_edits": false
}

And this is what my Debug.WriteLine() gives when I call my save function:

{
    [...]
    "_attachments": {
        "event_top_img.png": {
            "content_type": "image/png",
            "digest": "sha1-r/jbl9IqDKbTMa7LLjp84uBLKzY=",
            "length": 320447,
            "revpos": 89,
            "stub": true
        },
        "venue_top_img.png": {
            "content_type": "image/png",
            "digest": "sha1-UTVihTr8wPSRSaPziEjx1WyNi54=",
            "length": 242353,
            "revpos": 89,
            "stub": true
        }
    },
    [...]
}

Might the problem be because the record on the couchDB server have the attachments as MD5? Because since the replication fails, they do not get updated to the SHA1

[reyalpsirc]

By the way, this is the content that exists on the server side:

{
    [...]
    "_attachments": {
       "venue_top_img.png": {
           "content_type": "image/png",
           "revpos": 39,
           "digest": "md5-ravv2WuyJ0c93JdlR6qNUA==",
           "length": 242353,
           "stub": true
       },
       "event_top_img.png": {
           "content_type": "image/png",
           "revpos": 38,
           "digest": "md5-aYIzjerJ9DcliX/GrK52Og==",
           "length": 320447,
           "stub": true
       }
    }
    [...]
}

Not sure if it helps creating an Unit test or something.

[borrrden]

Just out of curiosity, have you considered using Sync Gateway and Couchbase Server instead of CouchDB? CouchDB is not technically an officially supported endpoint for Couchbase Lite. It's more of a best effort. I'm not saying you have to switch but I just wanted to make sure you knew about this situation.

[reyalpsirc]

I'm not sure but the guy that researched this before told us to use couchDB and started with it. I think it was something related to the HTTP API's

[borrrden]

I see, well just letting you know that we have a cloud product that we officially support for future reference ;). It also adds on a few more neat features that CouchDB doesn't have. You can find out more about it here: http://developer.couchbase.com/mobile/develop/guides/sync-gateway/ I'll still take a look at CouchDB related stuff though, but just know that replication with CouchDB is not as well tested as replication with Sync Gateway.

[reyalpsirc]

Oh thanks. For future projects will consider using that then =). But on this one we can't change now unfortunately because it is already big and other things.

[reyalpsirc]

@borrrden just by curiosity, is this working with sync gateway?

[borrrden]

It should. I have around 2-3 dozen integration tests that test various replication scenarios with sync gateway (including attachments). I'll set up a test for CouchDB as well when I have a chance. If you want to submit one, that would push things along even faster.

[reyalpsirc]

You mean a little project that replicates the issue? But for that I will also need an online server with records causing the problem right?

[borrrden]

What I do is I start an instance of CouchDB on localhost and try to add similar items via C# REST calls. You can see some examples in my replication tests, for example https://github.com/couchbase/couchbase-lite-net/blob/master/src/Couchbase.Lite.Tests.Shared/ReplicationTest.cs#L669-L676

[reyalpsirc]

Ah ok. I do not have yet too much experience writing tests but, if I have some time available to try to make something similar to that, I will let you know here. But I don't think I will be able to do it today.

[reyalpsirc]

Ok, I'm currently trying to make a Xamarin Android Unit Tests project for this issue against CouchDB. Will let you know when done :)

[borrrden]

You can use the tests in the repo as examples to help you out. They are all
platform agnostic (I run them on all platforms).

[reyalpsirc]

I tried to make a rebuild of them but I get error on CollectionAssert. Anyway, I started a new Android Unit Tests on Xamarin and I'm using just some functions from the code that the other tests have. Once I have it done, is there a way I can send it to you?

[borrrden]

If it's an nunit test like the others then make a pull request. Otherwise put the main logic into a gist.

[reyalpsirc]

Ok @borrrden, I've been able to replicate this on a Unit Test project (but I think the test is not done as it should but works to see the issue).
The problem happens on the following situation:

• Server has a record with _rev=3 and with an attachment A.pngthat has revpos=2.
• App pulls the record through a continuous pull replication.
• App changes the record and sends it to server through a continuous push replication.
• An HttpResponseException: StatusCode = PreconditionFailed occurs and record is not updated on server
  ** The reason for the error is that when the push is done by the replication, it tries to send revpos=3 instead of revpos=2.

Here's the gist

[borrrden]

Great job! With some slight tweaking I will be able to throw this right in alongside the other unit tests we have! I'll let you know when I've done that.

[reyalpsirc]

Thanks :)

[borrrden]

Ok I've figured out what is going wrong, and a fix. I've also confirmed that this behavior happens in iOS native as well so I need to talk to the rest of the team to figure out if the behavior is intentional or not.

[reyalpsirc]

Ok, thanks. Let me know then if it will have a fix or how this should be handled.

[snej]

Did you confirm it with CBL/iOS 1.1 or with the master branch?
I fixed a slightly related issue, couchbase/couchbase-lite-ios#802, last week … it probably wouldn't have addressed this one, though.

[reyalpsirc]

It was with the master branch but, I might have mine out of date. Let me try pulling the most recent one and test again tomorrow.

[borrrden]

@reyalpsirc I think that comment was for me.
@snej I ran the tests on commit 78e23ef

[reyalpsirc]

Ok. Anyway, I tested this with the most recent version on the master (a7fa45a441fc024fa1759e00ab38dd53e3e805f5) and I can confirm that it still happens.

[borrrden]

Right, I didn't include the fix yet because I need to confirm with the Sync Gateway team first on whether or not this will cause issues with Sync Gateway. But I will post an update after we have talked about it.

[reyalpsirc]

Ok, thanks @borrrden, for everything :)

[reyalpsirc]

By the way, because of this issue, if a record is changed directly on Futon during tests, the continuous pull replication will work but, future pushs made through continuous push replication will also cause a PreconditionFailed. I though it was worth to mention this.

[reyalpsirc]

@borrrden Is it possible to make a fix on a separate branch temporarily? I need to finish a code until Friday that is dependent of this =/

[borrrden]

I have put my tentative fix into the issue/449 branch already. https://github.com/couchbase/couchbase-lite-net/tree/issue/449

[reyalpsirc]

Oh, thanks :D. Gonna try it out then.

[reyalpsirc]

@borrrden I tried it out but, has soon as I update the document via Futon, the pull replication gets it but, once I change it on the app, the push replication fails again with same error (PreconditionFailed)

[borrrden]

What about your unit test? Is that working?

[borrrden]

Oh wow, I'm sorry. I pushed some other stuff to that branch but not the actual fix. Update your branch and try again.

[reyalpsirc]

I tested with that fix now and I got other error on the UnitTest:

SqlitePCLRawStorageEngine: RawQuery sql: SELECT sequence, parent, revid, deleted, json isnull FROM revs WHERE doc_id=? ORDER BY sequence DESC (3)
Pusher: Unhandled exception in Pusher.ProcessInbox
    System.NullReferenceException: Object reference not set to an instance of an object
        at Couchbase.Lite.Store.SqliteCouchStore+<GetRevisionHistory>c__AnonStoreyD.<>m__0 (Couchbase.Lite.Cursor c) [0x000b4] in <filename unknown>:0 
        at Couchbase.Lite.Store.SqliteCouchStore.TryQuery (System.Func`2 action, Boolean readUncommit, System.String sqlQuery, System.Object[] args) [0x0004d] in <filename unknown>:0 
        at Couchbase.Lite.Store.SqliteCouchStore.GetRevisionHistory (Couchbase.Lite.Internal.RevisionInternal rev, ICollection`1 ancestorRevIds) [0x0008a] in <filename unknown>:0 
        at Couchbase.Lite.Database.GetRevisionHistory (Couchbase.Lite.Internal.RevisionInternal rev, IList`1 ancestorRevIds) [0x0001a] in <filename unknown>:0 
        at Couchbase.Lite.Replicator.Pusher+<ProcessInbox>c__AnonStorey0.<>m__0 (System.Object response, System.Exception e) [0x001ef] in <filename unknown>:0 
Pusher: processInbox() calling AsyncTaskFinished()

I also tested this on my project and I get other error while it is pulling the records:

Puller:    failed to write {1d317ef4d2e579658427c6273d0017c4 #118-2f382124afaa5953af7eaa34b97fb17e}: status=BadAttachment
Replication:    Progress: set error = 
    Couchbase.Lite.CouchbaseLiteException: Coucbase Lite error: BadAttachment
        at Couchbase.Lite.Database.ForceInsert (Couchbase.Lite.Internal.RevisionInternal inRev, IList`1 revHistory, System.Uri source) [0x000e9] in <filename unknown>:0 
        at Couchbase.Lite.Replicator.Puller+<InsertDownloads>c__AnonStorey3.<>m__0 () [0x000d7] in <filename unknown>:0 

This one seems weird to me because according to your code, it would mean that the attachment has no revpos but, maybe both issues are connected since the Unit Tests fail when pushing records (maybe because one of them has an attachment)?

[borrrden]

Interesting. What do you get when you get that revision in the browser (not through FUTON)? You can issue a command to http://:5984//1d317ef4d2e579658427c6273d0017c4?rev= 118-2f382124afaa5953af7eaa34b97fb17e

EDIT It also wouldn't hurt for me to ask what version of CouchDB you are using to make sure I am using the same one. I am on 1.6.1

[reyalpsirc]

I'm using the 1.6.0 version of CouchDB.
The json data that I get when I enter the direct url to the document revision is:

{
    "_id": "1d317ef4d2e579658427c6273d0017c4",
    "_rev": "118-2f382124afaa5953af7eaa34b97fb17e",
    "name": "Mosaic",
    "venueid": "92c23b33a21a7c25dfac762acd000f39",
    "description": "at DJ House",
    "premium": false,
    "extraminutes": 10,
    "type": "event",
    "image": [
        "event_top_img.png",
        "venue_top_img.png"
    ],
    "starttime": [
        2015,
        7,
        15,
        1,
        0,
        0
    ],
    "endtime": [
        2015,
        7,
        15,
        23,
        0,
        0
    ],
    "_attachments": {
        "ddMs51436968050933.png": {
            "content_type": "image/png",
            "revpos": 118,
            "digest": "md5-wDNcpluzrOGBDW1b3Yt4hg==",
            "length": 387666,
            "stub": true
        },
        "SETmt1436968046235.png": {
            "content_type": "image/png",
            "revpos": 118,
            "digest": "md5-xJbM4D7czo9DmAo/4bGtlA==",
            "length": 316787,
            "stub": true
        }
    }
}

[borrrden]

That all looks fine, but without the complete revision history to test on I cannot be more specific. I pushed a possible fix for the null reference exception you showed though.

[reyalpsirc]

It still gave the exception:

Puller:    failed to write {1d317ef4d2e579658427c6273d0017c4 #139-14a4d1c33afb8b6af1697cf01da396fd}: status=BadAttachment
Replication:    Progress: set error = 
    Couchbase.Lite.CouchbaseLiteException: Coucbase Lite error: BadAttachment
        at Couchbase.Lite.Database.ForceInsert (Couchbase.Lite.Internal.RevisionInternal inRev, IList`1 revHistory, System.Uri source) [0x000e9] in <filename unknown>:0 
        at Couchbase.Lite.Replicator.Puller+<InsertDownloads>c__AnonStorey3.<>m__0 () [0x000d7] in <filename unknown>:0 

So I will delete and re-add the document to check if it works (so that we know if it is an older revision problem)

[reyalpsirc]

Ok, after some time, I've been ablet to delete, purge and compact the document completely (there was indeed something wrong with him before but I'm sure it was now deleted since CouchDb was saying "missing" to his id).

Now I tried to create the document with the same id and the I added the image through the form of our web project and so, I got to this data:

{
    "_id": "1d317ef4d2e579658427c6273d0017c4",
    "_rev": "3-81fd3b938f1f6e694af250c0e64a8fe8",
    "name": "Mosaic",
    "venueid": "92c23b33a21a7c25dfac762acd000f39",
    "description": "at DJ House",
    "premium": false,
    "extraminutes": 30,
    "type": "event",
    "image": [
        "event_top_img.png",
        "venue_top_img.png"
    ],
    "starttime": [
        2015,
        7,
        16,
        1,
        0,
        0
    ],
    "endtime": [
        2015,
        7,
        16,
        23,
        30,
        0
    ],
    "_attachments": {
        "u3BxJ1437131406160.png": {
            "content_type": "image/png",
            "revpos": 3,
            "digest": "md5-xJbM4D7czo9DmAo/4bGtlA==",
            "length": 316787,
            "stub": true
        }
    }
}

After that, I tried it again and got the same error:

Puller: Inserting 1d317ef4d2e579658427c6273d0017c4 ["3-81fd3b938f1f6e694af250c0e64a8fe8","2-cd6cf4f0e3a3841bfcea81abef1cb5ad","1-84d1c090998e9e1711a2e834cdef4949"]
Puller:    failed to write {1d317ef4d2e579658427c6273d0017c4 #3-81fd3b938f1f6e694af250c0e64a8fe8}: status=BadAttachment
Replication:    Progress: set error = 
    Couchbase.Lite.CouchbaseLiteException: Coucbase Lite error: BadAttachment
        at Couchbase.Lite.Database.ForceInsert (Couchbase.Lite.Internal.RevisionInternal inRev, IList`1 revHistory, System.Uri source) [0x000e9] in <filename unknown>:0 
        at Couchbase.Lite.Replicator.Puller+<InsertDownloads>c__AnonStorey3.<>m__0 () [0x000d7] in <filename unknown>:0 
Replication: Firing NotifyChangeListeners event! [SingleTaskThreadpoolScheduler -> SynchronizationContextTaskScheduler]

So, the error persists but, since now I only have 2 more revisions, here goes the content of each one:
Rev 2:

{
    "_id": "1d317ef4d2e579658427c6273d0017c4",
    "_rev": "2-cd6cf4f0e3a3841bfcea81abef1cb5ad",
    "name": "Mosaic",
    "venueid": "92c23b33a21a7c25dfac762acd000f39",
    "description": "at DJ House",
    "premium": false,
    "extraminutes": 30,
    "type": "event",
    "image": [
        "event_top_img.png",
        "venue_top_img.png"
    ],
    "starttime": [
        2015,
        7,
        16,
        1,
        0,
        0
    ],
    "endtime": [
        2015,
        7,
        16,
        23,
        30,
        0
    ]
}

Rev 1:

{
    "_id": "1d317ef4d2e579658427c6273d0017c4",
    "_rev": "1-84d1c090998e9e1711a2e834cdef4949",
    "name": "Mosaic",
    "venueid": "92c23b33a21a7c25dfac762acd000f39",
    "description": "at DJ House",
    "premium": false,
    "extraminutes": 30,
    "type": "event",
    "image": [
        "event_top_img.png",
        "venue_top_img.png"
    ],
    "starttime": [
        2015,
        7,
        16,
        1,
        0,
        0
    ],
    "endtime": [
        2015,
        7,
        16,
        23,
        30,
        0
    ]
}

[borrrden]

@reyalpsirc Thanks to that data I was able to find the problem. Check the latest update on the branch (actually only one character needed to be changed).

[reyalpsirc]

It worked! Thanks @borrrden :).