HttpsURLConnection on Android upload over SSL freezes up (with varying failure modes)

Question

Would appreciate any input on this. I need to upload non-trivial amounts of data (just tens of kilobytes for testing) via streaming HTTPS from Android. Testing on Kitkat 4.4.2 tablet for now. My problems are the same with HttpURLConnection and OkHttp 2.0 (which appears to require Java 7, so ultimately will need to support ICS 4.0.3, so probably HUC is my only option).

On the service side, I am using Jersey with Glassfish 4.0.1 b10 (which I think has Jersey 2.11). I upgraded from Glassfish 4.0 in case that was an issue, but have not observed any difference in behavior. I would like to move to Wildfly, but do not have time now.

For a relatively small amount of data, everything works fine. Once I throw in not-small amounts of data (tens of kilobytes), the app gets 400 Bad Request from the server, without ever reaching my server code. Server requires client cert authentication, which works in all other cases, but in this case I get null principal and failure to grant permissions (note the error on the client is not 401). In other successful authentications, the principal is the CN on the certificate. After a while, I get nothing but SSL handshake timeout, on this type of request and other requests that had worked earlier. The timeout I record below came after waiting 5 minutes for a server response.

When I do get the service to be called (and at this point I no longer remember what I did to reach such a blessed outcome), my server code recorded about 5668 characters of input and then stopped. Then once the timeout expires (30 seconds), everything failed. But sometimes it fails to reach the service at all, giving back a 400 response to an apparent failure to authenticate.

I have read through Web posts on HttpURLConnection until I am blue in my face, and have ruled out the obvious. I am not calling getInputStream() until I have written to and flushed the output stream. I am not closing the output stream because some posts claim it closes the socket (I do flush it). I would like HTTP caching but have turned it off to eliminate that as a reason. I would like streaming mode, but I do not set chunked streaming mode to eliminate that as a reason. I have read posts anyway where people claim that even with chunked streaming, HUC builds the request entity in memory before sending. I think I am careful to eat all responses, as used to be recommended. I do not believe this is a header issue corrupting the syntax of the HTTP request, this request type only sends the same request headers that the other request types do, and they work fine (they also use POST). I don't need a response entity from the service for this request type, but I've added it just to eliminate that as an reason. I do notice that when I added @Produces to the resource method, then (on OkHttp 2.0) I started getting the client blocked waiting for the response entity. Then SSL handshake timeout exception manifested itself after that timeout.....

App log (sample):

D/org.foo.main.rest.RequestProcessor(2325): javax.net.ssl.SSLException: Connection closed by peer 09-04 17:24:55.743: D/org.foo.main.rest.RequestProcessor(2325): at com.android.org.conscrypt.NativeCrypto.SSL_do_handshake(Native Method) 09-04 17:24:55.743: D/org.foo.main.rest.RequestProcessor(2325): at com.android.org.conscrypt.OpenSSLSocketImpl.startHandshake(OpenSSLSocketImpl.java:405) 09-04 17:24:55.743: D/org.foo.main.rest.RequestProcessor(2325): at com.android.okhttp.Connection.upgradeToTls(Connection.java:146) 09-04 17:24:55.743: D/org.foo.main.rest.RequestProcessor(2325): at com.android.okhttp.Connection.connect(Connection.java:107) 09-04 17:24:55.743: D/org.foo.main.rest.RequestProcessor(2325): at com.android.okhttp.internal.http.HttpEngine.connect(HttpEngine.java:294) 09-04 17:24:55.743: D/org.foo.main.rest.RequestProcessor(2325): at com.android.okhttp.internal.http.HttpEngine.sendSocketRequest(HttpEngine.java:255) 09-04 17:24:55.743: D/org.foo.main.rest.RequestProcessor(2325): at com.android.okhttp.internal.http.HttpEngine.sendRequest(HttpEngine.java:206) 09-04 17:24:55.743: D/org.foo.main.rest.RequestProcessor(2325): at com.android.okhttp.internal.http.HttpURLConnectionImpl.execute(HttpURLConnectionImpl.java:345) 09-04 17:24:55.743: D/org.foo.main.rest.RequestProcessor(2325): at com.android.okhttp.internal.http.HttpURLConnectionImpl.getResponse(HttpURLConnectionImpl.java:296) 09-04 17:24:55.743: D/org.foo.main.rest.RequestProcessor(2325): at com.android.okhttp.internal.http.HttpURLConnectionImpl.getResponseCode(HttpURLConnectionImpl.java:503) 09-04 17:24:55.743: D/org.foo.main.rest.RequestProcessor(2325): at com.android.okhttp.internal.http.HttpsURLConnectionImpl.getResponseCode(HttpsURLConnectionImpl.java:136)

Server log:

[2014-09-04T21:19:54.492+0000] [glassfish 4.0] [FINE] [] [javax.enterprise.system.core.security] [tid: _ThreadID=36 _ThreadName=http-listener-2(5)] [timeMillis: 1409865594492] [levelValue: 500] [CLASSNAME: com.sun.enterprise.security.ssl.J2EEKeyManager] [METHODNAME: getPrivateKey] [[ Getting private key for alias:server-cert]]

[2014-09-04T21:19:54.492+0000] [glassfish 4.0] [FINE] [] [javax.enterprise.system.core.security] [tid: _ThreadID=36 _ThreadName=http-listener-2(5)] [timeMillis: 1409865594492] [levelValue: 500] [CLASSNAME: com.sun.enterprise.security.ssl.J2EEKeyManager] [METHODNAME: getCertificateChain] [[ Getting certificate chain]]

[2014-09-04T21:19:55.191+0000] [glassfish 4.0] [FINE] [] [javax.enterprise.system.container.web.com.sun.web.security] [tid: _ThreadID=33 _ThreadName=http-listener-2(2)] [timeMillis: 1409865595191] [levelValue: 500] [CLASSNAME: com.sun.web.security.RealmAdapter] [METHODNAME: hasUserDataPermission] [[ [Web-Security][ hasUserDataPermission ] Principal: null ContextPath: /bar-data]]

[2014-09-04T21:19:55.192+0000] [glassfish 4.0] [FINE] [] [javax.enterprise.system.container.web.com.sun.web.security] [tid: _ThreadID=33 _ThreadName=http-listener-2(2)] [timeMillis: 1409865595192] [levelValue: 500] [CLASSNAME: com.sun.web.security.RealmAdapter] [METHODNAME: hasUserDataPermission] [[ [Web-Security] request.getRequest().isSecure(): true]]

[2014-09-04T21:19:55.192+0000] [glassfish 4.0] [FINE] [] [javax.enterprise.system.container.web.com.sun.web.security] [tid: _ThreadID=33 _ThreadName=http-listener-2(2)] [timeMillis: 1409865595192] [levelValue: 500] [CLASSNAME: com.sun.web.security.RealmAdapter] [METHODNAME: invokeWebSecurityManager] [[ [Web-Security] [ hasResourcePermission ] Principal: null ContextPath: /bar-data]]

[2014-09-04T21:19:55.193+0000] [glassfish 4.0] [FINE] [] [javax.enterprise.system.core.security] [tid: _ThreadID=33 _ThreadName=http-listener-2(2)] [timeMillis: 1409865595193] [levelValue: 500] [CLASSNAME: com.sun.enterprise.security.web.integration.WebSecurityManager] [METHODNAME: setPolicyContext] [[ [Web-Security] Setting Policy Context ID: old = null ctxID = BarAppDemo/barrestcertswebservice-1_0_0_war]]

[2014-09-04T21:19:55.196+0000] [glassfish 4.0] [FINE] [] [javax.enterprise.system.core.security] [tid: _ThreadID=33 _ThreadName=http-listener-2(2)] [timeMillis: 1409865595196] [levelValue: 500] [CLASSNAME: com.sun.enterprise.security.web.integration.WebSecurityManager] [METHODNAME: checkPermissionWithoutCache] [[ [Web-Security] Codesource with Web URL: file:/BarAppDemo/barrestcertswebservice-1_0_0_war]]

[2014-09-04T21:19:55.200+0000] [glassfish 4.0] [FINE] [] [javax.enterprise.system.core.security] [tid: _ThreadID=33 _ThreadName=http-listener-2(2)] [timeMillis: 1409865595200] [levelValue: 500] [CLASSNAME: com.sun.enterprise.security.web.integration.WebSecurityManager] [METHODNAME: checkPermissionWithoutCache] [[ [Web-Security] Checking Web Permission with Principals : null]]

[2014-09-04T21:19:55.201+0000] [glassfish 4.0] [FINE] [] [javax.enterprise.system.core.security] [tid: _ThreadID=33 _ThreadName=http-listener-2(2)] [timeMillis: 1409865595201] [levelValue: 500] [CLASSNAME: com.sun.enterprise.security.web.integration.WebSecurityManager] [METHODNAME: checkPermissionWithoutCache] [[ [Web-Security] Web Permission = ("javax.security.jacc.WebResourcePermission" "/resources/upload/data/51" "POST")]]

[2014-09-04T21:19:55.201+0000] [glassfish 4.0] [FINEST] [] [javax.enterprise.system.core.security] [tid: _ThreadID=33 _ThreadName=http-listener-2(2)] [timeMillis: 1409865595201] [levelValue: 300] [CLASSNAME: com.sun.enterprise.security.provider.BasePolicyWrapper] [METHODNAME: doImplies] [[ JACC Policy Provider: PolicyWrapper.implies, context (BarAppDemo/barrestcertswebservice-1_0_0_war)- result was(false) permission (("javax.security.jacc.WebResourcePermission" "/resources/upload/data/51" "POST"))]]

[2014-09-04T21:19:55.202+0000] [glassfish 4.0] [FINE] [] [javax.enterprise.system.core.security] [tid: _ThreadID=33 _ThreadName=http-listener-2(2)] [timeMillis: 1409865595202] [levelValue: 500] [CLASSNAME: com.sun.enterprise.security.web.integration.WebSecurityManager] [METHODNAME: hasResourcePermission] [[ [Web-Security] hasResource isGranted: false]]

[2014-09-04T21:19:55.202+0000] [glassfish 4.0] [FINE] [] [javax.enterprise.system.core.security] [tid: _ThreadID=33 _ThreadName=http-listener-2(2)] [timeMillis: 1409865595202] [levelValue: 500] [CLASSNAME: com.sun.enterprise.security.web.integration.WebSecurityManager] [METHODNAME: hasResourcePermission] [[ [Web-Security] hasResource perm: ("javax.security.jacc.WebResourcePermission" "/resources/upload/data/51" "POST")]]

Server code:

    private static final String UPLOAD_RESPONSE_ENTITY = "{ \"status\" : 200 }";

@Path(ServiceUris.UPLOAD_DATA_PATH + "/{id}")
@POST
@Consumes(MediaType.APPLICATION_OCTET_STREAM)
@Produces(MediaType.APPLICATION_JSON)
public Response uploadData(@PathParam("id") String id, 
                           InputStream is) {
    try {
        logger.info("Data upload is starting.");
        byte[] buf = new byte[80];
        int sum = 0;
        int n = is.read(buf);
        while (n >= 0) {
            sum += n;
            logger.info("Data upload so far: "+new String(buf, "UTF-8"));
            n = is.read(buf);
        }
        logger.info("Data upload read "+sum+" bytes.");
        return Response.serverError().entity(UPLOAD_RESPONSE_ENTITY).build();

    } catch (IOException e) {
        logger.log(Level.SEVERE, "Data upload got exception.", e);
        return Response.serverError().build();
    } finally {
    }
  }

In case it isn't obvious, I'm using OCTET STREAM for the input entity type to eliminate any possibility of problems with more specific types. Originally it was multipart form data.

Appreciate any help. I will keep my opinion of the HttpURLConnection API to myself, as I don't want to offend anyone.

Dalkvik was giving me errors about missing nio libraries, and I thought I remembered a comment from an OkHttp developer that they required Java 7. But I could be hallucinating. — Taylor
Those are warnings and aren't used on Android anyway. Compilation requires JDK 7 which is what you might be thinking of. — Jake Wharton
new String(buf, "UTF-8") should be new String(buf, 0, n, "UTF-8"). You should use a buffer much bigger than 80 bytes. Try 16k. And finally you should actually do something with the data, not just log it. — user207421
@JakeWharton Thanks for the clarification. I may just include OkHttp's wrapper for HUC as a library then, it fixes a bug where, under SSL, HUC always builds the response in memory before sending it. — Taylor

Taylor Taylor · Accepted Answer · 2014-09-05T02:37:33

Ok progress, and this may be of help to anyone else trying to upload files over SSL. I now have the service request succeeding. It still fails sometimes, but it is progress. I did some cosmetic things like removing calls to connect(), setDoInput() and setDoOutput(). Reading SO posts, these seem to be just there to cause confusion. But I think what made the difference was, on the server side, on the HTTP Listener, bumping up the Max Post Size and Max Post Save Size to 100000. I had already turned off Upload Timeout, but clearly no upload of a few kilobytes should take more than five minutes. So it looks like it may have been a buffer overflow on Glassfish that did not even get logged, just resulted in bizarre behavior. It sure would be nice to have a way of finding out when this happens.

I am still getting this periodically on Android (when the same request decides to fail):

09-04 22:05:09.347: D/org.foo.main.rest.RequestProcessor(3346): javax.net.ssl.SSLException: Connection closed by peer 09-04 22:05:09.347: D/org.foo.main.rest.RequestProcessor(3346): at com.android.org.conscrypt.NativeCrypto.SSL_do_handshake(Native Method) 09-04 22:05:09.347: D/org.foo.main.rest.RequestProcessor(3346): at com.android.org.conscrypt.OpenSSLSocketImpl.startHandshake(OpenSSLSocketImpl.java:405) 09-04 22:05:09.347: D/org.foo.main.rest.RequestProcessor(3346): at com.android.okhttp.Connection.upgradeToTls(Connection.java:146) 09-04 22:05:09.347: D/org.foo.main.rest.RequestProcessor(3346): at com.android.okhttp.Connection.connect(Connection.java:107) 09-04 22:05:09.347: D/org.foo.main.rest.RequestProcessor(3346): at com.android.okhttp.internal.http.HttpEngine.connect(HttpEngine.java:294) 09-04 22:05:09.347: D/org.foo.main.rest.RequestProcessor(3346): at com.android.okhttp.internal.http.HttpEngine.sendSocketRequest(HttpEngine.java:255) 09-04 22:05:09.347: D/org.foo.main.rest.RequestProcessor(3346): at com.android.okhttp.internal.http.HttpEngine.sendRequest(HttpEngine.java:206) 09-04 22:05:09.347: D/org.foo.main.rest.RequestProcessor(3346): at com.android.okhttp.internal.http.HttpURLConnectionImpl.execute(HttpURLConnectionImpl.java:345) 09-04 22:05:09.347: D/org.foo.main.rest.RequestProcessor(3346): at com.android.okhttp.internal.http.HttpURLConnectionImpl.getResponse(HttpURLConnectionImpl.java:296) 09-04 22:05:09.347: D/org.foo.main.rest.RequestProcessor(3346): at com.android.okhttp.internal.http.HttpURLConnectionImpl.getResponseCode(HttpURLConnectionImpl.java:503) 09-04 22:05:09.347: D/org.foo.main.rest.RequestProcessor(3346): at com.android.okhttp.internal.http.HttpsURLConnectionImpl.getResponseCode(HttpsURLConnectionImpl.java:136) 09-04 22:05:09.347: D/org.foo.main.rest.RequestProcessor(3346): at org.foo.main.rest.RestMethod.throwErrors(RestMethod.java:602)

It may be because I am returning 500 RC while I try to figure this out, and the failures may be confusing SSL handshake (if that even makes sense, I just notice SSL handshake timeouts seemed to cascade after my earlier failure, to the point where ALL types of requests started getting this handshake timeout). Or perhaps there are race conditions in the Android SSL handshake with the server that periodically lock it up.

Now I guess will try turning on chunking.....

HttpsURLConnection on Android upload over SSL freezes up (with varying failure modes)

1 Answers