requests to io.vertx.core.http.impl.Http1xServerRequest.trace() are throwing NullPointerException

[amrsantos]

Version

Vert.x 4.1.1

Context

After upgrading to Vert.x 4.1.1 we started experiencing these errors on our logs

java.lang.NullPointerException: Cannot invoke "io.vertx.core.http.impl.Http1xServerRequest.trace()" because "request" is null
at io.vertx.core.http.impl.Http1xServerConnection.reportResponseComplete(Http1xServerConnection.java:277) ~[vertx-core-4.1.1.jar:4.1.1]
at io.vertx.core.http.impl.Http1xServerConnection.responseComplete(Http1xServerConnection.java:211) ~[vertx-core-4.1.1.jar:4.1.1]
at io.vertx.core.http.impl.Http1xServerResponse.end(Http1xServerResponse.java:409) ~[vertx-core-4.1.1.jar:4.1.1]
at io.vertx.core.http.impl.Http1xServerResponse.end(Http1xServerResponse.java:388) ~[vertx-core-4.1.1.jar:4.1.1]
at io.vertx.core.http.impl.Http1xServerResponse.end(Http1xServerResponse.java:444) ~[vertx-core-4.1.1.jar:4.1.1]
at io.vertx.reactivex.core.http.HttpServerResponse.end(HttpServerResponse.java:156) ~[vertx-rx-java2-4.1.1.jar:4.1.1]
at io.vertx.reactivex.core.http.HttpServerResponse.end(HttpServerResponse.java:163) ~[vertx-rx-java2-4.1.1.jar:4.1.1]

something similar to #3897 but on the trace() call

Do you have a reproducer?

We found out that this snippet throws the exception:

private void setErrorResponse(HttpServerResponse response) {
        response
                .setStatusCode(INTERNAL_SERVER_ERROR.code())
                .putHeader(X_SHOULD_LOG_AS_WARNING, Boolean.TRUE.toString())
                .end();
    }

but this one doesn't

private void setErrorResponse(ServiceException exception, HttpServerResponse response) {
        int httpError = exception.getError().getHttpError();
        response
                .setStatusCode(httpError)
                .putHeader(X_SHOULD_LOG_AS_WARNING, Boolean.TRUE.toString())
                .end(Json.encode(exception));
    }

thanks in advance

[vietj]

does it always happen

[vietj]

what used to be your vertx version before 4.1.1 ?

[vietj]

can you provide a full reproducer ?

[amrsantos]

@vietj

does it always happen

this is always related with an error that we have in the web sockets

[amrsantos]

what used to be your vertx version before 4.1.1 ?

we were using 3.9.4

[amrsantos]

can you provide a full reproducer ?

In the afternoon we're going to give it another look to get more information and see if it's possible to create a producer

[amrsantos]

Hi @vietj ,

Could not create a producer, but will try to explain what happens the best I can:

We have a SPA with a simple backend in java+vert.x

1. SPA registers to receive push events, it calls wss://{domain}/api/2/notifications/eventbus/775/w5riuc5n/websocket
2. On our backend we have a SockJs handler registered
3. We have this failure handler registered (the one that triggers this issue)

private void registerFailureHandler(Route route) {
    route.failureHandler(ctx -> DefaultHttpPresenter
            .create(ctx, requestContextFactory.create(ctx))
            .onError(ctx.failure(), FROM_VERTX_FAILURE_HANDLER));
}

4. whenever there is an exception on the websocket process, and the throwable is null, we catch it in the following code:

HttpServerRequest request = routingContext.request();
HttpServerResponse response = routingContext.response();
if (request.path().contains("/api/2/notifications/eventbus/") && throwable == null) {
    LOG.debug("response.closed: " + response.closed()); //false - TCP connection is still open
    LOG.debug("response.ended: " + response.ended()); //false - response was not yet written 
    LOG.debug("request.isEnded: " + request.isEnded()); //true - request was already read
    //return;
}
HttpServerResponse response = routingContext.response();
response
                .setStatusCode(INTERNAL_SERVER_ERROR.code())
                .putHeader(X_SHOULD_LOG_AS_WARNING, Boolean.TRUE.toString())
                .end(); //response.end() will be invoked and NPE will be thrown

5. here are the logs that we see:

2021-07-15 14:32:14,826 ERROR [vert.x-eventloop-thread-1] i.v.e.w.RoutingContext - Unhandled exception in router
java.lang.NullPointerException: Cannot invoke "io.vertx.core.http.impl.Http1xServerRequest.trace()" because "request" is null
            at io.vertx.core.http.impl.Http1xServerConnection.reportResponseComplete(Http1xServerConnection.java:277) ~[vertx-core-4.1.1.jar:4.1.1]
            at io.vertx.core.http.impl.Http1xServerConnection.responseComplete(Http1xServerConnection.java:211) ~[vertx-core-4.1.1.jar:4.1.1]
            at io.vertx.core.http.impl.Http1xServerResponse.end(Http1xServerResponse.java:409) ~[vertx-core-4.1.1.jar:4.1.1]
            at io.vertx.core.http.impl.Http1xServerResponse.end(Http1xServerResponse.java:388) ~[vertx-core-4.1.1.jar:4.1.1]
            at io.vertx.core.http.impl.Http1xServerResponse.end(Http1xServerResponse.java:444) ~[vertx-core-4.1.1.jar:4.1.1]
            at io.vertx.reactivex.core.http.HttpServerResponse.end(HttpServerResponse.java:156) ~[vertx-rx-java2-4.1.1.jar:4.1.1]
            at io.vertx.reactivex.core.http.HttpServerResponse.end(HttpServerResponse.java:163) ~[vertx-rx-java2-4.1.1.jar:4.1.1]

[vietj]

thanks @amrsantos

[vietj]

ok I see what is incorrect here then. thanks

[vietj]

there is definitely something we can do to avoid the NPE, however you should not try to end the response here since the HTTP response is already ended after the WebSocket handshake. I will update the implementation so that you get another error when ending the response such as an IllegalStateException that signals the response is already ended.

[vietj]

i.e response.ended() should print true here and it prints false

[amrsantos]

@vietj Thanks a lot