Push replication stops with error `400 bad_request`

[pahmed]

I have an issue where the the push replicator stops after receiving this error

Error Domain=CBLHTTP Code=400 "400 bad_request" UserInfo={NSURL=http://xxx:4984/xxx/contact%3AE0294D55-EB14-4C71-8100-98B71E772C01?new_edits=false, NSLocalizedFailureReason=bad_request, NSLocalizedDescription=400 bad_request}

When i tried to get that document, i didn't find it. I noticed also that after terminating and reopening again, the replicator pushes some changes and stops again. I tried disabling ForestDB but that didn't solve the problem.

I have enabled logging SyncVerbose, RemoteRequest and attached the logs sync_logs.txt

---

• Version: CBL 1.2
• Client OS: iOS 9.3.1
• Server: 3.0.1 Community Edition
• Syncgateway: 1.2

[snej]

RemoteRequest: CBLMultipartUploader[PUT http://xxx:4984/xxx/contact%3AE0294D55-EB14-4C71-8100-98B71E772C01?new_edits=false]: Got response, status 400
CBLMultipartUploader[PUT http://xxx:4984/xxx/contact%3AE0294D55-EB14-4C71-8100-98B71E772C01?new_edits=false]: Got error Error Domain=CBLHTTP Code=400 "400 bad_request" UserInfo={NSURL=http://xxx:4984/xxx/contact%3AE0294D55-EB14-4C71-8100-98B71E772C01?new_edits=false, NSLocalizedFailureReason=bad_request, NSLocalizedDescription=400 bad_request}

The actual document ID is contact:E0294D55-EB14-4C71-8100-98B71E772C01. Could you post the JSON of this document?

Also, could you show the log output from Sync Gateway for that HTTP request?

[pahmed]

When i tried to get it from sync gateway i got this error {"error":"not_found","reason":"missing"}

And this is how the document looks

{
    "_attachments" =     {
        "large_picture#94FF8EEB-1914-4AE2-8495-F8A935F44CFC" =         {
            "content_type" = "image/jpeg";
            digest = "sha1-cbDRPVlIrldHPVETFdtgyLrUVhE=";
            length = 20279;
            revpos = 1;
            stub = 1;
        };
        "small_picture#F69D796C-467E-422B-98BD-AEB8703BC8B2" =         {
            "content_type" = "image/jpeg";
            digest = "sha1-6FcNAyzCKDdCATNyeeSpRUQv3Zc=";
            length = 3676;
            revpos = 1;
            stub = 1;
        };
    };
    "_id" = "contact:E0294D55-EB14-4C71-8100-98B71E772C01";
    "_rev" = "1-298864b6526076030a55bece551ec527";
    addresses =     (
    );
    avatars =     {
        "_deleted" = 0;
        fromProfile = 0;
        fromWork = 0;
        isActive = 0;
        isRandom = 0;
        large = "large_picture#94FF8EEB-1914-4AE2-8495-F8A935F44CFC";
        small = "small_picture#F69D796C-467E-422B-98BD-AEB8703BC8B2";
        visibility = 2;
    };
    createdAt = "1459785414441.8";
    dates =     (
    );
    emails =     (
                {
            "_deleted" = 0;
            fromWork = 0;
            isActive = 0;
            isObsolete = 0;
            primary = 0;
            type = Other;
            value = "xxx";
            verified = 0;
            visibility = 2;
        },
                {
            "_deleted" = 0;
            fromWork = 0;
            isActive = 0;
            isObsolete = 0;
            primary = 0;
            type = Other;
            value = "xxx";
            verified = 0;
            visibility = 2;
        }
    );
    initialHash = 0684a525c10a74939699d80fe3082d13;
    instantMessaging =     (
    );
    names =     {
        primary =         {
            "_deleted" = 0;
            first = Reham;
            fromWork = 0;
            isActive = 0;
            last = Nozom;
            middle = Yousry;
            visibility = 2;
        };
    };
    organization =     {
        "_deleted" = 0;
        fromWork = 0;
        isActive = 0;
        verified = 0;
        visibility = 2;
    };
    owner = "632b157d-d5ca-49c6-9157-92e885137afe";
    phones =     (
                {
            "_deleted" = 0;
            fromWork = 0;
            isActive = 0;
            isObsolete = 0;
            primary = 0;
            type = Other;
            value = "xxx";
            verified = 0;
            visibility = 2;
        }
    );
    related =     (
    );
    socialAccounts =     (
    );
    type = contact;
    updatedAt = "1459785414441.8";
    urls =     (
    );
}

[snej]

The document looks OK; I don't know why Sync Gateway is getting an error with it. As a wild guess, it might not like the "#" characters in the attachment names, but that seems unlikely.

@adamcfraser @ajres — do you have any idea?

[adamcfraser]

It looks to me like the document is valid. You'd get a 400 returned if the referenced attachments weren't included in the request - it might have something to do with that.

As @snej recommended - getting the log output from the Sync Gateway log is the best way to get to the bottom of this. It will provide more detailed information on why Sync Gateway is returning a 400.

[pahmed]

Those are some of the sync gateway logs

sg_logs.txt

[snej]

No warnings, or even error codes, in the logs:

16:36:15.520305 2016-04-06T16:36:15.520Z HTTP:  #134677: PUT /xxxx/contact%3AE0294D55-EB14-4C71-8100-98B71E772C01?new_edits=false  (as 632b157d-d5ca-49c6-9157-92e885137afe)

[adamcfraser]

Those logs look like an excerpt (maybe filtered by doc ID) that's missing the 400 logging I'd expect to see.

For example, when running locally I see the following getting written to HTTP logging when I hit a couple of flavours of 400:

2016-04-08T16:01:02.159-07:00 HTTP:  #008: PUT /source/contact%3AE0294D55-EB14-4C71-8100-98B71E772C01?new_edits=false  (ADMIN)
2016-04-08T16:01:02.159-07:00 WARNING: Couldn't parse JSON in HTTP request: invalid character '}' looking for beginning of object key string -- db.ReadJSONFromMIME() at attachment.go:174
2016-04-08T16:01:02.159-07:00 HTTP: #008:     --> 400 Bad JSON  (0.1 ms)
2016-04-08T16:02:43.398-07:00 HTTP:  #009: PUT /source/contact%3AE0294D55-EB14-4C71-8100-98B71E772C01?new_edits=false  (ADMIN)
2016-04-08T16:02:43.398-07:00 HTTP: #009:     --> 400 Missing data of attachment "large_picture#94FF8EEB-1914-4AE2-8495-F8A935F44CFC"  (0.3 ms)****

@pahmed Can you share the lines that come immediately after this line from your logs?

14:46:20.919230 2016-04-09T14:46:20.919Z HTTP:  #12102: PUT /xxxx/contact%3AE0294D55-EB14-4C71-8100-98B71E772C01?new_edits=false  (as 632b157d-d5ca-49c6-9157-92e885137afe) 

[pahmed]

I asked me colleague in the backend team and told me that she didn't see warnings or errors (but she is not sure), we couldn't get the logs again because the staging database has been deleted, i'll try to reproduce this (it is not very frequent, but it happened with us many times).

[brendand]

I'm now seeing something similar, but I'm not using SyncGateway. I'm using IBM Cloudant.

Here's what I'm seeing:

2016-05-06 12:18:08.183 Tap Forms[2065:833366] Sync: CBLReplication[to https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: active, progress = 0 / 4, err: (null)
2016-05-06 12:18:08.482 Tap Forms[2065:833452] Sync: CBLRestPuller[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: Caught up with changes!
2016-05-06 12:18:08.482 Tap Forms[2065:833452] Sync: CBLRestPuller[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] Progress: set active = 0
2016-05-06 12:18:08.487 Tap Forms[2065:833366] Sync: CBLReplication[from https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: idle, progress = 0 / 0, err: (null)
2016-05-06 12:18:08.884 Tap Forms[2065:833366] Conflicted documents: 0
2016-05-06 12:18:10.454 Tap Forms[2065:833452] CBLMultipartUploader[PUT https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b/rec-df9b23287fdf4893ae0451a43d37116e?new_edits=false]: Got error CBLHTTP[400, "400 bad request", <https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b/rec-df9b23287fdf4893ae0451a43d37116e?new_edits=false>]
2016-05-06 12:18:10.455 Tap Forms[2065:833452] Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] Progress: set error = CBLHTTP[400, "400 bad request", <https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b/rec-df9b23287fdf4893ae0451a43d37116e?new_edits=false>]
2016-05-06 12:18:10.455 Tap Forms[2065:833452] Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] STOPPING...
2016-05-06 12:18:10.456 Tap Forms[2065:833452] Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] Progress: 4 / 4
2016-05-06 12:18:10.456 Tap Forms[2065:833452] Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] Progress: set active = 0
2016-05-06 12:18:10.472 Tap Forms[2065:833452] Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] STOPPED
2016-05-06 12:18:10.472 Tap Forms[2065:833452] Replication: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] took 3.190 sec; error=CBLHTTP[400, "400 bad request", <https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b/rec-df9b23287fdf4893ae0451a43d37116e?new_edits=false>]
2016-05-06 12:18:10.475 Tap Forms[2065:833366] Sync: CBLReplication[to https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: stopped, progress = 4 / 4, err: CBLHTTP[400, "400 bad request", <https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b/rec-df9b23287fdf4893ae0451a43d37116e?new_edits=false>]
2016-05-06 12:18:20.475 Tap Forms[2065:833452] Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] STOPPING...

I'll turn on LogSyncVerbose to see if I can get more information.

I'm using dev beta 1.3 commit 55ec67eb8e9b92ffb06fcdc50b8adf2c221790c6 iOS 9.3.1

[brendand]

So sync is stopping after I launch my app and won't sync again after. I'm going to try and track down what attachment file is causing this error.

[brendand]

Here's some more output from trying to push an attachment:

02:05:05.314| Sync: CBLReplication[from https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: offline, progress = 0 / 0, err: (null)
02:05:05.314| Sync: CBLReplication[to https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: offline, progress = 0 / 0, err: (null)
02:05:05.317‖ Sync: CBLRestPuller[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] STARTING ...
02:05:05.319‖ Sync: CBLRestPuller[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: Reachability state = <tapzapp.cloudant.com>:reachable (02), suspended=0
02:05:05.319‖ Sync: CBLRestPuller[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: Going online
02:05:05.319‖ Sync: CBLRestPuller[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] Progress: set active = 1
02:05:05.319‖ Sync: CBLRestPuller[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
02:05:05.319‖ Sync: CBLRestPuller[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: GET _local/3a54b9178ef9a7a822f7e742d0f08fdd4deacf20
02:05:05.319‖ Sync: CBLRestPuller[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
02:05:05.320| Sync: CBLReplication[from https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: active, progress = 0 / 0, err: (null)
02:05:05.320‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] STARTING ...
02:05:05.321‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: Reachability state = <tapzapp.cloudant.com>:reachable (02), suspended=0
02:05:05.321‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: Going online
02:05:05.322‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] Progress: set active = 1
02:05:05.322‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
02:05:05.322‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: GET _local/490cbbfa5978f62dfb82551f43df94ef2d1ae30d
02:05:05.322‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
02:05:05.325| Sync: CBLReplication[to https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: active, progress = 0 / 0, err: (null)
02:05:05.612‖ Sync: CBLRestPuller[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: Server is CouchDB/1.0.2 (Erlang OTP/17)
02:05:05.612‖ Sync: CBLRestPuller[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: Replicating from lastSequence=159538-g1AAAAGxeJzLYWBgYMlgTmxxxxxxxxxxxxxxxxxxx9NScwr0ctLLckBKmRKZEiy____f1YGcxIDw_S-XKAYe7KhuaVliilhE0C2KMDVGBrgtibJAUgm1cxxxxxxxxxxxxxxxxLZJNkC3PCBhEdehDLDkAsg3xxxxxxxxGZQEANTyLhw
02:05:05.612‖ Sync: CBLRestPuller[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] starting ChangeTracker: mode=0, since=159538-g1AAAAGxeJzLYWBxxxxxxxxxxxx88z0kvOyS9NScwr0ctLLckBKmRKZEiy____f1YGcxIDw_S-XKAYe7KhuaVliilhE0C2KMDVGBrgtibJAUgm1cNtmpYKtixxxxxxxxxxxxxxx7YNmPLZJNkC3PCBhEdehDLDkAsxxxxxxIGZQEANTyLhw
02:05:05.613‖ Sync: CBLSocketChangeTracker[0x6080001ab0c0 db-1deccd0e15dc4047ab96eba344144f3b]: POST //tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b/_changes?feed=normal&heartbeat=300000&style=all_docs&since=159538-g1AAAAGxeJzLYWBgYMlgTmGxxxxxxxxxxxxxxxx0ctLLckBKmRKZEiy____f1YGcxIDw_S-XKAYe7KhuaVliilhE0C2KMDVGBxxxxxxxxxxxxxxxxh9g28x7YNmPLZJNkC3PCBhEdehDLDkAsg3xxxxxx8IGZQEANTyLhw
02:05:05.615‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: Server is CouchDB/1.0.2 (Erlang OTP/17)
02:05:05.615‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: Replicating from lastSequence=172007
02:05:05.627‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: Received 1 revs
02:05:05.628‖ Sync: *** CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: BEGIN processInbox (1 sequences)
02:05:05.628‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: POST _revs_diff
02:05:05.628‖ Sync: *** CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: END processInbox (lastSequence=172007)
02:05:05.706‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: postProgressChanged (0/1, active=1 (batch=0, net=1), online=1)
02:05:05.706‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: Queuing CBLMultipartUploader[PUT https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b/rec-df9b23287fdf4893ae0451a43d37116e?new_edits=false] (multipart, 1647kb)
02:05:05.706‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: Starting CBLMultipartUploader[PUT https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b/rec-df9b23287fdf4893ae0451a43d37116e?new_edits=false]
02:05:05.707| Sync: CBLReplication[to https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: active, progress = 0 / 1, err: (null)
02:05:06.005‖ Sync: CBLSocketChangeTracker[0x6080001ab0c0 db-1deccd0e15dc4047ab96eba344144f3b]: GET //tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b/_changes?feed=normal&heartbeat=300000&style=all_docs&since=159538-g1AAAAGxeJzLYWBgYMlgTmGQTxxxxxxxxxxxxxxxxcwr0ctLLckBKmRKZEiy____f1YGcxIDw_S-XKAYe7KhuaxxxxxxxxxxxxxxxxxxxxxxDJ0ACkgJbth9g28x7YNmPLZJNkC3PCBhEdehDLDkAsg3pteSLEMrOUFEtTQ8IGZQEANTyLhw
02:05:06.274‖ Sync: CBLRestPuller[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: Caught up with changes!
02:05:06.274‖ Sync: CBLRestPuller[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] Progress: set active = 0
02:05:06.274‖ Sync: CBLRestPuller[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
02:05:06.274‖ Sync: CBLSocketChangeTracker[0x6080001ab0c0 db-1deccd0e15dc4047ab96eba344144f3b]: GET //tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b/_changes?feed=longpoll&heartbeat=300000&style=all_docs&since=159538-g1AAAAGxeJzLYWBgYMlgTmGQTxxxxxxxxxxxxxxxxxxx0ctLLckBKmRKZExxxxxxxxxYGcxIDw_S-XKAYe7KhuaVxxxxxxxxxxJ26Y8FiDJ0ACkgJbth9g28x7YNmPLZJNkC3PCBhxxxxxxxFEtTQ8IGZQEANTyLhw
02:05:06.275| Sync: CBLReplication[from https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: idle, progress = 0 / 0, err: (null)
2016-05-07 02:05:06.336 Tap Forms[47625:16225945] Conflicted documents: 0
02:05:07.640‖ CBLMultipartUploader[PUT https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b/rec-df9b23287fdf4893ae0451a43d37116e?new_edits=false]: Got error CBLHTTP[400, "400 bad request", <https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b/rec-df9b23287fdf4893ae0451a43d37116e?new_edits=false>]
02:05:07.640‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] Progress: set error = CBLHTTP[400, "400 bad request", <https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b/rec-df9b23287fdf4893ae0451a43d37116e?new_edits=false>]
02:05:07.640‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] STOPPING...
02:05:07.640‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] Progress: 1 / 1
02:05:07.640‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: postProgressChanged (1/1, active=1 (batch=0, net=1), online=1)
02:05:07.640‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] Progress: set active = 0
02:05:07.640‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: postProgressChanged (1/1, active=0 (batch=0, net=0), online=1)
02:05:07.641‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] STOPPED
02:05:07.641‖ Replication: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] took 2.320 sec; error=CBLHTTP[400, "400 bad request", <https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b/rec-df9b23287fdf4893ae0451a43d37116e?new_edits=false>]
02:05:07.641| Sync: CBLReplication[to https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b]: stopped, progress = 1 / 1, err: CBLHTTP[400, "400 bad request", <https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b/rec-df9b23287fdf4893ae0451a43d37116e?new_edits=false>]
2016-05-07 02:05:07.641 Tap Forms[47625:16225945] Error pushing: Error Domain=CBLHTTP Code=400 "400 bad request" UserInfo={NSErrorFailingURLKey=https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b/rec-df9b23287fdf4893ae0451a43d37116e?new_edits=false, NSLocalizedDescription=400 bad request, NSLocalizedFailureReason=bad request}
2016-05-07 02:05:07.641 Tap Forms[47625:16225945] MainWindowController: syncFailed
02:05:17.645‖ Sync: CBLRestPusher[https://tapzapp.cloudant.com/db-1deccd0e15dc4047ab96eba344144f3b] STOPPING...

And here's the JSON of the document that's failing to be pushed from my Mac:

{
    "_attachments": {
        "99F3C2A6-E2F2-46ED-97E4-590CD081CDC4_L0_001.jpeg": {
            "content_type": "image/jpeg",
            "digest": "sha1-Y7FJ7vw75Bn82STwbHE82fLfaHI=",
            "length": 852061,
            "revpos": 26,
            "stub": true
        },
        "D426B204-4C5C-44F6-9B76-C4683594B623_L0_001.jpeg": {
            "content_type": "image/jpeg",
            "digest": "sha1-qb7kU7ijNHJL2BpnP+7SNLXzrjA=",
            "length": 832735,
            "revpos": 26,
            "stub": true
        },
        "E45EA5FF-7CFD-4A04-953A-E6A03A9B3759_L0_001.jpeg": {
            "content_type": "image/jpeg",
            "digest": "sha1-KzgDUThgyEeXjQUuTMVHnrB4vh0=",
            "length": 757004,
            "revpos": 25,
            "stub": true
        },
        "c9ccd764419e4b9b824d7de4b3a4a4ae.jpg": {
            "content_type": "image/jpeg",
            "digest": "sha1-kCQmMQDLBRQwVlurNEmiVtMy1Y0=",
            "length": 2989233,
            "revpos": 3,
            "stub": true
        }
    },
    "dateCreated": "2016-04-14T02:44:22.347Z",
    "dateModified": "2016-05-07T06:53:48.410Z",
    "dbID": "db-1deccd0e15dc4047ab96eba344144f3b",
    "form": "frm-3a120db80af84866934f977a590691d0",
    "recordColourHex": "0xFFFFFDE0",
    "type": "frm-3a120db80af84866934f977a590691d0",
    "values": {
        "fld-15d8ecdb773b4e21819765bcbd5290bb": [{
            "dimensions": "{3024, 4032}",
            "filename": "c9ccd764419e4b9b824d7de4b3a4a4ae.jpg"
        }, {
            "dimensions": "{2048, 1536}",
            "filename": "E45EA5FF-7CFD-4A04-953A-E6A03A9B3759_L0_001.jpeg",
            "mimetype": "image/jpeg"
        }, {
            "dimensions": "{2052, 1533}",
            "filename": "99F3C2A6-E2F2-46ED-97E4-590CD081CDC4_L0_001.jpeg",
            "mimetype": "image/jpeg"
        }, {
            "dimensions": "{2048, 1536}",
            "filename": "D426B204-4C5C-44F6-9B76-C4683594B623_L0_001.jpeg",
            "mimetype": "image/jpeg"
        }],
        "fld-1a217fa8ff2a41d092d4938b0c9005d1": "Kelly",
        "fld-1c9ccc74aab2446c9a2505b29bfdab34": "Kelly",
        "fld-200e89c96f6048479378eebbaf9c748c": "Kelly",
        "fld-4d6e7841727d4c8281967e68c69e8e7c": 5.0,
        "fld-5292f2de77c445c2893e4dbfea6e88c4": true,
        "fld-6f9cf9898aad4ce3b63fb298d7943c6f": "Kelly",
        "fld-7c94dfa538a043688430b930dd5b11e1": "Brendan",
        "fld-963ce8da34e64add9cf60b8e1193d3d3": "Kelly",
        "fld-b54708d6cb9e4a39b7e7a1be6fb27d17": "Kelly",
        "fld-d8a545749e7a41dbb44c61a38618ce43": "Kelly",
        "fld-ef1e87f9b0b94b4c893cf227469cffe7": "Kelly"
    }
}

and if it helps, here's the JSON of the same document on the Cloudant server:

{
  "_id": "rec-df9b23287fdf4893ae0451a43d37116e",
  "_rev": "25-7276f3025d84237b3c8d04fd04315739",
  "dateCreated": "2016-04-14T02:44:22.347Z",
  "dateModified": "2016-05-06T07:36:12.148Z",
  "dbID": "db-1deccd0e15dc4047ab96eba344144f3b",
  "form": "frm-3a120db80af84866934f977a590691d0",
  "recordColourHex": "0xFFFFFDE0",
  "type": "frm-3a120db80af84866934f977a590691d0",
  "values": {
    "fld-15d8ecdb773b4e21819765bcbd5290bb": [
      {
        "dimensions": "{3024, 4032}",
        "filename": "c9ccd764419e4b9b824d7de4b3a4a4ae.jpg"
      },
      {
        "dimensions": "{2048, 1536}",
        "filename": "E45EA5FF-7CFD-4A04-953A-E6A03A9B3759_L0_001.jpeg",
        "mimetype": "image/jpeg"
      }
    ],
    "fld-1a217fa8ff2a41d092d4938b0c9005d1": "Kelly",
    "fld-1c9ccc74aab2446c9a2505b29bfdab34": "Kelly",
    "fld-200e89c96f6048479378eebbaf9c748c": "Kelly",
    "fld-5292f2de77c445c2893e4dbfea6e88c4": false,
    "fld-6f9cf9898aad4ce3b63fb298d7943c6f": "Kelly",
    "fld-963ce8da34e64add9cf60b8e1193d3d3": "Kelly",
    "fld-b54708d6cb9e4a39b7e7a1be6fb27d17": "Kelly",
    "fld-d8a545749e7a41dbb44c61a38618ce43": "Kelly",
    "fld-ef1e87f9b0b94b4c893cf227469cffe7": "Kelly"
  },
  "_attachments": {
    "c9ccd764419e4b9b824d7de4b3a4a4ae.jpg": {
      "content_type": "image/jpeg",
      "revpos": 3,
      "digest": "md5-CdzJRV4fl+8ftGpllzx45g==",
      "length": 2989233,
      "stub": true
    },
    "E45EA5FF-7CFD-4A04-953A-E6A03A9B3759_L0_001.jpeg": {
      "content_type": "image/jpeg",
      "revpos": 25,
      "digest": "md5-f/Ze2VkucGRLLOdR292+Ig==",
      "length": 757004,
      "stub": true
    }
  }
}

Just adding a couple of more attachments and modifying some of the fields.

[brendand]

I've discovered something interesting today when testing this out. In my app I allow the user to pick one or more photos from a photo picker. If I pick one photo at a time and set the attachment on my record, everything works fine. But if I pick more than one photo at a time and there's multiple new attachments to sync, that's when I get the 400 bad request error. So there's something odd going on with pushing multiple attachments at the same time.

I thought maybe there was something wrong with the specific photos I was selecting, but that wasn't the case since adding them one at a time and letting the push replicator do its thing in between adding new photos it worked just fine. But adding multiple photos in one go would cause the failure.

I'm not doing anything more complicated than this in a loop (one for each PHAsset coming from the iOS Photos framework):

[self.formEntry setAttachmentNamed:filename
                withContentType:(__bridge NSString *)mimeType
                        content:imageData];

The call above is occurring on the main thread, so I don't think it's a threading issue.

But here's a gist of the full code that's being called:

https://gist.github.com/brendand/05579727078fe99a1b4e1a6c24a57ac3

So ya, setting multiple attachments at the same time causes this issue for me.

[brendand]

What's also interesting is after this failure, I will always get that error. But if I delete the photos I added, then add them one at a time, it works again.

[snej]

It sounds like the error is triggered by the PUT with multiple attachments in the body. (If you add attachments one at a time, with a push in between, each push will only include one attachment body.) So it may have something to do with the MIME multipart formatting.

Could you capture the body of the PUT (the one whose URL ends in ?new_edits=false)? You'll probably need to use Charles Proxy since this is over HTTPS. If you can, get both the request and response, since the JSON body of the response may have a message with more details about the error.

[snej]

Also, note to self: Check whether any of the CBL unit tests upload multiple attachments at once. There may not be any tests that do this...

[brendand]

Ok, I'll setup Charles Proxy and see what I can find out.

[brendand]

Ok, so the first clue is this expanded response:

{
    "error": "bad_request",
    "reason": "attachment longer than expected"
}

I'm working on getting the request body now.

[brendand]

Here's the request body that caused the above failure. I stripped out the actual binary data of the attachment bodies and I formatted the JSON request part to make it more legible, otherwise it was just all strung together as one big string.

--C395D8B5-9E88-4D71-A322-DAB9639CDE27
Content-Length: 2704
Content-Type: application/json

{
    "_attachments": {
        "2016 Las Vegas Itinerary.pdf": {
            "revpos": 2,
            "stub": true
        },
        "2536_front.jpg": {
            "revpos": 3,
            "stub": true
        },
        "42804d2a57454b738e3d7f07c459c3fa.jpg": {
            "revpos": 6,
            "stub": true
        },
        "46701_front.jpg": {
            "revpos": 4,
            "stub": true
        },
        "83888_front.jpg": {
            "revpos": 5,
            "stub": true
        },
        "BD8E5E0B-533F-4776-8A50-1225F565E0AA.jpg": {
            "revpos": 8,
            "stub": true
        },
        "Billable Clients.tff": {
            "content_type": "application/tapforms-tff",
            "digest": "sha1-KS8vrmn3A0pHK7TC0Z77mGFkkqE=",
            "follows": true,
            "length": 53594,
            "revpos": 9
        },
        "Braveheart.jpg": {
            "content_type": "image/jpeg",
            "digest": "sha1-xq+Rrw/1qX1En9W+GKDeeCbTrCE=",
            "follows": true,
            "length": 292472,
            "revpos": 10
        },
        "f0f72f62dadf455998bae97677552192.jpg": {
            "revpos": 7,
            "stub": true
        }
    },
    "_id": "rec-bfcaf4e5870b43a58e5c6ccd6cea3a0c",
    "_rev": "10-a960e98b4e84ff95ddaac3cec7e8c65c",
    "_revisions": {
        "ids": ["a960e98b4e84ff95ddaac3cec7e8c65c", "c147f42e35a443c40f45d637d562f6d3", "0ba1f0adc74ec80741737f0102306d8d"],
        "start": 10
    },
    "dateCreated": "2016-05-09T17:40:39.867Z",
    "dateModified": "2016-05-09T17:45:56.595Z",
    "dbID": "db-292a4cdc2eba4e0186c489ad50b33de0",
    "form": "frm-283aa45a848e4f19a5a65a3660b9cae2",
    "type": "frm-283aa45a848e4f19a5a65a3660b9cae2",
    "values": {
        "fld-d178e5917ac7433ca2b872fd1dadf58d": [{
            "dimensions": "{512, 512}",
            "filename": "42804d2a57454b738e3d7f07c459c3fa.jpg",
            "mimetype": "image/jpeg"
        }, {
            "dimensions": "{512, 512}",
            "filename": "f0f72f62dadf455998bae97677552192.jpg",
            "mimetype": "image/jpeg"
        }],
        "fld-d88476bbac4346c28fc6b8eb57a9e8ca": [{
            "creationdate": "2016-02-29T20:44:05.000Z",
            "filename": "2016 Las Vegas Itinerary.pdf",
            "filesize": 7313675,
            "isalias": false,
            "mimetype": "application/pdf",
            "modifieddate": "2016-02-29T20:44:05.000Z"
        }, {
            "creationdate": "2016-02-03T09:14:50.000Z",
            "filename": "2536_front.jpg",
            "filesize": 638838,
            "isalias": false,
            "mimetype": "image/jpeg",
            "modifieddate": "2016-02-03T09:14:50.000Z"
        }, {
            "creationdate": "2016-03-29T18:04:33.000Z",
            "filename": "46701_front.jpg",
            "filesize": 2677523,
            "isalias": false,
            "mimetype": "image/jpeg",
            "modifieddate": "2016-03-29T18:04:33.000Z"
        }, {
            "creationdate": "2016-03-29T18:05:17.000Z",
            "filename": "83888_front.jpg",
            "filesize": 1835061,
            "isalias": false,
            "mimetype": "image/jpeg",
            "modifieddate": "2016-03-29T18:05:17.000Z"
        }, {
            "creationdate": "2015-10-26T23:27:05.000Z",
            "filename": "BD8E5E0B-533F-4776-8A50-1225F565E0AA.jpg",
            "filesize": 39854,
            "isalias": false,
            "mimetype": "image/jpeg",
            "modifieddate": "2015-10-26T23:27:05.000Z"
        }, {
            "creationdate": "2016-03-14T20:49:04.000Z",
            "filename": "Billable Clients.tff",
            "filesize": 53594,
            "isalias": false,
            "mimetype": "application/tapforms-tff",
            "modifieddate": "2016-03-14T20:49:04.000Z"
        }, {
            "creationdate": "2016-02-22T09:38:47.000Z",
            "filename": "Braveheart.jpg",
            "filesize": 292472,
            "isalias": false,
            "mimetype": "image/jpeg",
            "modifieddate": "2016-02-22T09:38:47.000Z"
        }]
    }
}

--C395D8B5-9E88-4D71-A322-DAB9639CDE27
Content-Length: 53594
Content-Disposition: attachment; filename="Billable Clients.tff"

[ attachment data removed ]

--C395D8B5-9E88-4D71-A322-DAB9639CDE27
Content-Length: 292472
Content-Disposition: attachment; filename="Braveheart.jpg"

[ attachment data removed ]

--C395D8B5-9E88-4D71-A322-DAB9639CDE27--

[brendand]

So initially I had added about 7 attachments all in one go to see what would happen. It seemed to work just fine initially. After it finished syncing the 7 attachments, I added 2 more at the same time and that's when I got the above error message. I added the Billable Clients.tff and Braveheart.jpg attachments at the same time.

The Content-Length values appear to match up with the values in the _attachments property.

[brendand]

So I just initiated a one-shot sync and they synced fine together now. Normally I just get the same error over and over again. I'll keep trying.

[brendand]

Here's a new one: 412 precondition failed

The response error is:

{
    "error": "missing_stub",
    "reason": "Invalid attachment stub in rec-29b0db40981e47e595351efc0c2537f4 for 918u6O2FCJL._SL1500_.jpg"
}

[snej]

The request looks fine; as you pointed out, the content-lengths match up. The attachments are in the same order in which they appear in the JSON, which shouldn't be necessary but CouchDB requires.

Either the actual MIME body lengths don't match the Content-Length headers, or there's some bug on Cloudant's side. Could you save the entire raw request body to a file and email it to me?

[snej]

For the 412 error, can you also capture the request body? In this case only the JSON is needed.

[brendand]

Here's the 412 error request body:

{
    "_attachments": {
        "2536_front.jpg": {
            "content_type": "image/jpeg",
            "digest": "sha1-nWNlsTzQqlZTjcRYYBrJUXWvzks=",
            "follows": true,
            "length": 638838,
            "revpos": 6
        },
        "918u6O2FCJL._SL1500_.jpg": {
            "revpos": 5,
            "stub": true
        },
        "wild rose report PDF.pdf": {
            "revpos": 3,
            "stub": true
        },
        "בחורים.csv": {
            "revpos": 4,
            "stub": true
        }
    },
    "_id": "rec-29b0db40981e47e595351efc0c2537f4",
    "_rev": "6-3e88dc3d7ca4fc1672f985ffb1aeb188",
    "_revisions": {
        "ids": ["3e88dc3d7ca4fc1672f985ffb1aeb188", "5279c47c42d1828bc62da3eec15f0229"],
        "start": 6
    },
    "dateCreated": "2016-05-09T18:12:24.206Z",
    "dateModified": "2016-05-09T18:13:10.431Z",
    "dbID": "db-292a4cdc2eba4e0186c489ad50b33de0",
    "form": "frm-283aa45a848e4f19a5a65a3660b9cae2",
    "type": "frm-283aa45a848e4f19a5a65a3660b9cae2",
    "values": {
        "fld-b08f031add7b4ae5accc14a410e65ad7": "three",
        "fld-d88476bbac4346c28fc6b8eb57a9e8ca": [{
            "creationdate": "2016-03-04T19:45:14.000Z",
            "filename": "wild rose report PDF.pdf",
            "filesize": 102589,
            "isalias": false,
            "mimetype": "application/pdf",
            "modifieddate": "2016-03-04T19:45:14.000Z"
        }, {
            "creationdate": "2015-11-10T22:05:49.000Z",
            "filename": "בחורים.csv",
            "filesize": 106398,
            "isalias": false,
            "mimetype": "text/csv",
            "modifieddate": "2015-11-10T22:05:49.000Z"
        }, {
            "creationdate": "2016-03-29T18:06:54.000Z",
            "filename": "918u6O2FCJL._SL1500_.jpg",
            "filesize": 294891,
            "isalias": false,
            "mimetype": "image/jpeg",
            "modifieddate": "2016-03-29T18:06:54.000Z"
        }, {
            "creationdate": "2016-02-03T09:14:50.000Z",
            "filename": "2536_front.jpg",
            "filesize": 638838,
            "isalias": false,
            "mimetype": "image/jpeg",
            "modifieddate": "2016-02-03T09:14:50.000Z"
        }]
    }
}

[brendand]

By the way, the strange characters in the .csv file attachment are because I dragged in a file to my File Attachments field which has a hebrew file name. It should be: בחורים.csv (except in the Finder it displays backwards with csv. first and then the name). I guess Charles Proxy messes up the file name encoding.

[brendand]

I'm not sure if you've ever run Charles against Cloudant, but there are other errors that popup too, such as 405 method not allowed:

{
    "error": "method_not_allowed",
    "reason": "Only GET,HEAD allowed"
}

That's when sending this request:

POST /db-292a4cdc2eba4e0186c489ad50b33de0/_changes?feed=normal&heartbeat=300000&style=all_docs&since=143-xxxxxxxx HTTP/1.1

(I replaced a bunch of random session-like characters with xxxxxxx in the above request'

[snej]

Yeah, Cloudant doesn't support POST to _changes yet. We handle the error by falling back to GET.

[brendand]

Ah ok, no worries then.

[brendand]

It also gives a 500 error with the response:

{
    "error": "function_clause",
    "reason": null,
    "ref": 1385787079
}

When calling: https://tapzapp.cloudant.com/db-292a4cdc2eba4e0186c489ad50b33de0/_bulk_docs

Not all of them, but some of the _bulk_docs calls appear to generate that error. I suspect it's a Cloudant issue maybe not being able to handle the traffic?

Not very informative I know.

[snej]

The 500 error sounds like some Erlang exception, based on the function_clause message — that's likely a Cloudant bug that you should take up with their tech support.

CBL interprets 5xx responses as intermittent and will retry the request, so as long as it's not consistently happening whenever it sends the same data, the docs will eventually get replicated.

[brendand]

Ah ok. Thanks. If you need any more request dumps let me know and I can email you some more.

[snej]

Reminder: Can you send me the entire request that triggers the "attachment longer than expected" error? You can email it to me as a binary file.

[brendand]

@snej I did send you one just the other day directly via email. The title of the message was "Raw request that caused 400 attachment longer than expected error". It was the entire request file. Did you not get that? From my gmail account.

[snej]

I found the email, and the request is definitely wrong: the MIME body is a few kbytes(?) longer than its Content-Length specifies. I've looked through the code and don't know how this could happen; my guess is that the file was added as an attachment while it was still being written to, so the initial length was shorter than the final length. But CBLAttachment should have updated the length property correctly when it copied the attachment to the blob-store.

I've made some improvements to the attachment handling. Most importantly, the Content-Length is now derived from the actual length of the stored attachment, not what's in the _attachments metadata. It's still bad if the two disagree; I've added a warning when this happens. Also, if you turn on Database logging you'll get a log whenever a CBLAttachment is saved to the blob-store, showing its current metadata.

Brendan, could you try to reproduce the problem again? Even if the 400 error goes away, look for warnings in the CBL log output. Thanks!

[brendand]

Ok, working on it. But first crack at it with the latest dev commit # 955e8c671507446707396f5e78a6ff9af52dd13d I get these errors syncing with Cloudant:

14:16:34.084‖ CBLRemoteJSONRequest[POST https://tapzapp.cloudant.com/db-0ed52ecc24b24b688ca3cf7a9341022b/_bulk_docs]: Got error CBLHTTP[412, "Invalid attachment stub in frm-7ef258070e0e45f8a4d11958d5e151c2 for icon", <https://tapzapp.cloudant.com/db-0ed52ecc24b24b688ca3cf7a9341022b/_bulk_docs>]
14:16:34.086‖ Replication: CBLRestPusher[https://tapzapp.cloudant.com/db-0ed52ecc24b24b688ca3cf7a9341022b] took 0.645 sec; error=CBLHTTP[412, "Invalid attachment stub in frm-7ef258070e0e45f8a4d11958d5e151c2 for icon", <https://tapzapp.cloudant.com/db-0ed52ecc24b24b688ca3cf7a9341022b/_bulk_docs>]
2016-05-16 14:16:34.086 Tap Forms[41618:1073447] Error pushing: Error Domain=CBLHTTP Code=412 "Invalid attachment stub in frm-7ef258070e0e45f8a4d11958d5e151c2 for icon" UserInfo={NSLocalizedDescription=Invalid attachment stub in frm-7ef258070e0e45f8a4d11958d5e151c2 for icon, NSErrorFailingURLKey=https://tapzapp.cloudant.com/db-0ed52ecc24b24b688ca3cf7a9341022b/_bulk_docs, CBLServerErrorInfo=<CFBasicHash 0x610000a738c0 [0x7fff7b59b440]>{type = immutable dict, count = 2,
entries =>
    0 : error = <CFString 0x610000837940 [0x7fff7b59b440]>{contents = "missing_stub"}
    2 : reason = <CFString 0x6100002b5ba0 [0x7fff7b59b440]>{contents = "Invalid attachment stub in frm-7ef258070e0e45f8a4d11958d5e151c2 for icon"}
}
, NSLocalizedFailureReason=Invalid attachment stub in frm-7ef258070e0e45f8a4d11958d5e151c2 for icon}

I had a bunch of forms without icons, but then I went through them all to make sure they all had icons and I still got the same error. icon is the name of the attachment I use for the icon that represents of form in my database.

[brendand]

And in a different database I just added 4 new attachments and got the 400 bad request error:

14:22:07.757| Database: CBL_BlobStore /Users/brendan/Library/Containers/com.tapzapp.tapforms-mac/Data/Documents/Archive Test.tapforms/db-292a4cdc2eba4e0186c489ad50b33de0.cblite2/attachments created tempDir /private/var/folders/gy/pdjjqyr88xg9gn001s6sl56h0000gn/T/com.tapzapp.tapforms-mac/TemporaryItems/(A Document Being Saved By Tap Forms)
14:22:07.759| Database: db-292a4cdc2eba4e0186c489ad50b33de0: Stored new CBLAttachment '918u6O2FCJL._SL1500 test_.jpg' {"content_type": "image/jpeg", "digest": "md5-NKYjdOAT/zuyk52aOsuScg==", "follows": 1, "length": 114313}
14:22:07.759| Database: PUT _id=rec-29b0db40981e47e595351efc0c2537f4, _rev=74-87d1c540ae4730c65a21350192225a9e (allowConflict=0)
14:22:07.759| Database: {{ Begin transaction (level 1)...
14:22:07.760| Database: }} Commit transaction (level 1)
14:22:07.761| Database: ---> Added: {rec-29b0db40981e47e595351efc0c2537f4 #75-b228e840ad4867bb3fef465758f9861b} as seq 1941
14:22:07.797| Database: db-292a4cdc2eba4e0186c489ad50b33de0: Stored new CBLAttachment '83888_front.jpg' {"content_type": "image/jpeg", "digest": "md5-ZKwBvVgiCP4RPG5IhfhdgQ==", "follows": 1, "length": 1835061}
14:22:07.798| Database: PUT _id=rec-29b0db40981e47e595351efc0c2537f4, _rev=75-b228e840ad4867bb3fef465758f9861b (allowConflict=0)
14:22:07.800| Database: {{ Begin transaction (level 1)...
14:22:07.801| Database: }} Commit transaction (level 1)
14:22:07.801| Database: ---> Added: {rec-29b0db40981e47e595351efc0c2537f4 #76-78ca29c9bb370c00763356d50b0994bc} as seq 1942
14:22:07.837| Database: db-292a4cdc2eba4e0186c489ad50b33de0: Stored new CBLAttachment 'AustralianPostcodes.csv' {"content_type": "text/csv", "digest": "md5-7E2C1yZndx5WOuE/O9kk+g==", "follows": 1, "length": 2289355}
14:22:07.837| Database: PUT _id=rec-29b0db40981e47e595351efc0c2537f4, _rev=76-78ca29c9bb370c00763356d50b0994bc (allowConflict=0)
14:22:07.838| Database: {{ Begin transaction (level 1)...
14:22:07.839| Database: }} Commit transaction (level 1)
14:22:07.840| Database: ---> Added: {rec-29b0db40981e47e595351efc0c2537f4 #77-c635351d1b4a699bb141ea534aa6bb8d} as seq 1943
14:22:07.854| Database: db-292a4cdc2eba4e0186c489ad50b33de0: Stored new CBLAttachment 'B08E1464-E55F-4EF7-8985-20D40698204A.jpg' {"content_type": "image/jpeg", "digest": "md5-AQxfKKZzqr7yZQp68wtnAw==", "follows": 1, "length": 1269905}
14:22:07.854| Database: PUT _id=rec-29b0db40981e47e595351efc0c2537f4, _rev=77-c635351d1b4a699bb141ea534aa6bb8d (allowConflict=0)
14:22:07.855| Database: {{ Begin transaction (level 1)...
14:22:07.855| Database: }} Commit transaction (level 1)
14:22:07.856| Database: ---> Added: {rec-29b0db40981e47e595351efc0c2537f4 #78-660deceaa463ba5c73eefae6b932b7bb} as seq 1944
2016-05-16 14:22:08.607 Tap Forms[41618:1073447] Conflicted documents: 0
2016-05-16 14:22:10.864 Tap Forms[41618:1073447] Conflicted documents: 0
14:22:15.183‖ CBLMultipartUploader[PUT https://tapzapp.cloudant.com/db-292a4cdc2eba4e0186c489ad50b33de0/rec-29b0db40981e47e595351efc0c2537f4?new_edits=false]: Got error CBLHTTP[400, "bad request", <https://tapzapp.cloudant.com/db-292a4cdc2eba4e0186c489ad50b33de0/rec-29b0db40981e47e595351efc0c2537f4?new_edits=false>]
14:22:15.183‖ Replication: CBLRestPusher[https://tapzapp.cloudant.com/db-292a4cdc2eba4e0186c489ad50b33de0] took 43.690 sec; error=CBLHTTP[400, "bad request", <https://tapzapp.cloudant.com/db-292a4cdc2eba4e0186c489ad50b33de0/rec-29b0db40981e47e595351efc0c2537f4?new_edits=false>]
2016-05-16 14:22:15.183 Tap Forms[41618:1073447] Error pushing: Error Domain=CBLHTTP Code=400 "bad request" UserInfo={NSErrorFailingURLKey=https://tapzapp.cloudant.com/db-292a4cdc2eba4e0186c489ad50b33de0/rec-29b0db40981e47e595351efc0c2537f4?new_edits=false, NSLocalizedDescription=bad request, NSLocalizedFailureReason=bad request}

Charles Proxy returns the same attachment size error:

{
    "error": "bad_request",
    "reason": "attachment longer than expected"
}

[brendand]

I wonder if the problem is in how I'm reading and then creating the attachments? If I do it one at a time it works just fine. But if I add multiple attachments in one operation, that's when it seems to fail. Although it fails after I've added the attachments. That is, I can quit and re-launch the app, the replicator starts, and then I get the failures.

This block of code gets executed once for every file I attach:

__weak FileAttachmentsViewController *weakSelf = self;

NSFileCoordinator *coordinator = [[NSFileCoordinator alloc] initWithFilePresenter:nil];

[coordinator coordinateReadingItemAtURL:sourceURL options:NSFileCoordinatorReadingForUploading error:&error byAccessor:^(NSURL * _Nonnull newURL) {

    NSString *mimeType = [Utilities mimeTypeForFileURL:newURL];

    [weakSelf.record setAttachmentNamed:sourceURL.lastPathComponent
                        withContentType:mimeType
                             contentURL:newURL];            

    NSMutableArray *existingFiles = [[weakSelf.record valueForField:weakSelf.field] mutableCopy];
    if (!existingFiles) {
        existingFiles = [NSMutableArray array];
    }
    NSPredicate *filenamePredicate = [NSPredicate predicateWithFormat:@"filename = %@", sourceURL.lastPathComponent];

    NSMutableDictionary *fileData = nil;

    NSDictionary *fileAttributes = [Utilities attributesForFileAtURL:newURL];
    NSNumber *fileSize = fileAttributes[NSFileSize];
    NSDate *creationDate = fileAttributes[NSFileCreationDate];
    NSDate *modificationDate = fileAttributes[NSFileModificationDate];

    NSArray *results = [existingFiles filteredArrayUsingPredicate:filenamePredicate];
    if (results.count == 0) {
        fileData = [NSMutableDictionary dictionary];
    } else {
        fileData = results.firstObject;
    }

    fileData[@"filename"] = sourceURL.lastPathComponent;
    fileData[@"mimetype"] = mimeType;
    fileData[@"filesize"] = fileSize;
    fileData[@"isalias"] = @(createBookmark);
    if (creationDate) {
        fileData[@"creationdate"] = [CBLJSON JSONObjectWithDate:creationDate];
    }
    if (modificationDate) {
        fileData[@"modifieddate"] = [CBLJSON JSONObjectWithDate:modificationDate];
    }

    [existingFiles addObject:fileData];

    [weakSelf.record setValue:existingFiles forField:weakSelf.field];

    NSError *error = nil;
    BOOL success = [weakSelf.record save:&error];
    if (!success) {
        TFFLog(@"Error saving attachment: %@", error);
    }

}];

[brendand]

It could be the NSFileCoordinator option I'm using: NSFileCoordinatorReadingForUploading

When this option is used, the file coordinator creates a temporary snapshot of the item being read and relinquishes its claim on the original file. This action prevents the read operation from blocking other coordinated writes during a potentially long upload.

I'll change that and see what happens.

[snej]

Well that sucks. I'm also disappointed that the "attachment longer than expected" message doesn't show up in the NSError — there's another recent fix (6f3c6fcf2b4b1b64fc3fdf0afacbb74569ca69c8) that's supposed to capture the "reason" property out of the JSON response.

[brendand]

I just tried using a different NSFileCoordinator (NSFileCoordinatorReadingResolvesSymbolicLink) option and the same thing happened. It also wouldn't explain the issue with multiple attachments in my photo field on iOS because I don't use a file coordinator when attaching multiple photos there. They all come in from the Photos framework and I use the NSData version of setAttachmentNamed and not the URL version.

[brendand]

Ya, I did see the attachment longer than expected error come in from the JSON response via Charles, but not output to the console log. I have seen other errors printed there though, like that missing stub error.

[snej]

OK, now I'm getting somewhere. I wrote a new unit test that adds several attachments to a doc, in separate revisions, then pushes it. Unfortunately it passed. But then I tried hardcoding the server URL to a Cloudant db, and now it fails. Hooray! So now I can reproduce this and troubleshoot.

[snej]

I think this is a Cloudant MIME parsing bug. The request looks fine to me, and neither Sync Gateway nor CouchDB 1.6 have trouble with it. I've attached the body as mime.txt, and you can send the request with: curl -X PUT -H 'Content-Type: multipart/related; boundary="2D0DAB20-BE70-4161-8A3E-CBF31CB525E6"' --data-binary @mime.txt 'http://snej.cloudant.com/attachment-test/mydoc-485135379?new_edits=false'

I've verified that each of the 3 parts is exactly the length stated in its Content-Type header (551, 3072 and 9216 bytes) and that the length properties of the attachments in the JSON match.

[snej]

BTW I fixed the error-message-detection code, so if you pull again it will report the Cloudant error message in the NSError.

But as for the actual problem, I think you'll have to ask Cloudant tech support, because AFAIK the multipart data I'm sending is fine.

[brendand]

Well done Jens!

I spoke with a Cloudant representative the other day and pointed him to this thread. I'll let him know of your findings and I'll submit this as a support request to Cloudant Support too.

Thanks!

[brendand]

While we wait for Cloudant to respond to my support request, is there any way to tell Couchbase Lite to send attachments separately than all combined into a single request? Perhaps that may temporarily solve the issue. There is a chance that Cloudant says they're not going to fix the bug too and I'll need some recourse to solve the problem. I believe they're working towards updating their systems to CouchDB 2.0.

[snej]

No, the attachments are part of the doc and have to be uploaded with it.

There's an instance variable _dontSendMultipart in CBLRestPusher.m that's used as a fallback if the server rejects a multipart upload. (I don't remember why this was added or what server it's to be compatible with; looks like it was about 3 ½ years ago.) You could edit the code to start it out as YES. The drawback is that uploading attachments will take longer, because they'll be base64-encoded.

[brendand]

Ah ok. Interesting. I'll use that as a last resort if Cloudant is unable to address this issue. I'm not going live with my app until June so there's still time.

[brendand]

FYI, I just wanted to test it out and yup, it worked. I may leave that on for now until Cloudant can fix the problem. At least my beta testers will be able to finish syncing.

[snej]

Just occurred to me that a good diagnostic tool would be to run a local instance of CouchDB (which is trivially easy; it's a double-clickable Mac app) and try syncing with it whenever you run into a problem with Cloudant. That may help isolate whether something is a Cloudant bug or not. (Although Cloudant inherits from CouchDB, and CouchDB has known issues with multipart that I've had to work around over the years.) You can also try Sync Gateway, although it's currently harder to configure since it lacks an admin UI.