2

In one of my clients logs I've seen an exception from Sun classes. The client uses OpenJDK 1.8.0_91.

I've tried to reproduce it without any luck.

From our logs, it seems like I'm getting the exception during Shutdown of the JVM (in ShutdownHook).

The issue is that this code works during the lifetime of the program and sends all the data as expected, however during shutdown, from time to time, we are getting this NPE.

Any ideas on how to solve? I've tried to have a look at the source code but for some reason I couldn't find it.

Here's the stack trace:

    2016-07-08 11:07:58,426 ERROR [Thread-0] [HttpClient] Failed to send 'POST' request to 'https://prod-x-gw.mycompany.co/api/v2/testDoMagic/'. Error: java.lang.NullPointerException
java.lang.NullPointerException: null
    at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1158) ~[na:1.8.0_91]
    at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:999) ~[na:1.8.0_91]
    at sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.connect(AbstractDelegateHttpsURLConnection.java:177) ~[na:1.8.0_91]
    at sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(HttpURLConnection.java:1283) ~[na:1.8.0_91]
    at sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1258) ~[na:1.8.0_91]
    at sun.net.www.protocol.https.HttpsURLConnectionImpl.getOutputStream(HttpsURLConnectionImpl.java:250) ~[na:1.8.0_91]
    at com.my.company.HttpClient.writeRequestBodyToOutputStream(HttpClient.java:152) ~[na:na]
    at com.my.company.HttpClient.sendRequest(HttpClient.java:52) ~[na:na]
    at com.my.company.JsonClient.sendHttpRequest(JsonClient.java:187) [na:na]
    at com.my.company.JsonClient.postRequest(JsonClient.java:92) [na:na]
    at com.my.company.JsonClient.postRequest(JsonClient.java:86) [na:na]
    at com.my.company.DoMagicServiceProxy.sendRequest(DoMagicServiceProxy.java:59) [na:na]
    at com.my.company.DoMagicServiceProxy.submitDoMagic(DoMagicServiceProxy.java:48) [na:na]
    at com.my.company.DoMagicQueueSender$2.process(DoMagicQueueSender.java:108) [na:na]
    at com.mycompany..commons.ChunksProcessor.processAsChunks(ChunksProcessor.java:35) [na:na]
    at com.my.company.DoMagicQueueSender$1.execute(DoMagicQueueSender.java:89) [na:na]
    at com.my.company.DoMagicQueueSender.shutdown(DoMagicQueueSender.java:46) [na:na]
    at com.mycompany.DoMagicManager.shutDown(DoMagicManager.java:77) [na:na]
    at com.mycompany.AM.shutdown(AM.java:145) [na:na]
    at com.mycompany.AM.access$000(AM.java:17) [na:na]
    at com.mycompany.AM$1.run(AM.java:157) [na:na]
2016-07-08 11:07:58,437 ERROR [Thread-0] [DoMagicServiceProxy] Failed while trying to submit DoMagic. Error:
java.lang.RuntimeException: Failed to send 'POST' request to 'https://prod-x-gw.mycompany.co/api/v2/testDoMagic/'. Error: java.lang.NullPointerException
    at com.my.company.HttpClient.sendRequest(HttpClient.java:70) ~[na:na]
    at com.my.company.JsonClient.sendHttpRequest(JsonClient.java:187) ~[na:na]
    at com.my.company.JsonClient.postRequest(JsonClient.java:92) ~[na:na]
    at com.my.company.JsonClient.postRequest(JsonClient.java:86) ~[na:na]
    at com.my.company.DoMagicServiceProxy.sendRequest(DoMagicServiceProxy.java:59) ~[na:na]
    at com.my.company.DoMagicServiceProxy.submitDoMagic(DoMagicServiceProxy.java:48) ~[na:na]
    at com.my.company.DoMagicQueueSender$2.process(DoMagicQueueSender.java:108) [na:na]
    at com.mycompany.commons.ChunksProcessor.processAsChunks(ChunksProcessor.java:35) [na:na]
    at com.my.company.DoMagicQueueSender$1.execute(DoMagicQueueSender.java:89) [na:na]
    at com.my.company.DoMagicQueueSender.shutdown(DoMagicQueueSender.java:46) [na:na]
    at com.mycompany.DoMagicManager.shutDown(DoMagicManager.java:77) [na:na]
    at com.mycompany.AM.shutdown(AM.java:145) [na:na]
    at com.mycompany.AM.access$000(AM.java:17) [na:na]
    at com.mycompany.AM$1.run(AM.java:157) [na:na]
Caused by: java.lang.NullPointerException: null
    at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1158) ~[na:1.8.0_91]
    at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:999) ~[na:1.8.0_91]
    at sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.connect(AbstractDelegateHttpsURLConnection.java:177) ~[na:1.8.0_91]
    at sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(HttpURLConnection.java:1283) ~[na:1.8.0_91]
    at sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1258) ~[na:1.8.0_91]
    at sun.net.www.protocol.https.HttpsURLConnectionImpl.getOutputStream(HttpsURLConnectionImpl.java:250) ~[na:1.8.0_91]
    at com.my.company.HttpClient.writeRequestBodyToOutputStream(HttpClient.java:152) ~[na:na]
    at com.my.company.HttpClient.sendRequest(HttpClient.java:52) ~[na:na]
    ... 13 common frames omitted

If that's helps, I'm my HttpClient implementation:

public class HttpClient {
private int readTimeoutInMS;
private int connectTimeoutInMS;
private String charset;
private final int SECOND = 1000;
private ILogFactory logFactory;
private ILogger log;

public HttpClient(){
    //By default, max timeout will be 130 seconds - 10 seconds to connect, and 120 seconds to read the final byte.
    connectTimeoutInMS = 10 * SECOND;
    readTimeoutInMS = 120 * SECOND;
    charset = "utf-8";
}

public void init() {
    if (log == null) {
        log = getLogger();
    }
}

public HttpResponse sendRequest(HttpRequest request)
{
    log.info("sendRequest was called. Remote url:'" + request.getUrl() + "'.");
    HttpRequestMethods requestMethod = request.getRequestMethod();
    HttpURLConnection connection = null;
    boolean originalFollowRedirects = HttpURLConnection.getFollowRedirects();
    try{

        URL targetUrl = new URL(request.getUrl());
        connection = (HttpURLConnection) targetUrl.openConnection();

        setupConnectionObject(request, requestMethod, connection);

        if (requestMethod == HttpRequestMethods.POST){
            writeRequestBodyToOutputStream(request, connection);
        }

        HttpResponse response = new HttpResponse();
        response.setStatusCode(connection.getResponseCode());
        if (response.getStatusCode() >= 400) {
            response.setResponseStream(connection.getErrorStream());
        }
        else {
            response.setResponseStream(connection.getInputStream());
        }

        return response;

    }catch (Exception e)
    {
        String msg = String.format("Failed to send '%s' request to '%s'. Error: %s", requestMethod, request.getUrl(), e);
        log.error(msg,e);
        throw new RuntimeException(msg, e);
    }
    finally {

        HttpURLConnection.setFollowRedirects(originalFollowRedirects);
    }
}


public int getReadTimeoutInMS() {
    return readTimeoutInMS;
}

public void setReadTimeoutInMS(int readTimeoutInMS) {
    this.readTimeoutInMS = readTimeoutInMS;
}

public int getConnectTimeoutInMS() {
    return connectTimeoutInMS;
}

public void setConnectTimeoutInMS(int connectTimeoutInMS) {
    this.connectTimeoutInMS = connectTimeoutInMS;
}


public String getCharset() {
    return charset;
}

public void setCharset(String charset) {
    this.charset = charset;
}

public ILogFactory getLogFactory() {
    return logFactory;
}

public void setLogFactory(ILogFactory logFactory) {
    this.logFactory = logFactory;
}

private void setupConnectionObject(HttpRequest request, HttpRequestMethods requestMethod, HttpURLConnection connection)throws ProtocolException {
    connection.setRequestMethod(requestMethod.toString());

    if (requestMethod == HttpRequestMethods.POST){
        //Mark the HttpMethod as post.
        connection.setDoOutput(true); // Allows to send message body on the output stream.
    } else if (requestMethod == HttpRequestMethods.HEAD)
    {
        HttpURLConnection.setFollowRedirects(false);
        connection.setRequestMethod("HEAD");
    }

    int connectTimeout = request.getConnectTimeout() != null? request.getConnectTimeout() : this.connectTimeoutInMS;
    if (connectTimeout >= 0)
    {
        connection.setConnectTimeout(connectTimeout);
    }

    int readTimeout = request.getReadTimeout() != null? request.getReadTimeout() : this.readTimeoutInMS;
    if (connectTimeout >= 0)
    {
        connection.setReadTimeout(readTimeout);
    }

    //Add HttpHeader
    if (request.getHttpHeaders() != null)
    {
        for (Entry<String, String> httpHeader : request.getHttpHeaders().entrySet()) {
            connection.setRequestProperty(httpHeader.getKey(), httpHeader.getValue());
        }
    }
    if (request.getCompressRequestBody() && connection.getDoOutput()){ //only turn on for request with output
        connection.setRequestProperty("Content-Encoding","gzip");
    }
}
private void writeRequestBodyToOutputStream(HttpRequest request,
        HttpURLConnection connection) throws IOException,
        UnsupportedEncodingException {
    DataOutputStream dataOutputSteam = null; 
    try{
        dataOutputSteam = new DataOutputStream(connection.getOutputStream());
        String requestBody = request.getRequestBody() != null ? request.getRequestBody() : "";
        String bodyCharset = request.getCharset() != null ? request.getCharset() : this.charset;
        byte[] requestBodyAsBytes = requestBody.getBytes(bodyCharset);

        if (request.getCompressRequestBody()) {
            //http://stackoverflow.com/questions/7153484/gzip-post-request-with-httpclient-in-java
            ByteArrayOutputStream baos = new ByteArrayOutputStream();
            try (GZIPOutputStream gzos = new GZIPOutputStream(baos)) {
                gzos.write(requestBodyAsBytes);
            }

            byte[] gzippedBytes = baos.toByteArray();
            requestBodyAsBytes = gzippedBytes;
        }
        dataOutputSteam.write(requestBodyAsBytes);
    }
    finally{
        if (dataOutputSteam != null)
        {
            dataOutputSteam.close();
        }
    }
}

private ILogger getLogger() {
    ILogger logger;
    if (logFactory != null)
    {
        logger = logFactory.getLogger("HttpClient");
    }
    else
    {
        logger = NullLogger.INSTANCE;
    }
    return logger;
}

}

nadavy
  • 1,755
  • 1
  • 18
  • 33

1 Answers1

2

My guess is that you disconnect from that url when the connection is actually still in use during the final cleanup before exiting (maybe it's the result of some finalizer doing its job), the fact that it happens only from time to time implies that you are using that HttpURLConnection concurrently without proper synchronization.

Check the source here, in this version of HttpURLConnection.plainConnect0() that line should be 1156 instead of 1158.

Try to put a breakpoint on HttpURLConnection.disconnect() (only for that url?).

uraimo
  • 19,081
  • 8
  • 48
  • 55
  • Thanks for the source & tips. I've attached my HttpClient. Do you see something which catches your eyes regarding the Synchronization issue? To me that looks safe. – nadavy Jul 11 '16 at 07:58
  • The `dataOutputStream` in `writeRequestBodyToOutputStream` should be connected to its `HttpURLConnection`, closing one should close the other. I don't know what's happening in your DoMagic* classes and in JSONClient, it seems to be a sequence of events (in non deterministic order for the unsynchronized use of the shared connection object) that sometimes lead to this. – uraimo Jul 11 '16 at 12:27
  • Basically the flow on the DoMagic classes has a single thread which only pushed data to an array (DoMagic) and the JsonClient serializes and create new HttpRequest with the relevant body and request type. – nadavy Jul 11 '16 at 13:38