Handle async servlet dispatch and streaming responses in Logbook filter

[aukevanleeuwen]

I've opened a discussion here: #2248 with some more details surrounding this PR.

[aukevanleeuwen]

As commented here: #2248 (comment) I was expecting this build to fail on coverage, but I need some input to see if we can even get rid of this branch altogether?

WDYT?

[aukevanleeuwen]

I've added a very convoluted test to imitate a duplicate call to LogbookFilter#write(...). The branch coverage is now at 100%. Marking this PR as ready for review.

[aukevanleeuwen]

@kasmarian (just picking one of the maintainers here): there is some code in RemoteRequest to attach the listener when startAsync is called. I've done it in a simpler way in the MR by just adding the listener to the async context after the return from the chain.filter() call.

Can we just get rid of that code in favor of https://github.com/aukevanleeuwen/logbook/blob/34a66a72c34df2b335f4419d378f5bcaf0148c0b/logbook-servlet/src/main/java/org/zalando/logbook/servlet/LogbookFilter.java#L76?

[kasmarian]

A very interesting find, @aukevanleeuwen! I tried finding a way to break it without the AtomicBoolean, but seems like the flow works fine with your changes, as it should have from the beginning, is seems. As AtomicBoolean was just patching a bug. Feel free to remove it in this PR.

The concern I had was that in case of these multi-step flows, LogbookFilter would be called several times with different AsyncContexts, each of which would trigger completion events and result in multiple duplicated log writes. But it looks like eventually only one onComplete.

The flow with the internally forwarded request from the test that you added looked like:

1. (first request)
   asyncStarted = false
   dispatcherType = REQUEST
   -> doFilter
   asyncStarted = true
   -> LogbookFilter adds the listener

2. (second internal request)
   asyncStarted = false
   dispatcherType = ASYNC
   -> doFilter
   asyncStarted = true
   dispatcherType = FORWARD
   somewhere here asyncContext.startAsync is called which resets listeners.
   -> LogbookFilter adds the listener again, but to a new context

asyncStarted = false
dispatcherType = ASYNC
....
onComplete() -> LogbookFilter.write()

[aukevanleeuwen]

@kasmarian I've rebased and removed the synchronizer code (and the async listener code in RemoteRequest). Let me know if you have any comments.

[aukevanleeuwen]

@lukasniemeier-zalando @kasmarian @msdousti @ChristianLohmann Any chance this can have another review? TIA.

[kasmarian]

sorry, somehow half of the logbook maintainers got sick last week. The changes look good to me

[kasmarian]

👍

[aukevanleeuwen]

@lukasniemeier-zalando @msdousti @ChristianLohmann Can one of you do another review perhaps?

[lukasniemeier-zalando]

👍

[aukevanleeuwen]

@kasmarian : do you have a release cadence of some kind by any chance?

[kasmarian]

we don't have a fixed cadence. I was waiting for a few other PRs to get resolved and reviewed by my colleagues, e.g. #2234 and #2184 to batch them together.
Do you want your fix soon? We can do a small release sooner for you, not a problem

[aukevanleeuwen]

Hey @kasmarian, that would be nice if possible. I can understand you want to batch them together, but to be honest it doesn't look like they will be done very soon. But maybe I'm mistaken. If they are close to finishing, fine. Otherwise I'd love to have a release earlier.

[kasmarian]

Let me check with a few people how close they feel their PR reviews are and do a release later this week either with other changes or not