How to Avoid Common Mistakes When Using Reactor Netty

Transcript

1. How to Avoid Common Mistakes When Using Reactor Netty September 2–3, 2020 springone.io session-how-to-avoid-common-mistakes-when-using-reactor-netty 1
2. Violeta Georgieva • VMware • Reactor Netty committer ◦ Netty contributor • Apache Tomcat committer ◦ RM for Tomcat 7 • Spring Framework contributor 2
3. Agenda • Reactor Netty • Logging • Memory Leaks • Timeouts • Connection Closed • Connection Pool 3
4. Reactor Netty
5. Reactor Netty • Reactive Streams API for Netty • Hides the complexity of Netty • Supports UDP, TCP and HTTP • Build-in Backpressure support 5
6. Reactor Netty ❤ Spring
7. Reactor Netty ❤ Spring • Spring Boot 2.x reactive web starter • Spring WebClient • Spring Cloud Gateway 7
8. Logging
9. @GetMapping("/hello/{delay}") public Mono<String> hello(@PathVariable("delay") long delay) { return Mono.just("Hello, World!") .delayElement(Duration.ofMillis(delay)); } 9 Logging
10. @GetMapping("/hello/{delay}") public Mono<String> hello(@PathVariable("delay") long delay) { return Mono.just("Hello, World!") .delayElement(Duration.ofMillis(delay)); } 10 Logging
11. @GetMapping("/hello/{delay}") public Mono<String> hello(@PathVariable("delay") long delay) { return Mono.just("Hello, World!") .delayElement(Duration.ofMillis(delay)); } 11 Logging Response is delayed
13. 17:51:48.453 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] New http connection, requesting read 17:51:48.453 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Initialized pipeline DefaultChannelPipeline... 17:51:48.462 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Increasing pending responses, now 1 17:51:48.462 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Handler is being applied: org.springframe… 17:51:48.463 ... [ctor-http-nio-3] ... [2db101be-2] HTTP GET "/hello/100" 17:51:48.463 ... [ctor-http-nio-3] ... [2db101be-2] Mapped to io.springone.demo.HelloController#hello(long) 17:51:48.464 ... [ctor-http-nio-3] ... [2db101be-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 17:51:48.464 ... [ctor-http-nio-3] ... [2db101be-2] 0..1 [java.lang.String] 17:51:48.578 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Decreasing pending responses, now 0 17:51:48.578 ... [ctor-http-nio-3] ... [2db101be-2] Completed 200 OK 17:51:48.578 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Last HTTP response frame 17:51:48.578 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Last HTTP packet was sent, terminating... 13 Logging
14. 14 17:51:48.453 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] New http connection, requesting read 17:51:48.453 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Initialized pipeline DefaultChannelPipeline... 17:51:48.462 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Increasing pending responses, now 1 17:51:48.462 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Handler is being applied: org.springframe… 17:51:48.463 ... [ctor-http-nio-3] ... [2db101be-2] HTTP GET "/hello/100" 17:51:48.463 ... [ctor-http-nio-3] ... [2db101be-2] Mapped to io.springone.demo.HelloController#hello(long) 17:51:48.464 ... [ctor-http-nio-3] ... [2db101be-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 17:51:48.464 ... [ctor-http-nio-3] ... [2db101be-2] 0..1 [java.lang.String] 17:51:48.578 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Decreasing pending responses, now 0 17:51:48.578 ... [ctor-http-nio-3] ... [2db101be-2] Completed 200 OK 17:51:48.578 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Last HTTP response frame 17:51:48.578 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Last HTTP packet was sent, terminating... Logging
15. 15 17:51:48.453 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] New http connection, requesting read 17:51:48.453 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Initialized pipeline DefaultChannelPipeline... 17:51:48.462 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Increasing pending responses, now 1 17:51:48.462 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Handler is being applied: org.springframe… 17:51:48.463 ... [ctor-http-nio-3] ... [2db101be-2] HTTP GET "/hello/100" 17:51:48.463 ... [ctor-http-nio-3] ... [2db101be-2] Mapped to io.springone.demo.HelloController#hello(long) 17:51:48.464 ... [ctor-http-nio-3] ... [2db101be-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 17:51:48.464 ... [ctor-http-nio-3] ... [2db101be-2] 0..1 [java.lang.String] 17:51:48.578 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Decreasing pending responses, now 0 17:51:48.578 ... [ctor-http-nio-3] ... [2db101be-2] Completed 200 OK 17:51:48.578 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Last HTTP response frame 17:51:48.578 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Last HTTP packet was sent, terminating... New connection established Logging
16. 16 17:51:48.453 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] New http connection, requesting read 17:51:48.453 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Initialized pipeline DefaultChannelPipeline... 17:51:48.462 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Increasing pending responses, now 1 17:51:48.462 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Handler is being applied: org.springframe… 17:51:48.463 ... [ctor-http-nio-3] ... [2db101be-2] HTTP GET "/hello/100" 17:51:48.463 ... [ctor-http-nio-3] ... [2db101be-2] Mapped to io.springone.demo.HelloController#hello(long) 17:51:48.464 ... [ctor-http-nio-3] ... [2db101be-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 17:51:48.464 ... [ctor-http-nio-3] ... [2db101be-2] 0..1 [java.lang.String] 17:51:48.578 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Decreasing pending responses, now 0 17:51:48.578 ... [ctor-http-nio-3] ... [2db101be-2] Completed 200 OK 17:51:48.578 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Last HTTP response frame 17:51:48.578 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Last HTTP packet was sent, terminating... Request received Logging
17. 17 17:51:48.453 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] New http connection, requesting read 17:51:48.453 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Initialized pipeline DefaultChannelPipeline... 17:51:48.462 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Increasing pending responses, now 1 17:51:48.462 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Handler is being applied: org.springframe… 17:51:48.463 ... [ctor-http-nio-3] ... [2db101be-2] HTTP GET "/hello/100" 17:51:48.463 ... [ctor-http-nio-3] ... [2db101be-2] Mapped to io.springone.demo.HelloController#hello(long) 17:51:48.464 ... [ctor-http-nio-3] ... [2db101be-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 17:51:48.464 ... [ctor-http-nio-3] ... [2db101be-2] 0..1 [java.lang.String] 17:51:48.578 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Decreasing pending responses, now 0 17:51:48.578 ... [ctor-http-nio-3] ... [2db101be-2] Completed 200 OK 17:51:48.578 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Last HTTP response frame 17:51:48.578 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Last HTTP packet was sent, terminating... Response completed Logging
18. 18 17:51:48.453 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] New http connection, requesting read 17:51:48.453 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Initialized pipeline DefaultChannelPipeline... 17:51:48.462 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Increasing pending responses, now 1 17:51:48.462 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Handler is being applied: org.springframe… 17:51:48.463 ... [ctor-http-nio-3] ... [2db101be-2] HTTP GET "/hello/100" 17:51:48.463 ... [ctor-http-nio-3] ... [2db101be-2] Mapped to io.springone.demo.HelloController#hello(long) 17:51:48.464 ... [ctor-http-nio-3] ... [2db101be-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 17:51:48.464 ... [ctor-http-nio-3] ... [2db101be-2] 0..1 [java.lang.String] 17:51:48.578 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Decreasing pending responses, now 0 17:51:48.578 ... [ctor-http-nio-3] ... [2db101be-2] Completed 200 OK 17:51:48.578 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Last HTTP response frame 17:51:48.578 ... [ctor-http-nio-3] ... [id: 0x2db101be, L:/XXX - R:/YYY] Last HTTP packet was sent, terminating… Logging
20. 20 19:09:01.128 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] New http connection, requesting read 19:09:01.129 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Initialized pipeline DefaultChannelPipeline... 19:09:01.164 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Increasing pending responses, now 1 19:09:01.170 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Handler is being applied: org.springframework.. 19:09:01.181 ... [ctor-http-nio-5] ... [3f368fe3-2] HTTP GET "/hello/100" 19:09:01.199 ... [ctor-http-nio-5] ... [3f368fe3-2] Mapped to io.springone.demo.HelloController#hello(long) 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] 0..1 [java.lang.String] 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] New http connection, requesting read 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] New http connection, requesting read 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Increasing pending responses, now 1 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Handler is being applied: org.springframework.. 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] HTTP GET "/hello/100" Logging
21. 21 19:09:01.128 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] New http connection, requesting read 19:09:01.129 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Initialized pipeline DefaultChannelPipeline... 19:09:01.164 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Increasing pending responses, now 1 19:09:01.170 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Handler is being applied: org.springframework.. 19:09:01.181 ... [ctor-http-nio-5] ... [3f368fe3-2] HTTP GET "/hello/100" 19:09:01.199 ... [ctor-http-nio-5] ... [3f368fe3-2] Mapped to io.springone.demo.HelloController#hello(long) 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] 0..1 [java.lang.String] 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] New http connection, requesting read 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] New http connection, requesting read 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Increasing pending responses, now 1 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Handler is being applied: org.springframework.. 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] HTTP GET "/hello/100" Logging
22. 22 19:09:01.128 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] New http connection, requesting read 19:09:01.129 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Initialized pipeline DefaultChannelPipeline... 19:09:01.164 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Increasing pending responses, now 1 19:09:01.170 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Handler is being applied: org.springframework.. 19:09:01.181 ... [ctor-http-nio-5] ... [3f368fe3-2] HTTP GET "/hello/100" 19:09:01.199 ... [ctor-http-nio-5] ... [3f368fe3-2] Mapped to io.springone.demo.HelloController#hello(long) 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] 0..1 [java.lang.String] 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] New http connection, requesting read 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] New http connection, requesting read 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Increasing pending responses, now 1 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Handler is being applied: org.springframework.. 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] HTTP GET "/hello/100" New connection established Logging
23. 23 19:09:01.128 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] New http connection, requesting read 19:09:01.129 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Initialized pipeline DefaultChannelPipeline... 19:09:01.164 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Increasing pending responses, now 1 19:09:01.170 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Handler is being applied: org.springframework.. 19:09:01.181 ... [ctor-http-nio-5] ... [3f368fe3-2] HTTP GET "/hello/100" 19:09:01.199 ... [ctor-http-nio-5] ... [3f368fe3-2] Mapped to io.springone.demo.HelloController#hello(long) 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] 0..1 [java.lang.String] 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] New http connection, requesting read 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] New http connection, requesting read 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Increasing pending responses, now 1 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Handler is being applied: org.springframework.. 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] HTTP GET "/hello/100" Request received Logging
24. 24 19:09:01.128 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] New http connection, requesting read 19:09:01.129 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Initialized pipeline DefaultChannelPipeline... 19:09:01.164 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Increasing pending responses, now 1 19:09:01.170 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Handler is being applied: org.springframework.. 19:09:01.181 ... [ctor-http-nio-5] ... [3f368fe3-2] HTTP GET "/hello/100" 19:09:01.199 ... [ctor-http-nio-5] ... [3f368fe3-2] Mapped to io.springone.demo.HelloController#hello(long) 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] 0..1 [java.lang.String] 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] New http connection, requesting read 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] New http connection, requesting read 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Increasing pending responses, now 1 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Handler is being applied: org.springframework.. 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] HTTP GET "/hello/100" Another connection established Logging
25. 25 19:09:01.128 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] New http connection, requesting read 19:09:01.129 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Initialized pipeline DefaultChannelPipeline... 19:09:01.164 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Increasing pending responses, now 1 19:09:01.170 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Handler is being applied: org.springframework.. 19:09:01.181 ... [ctor-http-nio-5] ... [3f368fe3-2] HTTP GET "/hello/100" 19:09:01.199 ... [ctor-http-nio-5] ... [3f368fe3-2] Mapped to io.springone.demo.HelloController#hello(long) 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] 0..1 [java.lang.String] 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] New http connection, requesting read 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] New http connection, requesting read 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Increasing pending responses, now 1 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Handler is being applied: org.springframework.. 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] HTTP GET "/hello/100" Third connection established Logging
26. 26 19:09:01.128 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] New http connection, requesting read 19:09:01.129 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Initialized pipeline DefaultChannelPipeline... 19:09:01.164 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Increasing pending responses, now 1 19:09:01.170 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Handler is being applied: org.springframework.. 19:09:01.181 ... [ctor-http-nio-5] ... [3f368fe3-2] HTTP GET "/hello/100" 19:09:01.199 ... [ctor-http-nio-5] ... [3f368fe3-2] Mapped to io.springone.demo.HelloController#hello(long) 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] 0..1 [java.lang.String] 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] New http connection, requesting read 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] New http connection, requesting read 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Increasing pending responses, now 1 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Handler is being applied: org.springframework.. 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] HTTP GET "/hello/100" Logging Request received
27. 27 19:09:01.128 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] New http connection, requesting read 19:09:01.129 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Initialized pipeline DefaultChannelPipeline... 19:09:01.164 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Increasing pending responses, now 1 19:09:01.170 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Handler is being applied: org.springframework.. 19:09:01.181 ... [ctor-http-nio-5] ... [3f368fe3-2] HTTP GET "/hello/100" 19:09:01.199 ... [ctor-http-nio-5] ... [3f368fe3-2] Mapped to io.springone.demo.HelloController#hello(long) 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] 0..1 [java.lang.String] 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] New http connection, requesting read 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] New http connection, requesting read 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Increasing pending responses, now 1 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Handler is being applied: org.springframework.. 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] HTTP GET "/hello/100" !??!! Logging
28. what’s happened?
29. @GetMapping("/hello/{delay}") public Mono<String> hello(@PathVariable("delay") long delay) { return Mono.just("Hello, World!") .delayElement(Duration.ofMillis(delay)); } 29 Logging
30. @GetMapping("/hello/{delay}") public Mono<String> hello(@PathVariable("delay") long delay) { return Mono.just("Hello, World!") .delayElement(Duration.ofMillis(delay)); } 30 Response is delayed Logging
31. Non-Blocking I/O 31 Requests etc. Intensive Operations File System Database Computation Register Callback Operation Complete Event Loop Trigger Callback
32. 32 19:09:01.128 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] New http connection, requesting read 19:09:01.129 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Initialized pipeline DefaultChannelPipeline... 19:09:01.164 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Increasing pending responses, now 1 19:09:01.170 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Handler is being applied: org.springframework.. 19:09:01.181 ... [ctor-http-nio-5] ... [3f368fe3-2] HTTP GET "/hello/100" 19:09:01.199 ... [ctor-http-nio-5] ... [3f368fe3-2] Mapped to io.springone.demo.HelloController#hello(long) 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] 0..1 [java.lang.String] 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] New http connection, requesting read 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] New http connection, requesting read 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Increasing pending responses, now 1 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Handler is being applied: org.springframework.. 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] HTTP GET "/hello/100" Logging
33. 33 19:09:01.128 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] New http connection, requesting read 19:09:01.129 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Initialized pipeline DefaultChannelPipeline... 19:09:01.164 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Increasing pending responses, now 1 19:09:01.170 ... [ctor-http-nio-5] ... [id: 0x3f368fe3, L:/XXX - R:/AAA] Handler is being applied: org.springframework.. 19:09:01.181 ... [ctor-http-nio-5] ... [3f368fe3-2] HTTP GET "/hello/100" 19:09:01.199 ... [ctor-http-nio-5] ... [3f368fe3-2] Mapped to io.springone.demo.HelloController#hello(long) 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 19:09:01.228 ... [ctor-http-nio-5] ... [3f368fe3-2] 0..1 [java.lang.String] 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] New http connection, requesting read 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] New http connection, requesting read 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0x97fe3c71, L:/XXX - R:/CCC] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Increasing pending responses, now 1 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Handler is being applied: org.springframework.. 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] HTTP GET "/hello/100" Logging
34. 34 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] New http connection, requesting read 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Increasing pending responses, now 1 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Handler is being applied: org.springframework.. 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] HTTP GET "/hello/100" 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] Mapped to io.springone.demo.HelloController#hello(long) 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 19:09:01.241 ... [ctor-http-nio-5] ... [e2dd0ccb-24] 0..1 [java.lang.String] 19:09:01.371 ... [ parallel-1] ... [e2dd0ccb-24] Writing "Hello, World!" 19:09:01.384 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Decreasing pending responses, now 0 19:09:01.385 ... [ctor-http-nio-5] ... [e2dd0ccb-24] Completed 200 OK 19:09:01.385 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Last HTTP response frame 19:09:01.385 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Last HTTP packet was sent, terminating the channel Logging
35. 35 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] New http connection, requesting read 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Increasing pending responses, now 1 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Handler is being applied: org.springframework.. 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] HTTP GET "/hello/100" 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] Mapped to io.springone.demo.HelloController#hello(long) 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 19:09:01.241 ... [ctor-http-nio-5] ... [e2dd0ccb-24] 0..1 [java.lang.String] 19:09:01.371 ... [ parallel-1] ... [e2dd0ccb-24] Writing "Hello, World!" 19:09:01.384 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Decreasing pending responses, now 0 19:09:01.385 ... [ctor-http-nio-5] ... [e2dd0ccb-24] Completed 200 OK 19:09:01.385 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Last HTTP response frame 19:09:01.385 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Last HTTP packet was sent, terminating the channel New connection established Logging
36. 36 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] New http connection, requesting read 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Increasing pending responses, now 1 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Handler is being applied: org.springframework.. 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] HTTP GET "/hello/100" 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] Mapped to io.springone.demo.HelloController#hello(long) 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 19:09:01.241 ... [ctor-http-nio-5] ... [e2dd0ccb-24] 0..1 [java.lang.String] 19:09:01.371 ... [ parallel-1] ... [e2dd0ccb-24] Writing "Hello, World!" 19:09:01.384 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Decreasing pending responses, now 0 19:09:01.385 ... [ctor-http-nio-5] ... [e2dd0ccb-24] Completed 200 OK 19:09:01.385 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Last HTTP response frame 19:09:01.385 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Last HTTP packet was sent, terminating the channel Request received Logging
37. 37 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] New http connection, requesting read 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Increasing pending responses, now 1 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Handler is being applied: org.springframework.. 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] HTTP GET "/hello/100" 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] Mapped to io.springone.demo.HelloController#hello(long) 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 19:09:01.241 ... [ctor-http-nio-5] ... [e2dd0ccb-24] 0..1 [java.lang.String] 19:09:01.371 ... [ parallel-1] ... [e2dd0ccb-24] Writing "Hello, World!" 19:09:01.384 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Decreasing pending responses, now 0 19:09:01.385 ... [ctor-http-nio-5] ... [e2dd0ccb-24] Completed 200 OK 19:09:01.385 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Last HTTP response frame 19:09:01.385 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Last HTTP packet was sent, terminating the channel Response prepared Logging
38. 38 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] New http connection, requesting read 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Increasing pending responses, now 1 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Handler is being applied: org.springframework.. 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] HTTP GET "/hello/100" 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] Mapped to io.springone.demo.HelloController#hello(long) 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 19:09:01.241 ... [ctor-http-nio-5] ... [e2dd0ccb-24] 0..1 [java.lang.String] 19:09:01.371 ... [ parallel-1] ... [e2dd0ccb-24] Writing "Hello, World!" 19:09:01.384 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Decreasing pending responses, now 0 19:09:01.385 ... [ctor-http-nio-5] ... [e2dd0ccb-24] Completed 200 OK 19:09:01.385 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Last HTTP response frame 19:09:01.385 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Last HTTP packet was sent, terminating the channel Response completed Logging
39. 39 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] New http connection, requesting read 19:09:01.238 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Initialized pipeline DefaultChannelPipeline... 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Increasing pending responses, now 1 19:09:01.239 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Handler is being applied: org.springframework.. 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] HTTP GET "/hello/100" 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] Mapped to io.springone.demo.HelloController#hello(long) 19:09:01.240 ... [ctor-http-nio-5] ... [e2dd0ccb-24] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 19:09:01.241 ... [ctor-http-nio-5] ... [e2dd0ccb-24] 0..1 [java.lang.String] 19:09:01.371 ... [ parallel-1] ... [e2dd0ccb-24] Writing "Hello, World!" 19:09:01.384 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Decreasing pending responses, now 0 19:09:01.385 ... [ctor-http-nio-5] ... [e2dd0ccb-24] Completed 200 OK 19:09:01.385 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Last HTTP response frame 19:09:01.385 ... [ctor-http-nio-5] ... [id: 0xe2dd0ccb, L:/XXX - R:/BBB] Last HTTP packet was sent, terminating the channel Logging
40. reactor.netty.http.server.HttpServer : [id: 0xe2dd0ccb, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:61889] o.s.w.s.adapter.HttpWebHandlerAdapter : [e2dd0ccb-24] 40 HTTP/1.1
41. reactor.netty.http.server.HttpServer : [id: 0xe2dd0ccb, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:61889] o.s.w.s.adapter.HttpWebHandlerAdapter : [e2dd0ccb-24] 41 Connection ID HTTP/1.1
42. reactor.netty.http.server.HttpServer : [id: 0xe2dd0ccb, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:61889] o.s.w.s.adapter.HttpWebHandlerAdapter : [e2dd0ccb-24] 42 Local Address HTTP/1.1
43. reactor.netty.http.server.HttpServer : [id: 0xe2dd0ccb, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:61889] o.s.w.s.adapter.HttpWebHandlerAdapter : [e2dd0ccb-24] 43 Remote Address HTTP/1.1
44. [id: 0xe2dd0ccb, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:61889] 44 HTTP/1.1 Connection opened
45. [id: 0xe2dd0ccb, L:/[0:0:0:0:0:0:0:1]:8080 ! R:/[0:0:0:0:0:0:0:1]:61889] 45 HTTP/1.1 Connection closed
46. reactor.netty.http.server.HttpServer : [id: 0x00a8a364, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:53976](H2 - 1) o.s.w.s.adapter.HttpWebHandlerAdapter : [00a8a364/1-4] 46 HTTP/2
47. reactor.netty.http.server.HttpServer : [id: 0x00a8a364, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:53976](H2 - 1) o.s.w.s.adapter.HttpWebHandlerAdapter : [00a8a364/1-4] 47 Stream ID HTTP/2
48. @GetMapping("/hello/{delay}") public Mono<String> hello(ServerWebExchange exchange, @PathVariable("delay") long delay) { var logPrefix = exchange.getLogPrefix(); log.debug(logPrefix + "Preparing the response"); return Mono.just("Hello, World!") .delayElement(Duration.ofMillis(delay)) .doFinally(sig -> log.debug(logPrefix + "Response sent")); } 48 Logging - Log Prefix
49. @GetMapping("/hello/{delay}") public Mono<String> hello(ServerWebExchange exchange, @PathVariable("delay") long delay) { var logPrefix = exchange.getLogPrefix(); log.debug(logPrefix + "Preparing the response"); return Mono.just("Hello, World!") .delayElement(Duration.ofMillis(delay)) .doFinally(sig -> log.debug(logPrefix + "Response sent")); } 49 Log ID Logging - Log Prefix
50. 50 12:34:19.206 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] New http connection, requesting read 12:34:19.206 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] Initialized pipeline DefaultChannelPipeline... 12:34:19.215 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] Increasing pending responses, now 1 12:34:19.215 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] Handler is being applied: org.springframe... 12:34:19.215 ... [ctor-http-nio-3] ... [c5a4f03d-2] HTTP GET "/hello/100" 12:34:19.215 ... [ctor-http-nio-3] ... [c5a4f03d-2] Mapped to io.springone.demo.HelloController#hello... 12:34:19.216 ... [ctor-http-nio-3] ... [c5a4f03d-2] Preparing the response 12:34:19.216 ... [ctor-http-nio-3] ... [c5a4f03d-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 12:34:19.216 ... [ctor-http-nio-3] ... [c5a4f03d-2] 0..1 [java.lang.String] 12:34:19.321 ... [ parallel-2] ... [c5a4f03d-2] Writing "Hello, World!" 12:34:19.332 ... [ parallel-2] ... [c5a4f03d-2] Response sent 12:34:19.332 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] Decreasing pending responses, now 0 12:34:19.333 ... [ctor-http-nio-3] ... [c5a4f03d-2] Completed 200 OK 12:34:19.333 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] Last HTTP response frame 12:34:19.333 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] Last HTTP packet was sent, terminating... Logging - Log Prefix
51. 51 12:34:19.206 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] New http connection, requesting read 12:34:19.206 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] Initialized pipeline DefaultChannelPipeline... 12:34:19.215 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] Increasing pending responses, now 1 12:34:19.215 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] Handler is being applied: org.springframe... 12:34:19.215 ... [ctor-http-nio-3] ... [c5a4f03d-2] HTTP GET "/hello/100" 12:34:19.215 ... [ctor-http-nio-3] ... [c5a4f03d-2] Mapped to io.springone.demo.HelloController#hello... 12:34:19.216 ... [ctor-http-nio-3] ... [c5a4f03d-2] Preparing the response 12:34:19.216 ... [ctor-http-nio-3] ... [c5a4f03d-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 12:34:19.216 ... [ctor-http-nio-3] ... [c5a4f03d-2] 0..1 [java.lang.String] 12:34:19.321 ... [ parallel-2] ... [c5a4f03d-2] Writing "Hello, World!" 12:34:19.332 ... [ parallel-2] ... [c5a4f03d-2] Response sent 12:34:19.332 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] Decreasing pending responses, now 0 12:34:19.333 ... [ctor-http-nio-3] ... [c5a4f03d-2] Completed 200 OK 12:34:19.333 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] Last HTTP response frame 12:34:19.333 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] Last HTTP packet was sent, terminating... Application logs Logging - Log Prefix
52. 52 12:34:19.206 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] New http connection, requesting read 12:34:19.206 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] Initialized pipeline DefaultChannelPipeline... 12:34:19.215 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] Increasing pending responses, now 1 12:34:19.215 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] Handler is being applied: org.springframe... 12:34:19.215 ... [ctor-http-nio-3] ... [c5a4f03d-2] HTTP GET "/hello/100" 12:34:19.215 ... [ctor-http-nio-3] ... [c5a4f03d-2] Mapped to io.springone.demo.HelloController#hello... 12:34:19.216 ... [ctor-http-nio-3] ... [c5a4f03d-2] Preparing the response 12:34:19.216 ... [ctor-http-nio-3] ... [c5a4f03d-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported... 12:34:19.216 ... [ctor-http-nio-3] ... [c5a4f03d-2] 0..1 [java.lang.String] 12:34:19.321 ... [ parallel-2] ... [c5a4f03d-2] Writing "Hello, World!" 12:34:19.332 ... [ parallel-2] ... [c5a4f03d-2] Response sent 12:34:19.332 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] Decreasing pending responses, now 0 12:34:19.333 ... [ctor-http-nio-3] ... [c5a4f03d-2] Completed 200 OK 12:34:19.333 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] Last HTTP response frame 12:34:19.333 ... [ctor-http-nio-3] ... [id: 0xc5a4f03d, L:/XXX - R:/YYY] Last HTTP packet was sent, terminating... Application logs Logging - Log Prefix
53. Spring WebFlux Logging ID Server • ServerWebExchange#LOG_ID_ATTRIBUTE • ServerWebExchange#getLogPrefix() Client • ClientRequest#LOG_ID_ATTRIBUTE • ClientRequest#logPrefix() https://docs.spring.io/spring/docs/current/spring-framework-reference/web-reactive.html#webflux-logging-id 53
54. Wire Logging
55. 55 @Component public class MyNettyWebServerCustomizer implements WebServerFactoryCustomizer<NettyReactiveWebServerFactory> { @Override public void customize(NettyReactiveWebServerFactory factory) { factory.addServerCustomizers(httpServer -> httpServer.wiretap(true)); } } Server Side - Wire Logging
56. 56 @Component public class MyNettyWebServerCustomizer implements WebServerFactoryCustomizer<NettyReactiveWebServerFactory> { @Override public void customize(NettyReactiveWebServerFactory factory) { factory.addServerCustomizers(httpServer -> httpServer.wiretap(true)); } } Wire logging Server Side - Wire Logging
57. Client Side - Wire Logging var httpClient = HttpClient.create() .wiretap(true); WebClient.builder() .clientConnector(new ReactorClientHttpConnector(httpClient)) .build(); 57
58. 58 Client Side - Wire Logging var httpClient = HttpClient.create() .wiretap(true); WebClient.builder() .clientConnector(new ReactorClientHttpConnector(httpClient)) .build(); 6 Wire logging
59. 59 14:43:26.250 ... [ctor-http-nio-6] ... [id: 0x6e9c38fd, L:/XXX - R:/YYY] READ: 87B +——————————————————————+ | 0 1 2 3 4 5 6 7 8 9 a b c d e f | +————+——————————————————————+————————+ |00000000| 47 45 54 20 2f 68 65 6c 6c 6f 2f 31 30 30 20 48 | GET /hello/100 H | |00000010| 54 54 50 2f 31 2e 31 0d 0a 48 6f 73 74 3a 20 6c | TTP/1.1..Host: l. | |00000020| 6f 63 61 6c 68 6f 73 74 3a 38 30 38 30 0d 0a 55 | ocalhost:8080..U. | |00000030| 73 65 72 2d 41 67 65 6e 74 3a 20 63 75 72 6c 2f | ser-Agent: curl/. | |00000040| 37 2e 37 31 2e 31 0d 0a 41 63 63 65 70 74 3a 20 | 7.71.1..Accept: | |00000050| 2a 2f 2a 0d 0a 0d 0a | */*…. | +————+——————————————————————+————————+ Wire Logging HTTP/1.1 - Read Events
60. 60 14:43:26.366 ... [ctor-http-nio-6] ... [id: 0x6e9c38fd, L:/XXX - R:/YYY] WRITE: 92B +——————————————————————+ | 0 1 2 3 4 5 6 7 8 9 a b c d e f | +————+——————————————————————+———————-—+ |00000000| 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0d | HTTP/1.1 200 OK.| |00000010| 0a 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 74 | .Content-Type: t. | |00000020| 65 78 74 2f 70 6c 61 69 6e 3b 63 68 61 72 73 65 | ext/plain;charse | |00000030| 74 3d 55 54 46 2d 38 0d 0a 43 6f 6e 74 65 6e 74 | t=UTF-8..Content. | |00000040| 2d 4c 65 6e 67 74 68 3a 20 31 33 0d 0a 0d 0a 48 | -Length: 13….H. | |00000050| 65 6c 6c 6f 2c 20 57 6f 72 6c 64 21 | ello, World! | +————+——————————————————————+———————-—+ 14:43:26.366 ... [ctor-http-nio-6] ... [id: 0x6e9c38fd, L:/XXX - R:/YYY] FLUSH Wire Logging HTTP/1.1 - Write Events
61. 61 [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND SETTINGS: ack=false settings={MAX_HEADER_LIST_SIZE=8192} [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND SETTINGS: ack=false settings={ENABLE_PUSH=0, MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=33554432} [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND SETTINGS: ack=true [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND WINDOW_UPDATE: streamId=0 windowSizeIncrement=33488897 [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND HEADERS: streamId=1 headers=DefaultHttp2Headers[:method: GET, :path: /hello/100, :scheme: https, :authority: localhost:8090, user-agent: curl/7.71.1, accept: */*] padding=0 endStream=true [id: 0x1d3dcabb, L:/XXX - R:/YYY](H2 - 1) New HTTP/2 stream [id: 0x1d3dcabb, L:/XXX - R:/YYY](H2 - 1) Initialized HTTP/2 stream pipeline AbstractHttp2StreamChannel$3… [id: 0x1d3dcabb, L:/XXX - R:/YYY](H2 - 1) Handler is being applied: org.springframework… [1d3dcabb/1-2] HTTP GET "/hello/100" [1d3dcabb/1-2] Mapped to io.springone.demo.HelloController#hello(ServerWebExchange, long) [1d3dcabb/1-2] Preparing the response [1d3dcabb/1-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported [text/plain;charset=UTF-8, text/event-stream, text/plain;charset=UTF-8, */*] [1d3dcabb/1-2] 0..1 [java.lang.String] [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND SETTINGS: ack=true [1d3dcabb/1-2] Writing "Hello, World!" [1d3dcabb/1-2] Response sent [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND HEADERS: streamId=1 headers=DefaultHttp2Headers[:status: 200, content-type: text/plain;charset=UTF-8, content-length: 13] padding=0 endStream=false [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND DATA: streamId=1 padding=0 endStream=true length=13 bytes=48656c6c6f2c20576f726c6421 [1d3dcabb/1-2] Completed 200 OK Wire Logging HTTP/2
62. 62 [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND SETTINGS: ack=false settings={MAX_HEADER_LIST_SIZE=8192} [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND SETTINGS: ack=false settings={ENABLE_PUSH=0, MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=33554432} [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND SETTINGS: ack=true [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND WINDOW_UPDATE: streamId=0 windowSizeIncrement=33488897 [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND HEADERS: streamId=1 headers=DefaultHttp2Headers[:method: GET, :path: /hello/100, :scheme: https, :authority: localhost:8090, user-agent: curl/7.71.1, accept: */*] padding=0 endStream=true [id: 0x1d3dcabb, L:/XXX - R:/YYY](H2 - 1) New HTTP/2 stream [id: 0x1d3dcabb, L:/XXX - R:/YYY](H2 - 1) Initialized HTTP/2 stream pipeline AbstractHttp2StreamChannel$3… [id: 0x1d3dcabb, L:/XXX - R:/YYY](H2 - 1) Handler is being applied: org.springframework… [1d3dcabb/1-2] HTTP GET "/hello/100" [1d3dcabb/1-2] Mapped to io.springone.demo.HelloController#hello(ServerWebExchange, long) [1d3dcabb/1-2] Preparing the response [1d3dcabb/1-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported [text/plain;charset=UTF-8, text/event-stream, text/plain;charset=UTF-8, */*] [1d3dcabb/1-2] 0..1 [java.lang.String] [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND SETTINGS: ack=true [1d3dcabb/1-2] Writing "Hello, World!" [1d3dcabb/1-2] Response sent [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND HEADERS: streamId=1 headers=DefaultHttp2Headers[:status: 200, content-type: text/plain;charset=UTF-8, content-length: 13] padding=0 endStream=false [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND DATA: streamId=1 padding=0 endStream=true length=13 bytes=48656c6c6f2c20576f726c6421 [1d3dcabb/1-2] Completed 200 OK Wire Logging HTTP/2
63. 63 [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND SETTINGS: ack=false settings={MAX_HEADER_LIST_SIZE=8192} [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND SETTINGS: ack=false settings={ENABLE_PUSH=0, MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=33554432} [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND SETTINGS: ack=true [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND WINDOW_UPDATE: streamId=0 windowSizeIncrement=33488897 [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND HEADERS: streamId=1 headers=DefaultHttp2Headers[:method: GET, :path: /hello/100, :scheme: https, :authority: localhost:8090, user-agent: curl/7.71.1, accept: */*] padding=0 endStream=true [id: 0x1d3dcabb, L:/XXX - R:/YYY](H2 - 1) New HTTP/2 stream [id: 0x1d3dcabb, L:/XXX - R:/YYY](H2 - 1) Initialized HTTP/2 stream pipeline AbstractHttp2StreamChannel$3… [id: 0x1d3dcabb, L:/XXX - R:/YYY](H2 - 1) Handler is being applied: org.springframework… [1d3dcabb/1-2] HTTP GET "/hello/100" [1d3dcabb/1-2] Mapped to io.springone.demo.HelloController#hello(ServerWebExchange, long) [1d3dcabb/1-2] Preparing the response [1d3dcabb/1-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported [text/plain;charset=UTF-8, text/event-stream, text/plain;charset=UTF-8, */*] [1d3dcabb/1-2] 0..1 [java.lang.String] [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND SETTINGS: ack=true [1d3dcabb/1-2] Writing "Hello, World!" [1d3dcabb/1-2] Response sent [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND HEADERS: streamId=1 headers=DefaultHttp2Headers[:status: 200, content-type: text/plain;charset=UTF-8, content-length: 13] padding=0 endStream=false [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND DATA: streamId=1 padding=0 endStream=true length=13 bytes=48656c6c6f2c20576f726c6421 [1d3dcabb/1-2] Completed 200 OK Wire Logging HTTP/2
64. 64 [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND SETTINGS: ack=false settings={MAX_HEADER_LIST_SIZE=8192} [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND SETTINGS: ack=false settings={ENABLE_PUSH=0, MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=33554432} [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND SETTINGS: ack=true [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND WINDOW_UPDATE: streamId=0 windowSizeIncrement=33488897 [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND HEADERS: streamId=1 headers=DefaultHttp2Headers[:method: GET, :path: /hello/100, :scheme: https, :authority: localhost:8090, user-agent: curl/7.71.1, accept: */*] padding=0 endStream=true [id: 0x1d3dcabb, L:/XXX - R:/YYY](H2 - 1) New HTTP/2 stream [id: 0x1d3dcabb, L:/XXX - R:/YYY](H2 - 1) Initialized HTTP/2 stream pipeline AbstractHttp2StreamChannel$3… [id: 0x1d3dcabb, L:/XXX - R:/YYY](H2 - 1) Handler is being applied: org.springframework… [1d3dcabb/1-2] HTTP GET "/hello/100" [1d3dcabb/1-2] Mapped to io.springone.demo.HelloController#hello(ServerWebExchange, long) [1d3dcabb/1-2] Preparing the response [1d3dcabb/1-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported [text/plain;charset=UTF-8, text/event-stream, text/plain;charset=UTF-8, */*] [1d3dcabb/1-2] 0..1 [java.lang.String] [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND SETTINGS: ack=true [1d3dcabb/1-2] Writing "Hello, World!" [1d3dcabb/1-2] Response sent [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND HEADERS: streamId=1 headers=DefaultHttp2Headers[:status: 200, content-type: text/plain;charset=UTF-8, content-length: 13] padding=0 endStream=false [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND DATA: streamId=1 padding=0 endStream=true length=13 bytes=48656c6c6f2c20576f726c6421 [1d3dcabb/1-2] Completed 200 OK Wire Logging HTTP/2
65. 65 [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND SETTINGS: ack=false settings={MAX_HEADER_LIST_SIZE=8192} [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND SETTINGS: ack=false settings={ENABLE_PUSH=0, MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=33554432} [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND SETTINGS: ack=true [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND WINDOW_UPDATE: streamId=0 windowSizeIncrement=33488897 [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND HEADERS: streamId=1 headers=DefaultHttp2Headers[:method: GET, :path: /hello/100, :scheme: https, :authority: localhost:8090, user-agent: curl/7.71.1, accept: */*] padding=0 endStream=true [id: 0x1d3dcabb, L:/XXX - R:/YYY](H2 - 1) New HTTP/2 stream [id: 0x1d3dcabb, L:/XXX - R:/YYY](H2 - 1) Initialized HTTP/2 stream pipeline AbstractHttp2StreamChannel$3… [id: 0x1d3dcabb, L:/XXX - R:/YYY](H2 - 1) Handler is being applied: org.springframework… [1d3dcabb/1-2] HTTP GET "/hello/100" [1d3dcabb/1-2] Mapped to io.springone.demo.HelloController#hello(ServerWebExchange, long) [1d3dcabb/1-2] Preparing the response [1d3dcabb/1-2] Using 'text/plain;charset=UTF-8' given [*/*] and supported [text/plain;charset=UTF-8, text/event-stream, text/plain;charset=UTF-8, */*] [1d3dcabb/1-2] 0..1 [java.lang.String] [id: 0x1d3dcabb, L:/XXX - R:/YYY] INBOUND SETTINGS: ack=true [1d3dcabb/1-2] Writing "Hello, World!" [1d3dcabb/1-2] Response sent [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND HEADERS: streamId=1 headers=DefaultHttp2Headers[:status: 200, content-type: text/plain;charset=UTF-8, content-length: 13] padding=0 endStream=false [id: 0x1d3dcabb, L:/XXX - R:/YYY] OUTBOUND DATA: streamId=1 padding=0 endStream=true length=13 bytes=48656c6c6f2c20576f726c6421 [1d3dcabb/1-2] Completed 200 OK Wire Logging HTTP/2
66. Memory Leaks
67. @GetMapping("/remote") public Mono<String> remote() { return webClient.get() .uri("http://localhost:8080/") .exchange() .flatMap(response -> Mono.just(response.statusCode() .toString())) .timeout(Duration.ofSeconds(5)); } Memory Leaks 67
68. LEAK: ByteBuf.release() was not called before it's garbage-collected. See https://netty.io/wiki/reference-counted-objects.html for more information. Recent access records: Created at: io.netty.buffer.PooledByteBufAllocator.newDirectBuffer(PooledByteBufAllocator.java:363) io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:187) io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:178) io.netty.buffer.AbstractByteBufAllocator.ioBuffer(AbstractByteBufAllocator.java:139) io.netty.channel.DefaultMaxMessagesRecvByteBufAllocator$MaxMessageHandle.allocate(DefaultMaxMessagesRecvByteBufAllocator.java:114) io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:147) io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714) io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650) io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576) io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) java.base/java.lang.Thread.run(Thread.java:832) Memory Leaks 68
69. • -Dio.netty.leakDetectionLevel=paranoid • logging.level.reactor.netty=debug ◦ logging.level.reactor.netty.channel.FluxReceive=debug 69 Memory Leaks
70. LEAK: ByteBuf.release() was not called before it's garbage-collected. See https://netty.io/wiki/reference-counted-objects.html for more information. Recent access records: #1: Hint: [id: 0x2c17d156, L:/127.0.0.1:62487 - R:localhost/127.0.0.1:8080] Buffered ByteBufHolder in Inbound Flux Queue io.netty.handler.codec.http.DefaultHttpContent.touch(DefaultHttpContent.java:86) io.netty.handler.codec.http.DefaultHttpContent.touch(DefaultHttpContent.java:25) reactor.netty.channel.FluxReceive.onInboundNext(FluxReceive.java:357) reactor.netty.channel.ChannelOperations.onInboundNext(ChannelOperations.java:373) reactor.netty.http.client.HttpClientOperations.onInboundNext(HttpClientOperations.java:686) reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:94) ... #2: Hint: 'reactor.right.reactiveBridge' will handle the message from this point. io.netty.handler.codec.http.DefaultHttpContent.touch(DefaultHttpContent.java:86) io.netty.handler.codec.http.DefaultHttpContent.touch(DefaultHttpContent.java:25) io.netty.channel.DefaultChannelPipeline.touch(DefaultChannelPipeline.java:116) io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436) ... Memory Leaks 70
71. LEAK: ByteBuf.release() was not called before it's garbage-collected. See https://netty.io/wiki/reference-counted-objects.html for more information. Recent access records: #1: Hint: [id: 0x2c17d156, L:/127.0.0.1:62487 - R:localhost/127.0.0.1:8080] Buffered ByteBufHolder in Inbound Flux Queue io.netty.handler.codec.http.DefaultHttpContent.touch(DefaultHttpContent.java:86) io.netty.handler.codec.http.DefaultHttpContent.touch(DefaultHttpContent.java:25) reactor.netty.channel.FluxReceive.onInboundNext(FluxReceive.java:357) reactor.netty.channel.ChannelOperations.onInboundNext(ChannelOperations.java:373) reactor.netty.http.client.HttpClientOperations.onInboundNext(HttpClientOperations.java:686) reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:94) ... #2: Hint: 'reactor.right.reactiveBridge' will handle the message from this point. io.netty.handler.codec.http.DefaultHttpContent.touch(DefaultHttpContent.java:86) io.netty.handler.codec.http.DefaultHttpContent.touch(DefaultHttpContent.java:25) io.netty.channel.DefaultChannelPipeline.touch(DefaultChannelPipeline.java:116) io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436) ... Connection ID Memory Leaks 71
72. LEAK: ByteBuf.release() was not called before it's garbage-collected. See https://netty.io/wiki/reference-counted-objects.html for more information. Recent access records: #1: Hint: [id: 0x2c17d156, L:/127.0.0.1:62487 - R:localhost/127.0.0.1:8080] Buffered ByteBufHolder in Inbound Flux Queue io.netty.handler.codec.http.DefaultHttpContent.touch(DefaultHttpContent.java:86) io.netty.handler.codec.http.DefaultHttpContent.touch(DefaultHttpContent.java:25) reactor.netty.channel.FluxReceive.onInboundNext(FluxReceive.java:357) reactor.netty.channel.ChannelOperations.onInboundNext(ChannelOperations.java:373) reactor.netty.http.client.HttpClientOperations.onInboundNext(HttpClientOperations.java:686) reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:94) ... #2: Hint: 'reactor.right.reactiveBridge' will handle the message from this point. io.netty.handler.codec.http.DefaultHttpContent.touch(DefaultHttpContent.java:86) io.netty.handler.codec.http.DefaultHttpContent.touch(DefaultHttpContent.java:25) io.netty.channel.DefaultChannelPipeline.touch(DefaultChannelPipeline.java:116) io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436) ... Incoming Data Buffered Memory Leaks 72
73. 10:55:23.820 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Channel acquired, now 500 active connections and 0 inactive connections 10:55:23.820 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Handler is being applied: {uri=http:// localhost:8080/, method=GET} 10:55:23.821 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Received response (auto-read:false) : [Content- Type=text/html;charset=UTF-8, Transfer-Encoding=chunked, Date=Sun, 30 Aug 2020 07:55:23 GMT, Connection=close] 10:55:23.821 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Received last HTTP packet Hint: [id: 0x2c17d156, L:/XXX - R:YYY] Buffered ByteBufHolder in Inbound Flux Queue Memory Leaks 73
74. 10:55:23.820 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Channel acquired, now 500 active connections and 0 inactive connections 10:55:23.820 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Handler is being applied: {uri=http:// localhost:8080/, method=GET} 10:55:23.821 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Received response (auto-read:false) : [Content- Type=text/html;charset=UTF-8, Transfer-Encoding=chunked, Date=Sun, 30 Aug 2020 07:55:23 GMT, Connection=close] 10:55:23.821 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Received last HTTP packet Hint: [id: 0x2c17d156, L:/XXX - R:YYY] Buffered ByteBufHolder in Inbound Flux Queue Memory Leaks 74
75. 10:55:23.820 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Channel acquired, now 500 active connections and 0 inactive connections 10:55:23.820 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Handler is being applied: {uri=http:// localhost:8080/, method=GET} 10:55:23.821 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Received response (auto-read:false) : [Content- Type=text/html;charset=UTF-8, Transfer-Encoding=chunked, Date=Sun, 30 Aug 2020 07:55:23 GMT, Connection=close] 10:55:23.821 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Received last HTTP packet Hint: [id: 0x2c17d156, L:/XXX - R:YYY] Buffered ByteBufHolder in Inbound Flux Queue Memory Leaks 75
76. 76 10:55:23.820 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Channel acquired, now 500 active connections and 0 inactive connections 10:55:23.820 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Handler is being applied: {uri=http:// localhost:8080/, method=GET} 10:55:23.821 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Received response (auto-read:false) : [Content- Type=text/html;charset=UTF-8, Transfer-Encoding=chunked, Date=Sun, 30 Aug 2020 07:55:23 GMT, Connection=close] 10:55:23.821 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Received last HTTP packet Hint: [id: 0x2c17d156, L:/XXX - R:YYY] Buffered ByteBufHolder in Inbound Flux Queue 6 Memory Leaks
77. 10:55:23.820 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Channel acquired, now 500 active connections and 0 inactive connections 10:55:23.820 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Handler is being applied: {uri=http:// localhost:8080/, method=GET} 10:55:23.821 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Received response (auto-read:false) : [Content- Type=text/html;charset=UTF-8, Transfer-Encoding=chunked, Date=Sun, 30 Aug 2020 07:55:23 GMT, Connection=close] 10:55:23.821 ... [ctor-http-nio-9] ... [id: 0x2c17d156, L:/XXX - R:YYY] Received last HTTP packet Hint: [id: 0x2c17d156, L:/XXX - R:YYY] Buffered ByteBufHolder in Inbound Flux Queue Was the incoming data consumed !??!! Memory Leaks 77
78. @GetMapping("/remote") public Mono<String> remote() { return webClient.get() .uri("http://localhost:8080/") .exchange() .flatMap(response -> Mono.just(response.statusCode() .toString())) .timeout(Duration.ofSeconds(5)); } Memory Leaks 78
79. @GetMapping("/remote") public Mono<String> remote() { return webClient.get() .uri("http://localhost:8080/") .exchange() .flatMap(response -> Mono.just(response.statusCode() .toString())) .timeout(Duration.ofSeconds(5)); } Was the incoming data consumed !??!! Memory Leaks 79
80. Unlike retrieve(), when using exchange(), it is the responsibility of the application to consume any response content regardless of the scenario (success, error, unexpected data, etc). Not doing so can cause a memory leak. https://docs.spring.io/spring/docs/current/spring-framework-reference/web- reactive.html#webflux-client-exchange 80 Memory Leaks
81. @GetMapping("/remote") public Mono<String> remote() { return webClient.get() .uri("http://localhost:8080/") .retrieve() .toEntity(String.class) .flatMap(entity -> Mono.just(entity.getStatusCode() .toString())) .timeout(Duration.ofSeconds(5)); } ResponseEntity 81
82. @GetMapping("/remote") public Mono<String> remote() { return webClient.get() .uri("http://localhost:8080/") .retrieve() .toEntity(String.class) .flatMap(entity -> Mono.just(entity.getStatusCode() .toString())) .timeout(Duration.ofSeconds(5)); } ResponseEntity Status Code Headers Body 82
83. @GetMapping("/remote") public Mono<String> remote() { return webClient.get() .uri("http://localhost:8080/") .retrieve() .onStatus(HttpStatus::is4xxClientError, response -> Mono.error(new RuntimeException("Client error"))) .onStatus(HttpStatus::is5xxServerError, response -> Mono.error(new RuntimeException("Server error"))) .bodyToMono(String.class) .timeout(Duration.ofSeconds(5)); } OnStatus 83
84. @GetMapping("/remote") public Mono<String> remote() { return webClient.get() .uri("http://localhost:8080/") .retrieve() .onStatus(HttpStatus::is4xxClientError, response -> Mono.error(new RuntimeException("Client error"))) .onStatus(HttpStatus::is5xxServerError, response -> Mono.error(new RuntimeException("Server error"))) .bodyToMono(String.class) .timeout(Duration.ofSeconds(5)); } OnStatus Custom Exception 84
85. When onStatus is used, if the response is expected to have content, then the onStatus callback should consume it. If not, the content will be automatically drained to ensure resources are released. https://docs.spring.io/spring/docs/current/spring-framework-reference/web- reactive.html#webflux-client-retrieve 85 OnStatus
86. Releasing the Data • releaseBody() • toBodilessEntity() • bodyToMono(Void.class) !Closes the connection! 86
87. Timeouts
88. Server Side - Read Timeout @Component public class MyNettyWebServerCustomizer implements WebServerFactoryCustomizer<NettyReactiveWebServerFactory> { @Override public void customize(NettyReactiveWebServerFactory factory) { factory.addServerCustomizers( server -> server.doOnConnection(conn -> conn.addHandlerFirst( new ReadTimeoutHandler(50, TimeUnit.MILLISECONDS)))); } } 88
89. Server Side - Read Timeout @Component public class MyNettyWebServerCustomizer implements WebServerFactoryCustomizer<NettyReactiveWebServerFactory> { @Override public void customize(NettyReactiveWebServerFactory factory) { factory.addServerCustomizers( server -> server.doOnConnection(conn -> conn.addHandlerFirst( new ReadTimeoutHandler(50, TimeUnit.MILLISECONDS)))); } } Read timeout 89
90. Server Side - Read Timeout • Time between two requests • Timeout for the incoming data ◦ network latency • May interfere when TLS handshake • May interfere when sending a response ◦ processing latency 90
91. Client Side - Timeouts var provider = ConnectionProvider.builder("demo") .maxConnections(16) .maxIdleTime(Duration.ofSeconds(60)) .maxLifeTime(Duration.ofSeconds(60)) .build(); var httpClient = HttpClient.create() .option(ChannelOption.CONNECT_TIMEOUT_MILLIS, 60000) .wiretap(true) .responseTimeout(Duration.ofSeconds(1)); WebClient.builder() .clientConnector(new ReactorClientHttpConnector(httpClient)) .build(); 91
92. Client Side - Connection Pool var provider = ConnectionProvider.builder("demo") .maxConnections(16) .maxIdleTime(Duration.ofSeconds(60)) .maxLifeTime(Duration.ofSeconds(60)) .build(); var httpClient = HttpClient.create() .option(ChannelOption.CONNECT_TIMEOUT_MILLIS, 60000) .wiretap(true) .responseTimeout(Duration.ofSeconds(1)); WebClient.builder() .clientConnector(new ReactorClientHttpConnector(httpClient)) .build(); Max idle time in the pool 92
93. Client Side - Connection Pool var provider = ConnectionProvider.builder("demo") .maxConnections(16) .maxIdleTime(Duration.ofSeconds(60)) .maxLifeTime(Duration.ofSeconds(60)) .build(); var httpClient = HttpClient.create() .option(ChannelOption.CONNECT_TIMEOUT_MILLIS, 60000) .wiretap(true) .responseTimeout(Duration.ofSeconds(1)); WebClient.builder() .clientConnector(new ReactorClientHttpConnector(httpClient)) .build(); Max life time for the connection 93
94. Client Side - Establishing Connection var provider = ConnectionProvider.builder("demo") .maxConnections(16) .maxIdleTime(Duration.ofSeconds(60)) .maxLifeTime(Duration.ofSeconds(60)) .build(); var httpClient = HttpClient.create() .option(ChannelOption.CONNECT_TIMEOUT_MILLIS, 60000) .wiretap(true) .responseTimeout(Duration.ofSeconds(1)); WebClient.builder() .clientConnector(new ReactorClientHttpConnector(httpClient)) .build(); Max time waiting to establish connection 94
95. Client Side - Response Timeout var provider = ConnectionProvider.builder("demo") .maxConnections(16) .maxIdleTime(Duration.ofSeconds(60)) .maxLifeTime(Duration.ofSeconds(60)) .build(); var httpClient = HttpClient.create() .option(ChannelOption.CONNECT_TIMEOUT_MILLIS, 60000) .wiretap(true) .responseTimeout(Duration.ofSeconds(1)); WebClient.builder() .clientConnector(new ReactorClientHttpConnector(httpClient)) .build(); Max time waiting for a response 95
96. 96 Client Side - Response Timeout @GetMapping("/remote") public Mono<String> remote() { return webClient.get() .uri("http://localhost:8080/") .httpRequest(request -> ((HttpClientRequest) request.getNativeRequest()) .responseTimeout(Duration.ofSeconds(1))) .retrieve() … } 6
97. Client Side - Response Timeout @GetMapping("/remote") public Mono<String> remote() { return webClient.get() .uri("http://localhost:8080/") .httpRequest(request -> ((HttpClientRequest) request.getNativeRequest()) .responseTimeout(Duration.ofSeconds(1))) .retrieve() … } Max time waiting for a response 97
98. Client Side - Timeout for Mono/Flux @GetMapping("/remote") public Mono<String> remote() { return webClient.get() .uri("http://localhost:8080/") .retrieve() … .timeout(…) } 98
99. Client Side - Timeout for Mono/Flux @GetMapping("/remote") public Mono<String> remote() { return webClient.get() .uri("http://localhost:8080/") .retrieve() … .timeout(…) } Timeout for this Mono 99
100. • Time between two signals from this Flux/Mono • Timeout for the incoming data ◦ network latency • May interfere when establishing connection • May interfere when TLS handshake • May interfere when sending a request ◦ processing latency 100 Client Side - Timeout for Mono/Flux
101. Connection Closed
102. Network Latency ⏰ Read Timeout
103. Target Server - Read Timeout @Component public class MyNettyWebServerCustomizer implements WebServerFactoryCustomizer<NettyReactiveWebServerFactory> { @Override public void customize(NettyReactiveWebServerFactory factory) { factory.addServerCustomizers( server -> server.doOnConnection(conn -> conn.addHandlerFirst( new ReadTimeoutHandler(50, TimeUnit.MILLISECONDS)))); } } 103
104. Target Server - Read Timeout @Component public class MyNettyWebServerCustomizer implements WebServerFactoryCustomizer<NettyReactiveWebServerFactory> { @Override public void customize(NettyReactiveWebServerFactory factory) { factory.addServerCustomizers( server -> server.doOnConnection(conn -> conn.addHandlerFirst( new ReadTimeoutHandler(50, TimeUnit.MILLISECONDS)))); } } Read timeout (50ms) 104
105. Target Server - Read Timeout @PostMapping("/echo") public String echo(@RequestBody String body) { return body; } 105
106. 106 Client - Read Timeout @GetMapping("/remote") public Mono<String> remote() { var flux = Flux.just(CONTENT, CONTENT) .delayElements(Duration.ofMillis(100)); return webClient.post() .uri(“http://localhost:8080/echo") .body(BodyInserters.fromPublisher(flux, String.class)) .retrieve() .bodyToMono(String.class); } 6
107. Client - Read Timeout @GetMapping("/remote") public Mono<String> remote() { var flux = Flux.just(CONTENT, CONTENT) .delayElements(Duration.ofMillis(100)); return webClient.post() .uri(“http://localhost:8080/echo") .body(BodyInserters.fromPublisher(flux, String.class)) .retrieve() .bodyToMono(String.class); } Simulate Network Latency 107
108. 15:18:39.799 ... [ctor-http-nio-1] ... [id: 0x808fe695] Created a new pooled channel, now 16 active connections and 0 inactive… 15:18:39.799 ... [ctor-http-nio-1] ... [id: 0x808fe695] Initialized pipeline DefaultChannelPipeline.... 15:18:39.799 ... [ctor-http-nio-1] ... [id: 0x808fe695] REGISTERED 15:18:39.821 ... [ctor-http-nio-1] ... [id: 0x808fe695] CONNECT: localhost/127.0.0.1:8080 15:18:39.868 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 - R:YYY] Registering pool release on close event for… 15:18:39.868 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 - R:YYY] Channel connected, now 3 active connections… 15:18:39.868 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 - R:YYY] ACTIVE 15:18:39.868 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 - R:YYY] Handler is being applied: {uri=http://… 15:18:40.086 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 ! R:YYY] Channel closed, now 0 active connections and… 15:18:40.094 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 ! R:YYY] INACTIVE 15:18:40.094 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 ! R:YYY] The connection observed an error reactor.netty.http.client.PrematureCloseException: Connection has been closed BEFORE response, while sending request body Client - Read Timeout 108
109. 15:18:39.799 ... [ctor-http-nio-1] ... [id: 0x808fe695] Created a new pooled channel, now 16 active connections and 0 inactive… 15:18:39.799 ... [ctor-http-nio-1] ... [id: 0x808fe695] Initialized pipeline DefaultChannelPipeline.... 15:18:39.799 ... [ctor-http-nio-1] ... [id: 0x808fe695] REGISTERED 15:18:39.821 ... [ctor-http-nio-1] ... [id: 0x808fe695] CONNECT: localhost/127.0.0.1:8080 15:18:39.868 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 - R:YYY] Registering pool release on close event for… 15:18:39.868 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 - R:YYY] Channel connected, now 3 active connections… 15:18:39.868 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 - R:YYY] ACTIVE 15:18:39.868 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 - R:YYY] Handler is being applied: {uri=http://… 15:18:40.086 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 ! R:YYY] Channel closed, now 0 active connections and… 15:18:40.094 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 ! R:YYY] INACTIVE 15:18:40.094 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 ! R:YYY] The connection observed an error reactor.netty.http.client.PrematureCloseException: Connection has been closed BEFORE response, while sending request body Client - Read Timeout !??!! 109
110. 15:18:39.799 ... [ctor-http-nio-1] ... [id: 0x808fe695] Created a new pooled channel, now 16 active connections and 0 inactive… 15:18:39.799 ... [ctor-http-nio-1] ... [id: 0x808fe695] Initialized pipeline DefaultChannelPipeline.... 15:18:39.799 ... [ctor-http-nio-1] ... [id: 0x808fe695] REGISTERED 15:18:39.821 ... [ctor-http-nio-1] ... [id: 0x808fe695] CONNECT: localhost/127.0.0.1:8080 15:18:39.868 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 - R:YYY] Registering pool release on close event for… 15:18:39.868 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 - R:YYY] Channel connected, now 3 active connections… 15:18:39.868 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 - R:YYY] ACTIVE 15:18:39.868 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 - R:YYY] Handler is being applied: {uri=http://… 15:18:40.086 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 ! R:YYY] Channel closed, now 0 active connections and… 15:18:40.094 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 ! R:YYY] INACTIVE 15:18:40.094 ... [ctor-http-nio-1] ... [id: 0x808fe695, L:/127.0.0.1:50246 ! R:YYY] The connection observed an error reactor.netty.http.client.PrematureCloseException: Connection has been closed BEFORE response, while sending request body Client - Read Timeout Client port 110
111. 15:18:39.821 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] New http connection, requesting read 15:18:39.821 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Initialized pipeline DefaultChannelPipeline… 15:18:39.871 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Increasing pending responses, now 1 15:18:39.871 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Added encoder [ReadTimeoutHandler] at the… 15:18:39.871 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Handler is being applied: org.springframework.. 15:18:39.872 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] FluxReceive{pending=0, cancelled=false… 15:18:39.927 ... [ctor-http-nio-5] ... [d4c75b22-100] 500 Server Error for HTTP POST "/echo" io.netty.handler.timeout.ReadTimeoutException: null 15:18:39.928 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Decreasing pending responses, now 0 15:18:39.928 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Last HTTP packet was sent, terminating… 15:18:39.928 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Last HTTP response frame 15:18:39.928 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY ! R:/127.0.0.1:50246] Non Removed handler: ... Target Server - Read Timeout 111
112. 15:18:39.821 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] New http connection, requesting read 15:18:39.821 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Initialized pipeline DefaultChannelPipeline… 15:18:39.871 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Increasing pending responses, now 1 15:18:39.871 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Added encoder [ReadTimeoutHandler] at the… 15:18:39.871 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Handler is being applied: org.springframework.. 15:18:39.872 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] FluxReceive{pending=0, cancelled=false… 15:18:39.927 ... [ctor-http-nio-5] ... [d4c75b22-100] 500 Server Error for HTTP POST "/echo" io.netty.handler.timeout.ReadTimeoutException: null 15:18:39.928 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Decreasing pending responses, now 0 15:18:39.928 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Last HTTP packet was sent, terminating… 15:18:39.928 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Last HTTP response frame 15:18:39.928 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY ! R:/127.0.0.1:50246] Non Removed handler: ... Target Server - Read Timeout Client port 112
113. 15:18:39.821 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] New http connection, requesting read 15:18:39.821 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Initialized pipeline DefaultChannelPipeline… 15:18:39.871 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Increasing pending responses, now 1 15:18:39.871 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Added encoder [ReadTimeoutHandler] at the… 15:18:39.871 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Handler is being applied: org.springframework.. 15:18:39.872 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] FluxReceive{pending=0, cancelled=false… 15:18:39.927 ... [ctor-http-nio-5] ... [d4c75b22-100] 500 Server Error for HTTP POST "/echo" io.netty.handler.timeout.ReadTimeoutException: null 15:18:39.928 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Decreasing pending responses, now 0 15:18:39.928 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Last HTTP packet was sent, terminating… 15:18:39.928 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Last HTTP response frame 15:18:39.928 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY ! R:/127.0.0.1:50246] Non Removed handler: ... Target Server - Read Timeout 113
114. 15:18:39.821 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] New http connection, requesting read 15:18:39.821 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Initialized pipeline DefaultChannelPipeline… 15:18:39.871 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Increasing pending responses, now 1 15:18:39.871 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Added encoder [ReadTimeoutHandler] at the… 15:18:39.871 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Handler is being applied: org.springframework.. 15:18:39.872 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] FluxReceive{pending=0, cancelled=false… 15:18:39.927 ... [ctor-http-nio-5] ... [d4c75b22-100] 500 Server Error for HTTP POST "/echo" io.netty.handler.timeout.ReadTimeoutException: null 15:18:39.928 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Decreasing pending responses, now 0 15:18:39.928 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Last HTTP packet was sent, terminating… 15:18:39.928 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY - R:/127.0.0.1:50246] Last HTTP response frame 15:18:39.928 ... [ctor-http-nio-5] ... [id: 0xd4c75b22, L:/YYY ! R:/127.0.0.1:50246] Non Removed handler: ... Target Server - Read Timeout Read timeout (50ms) 114
115. Processing Latency ⏰ Read Timeout
116. 116 Target Server - Read Timeout @Component public class MyNettyWebServerCustomizer implements WebServerFactoryCustomizer<NettyReactiveWebServerFactory> { @Override public void customize(NettyReactiveWebServerFactory factory) { factory.addServerCustomizers( server -> server.doOnConnection(conn -> conn.addHandlerFirst( new ReadTimeoutHandler(50, TimeUnit.MILLISECONDS)))); } } 6
117. Target Server - Read Timeout @Component public class MyNettyWebServerCustomizer implements WebServerFactoryCustomizer<NettyReactiveWebServerFactory> { @Override public void customize(NettyReactiveWebServerFactory factory) { factory.addServerCustomizers( server -> server.doOnConnection(conn -> conn.addHandlerFirst( new ReadTimeoutHandler(50, TimeUnit.MILLISECONDS)))); } } Read timeout (50ms) 117
118. Target Server - Read Timeout @PostMapping("/echo") public Mono<String> echo(@RequestBody String body) { return Mono.just(body) .delayElement(Duration.ofMillis(100)); } 118
119. Target Server - Read Timeout @PostMapping("/echo") public Mono<String> echo(@RequestBody String body) { return Mono.just(body) .delayElement(Duration.ofMillis(100)); } Simulate Processing Latency 119
120. Client - Read Timeout @GetMapping("/remote") public Mono<String> remote() { var flux = Flux.just(CONTENT, CONTENT); return webClient.post() .uri(“http://localhost:8080/echo") .body(BodyInserters.fromPublisher(flux, String.class)) .retrieve() .bodyToMono(String.class); } 120
121. 16:22:03.936 ... [tor-http-nio-10] ... [id: 0x058eaaa2] Created a new pooled channel, now 3 active connections and 0 inactive... 16:22:03.937 ... [tor-http-nio-10] ... [id: 0x058eaaa2] Initialized pipeline DefaultChannelPipeline... 16:22:03.937 ... [tor-http-nio-10] ... [id: 0x058eaaa2] REGISTERED 16:22:03.964 ... [tor-http-nio-10] ... [id: 0x058eaaa2] CONNECT: localhost/127.0.0.1:8080 16:22:04.082 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 - R:YYY] Registering pool release on close event for... 16:22:04.082 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 - R:YYY] Channel connected, now 16 active connections... 16:22:04.082 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 - R:YYY] ACTIVE 16:22:04.082 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 - R:YYY] Handler is being applied: {uri=http:... 16:22:04.567 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 ! R:YYY] Channel closed, now 16 active connections and... 16:22:04.642 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 ! R:YYY] INACTIVE 16:22:04.642 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 ! R:YYY] The connection observed an error reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response Client - Read Timeout 121
122. 16:22:03.936 ... [tor-http-nio-10] ... [id: 0x058eaaa2] Created a new pooled channel, now 3 active connections and 0 inactive... 16:22:03.937 ... [tor-http-nio-10] ... [id: 0x058eaaa2] Initialized pipeline DefaultChannelPipeline... 16:22:03.937 ... [tor-http-nio-10] ... [id: 0x058eaaa2] REGISTERED 16:22:03.964 ... [tor-http-nio-10] ... [id: 0x058eaaa2] CONNECT: localhost/127.0.0.1:8080 16:22:04.082 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 - R:YYY] Registering pool release on close event for... 16:22:04.082 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 - R:YYY] Channel connected, now 16 active connections... 16:22:04.082 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 - R:YYY] ACTIVE 16:22:04.082 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 - R:YYY] Handler is being applied: {uri=http:... 16:22:04.567 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 ! R:YYY] Channel closed, now 16 active connections and... 16:22:04.642 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 ! R:YYY] INACTIVE 16:22:04.642 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 ! R:YYY] The connection observed an error reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response Client - Read Timeout !??!! 122
123. 16:22:03.936 ... [tor-http-nio-10] ... [id: 0x058eaaa2] Created a new pooled channel, now 3 active connections and 0 inactive... 16:22:03.937 ... [tor-http-nio-10] ... [id: 0x058eaaa2] Initialized pipeline DefaultChannelPipeline... 16:22:03.937 ... [tor-http-nio-10] ... [id: 0x058eaaa2] REGISTERED 16:22:03.964 ... [tor-http-nio-10] ... [id: 0x058eaaa2] CONNECT: localhost/127.0.0.1:8080 16:22:04.082 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 - R:YYY] Registering pool release on close event for... 16:22:04.082 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 - R:YYY] Channel connected, now 16 active connections... 16:22:04.082 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 - R:YYY] ACTIVE 16:22:04.082 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 - R:YYY] Handler is being applied: {uri=http:... 16:22:04.567 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 ! R:YYY] Channel closed, now 16 active connections and... 16:22:04.642 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 ! R:YYY] INACTIVE 16:22:04.642 ... [tor-http-nio-10] ... [id: 0x058eaaa2, L:/127.0.0.1:49908 ! R:YYY] The connection observed an error reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response Client - Read Timeout Client port 123
124. 16:22:04.016 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] New http connection, requesting read 16:22:04.017 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Initialized pipeline DefaultChannelPipeline... 16:22:04.099 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Increasing pending responses, now 1 16:22:04.099 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Added encoder [ReadTimeoutHandler] at the... 16:22:04.099 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Handler is being applied: org.springframework.. 16:22:04.106 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] FluxReceive{pending=0, cancelled=false... 16:22:04.178 ... [ctor-http-nio-4] ... [09740dff-3] 500 Server Error for HTTP POST "/echo" io.netty.handler.timeout.ReadTimeoutException: null 16:22:04.235 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Decreasing pending responses, now 0 16:22:04.238 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Last HTTP packet was sent, terminating... 16:22:04.239 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Last HTTP response frame 16:22:04.241 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY ! R:/127.0.0.1:49908] Non Removed handler... Target Server - Read Timeout 124
125. 16:22:04.016 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] New http connection, requesting read 16:22:04.017 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Initialized pipeline DefaultChannelPipeline... 16:22:04.099 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Increasing pending responses, now 1 16:22:04.099 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Added encoder [ReadTimeoutHandler] at the... 16:22:04.099 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Handler is being applied: org.springframework.. 16:22:04.106 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] FluxReceive{pending=0, cancelled=false... 16:22:04.178 ... [ctor-http-nio-4] ... [09740dff-3] 500 Server Error for HTTP POST "/echo" io.netty.handler.timeout.ReadTimeoutException: null 16:22:04.235 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Decreasing pending responses, now 0 16:22:04.238 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Last HTTP packet was sent, terminating... 16:22:04.239 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Last HTTP response frame 16:22:04.241 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY ! R:/127.0.0.1:49908] Non Removed handler... Target Server - Read Timeout Client port 125
126. 126 16:22:04.016 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] New http connection, requesting read 16:22:04.017 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Initialized pipeline DefaultChannelPipeline... 16:22:04.099 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Increasing pending responses, now 1 16:22:04.099 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Added encoder [ReadTimeoutHandler] at the... 16:22:04.099 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Handler is being applied: org.springframework.. 16:22:04.106 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] FluxReceive{pending=0, cancelled=false... 16:22:04.178 ... [ctor-http-nio-4] ... [09740dff-3] 500 Server Error for HTTP POST "/echo" io.netty.handler.timeout.ReadTimeoutException: null 16:22:04.235 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Decreasing pending responses, now 0 16:22:04.238 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Last HTTP packet was sent, terminating... 16:22:04.239 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Last HTTP response frame 16:22:04.241 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY ! R:/127.0.0.1:49908] Non Removed handler... 6 Target Server - Read Timeout
127. 16:22:04.016 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] New http connection, requesting read 16:22:04.017 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Initialized pipeline DefaultChannelPipeline... 16:22:04.099 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Increasing pending responses, now 1 16:22:04.099 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Added encoder [ReadTimeoutHandler] at the... 16:22:04.099 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Handler is being applied: org.springframework.. 16:22:04.106 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] FluxReceive{pending=0, cancelled=false... 16:22:04.178 ... [ctor-http-nio-4] ... [09740dff-3] 500 Server Error for HTTP POST "/echo" io.netty.handler.timeout.ReadTimeoutException: null 16:22:04.235 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Decreasing pending responses, now 0 16:22:04.238 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Last HTTP packet was sent, terminating... 16:22:04.239 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY - R:/127.0.0.1:49908] Last HTTP response frame 16:22:04.241 ... [ctor-http-nio-4] ... [id: 0x09740dff, L:/YYY ! R:/127.0.0.1:49908] Non Removed handler... Target Server - Read Timeout Read timeout (50ms) 127
128. Keep Alive Timeout
129. Target Server - Keep Alive Timeout Reactor Netty • ReadTimeoutHandler (default - no timeout) Tomcat • connectionTimeout (default 20s) • keepAliveTimeout (default == connectionTimeout) Proxy/Loadbalancer • keepAliveTimeout/maxIdleTimeout http://tomcat.apache.org/tomcat-9.0-doc/config/http.html#Standard_Implementation https://netty.io/4.1/api/io/netty/handler/timeout/ReadTimeoutHandler.html 129
130. Client - Connection Pool • Max idle time • Prefer LIFO vs. FIFO leasing strategy 130
131. Upload limit on the Target Server
132. Target Server - Upload Limit @Configuration public class WebConfig implements WebFluxConfigurer { @Override public void configureHttpMessageCodecs(ServerCodecConfigurer configurer) { configurer.defaultCodecs().maxInMemorySize(512); } } 132
133. Target Server - Upload Limit @Configuration public class WebConfig implements WebFluxConfigurer { @Override public void configureHttpMessageCodecs(ServerCodecConfigurer configurer) { configurer.defaultCodecs().maxInMemorySize(512); } } Max in memory configuration 133
134. Target Server - Upload Limit @PostMapping("/echo") public String echo(@RequestBody String body) { return body; } 134
135. Client - Upload Limit @GetMapping("/remote") public Mono<String> remote() { var flux = Flux.just(CONTENT, CONTENT); return webClient.post() .uri(“http://localhost:8080/echo") .body(BodyInserters.fromPublisher(flux, String.class)) .retrieve() .bodyToMono(String.class); } 135
136. ... [ctor-http-nio-2] ... [id: 0xbbc66538, L:/127.0.0.1:59307 - R:YYY] Channel acquired, now 16 active connections… ... [ctor-http-nio-2] ... [id: 0xbbc66538, L:/127.0.0.1:59307 - R:YYY] Handler is being applied: {uri=http://… ... [ctor-http-nio-2] ... [id: 0xbbc66538, L:/127.0.0.1:59307 ! R:YYY] Channel closed, now 15 active connections… ... [ctor-http-nio-2] ... [id: 0xbbc66538, L:/127.0.0.1:59307 ! R:YYY] The connection observed an error reactor.netty.http.client.PrematureCloseException: Connection has been closed BEFORE response, while sending request body Client - Upload Limit 136
137. ... [ctor-http-nio-2] ... [id: 0xbbc66538, L:/127.0.0.1:59307 - R:YYY] Channel acquired, now 16 active connections… ... [ctor-http-nio-2] ... [id: 0xbbc66538, L:/127.0.0.1:59307 - R:YYY] Handler is being applied: {uri=http://… ... [ctor-http-nio-2] ... [id: 0xbbc66538, L:/127.0.0.1:59307 ! R:YYY] Channel closed, now 15 active connections… ... [ctor-http-nio-2] ... [id: 0xbbc66538, L:/127.0.0.1:59307 ! R:YYY] The connection observed an error reactor.netty.http.client.PrematureCloseException: Connection has been closed BEFORE response, while sending request body Client - Upload Limit !??!! 137
138. ... [ctor-http-nio-2] ... [id: 0xbbc66538, L:/127.0.0.1:59307 - R:YYY] Channel acquired, now 16 active connections… ... [ctor-http-nio-2] ... [id: 0xbbc66538, L:/127.0.0.1:59307 - R:YYY] Handler is being applied: {uri=http://… ... [ctor-http-nio-2] ... [id: 0xbbc66538, L:/127.0.0.1:59307 ! R:YYY] Channel closed, now 15 active connections… ... [ctor-http-nio-2] ... [id: 0xbbc66538, L:/127.0.0.1:59307 ! R:YYY] The connection observed an error reactor.netty.http.client.PrematureCloseException: Connection has been closed BEFORE response, while sending request body Client - Upload Limit Client port 138
139. ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] New http connection, requesting read ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] Initialized pipeline DefaultChannelPipeline... ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] Increasing pending responses, now 1 ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] Handler is being applied: org.springframework... ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] FluxReceive{pending=0, cancelled=false, inboundDone=false... ... [ctor-http-nio-7] ... [5b9debd7-6] 500 Server Error for HTTP POST "/echo" org.springframework.core.io.buffer.DataBufferLimitException: Exceeded limit on max bytes to buffer : 512 at org.springframework.core.io.buffer.LimitedDataBufferList.raiseLimitException(LimitedDataBufferList.java:101) Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: Error has been observed at the following site(s): |_ checkpoint ⇢ HTTP POST "/echo" [ExceptionHandlingWebHandler] Stack trace: at org.springframework.core.io.buffer.LimitedDataBufferList.raiseLimitException(LimitedDataBufferList.java:101) ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] Decreasing pending responses, now 0 ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] Last HTTP packet was sent, terminating the channel ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] Last HTTP response frame Target Server - Upload Limit Client port 139
140. ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] New http connection, requesting read ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] Initialized pipeline DefaultChannelPipeline... ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] Increasing pending responses, now 1 ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] Handler is being applied: org.springframework... ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] FluxReceive{pending=0, cancelled=false, inboundDone=false... ... [ctor-http-nio-7] ... [5b9debd7-6] 500 Server Error for HTTP POST "/echo" org.springframework.core.io.buffer.DataBufferLimitException: Exceeded limit on max bytes to buffer : 512 at org.springframework.core.io.buffer.LimitedDataBufferList.raiseLimitException(LimitedDataBufferList.java:101) Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: Error has been observed at the following site(s): |_ checkpoint ⇢ HTTP POST "/echo" [ExceptionHandlingWebHandler] Stack trace: at org.springframework.core.io.buffer.LimitedDataBufferList.raiseLimitException(LimitedDataBufferList.java:101) ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] Decreasing pending responses, now 0 ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] Last HTTP packet was sent, terminating the channel ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] Last HTTP response frame Target Server - Upload Limit 140
141. ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] New http connection, requesting read ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] Initialized pipeline DefaultChannelPipeline... ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] Increasing pending responses, now 1 ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] Handler is being applied: org.springframework... ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] FluxReceive{pending=0, cancelled=false, inboundDone=false... ... [ctor-http-nio-7] ... [5b9debd7-6] 500 Server Error for HTTP POST "/echo" org.springframework.core.io.buffer.DataBufferLimitException: Exceeded limit on max bytes to buffer : 512 at org.springframework.core.io.buffer.LimitedDataBufferList.raiseLimitException(LimitedDataBufferList.java:101) Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: Error has been observed at the following site(s): |_ checkpoint ⇢ HTTP POST "/echo" [ExceptionHandlingWebHandler] Stack trace: at org.springframework.core.io.buffer.LimitedDataBufferList.raiseLimitException(LimitedDataBufferList.java:101) ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] Decreasing pending responses, now 0 ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] Last HTTP packet was sent, terminating the channel ... [ctor-http-nio-7] ... [id: 0x5b9debd7, L:/YYY - R:/127.0.0.1:59307] Last HTTP response frame Target Server - Upload Limit Max in memory exceeded 141
142. Connection Pool
143. Client Side - Connection Pool var provider = ConnectionProvider.create("demo", 1); var httpClient = HttpClient.create() .wiretap(true); WebClient.builder() .clientConnector(new ReactorClientHttpConnector(httpClient)) .build(); 143
144. Client Side - Connection Pool var provider = ConnectionProvider.create("demo", 1); var httpClient = HttpClient.create() .wiretap(true); WebClient.builder() .clientConnector(new ReactorClientHttpConnector(httpClient)) .build(); Max connections per remote address 144
145. Client Side - Connection Pool @GetMapping("/remote") public Mono<String> remote() { Mono<String> mono1 = webClient.get() .uri("https://example.com") .retrieve() .bodyToMono(String.class); Mono<String> mono2 = webClient.get() .uri("https://httpbin.org/get") .retrieve() .bodyToMono(String.class); return Flux.merge(mono1, mono2).next(); } 145
146. 146 Client Side - Connection Pool @GetMapping("/remote") public Mono<String> remote() { Mono<String> mono1 = webClient.get() .uri("https://example.com") .retrieve() .bodyToMono(String.class); Mono<String> mono2 = webClient.get() .uri("https://httpbin.org/get") .retrieve() .bodyToMono(String.class); return Flux.merge(mono1, mono2).next(); } 6 Need only the first result
147. 09:59:13.266 ... [ctor-http-nio-3] ... Creating a new [demo] client pool ... for [example.com… 09:59:13.272 ... [ctor-http-nio-3] ... [id: 0x233f98cc] Created a new pooled channel, now 1 active connection... 09:59:13.302 ... [ctor-http-nio-3] ... Creating a new [demo] client pool ... for [httpbin.org… 09:59:13.302 ... [ctor-http-nio-3] ... [id: 0xaca6699b] Created a new pooled channel, now 1 active connection... 09:59:13.330 ... [ctor-http-nio-3] ... [id: 0x233f98cc] CONNECT: example.com... 09:59:13.331 ... [ctor-http-nio-3] ... [id: 0xaca6699b] CONNECT: httpbin.org... Client Side - Connection Pool 147
148. 09:59:13.266 ... [ctor-http-nio-3] ... Creating a new [demo] client pool ... for [example.com… 09:59:13.272 ... [ctor-http-nio-3] ... [id: 0x233f98cc] Created a new pooled channel, now 1 active connection... 09:59:13.302 ... [ctor-http-nio-3] ... Creating a new [demo] client pool ... for [httpbin.org… 09:59:13.302 ... [ctor-http-nio-3] ... [id: 0xaca6699b] Created a new pooled channel, now 1 active connection... 09:59:13.330 ... [ctor-http-nio-3] ... [id: 0x233f98cc] CONNECT: example.com... 09:59:13.331 ... [ctor-http-nio-3] ... [id: 0xaca6699b] CONNECT: httpbin.org... Client Side - Connection Pool Connection Pool per remote address 148
149. 09:59:13.266 ... [ctor-http-nio-3] ... Creating a new [demo] client pool ... for [example.com… 09:59:13.272 ... [ctor-http-nio-3] ... [id: 0x233f98cc] Created a new pooled channel, now 1 active connection... 09:59:13.302 ... [ctor-http-nio-3] ... Creating a new [demo] client pool ... for [httpbin.org… 09:59:13.302 ... [ctor-http-nio-3] ... [id: 0xaca6699b] Created a new pooled channel, now 1 active connection... 09:59:13.330 ... [ctor-http-nio-3] ... [id: 0x233f98cc] CONNECT: example.com... 09:59:13.331 ... [ctor-http-nio-3] ... [id: 0xaca6699b] CONNECT: httpbin.org... Client Side - Connection Pool Connection Pool per remote address 149
150. 09:59:13.958 ... [ctor-http-nio-3] ... [id: 0x233f98cc, L:/XXX - R:example.com/...] CLOSE 09:59:13.962 ... [ctor-http-nio-3] ... [id: 0x233f98cc, L:/XXX ! R:example.com/...] Channel closed, now 0 active connections and 0 inactive connections 09:59:13.963 ... [ctor-http-nio-3] ... [id: 0xaca6699b, L:/XXX - R:httpbin.org/...] Releasing channel 09:59:13.964 ... [ctor-http-nio-3] ... [id: 0xaca6699b, L:/XXX - R:httpbin.org/...] Channel cleaned, now 0 active connections and 1 inactive connections Client Side - Connection Pool 150
151. 09:59:13.958 ... [ctor-http-nio-3] ... [id: 0x233f98cc, L:/XXX - R:example.com/...] CLOSE 09:59:13.962 ... [ctor-http-nio-3] ... [id: 0x233f98cc, L:/XXX ! R:example.com/...] Channel closed, now 0 active connections and 0 inactive connections 09:59:13.963 ... [ctor-http-nio-3] ... [id: 0xaca6699b, L:/XXX - R:httpbin.org/...] Releasing channel 09:59:13.964 ... [ctor-http-nio-3] ... [id: 0xaca6699b, L:/XXX - R:httpbin.org/...] Channel cleaned, now 0 active connections and 1 inactive connections Client Side - Connection Pool Connection returned to the pool 151
152. 09:59:13.958 ... [ctor-http-nio-3] ... [id: 0x233f98cc, L:/XXX - R:example.com/...] CLOSE 09:59:13.962 ... [ctor-http-nio-3] ... [id: 0x233f98cc, L:/XXX ! R:example.com/...] Channel closed, now 0 active connections and 0 inactive connections 09:59:13.963 ... [ctor-http-nio-3] ... [id: 0xaca6699b, L:/XXX - R:httpbin.org/...] Releasing channel 09:59:13.964 ... [ctor-http-nio-3] ... [id: 0xaca6699b, L:/XXX - R:httpbin.org/...] Channel cleaned, now 0 active connections and 1 inactive connections Client Side - Connection Pool Connection closed 152
153. Key Takeaways
154. Key Takeaways • Know your infrastructure and its configuration • Know how to configure your solution • Extensive testing for memory leaks, connection closed etc. • Your friends to ask for help ◦ TCP dump ◦ E2E traceability 154
155. Stay Connected. Violeta Georgieva @violeta_g_g session-how-to-avoid-common-mistakes-when-using-reactor-netty https://github.com/reactor/reactor-netty/ https://github.com/spring-projects/spring-framework https://projectreactor.io/docs/netty/release/reference/index.html https://docs.spring.io/spring/docs/current/spring-framework-reference/web-reactive.html #springone @springone
156. Safe Harbor Statement The following is intended to outline the general direction of VMware's offerings. It is intended for information purposes only and may not be incorporated into any contract. Any information regarding pre-release of VMware offerings, future updates or other planned modifications is subject to ongoing evaluation by VMware and is subject to change. This information is provided without warranty or any kind, express or implied, and is not a commitment to deliver any material, code, or functionality, and should not be relied upon in making purchasing decisions regarding VMware's offerings. These purchasing decisions should only be based on features currently available. The development, release, and timing of any features or functionality described for VMware's offerings in this presentation remain at the sole discretion of Pivotal. Pivotal has no obligation to update forward looking information in this presentation. 156