Bug hitting CrateDB blob store?

[mjwall]

I debated asking this is on stackoverflow since I am not sure it a bug. I created a repo at https://github.com/mjwall/okhttp-test to show what I am seeing. Unfortunately I only see the behavior against a CrateDB blob store, so the https://github.com/mjwall/okhttp-test/blob/master/README.md has instructions for running crate in docker or natively. Running mvn clean test with crate started and the blobs inserted will show failing test where I am seeing the issues. Pasting my description of the issue from that README below as well.

What appears to be happening, is this:

1. a call to a crate blob that doesn't exist returns a 404
2. the next call, no matter to what returns the same 404 response
3. the next call returns whatever was the response in Give the in-progress code a SNAPSHOT version number. #2
4. the next call returns whatever was in the response in Enforce javac version 1.7 or better. #3 and so on

It seems from that point on any call the hits the same IP address and uses the same connection from the connection pool is one response behind. If I evictAll on the pools after a non 200, then it works correctly. This is my current workaround but it seems wrong. See the OkHttpTest file.

I have spent way to much time stepping through Interceptors and RealBuffers trying to figure out why this happening but have been unable to make this happen with sample servers or understand why this happening. I suspect it is something with the response from crate, but inspecting the headers and trying to replicate did not work. Hence the instructions for starting crate below, either in docker or directly.

I do not see how anything is being cached, because there is no InternalCache on the CacheInterceptor. I did see #3020 but when I step through the CacheInterceptor the cacheResponse is null at https://github.com/square/okhttp/blob/parent-3.6.0/okhttp/src/main/java/okhttp3/internal/cache/CacheInterceptor.java#L144 so it never gets to the isCacheable call on line 147.

I have updated to okhttp to version 3.10.0 but the test results are the same. This is tested with 3.6.0.

Can anyone confirm this is a bug or show what I am doing wrong in my usage of the library. Thank you for your time.

[swankjesse]

Do you get the same behavior with no cache?
It seems like a bug in the Crate server.

[mjwall]

Thanks for the reply @swankjesse. I didn't setup a cache, so I think the answer is yes I get the same behavior.

It may very well be a bug with the crate server, but I can't explain what is causing it. It is troubling to me that once I get a 404, no response from OkHttp is correct. They all return the response from the prior call, if that makes sense.

[swankjesse]

Yeah, OkHttp doesn't remember previous responses so it can't do that. Take a look at Crate.

[mjwall]

Thanks. So I turned up logging on crate and ran testCallAfter404 which should be a 200, 404 then 200. Here is what crate logged

[2018-04-10T19:22:05,681][TRACE][i.c.p.h.HttpAuthUpstreamHandler] Authentication succeeded user "crate" and method "trust".
[2018-04-10T19:22:05,682][TRACE][i.c.p.h.HttpBlobHandler  ] matches index:.blob_myblob digest:6dcd4ce23d88e2ee9568ba546c007c63d9131c1b
[2018-04-10T19:22:05,684][TRACE][i.c.p.h.HttpBlobHandler  ] HTTPMessage:%nDefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
GET /_blobs/myblob/6dcd4ce23d88e2ee9568ba546c007c63d9131c1b HTTP/1.1
Host: 127.0.0.1:4200
Connection: Keep-Alive
Accept-Encoding: gzip
User-Agent: okhttp/3.6.0
[2018-04-10T19:22:05,687][TRACE][i.c.p.h.HttpBlobHandler  ] HttpResponse: DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200 OK
content-length: 1
accept-ranges: bytes
expires: Thu, 31 Dec 2037 23:59:59 GMT
cache-control: max-age=315360000
[2018-04-10T19:22:05,752][TRACE][i.c.p.h.HttpBlobHandler  ] transferFile operationComplete


[2018-04-10T19:22:05,772][TRACE][i.c.p.h.HttpAuthUpstreamHandler] Authentication succeeded user "crate" and method "trust".
[2018-04-10T19:22:05,772][TRACE][i.c.p.h.HttpBlobHandler  ] matches index:.blob_myblob digest:ae4f281df5a5d0ff3cad6371f76d5c29b6d953ec
[2018-04-10T19:22:05,772][TRACE][i.c.p.h.HttpBlobHandler  ] HTTPMessage:%nDefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
GET /_blobs/myblob/ae4f281df5a5d0ff3cad6371f76d5c29b6d953ec HTTP/1.1
Host: 127.0.0.1:4200
Connection: Keep-Alive
Accept-Encoding: gzip
User-Agent: okhttp/3.6.0


[2018-04-10T19:22:05,774][TRACE][i.c.p.h.HttpAuthUpstreamHandler] Authentication succeeded user "crate" and method "trust".
[2018-04-10T19:22:05,774][TRACE][i.c.p.h.HttpBlobHandler  ] matches index:.blob_myblob digest:6dcd4ce23d88e2ee9568ba546c007c63d9131c1b
[2018-04-10T19:22:05,774][TRACE][i.c.p.h.HttpBlobHandler  ] HTTPMessage:%nDefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
GET /_blobs/myblob/6dcd4ce23d88e2ee9568ba546c007c63d9131c1b HTTP/1.1
Host: 127.0.0.1:4200
Connection: Keep-Alive
Accept-Encoding: gzip
User-Agent: okhttp/3.6.0
[2018-04-10T19:22:05,775][TRACE][i.c.p.h.HttpBlobHandler  ] HttpResponse: DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200 OK
content-length: 1
accept-ranges: bytes
expires: Thu, 31 Dec 2037 23:59:59 GMT
cache-control: max-age=315360000
[2018-04-10T19:22:05,776][TRACE][i.c.p.h.HttpBlobHandler  ] transferFile operationComplete

The 404 call doesn't log the response or the line "transferFile operationComplete". Does it make sense that the 404 call from crate is never really finished but OkHttp returns a 404 anyway?

For comparison, I ran curl against what should be a 200 and then the same 404. Here is the output

[2018-04-10T19:30:14,825][TRACE][i.c.p.h.HttpBlobHandler  ] matches index:.blob_myblob digest:6dcd4ce23d88e2ee9568ba546c007c63d9131c1b
[2018-04-10T19:30:14,827][TRACE][i.c.p.h.HttpBlobHandler  ] HTTPMessage:%nDefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
GET /_blobs/myblob/6dcd4ce23d88e2ee9568ba546c007c63d9131c1b HTTP/1.1
User-Agent: curl/7.28.1
Host: 127.0.0.1:4200
Accept: */*
[2018-04-10T19:30:14,829][TRACE][i.c.p.h.HttpBlobHandler  ] HttpResponse: DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200 OK
content-length: 1
accept-ranges: bytes
expires: Thu, 31 Dec 2037 23:59:59 GMT
cache-control: max-age=315360000
[2018-04-10T19:30:14,860][TRACE][i.c.p.h.HttpBlobHandler  ] transferFile operationComplete


[2018-04-10T19:30:17,264][TRACE][i.c.p.h.HttpAuthUpstreamHandler] Authentication succeeded user "crate" and method "trust".
[2018-04-10T19:30:17,264][TRACE][i.c.p.h.HttpBlobHandler  ] matches index:.blob_myblob digest:ae4f281df5a5d0ff3cad6371f76d5c29b6d953ec
[2018-04-10T19:30:17,264][TRACE][i.c.p.h.HttpBlobHandler  ] HTTPMessage:%nDefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
GET /_blobs/myblob/ae4f281df5a5d0ff3cad6371f76d5c29b6d953ec HTTP/1.1
User-Agent: curl/7.28.1
Host: 127.0.0.1:4200
Accept: */*
[2018-04-10T19:30:17,283][DEBUG][i.c.p.h.HttpBlobHandler  ] Connection reset by peer

With the curl, the 404 logs "Connection reset by peer". The request headers are little different for that call.

Really appreciate the help looking at this.

[mjwall]

So, adding a "Connection: close" header to the request solves the issue. https://github.com/mjwall/okhttp-test/blob/master/src/test/java/com/mjwall/OkHttpTest.java#L44

Thanks again.

[swankjesse]

Still looks like a Crate bug.

[mjwall]

Filed bug with crate - crate/crate#7185