Add unique number to WebFlux log prefix for Reactor Netty server

[spring-projects-issues]

Robbert van Waveren opened SPR-17507 and commented

Expected behavior:
Every HTTP request is logged with a unique log prefix regardless of any tcp/ip connection or thread reuse.

Observed behavior:
Consecutive HTTP requests from Chrome (using keep-alive) that are handled by the same reactor-http-nio thread are logged with the same log prefix.

 

---

Affects: 5.1.2

Attachments:

• issue-project.zip (9.08 kB)

Issue Links:

• HTTP GET from Chrome with WebFlux Rest Controller never completes [SPR-17506] #22038 HTTP GET from Chrome with WebFlux Rest Controller never completes

[spring-projects-issues]

Rossen Stoyanchev commented

We use the channel id, intentionally matching to what Reactor Netty does. I see your point about the fact that connections are pooled and re-used. At the same time requests on the same connection do not overlap, so it doesn't prevent correctly correlating messages. It also provides a bit of extra information by showing that the same connection is being used, or not (when a connection is closed and re-opened).

[spring-projects-issues]

Robbert van Waveren commented

I've noticed that too and after reading the Javadocs it is somewhat clear to me that this can happen. Exposing it as ServerHttpRequest#getId though kind of makes it less obvious as id suggests uniqueness. 

 

Perhaps this ticket could be changed to an improvement request to for example make a separate getId and getChannelId available in the ServerWebExchange and ServerHttpRequest interfaces, if that is something you would want to support. As I feel that having truely unique http request id's would have a lot of value, especially assuming more and more requests will get multiplexed over the same channel in the future with http2 and 3. 

[spring-projects-issues]

Rossen Stoyanchev commented

For other servers we use an identity hex on the request instance, because a channel or connection id is not available. So having a separate getChannelId doesn't really make sense, as we couldn't implement it consistently across servers.

The main purpose of the getId() method is for logging purposes. We could consider appending "-N" to the id where N is an incremental number to make it unique, but I'm not convinced that's really necessary. Overall I'd really like to remain aligned with what Reactor Netty uses. Good point though about HTTP/2 where we might need to append a stream id as well. I will discuss this with the Reactor Netty team.

[spring-projects-issues]

Rossen Stoyanchev commented

Scheduling tentatively for 5.2 as we should consider an improvement for HTTP/2 streams.

[spring-projects-issues]

Rossen Stoyanchev commented

I've created  Reactor Netty #549 which we'll need in order to access the stream id.

[rstoyanchev]

HTTP/2 streams should be addressed as part of reactor/reactor-netty#549 and it looks like that will be transparent to us. In general where the underlying server exposes a connection id, we will use that, so if you need something further I believe that should be done at the Reactor Netty level. Otherwise the logs between Reactor Netty and WebFlux won't be entirely consistent.

[PyvesB]

We've enabled debug logging for incoming web server requests and have bumped into this issue as well. The Javadocs of ServerWebExchange suggest that the log prefix can be used to correlate messages for a given exchange:

spring-framework/spring-web/src/main/java/org/springframework/web/server/ServerWebExchange.java

Line 221 in daa30a9

* Return a log message prefix to use to correlate messages for this exchange.

However, as the underlying channel id is being used (see here), the same log prefix may be duplicated across different requests (for example if the connection is kept alive). Logs for different requests and responses will end up being mixed up together due to this.

@rstoyanchev suggestion about appending "-N" to the id where N is an incremental number to make it unique would be ideal, as it would prevent exchanges being confused with one another whilst still allowing to correlate with underlying reactor-netty log messages.

Could this issue please be reopened?

[PyvesB]

Thanks for working on this @rstoyanchev! 👍

[pdevalck]

I created issue #26430 for the Undertow reactive server