logbook icon indicating copy to clipboard operation
logbook copied to clipboard

Fix JAX-RS filter NPE for empty entities

Open msdousti opened this issue 5 months ago • 1 comments

In JAX-RS, when Logbook is registered as a response filter, and the response entity is empty, an NPE is thrown. Same seems to be the case for request filter and an empty request.

Description

The issue was reported to us but marked as reproducible (see below). However, I could reproduce it here: https://github.com/msdousti/quarkus-logbook

If you use install this branch to your local Maven, it works as expected. However, if you change logbook-bom.version in the above repo to 3.9.0 (current Logbook version), and run the test:

curl -iI http://localhost:8080/hello
HTTP/1.1 500 Internal Server Error
content-type: text/plain; charset=utf-8

In the server logs:

2024-09-22 02:13:20,426 TRACE [org.zal.log.Logbook] (executor-thread-1) Incoming Request: f0ce7f5363945e86
Remote: localhost:8080
HEAD http://localhost:8080/hello HTTP/1.1
Accept: */*
Host: localhost:8080
User-Agent: curl/8.5.0

2024-09-22 02:13:20,433 TRACE [org.zal.log.Logbook] (executor-thread-1) Outgoing Response: f0ce7f5363945e86
Duration: 11 ms
HTTP/1.1 200 OK
2024-09-22 02:13:20,437 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-1) HTTP Request to /hello failed, error id: e5624c9d-1e32-48e8-b1b3-56183b37467c-1: java.lang.NullPointerException: Cannot invoke "java.io.OutputStream.close()" because "this.original" is null
        at org.zalando.logbook.jaxrs.TeeOutputStream.close(TeeOutputStream.java:39)
        at io.quarkus.resteasy.runtime.standalone.VertxHttpResponse.finish(VertxHttpResponse.java:145)
        at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:174)
...

Root Cause

  1. LogbookServerFilter#filter calls response.expose().

  2. expose calls state.buffer(context)

  3. buffer is implemented as follows:

    https://github.com/zalando/logbook/blob/05ede67de9953342d6fb8992a56e73b02915dba7/logbook-jaxrs/src/main/java/org/zalando/logbook/jaxrs/LocalResponse.java#L57-L62

  4. When the response has no entity, then context.getEntityStream() is null. As such, TeeOutputStream will have a null stream (called "original"). When original.close is called, an NPE is thrown.

The exact same issue happens for Request Filters, when request.expose is called.

Fix

The fix is to call expose methods conditionally, only when the request/response entity exists.

Test

The existing tests use ResourceConfig (example), and they don't seem to suffer from this issue.

Quarkus does not seem to support ResourceConfig, so in my Quarkus project, I used a @Provide (see LogbookFilterSetup).

I wasn't able to write an automated test to cover this, but the existing tests plus cover for all branches already. Suggestions are welcome.

Motivation and Context

https://github.com/zalando/logbook/issues/1384

Types of changes

  • [x] Bug fix (non-breaking change which fixes an issue)
  • [ ] New feature (non-breaking change which adds functionality)
  • [ ] Breaking change (fix or feature that would cause existing functionality to change)

Checklist:

  • [ ] My change requires a change to the documentation.
  • [ ] I have updated the documentation accordingly.
  • [ ] I have added tests to cover my changes.

msdousti avatar Sep 22 '24 00:09 msdousti