CBLReplication error: strange URL in the error message. #1135

lucatorella · 2016-02-22T15:37:03Z

I'm trying to update to couchbase 1.2 (with ForestDB), I've updated the pod and luckily I didn't have to change any line and it just compile. Anyway I'm receiving a lot of weird error.

The code I have is quite simple:

I create a pull replication with a URL similar to https://mydata.mydomain.com/databaseName
I subscribe to kCBLReplicationChangeNotification notifications
(same thing for push replication).

With version 1.1.1 I don't get any error, but now I get tons of notification where replication?.lastError errorInfo is:

{
    NSErrorFailingURLKey = "https://mydata.mydomain.com,%20mydata.mydomain.com/customer_7036/_design/idx_product?rev=3-a30a2c33942e961e30716192397e712c&revs=true&attachments=true";
    NSErrorFailingURLStringKey = "https://mydata.mydomain.com,%20mydata.mydomain.com/customer_7036/_design/idx_product?rev=3-a30a2c33942e961e30716192397e712c&revs=true&attachments=true";
    NSLocalizedDescription = "A server with the specified hostname could not be found.";
   ...
}

As you can see it can't find some hostnames, and the URLs are clearly messed up. But I've no idea where it get's those URLs.

If for instance I change the initial URL to a wrong one like https://mydata.mydomain.com/fakeDatabaseName then I receive the error I'd expect, with the URL I used:

{
    NSLocalizedDescription = "404 not_found";
    NSLocalizedFailureReason = "not_found";
    NSURL = "https://mydata.mydomain.com/fakeDatabaseName/_changes";
}

Any idea what's going on?

Version: 1.2
Client OS: 9.2.1
Server: CouchDB 1.6.1

The text was updated successfully, but these errors were encountered:

snej · 2016-02-22T18:30:12Z

I've never seen a problem like that before — very weird. The URL is definitely mangled. Please turn on logging for Sync, SyncVerbose and RemoteRequest, and then upload the log somewhere like a gist.

Are you sure there isn't some new server-side configuration that could be causing this, like a redirect rule? Because the domain it's hitting is mydata.mydomain.com, mydata.mydomain.com, which looks like something that might happen if there were a quoting problem in a config file...

lucatorella · 2016-02-23T10:24:41Z

I'm sure there is no new server-side configuration, because if I go back to the branch with the old version of couchbase-lite (1.1) everything works fine

lucatorella · 2016-02-23T10:44:22Z

this is the log file till the first time I get an error, if I go on it will keep doing stuff and then I'll reach another error.

https://gist.github.com/lucatorella/96524767f5bf6cb105cd

snej · 2016-02-23T18:55:01Z

The error shows up at the end of the log:

2016-02-23 11:37:49.536 MyApp[6816:2232037] CBLMultipartDownloader[/customer_922/_design/backend]: Got error Error Domain=NSURLErrorDomain Code=-1003 "A server with the specified hostname could not be found." UserInfo={NSUnderlyingError=0x157811c10 {Error Domain=kCFErrorDomainCFNetwork Code=-1003 "A server with the specified hostname could not be found." UserInfo={NSErrorFailingURLStringKey=https://xxx-data1.yyy.com,%20xxx-data1.yyy.com/customer_922/_design/backend?rev=2-7eca4bc119a4894088d309bf3354a1ce&revs=true&attachments=true, ...

lucatorella · 2016-02-23T19:25:07Z

Yes and the URL (https://xxx-data1.yyy.com,%20xxx-data1.yyy.com/...) is not correct. There is a space and a repetition, it's the error I reported in my first post. Any idea why it's happening? The other URLs look good.

lucatorella · 2016-02-25T13:25:23Z

So today I was able to do more tests, and also check the logs on the server (it's CouchDB 1.6.1).

I also started from scratch and instead of using my app, I checked out the GrocerySync Demo app, I changed database name and the server DB URL. Moreover I added a basic authenticator:

let authenticator = CBLAuthenticator.basicAuthenticatorWithName(user, password: password)
_push.authenticator = authenticator
_pull.authenticator = authenticator

These are the only changes made to the GrocerySync app.

The behavior is identical to what I reported before, every seconds there is an error (and the alert shows up). The error says that the server with the specified hostname could not be found and if I check the URL inside the NSError I see a weird URL:

https://xxx-data1.yyy.com,%20xxx-data1.yyy.com/customer_922/_design/backend?rev=2-7eca4bc119a4894088d309bf3354a1ce&revs=true&attachments=true

Then I checked the logs on the server and they look like this:

85.6.155.169 - - [25/Feb/2016:14:02:49 +0100]  "GET /customer_922/_local/5a34d088942c32c19b21f8462a4708006c5b669a HTTP/1.1" 401 61 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.002 0.002 .
85.6.155.169 - - [25/Feb/2016:14:02:49 +0100]  "POST /customer_922/_changes HTTP/1.1" 401 61 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.036 0.002 .
85.6.155.169 - device_7237 [25/Feb/2016:14:02:49 +0100]  "GET /customer_922/_local/5a34d088942c32c19b21f8462a4708006c5b669a HTTP/1.1" 200 108 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.002 0.002 .
85.6.155.169 - - [25/Feb/2016:14:02:49 +0100]  "POST /customer_922/_revs_diff HTTP/1.1" 401 61 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.034 0.002 .
85.6.155.169 - - [25/Feb/2016:14:02:49 +0100]  "POST /customer_922/_revs_diff HTTP/1.1" 401 61 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.031 0.002 .
85.6.155.169 - - [25/Feb/2016:14:02:49 +0100]  "POST /customer_922/_revs_diff HTTP/1.1" 401 61 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.004 0.002 .
85.6.155.169 - - [25/Feb/2016:14:02:49 +0100]  "POST /customer_922/_revs_diff HTTP/1.1" 401 61 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.036 0.004 .
85.6.155.169 - - [25/Feb/2016:14:02:49 +0100]  "POST /customer_922/_revs_diff HTTP/1.1" 401 61 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.036 0.004 .
85.6.155.169 - - [25/Feb/2016:14:02:49 +0100]  "POST /customer_922/_revs_diff HTTP/1.1" 401 61 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.061 0.003 .
85.6.155.169 - - [25/Feb/2016:14:02:49 +0100]  "POST /customer_922/_revs_diff HTTP/1.1" 401 61 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.063 0.003 .
85.6.155.169 - - [25/Feb/2016:14:02:49 +0100]  "POST /customer_922/_revs_diff HTTP/1.1" 401 61 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.063 0.003 .
85.6.155.169 - device_7237 [25/Feb/2016:14:02:49 +0100]  "POST /customer_922/_revs_diff HTTP/1.1" 200 3 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.007 0.005 .
85.6.155.169 - - [25/Feb/2016:14:02:51 +0100]  "GET /customer_922/_design%2Fbackend?rev=2-7eca4bc119a4894088d309bf3354a1ce&revs=true&attachments=true HTTP/1.1" 401 61 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.006 0.006 .
85.6.155.169 - - [25/Feb/2016:14:02:51 +0100]  "GET /customer_922/_design%2Fidx_product?rev=1-93d2e3632c10fd83536b1497ddf584e2&revs=true&attachments=true HTTP/1.1" 401 61 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.006 0.006 .
85.6.155.169 - device_7237 [25/Feb/2016:14:02:51 +0100]  "POST /customer_922/_revs_diff HTTP/1.1" 200 3 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.009 0.008 .
85.6.155.169 - device_7237 [25/Feb/2016:14:02:51 +0100]  "POST /customer_922/_revs_diff HTTP/1.1" 200 3 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.008 0.007 .
85.6.155.169 - device_7237 [25/Feb/2016:14:02:51 +0100]  "POST /customer_922/_revs_diff HTTP/1.1" 200 3 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.010 0.010 .
85.6.155.169 - device_7237 [25/Feb/2016:14:02:51 +0100]  "POST /customer_922/_revs_diff HTTP/1.1" 200 3 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.010 0.009 .
85.6.155.169 - device_7237 [25/Feb/2016:14:02:51 +0100]  "POST /customer_922/_revs_diff HTTP/1.1" 200 3 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.010 0.009 .
85.6.155.169 - device_7237 [25/Feb/2016:14:02:51 +0100]  "POST /customer_922/_revs_diff HTTP/1.1" 200 3 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.011 0.011 .
85.6.155.169 - device_7237 [25/Feb/2016:14:02:51 +0100]  "POST /customer_922/_revs_diff HTTP/1.1" 200 3 "-" "CouchbaseLite/1.2 (iOS 1.2)" 0.056 0.055 .

The weird thing to notice is that is always trying first to do requests without authentication and then it try the same request using authentication.

Also, the same does not happen using couchbase-lite 1.1.

One more thing, the Android app using couchbase-lite 1.2 works properly and also doesn't make all these requests (unauthenticated and authenticated ones).

pasin · 2016-02-25T18:04:59Z

The weird thing to notice is that is always trying first to do requests without authentication and then it try the same request using authentication.

What you have seen is what is described in #1127 which turns out to be an CFNetwork bug. @snej have a workaround implemented in fix/1.2+basic_auth and dev branch.

lucatorella · 2016-02-25T19:02:10Z

that explains the multiple requests with and without authentication, but not the errors, right? :(

pasin · 2016-02-25T20:12:33Z

Yes, that's not the error.

From https://gist.github.com/lucatorella/96524767f5bf6cb105cd#file-replication-log-L352, it seems like the URL path is escaped correctly.

I did a quick test by doing the same thing as the CBLRestPuller does and the error contains the correct URL. I'm not sure what triggered the invalid URL for your case.

    NSString* docIDParam = CBLEscapeURLParam(@"_design/backend");
    NSString* revIDParam = CBLEscapeURLParam(@"2-7eca4bc119a4894088d309bf3354a1ce");
    NSString* path = $sprintf(@"%@?rev=%@&revs=true", docIDParam, revIDParam);
    NSLog(@"%@", path);

    NSURL *remoteURL = [NSURL URLWithString:@"https://xxx-data1.yyy.com/customer_922"];
    NSURL *targetURL = CBLAppendToURL(remoteURL, path);
    NSLog(@"%@", targetURL);

    NSError* error = nil;
    NSURLResponse* response = nil;
    [NSURLConnection sendSynchronousRequest: [NSURLRequest requestWithURL:targetURL]
                          returningResponse: &response
                                      error: &error];
    NSLog(@"%@", error);

Error has correct URL:

Error Domain=NSURLErrorDomain Code=-1003 "A server with the specified hostname could not be found." UserInfo={NSUnderlyingError=0x6040000ad510 {Error Domain=kCFErrorDomainCFNetwork Code=-1003 "A server with the specified hostname could not be found." UserInfo={NSErrorFailingURLStringKey=https://xxx-data1.yyy.com/customer_922/_design%2Fbackend?rev=2-7eca4bc119a4894088d309bf3354a1ce&revs=true, NSErrorFailingURLKey=https://xxx-data1.yyy.com/customer_922/_design%2Fbackend?rev=2-7eca4bc119a4894088d309bf3354a1ce&revs=true, _kCFStreamErrorCodeKey=8, _kCFStreamErrorDomainKey=12, NSLocalizedDescription=A server with the specified hostname could not be found.}}, NSErrorFailingURLStringKey=https://xxx-data1.yyy.com/customer_922/_design%2Fbackend?rev=2-7eca4bc119a4894088d309bf3354a1ce&revs=true, NSErrorFailingURLKey=https://xxx-data1.yyy.com/customer_922/_design%2Fbackend?rev=2-7eca4bc119a4894088d309bf3354a1ce&revs=true, _kCFStreamErrorDomainKey=12, _kCFStreamErrorCodeKey=8, NSLocalizedDescription=A server with the specified hostname could not be found.}

lucatorella · 2016-02-25T21:58:00Z

@pasin by xxx and yyy I'm covering the real values. The synchronization (as you can see from the part of the log till the first error), is actually working, and is eventually completing after many and many errors with the weird URL.

snej · 2016-02-25T23:33:10Z

In your app, if you turn off authentication, does the bug go away? I think the screwed up hostname may be a symptom of #1124, which is a nastier manifestation of the CFNetwork bug Pasin mentioned; we've seen some weird stuff in packet traces, where it looks as though CFNetwork gets mixed up at the TCP stream level.

We have a fix for these issues, on a branch fix/1.2+basic_auth. This is identical to the 1.2 release except for a change in how we handle HTTP basic auth. If you could build and test that, it would be a big help in troubleshooting this issue (and would likely get you around this problem you're having.)

lucatorella · 2016-02-26T15:19:46Z

I compiled the library from the fix/1.2+basic_auth branch, plug it into the GrocerySync app and I still get the error with the weird URL.

snej · 2016-02-28T20:31:50Z

Here's why I'm stumped: All of the requests sent by a replicator use the same hostname. And that problematic request gets sent correctly once and gets a 401 response; it's the second attempt, with the credentials, that fails. But NSURLConnection doesn't change the URL when it retries a request after authentication, so there's no way it should be hitting a different hostname.

Something to try: Use curl or some other HTTP client tool to send the same request, and see what the response is:

curl -i 'https://xxx-data1.yyy.com/customer_922/_design/backend?rev=2-7eca4bc119a4894088d309bf3354a1ce&revs=true&attachments=true' >response.txt

(The response may include binary data, so I redirect it to a file.)

Also, as I asked earlier, could you temporarily turn off authentication on the server and retry? Thanks.

lucatorella · 2016-02-28T20:43:33Z

the response is:

HTTP/1.1 401 Unauthorized
Server: nginx/1.6.2
Date: Sun, 28 Feb 2016 20:38:10 GMT
Content-Type: text/plain; charset=utf-8
Content-Length: 61
Connection: keep-alive
WWW-Authenticate: Basic realm="server"
Cache-Control: must-revalidate

{"error":"unauthorized","reason":"Authentication required."}

At the moment I can't temporarily turn off authentication. I'll see what I can do.

But why all requests are tried without authentication first? That sounds like a bug

snej · 2016-02-28T21:29:32Z

I forgot to say that you should authenticate the request. Add args --user username and it will prompt you for the password.

But why all requests are tried without authentication first? That sounds like a bug

Yes, #1127, as Pasin said above.

lucatorella · 2016-02-28T21:58:21Z

so response is:

HTTP/1.1 200 OK
Server: nginx/1.6.2
Date: Sun, 28 Feb 2016 21:57:52 GMT
Content-Type: text/plain; charset=utf-8
Content-Length: 568
Connection: keep-alive
Vary: Accept-Encoding
ETag: "2-7eca4bc119a4894088d309bf3354a1ce"
Cache-Control: must-revalidate

{"_id":"_design/backend","_rev":"2-7eca4bc119a4894088d309bf3354a1ce","language":"javascript","views":{"objects_by_type":{"map":"        function(doc){\n          emit(doc.type, 1);\n        }\n"},"count_objects_by_type":{"map":"        function(doc){\n          emit(doc.type, 1);\n        }\n","reduce":"_sum"}},"filters":{"replication_design_filter":"            function(doc, req) {\n              return (doc.type !== null && !doc._deleted)\n            }\n"},"_revisions":{"start":2,"ids":["7eca4bc119a4894088d309bf3354a1ce","21db8228c27fad95cc882d6bb826e9c3"]}}

lucatorella · 2016-03-01T19:25:01Z

would it help if I can give you the GrocerySync app modified with our endpoints? There it's reproducible 100% of the times

snej · 2016-03-01T19:28:23Z

If you can give me a login to your server, I probably don't need any code; I can just use LiteServ to run a pull replication from it. You can send the credentials to jens at couchbase.

snej · 2016-03-02T18:59:50Z

Got the credentials; thanks! I'm able to reproduce the bug by using LiteServ to pull the database. Now I can investigate…

lucatorella · 2016-03-02T19:00:50Z

that's great, good luck and thanks for looking into this 👍

snej · 2016-03-02T19:25:18Z

The server is returning a redirect (301 status) to the bogus URL. I see the NSURLSession delegate call happening in the app (though it doesn't log anything -- need to fix that, it would have made diagnosing this easier), and I can reproduce it using curl.

It looks like CouchDB wants to change the “%2F” in the URL into a “/“ so it redirects to that path, but the hostname in the URL gets mangled on the way back to the client. I suspect something is misconfigured on your nginx server.

$  curl -v -i --user USERNAME 'https://xxx-data1.yyy.com/customer_922/_design%2Fbackend?rev=2-7eca4bc119a4894088d309bf3354a1ce&revs=true&attachments=true'
Enter host password for user 'USERNAME':
*   Trying xx.xx.xx.xx...
* Connected to xxx-data1.yyy.com (xx.xx.xx.xx) port 443 (#0)
* TLS 1.2 connection using TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
* Server certificate: *.scandit.com
* Server certificate: RapidSSL SHA256 CA - G3
* Server certificate: GeoTrust Global CA
* Server auth using Basic with user 'USERNAME'
> GET /customer_922/_design%2Fbackend?rev=2-7eca4bc119a4894088d309bf3354a1ce&revs=true&attachments=true HTTP/1.1
> Host: xxx-data1.yyy.com
> Authorization: Basic ZGV2aWNlXzcyMzc6YTI4Yjg2NTg1MDgwMmEzY2E4NmUyMTdiYjRjYjMxNjUxNzhiNzQ3Mg==
> User-Agent: curl/7.43.0
> Accept: */*
> 
< HTTP/1.1 301 Moved Permanently
HTTP/1.1 301 Moved Permanently
< Server: nginx/1.6.2
Server: nginx/1.6.2
< Date: Wed, 02 Mar 2016 19:15:45 GMT
Date: Wed, 02 Mar 2016 19:15:45 GMT
< Content-Length: 0
Content-Length: 0
< Connection: keep-alive
Connection: keep-alive
< Location: https://xxx-data1.yyy.com, xxx-data1.yyy.com/customer_922/_design/backend?rev=2-7eca4bc119a4894088d309bf3354a1ce&revs=true&attachments=true
Location: https://xxx-data1.yyy.com, xxx-data1.yyy.com/customer_922/_design/backend?rev=2-7eca4bc119a4894088d309bf3354a1ce&revs=true&attachments=true

< 
* Connection #0 to host xxx-data1.yyy.com left intact

This would have helped diagnose #1135 much more easily -- the problem ended up being server-side, with a bogus hostname in the redirected URL.

lucatorella · 2016-03-03T09:26:58Z

Thanks for the feedback. I checked and yes, there was a bug in nginx which has been fixed. Anyway there is another issue here. The URL couchbase is trying is https://xxx-data1.yyy.com/customer_922/_design%2Fbackend?rev=2-7eca4bc119a4894088d309bf3354a1ce&revs=true&attachments=true where there is a %2F instead of a /. This causes CouchDB to suggest a redirection that was being screwed up by nginx.

I tried with the latest nightly build and the issue is still there. Now the redirection works, but you can save some requests by fixing the %2F bug.

This is part of the log coming from the server:

"GET /customer_922/_design%2Fsync?rev=6-edeee6325e2c97ab8fc4936833c62891&revs=true&attachments=true HTTP/1.1" 301 0 "-" "CouchbaseLite/1.2 (iOS 1.3)" 0.002 0.002 .
"GET /customer_922/_design%2Fidx_category?rev=3-2282166f82e03d80a9bf3e1f7f9357a9&revs=true&attachments=true HTTP/1.1" 301 0 "-" "CouchbaseLite/1.2 (iOS 1.3)" 0.002 0.002 .
"GET /customer_922/_design/sync?rev=6-edeee6325e2c97ab8fc4936833c62891&revs=true&attachments=true HTTP/1.1" 200 337 "-" "CouchbaseLite/1.2 (iOS 1.3)" 0.001 0.001 .
"GET /customer_922/_design/idx_category?rev=3-2282166f82e03d80a9bf3e1f7f9357a9&revs=true&attachments=true HTTP/1.1" 200 535 "-" "CouchbaseLite/1.2 (iOS 1.3)" 0.003 0.003 .

snej · 2016-03-03T21:07:11Z

To be honest, since it only occurs with design documents, and only with CouchDB, it's not going to be a priority to change it.

lucatorella changed the title ~~Replication error: strange URL in the error message.~~ CBLReplication error: strange URL in the error message. Feb 22, 2016

snej added f: Replication reproduce/investigate bug labels Feb 22, 2016

snej closed this as completed Mar 2, 2016

snej removed the reproduce/investigate label Mar 2, 2016

snej added a commit that referenced this issue Mar 2, 2016

Add a log message when CBLRemoteRequest gets an HTTP redirect

35b79c5

This would have helped diagnose #1135 much more easily -- the problem ended up being server-side, with a bogus hostname in the redirected URL.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

CBLReplication error: strange URL in the error message. #1135

CBLReplication error: strange URL in the error message. #1135

lucatorella commented Feb 22, 2016

snej commented Feb 22, 2016

lucatorella commented Feb 23, 2016

lucatorella commented Feb 23, 2016

snej commented Feb 23, 2016

lucatorella commented Feb 23, 2016

lucatorella commented Feb 25, 2016

pasin commented Feb 25, 2016

lucatorella commented Feb 25, 2016

pasin commented Feb 25, 2016

lucatorella commented Feb 25, 2016

snej commented Feb 25, 2016

lucatorella commented Feb 26, 2016

snej commented Feb 28, 2016

lucatorella commented Feb 28, 2016

snej commented Feb 28, 2016

lucatorella commented Feb 28, 2016

lucatorella commented Mar 1, 2016

snej commented Mar 1, 2016

snej commented Mar 2, 2016

lucatorella commented Mar 2, 2016

snej commented Mar 2, 2016

lucatorella commented Mar 3, 2016

snej commented Mar 3, 2016

CBLReplication error: strange URL in the error message. #1135

CBLReplication error: strange URL in the error message. #1135

Comments

lucatorella commented Feb 22, 2016

snej commented Feb 22, 2016

lucatorella commented Feb 23, 2016

lucatorella commented Feb 23, 2016

snej commented Feb 23, 2016

lucatorella commented Feb 23, 2016

lucatorella commented Feb 25, 2016

pasin commented Feb 25, 2016

lucatorella commented Feb 25, 2016

pasin commented Feb 25, 2016

lucatorella commented Feb 25, 2016

snej commented Feb 25, 2016

lucatorella commented Feb 26, 2016

snej commented Feb 28, 2016

lucatorella commented Feb 28, 2016

snej commented Feb 28, 2016

lucatorella commented Feb 28, 2016

lucatorella commented Mar 1, 2016

snej commented Mar 1, 2016

snej commented Mar 2, 2016

lucatorella commented Mar 2, 2016

snej commented Mar 2, 2016

lucatorella commented Mar 3, 2016

snej commented Mar 3, 2016