Slide 1

Slide 1 text

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

Slide 2

Slide 2 text

Violeta Georgieva ● VMware ● Reactor Netty committer ○ Netty contributor ● Apache Tomcat committer ○ RM for Tomcat 7 ● Spring Framework contributor 2

Slide 3

Slide 3 text

Agenda ● Reactor Netty ● Logging ● Memory Leaks ● Timeouts ● Connection Closed ● Connection Pool 3

Slide 4

Slide 4 text

Reactor Netty

Slide 5

Slide 5 text

Reactor Netty ● Reactive Streams API for Netty ● Hides the complexity of Netty ● Supports UDP, TCP and HTTP ● Build-in Backpressure support 5

Slide 6

Slide 6 text

Reactor Netty ❤ Spring

Slide 7

Slide 7 text

Reactor Netty ❤ Spring ● Spring Boot 2.x reactive web starter ● Spring WebClient ● Spring Cloud Gateway 7

Slide 8

Slide 8 text

Logging

Slide 9

Slide 9 text

@GetMapping("/hello/{delay}") public Mono hello(@PathVariable("delay") long delay) { return Mono.just("Hello, World!") .delayElement(Duration.ofMillis(delay)); } 9 Logging

Slide 10

Slide 10 text

@GetMapping("/hello/{delay}") public Mono hello(@PathVariable("delay") long delay) { return Mono.just("Hello, World!") .delayElement(Duration.ofMillis(delay)); } 10 Logging

Slide 11

Slide 11 text

@GetMapping("/hello/{delay}") public Mono hello(@PathVariable("delay") long delay) { return Mono.just("Hello, World!") .delayElement(Duration.ofMillis(delay)); } 11 Logging Response is delayed

Slide 12

Slide 12 text

No content

Slide 13

Slide 13 text

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

Slide 14

Slide 14 text

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

Slide 15

Slide 15 text

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

Slide 16

Slide 16 text

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

Slide 17

Slide 17 text

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

Slide 18

Slide 18 text

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

Slide 19

Slide 19 text

No content

Slide 20

Slide 20 text

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

Slide 21

Slide 21 text

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

Slide 22

Slide 22 text

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

Slide 23

Slide 23 text

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

Slide 24

Slide 24 text

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

Slide 25

Slide 25 text

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

Slide 26

Slide 26 text

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

Slide 27

Slide 27 text

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

Slide 28

Slide 28 text

what’s happened?

Slide 29

Slide 29 text

@GetMapping("/hello/{delay}") public Mono hello(@PathVariable("delay") long delay) { return Mono.just("Hello, World!") .delayElement(Duration.ofMillis(delay)); } 29 Logging

Slide 30

Slide 30 text

@GetMapping("/hello/{delay}") public Mono hello(@PathVariable("delay") long delay) { return Mono.just("Hello, World!") .delayElement(Duration.ofMillis(delay)); } 30 Response is delayed Logging

Slide 31

Slide 31 text

Non-Blocking I/O 31 Requests etc. Intensive Operations File System Database Computation Register Callback Operation Complete Event Loop Trigger Callback

Slide 32

Slide 32 text

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

Slide 33

Slide 33 text

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

Slide 34

Slide 34 text

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

Slide 35

Slide 35 text

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

Slide 36

Slide 36 text

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

Slide 37

Slide 37 text

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

Slide 38

Slide 38 text

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

Slide 39

Slide 39 text

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

Slide 40

Slide 40 text

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

Slide 41

Slide 41 text

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

Slide 42

Slide 42 text

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

Slide 43

Slide 43 text

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

Slide 44

Slide 44 text

[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

Slide 45

Slide 45 text

[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

Slide 46

Slide 46 text

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

Slide 47

Slide 47 text

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

Slide 48

Slide 48 text

@GetMapping("/hello/{delay}") public Mono 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

Slide 49

Slide 49 text

@GetMapping("/hello/{delay}") public Mono 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

Slide 50

Slide 50 text

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

Slide 51

Slide 51 text

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

Slide 52

Slide 52 text

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

Slide 53

Slide 53 text

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

Slide 54

Slide 54 text

Wire Logging

Slide 55

Slide 55 text

55 @Component public class MyNettyWebServerCustomizer implements WebServerFactoryCustomizer { @Override public void customize(NettyReactiveWebServerFactory factory) { factory.addServerCustomizers(httpServer -> httpServer.wiretap(true)); } } Server Side - Wire Logging

Slide 56

Slide 56 text

56 @Component public class MyNettyWebServerCustomizer implements WebServerFactoryCustomizer { @Override public void customize(NettyReactiveWebServerFactory factory) { factory.addServerCustomizers(httpServer -> httpServer.wiretap(true)); } } Wire logging Server Side - Wire Logging

Slide 57

Slide 57 text

Client Side - Wire Logging var httpClient = HttpClient.create() .wiretap(true); WebClient.builder() .clientConnector(new ReactorClientHttpConnector(httpClient)) .build(); 57

Slide 58

Slide 58 text

58 Client Side - Wire Logging var httpClient = HttpClient.create() .wiretap(true); WebClient.builder() .clientConnector(new ReactorClientHttpConnector(httpClient)) .build(); 6 Wire logging

Slide 59

Slide 59 text

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

Slide 60

Slide 60 text

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

Slide 61

Slide 61 text

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

Slide 62

Slide 62 text

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

Slide 63

Slide 63 text

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

Slide 64

Slide 64 text

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

Slide 65

Slide 65 text

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

Slide 66

Slide 66 text

Memory Leaks

Slide 67

Slide 67 text

@GetMapping("/remote") public Mono remote() { return webClient.get() .uri("http://localhost:8080/") .exchange() .flatMap(response -> Mono.just(response.statusCode() .toString())) .timeout(Duration.ofSeconds(5)); } Memory Leaks 67

Slide 68

Slide 68 text

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

Slide 69

Slide 69 text

● -Dio.netty.leakDetectionLevel=paranoid ● logging.level.reactor.netty=debug ○ logging.level.reactor.netty.channel.FluxReceive=debug 69 Memory Leaks

Slide 70

Slide 70 text

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

Slide 71

Slide 71 text

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

Slide 72

Slide 72 text

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

Slide 73

Slide 73 text

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

Slide 74

Slide 74 text

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

Slide 75

Slide 75 text

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

Slide 76

Slide 76 text

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

Slide 77

Slide 77 text

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

Slide 78

Slide 78 text

@GetMapping("/remote") public Mono remote() { return webClient.get() .uri("http://localhost:8080/") .exchange() .flatMap(response -> Mono.just(response.statusCode() .toString())) .timeout(Duration.ofSeconds(5)); } Memory Leaks 78

Slide 79

Slide 79 text

@GetMapping("/remote") public Mono 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

Slide 80

Slide 80 text

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

Slide 81

Slide 81 text

@GetMapping("/remote") public Mono 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

Slide 82

Slide 82 text

@GetMapping("/remote") public Mono 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

Slide 83

Slide 83 text

@GetMapping("/remote") public Mono 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

Slide 84

Slide 84 text

@GetMapping("/remote") public Mono 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

Slide 85

Slide 85 text

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

Slide 86

Slide 86 text

Releasing the Data ● releaseBody() ● toBodilessEntity() ● bodyToMono(Void.class) !Closes the connection! 86

Slide 87

Slide 87 text

Timeouts

Slide 88

Slide 88 text

Server Side - Read Timeout @Component public class MyNettyWebServerCustomizer implements WebServerFactoryCustomizer { @Override public void customize(NettyReactiveWebServerFactory factory) { factory.addServerCustomizers( server -> server.doOnConnection(conn -> conn.addHandlerFirst( new ReadTimeoutHandler(50, TimeUnit.MILLISECONDS)))); } } 88

Slide 89

Slide 89 text

Server Side - Read Timeout @Component public class MyNettyWebServerCustomizer implements WebServerFactoryCustomizer { @Override public void customize(NettyReactiveWebServerFactory factory) { factory.addServerCustomizers( server -> server.doOnConnection(conn -> conn.addHandlerFirst( new ReadTimeoutHandler(50, TimeUnit.MILLISECONDS)))); } } Read timeout 89

Slide 90

Slide 90 text

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

Slide 91

Slide 91 text

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

Slide 92

Slide 92 text

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

Slide 93

Slide 93 text

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

Slide 94

Slide 94 text

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

Slide 95

Slide 95 text

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

Slide 96

Slide 96 text

96 Client Side - Response Timeout @GetMapping("/remote") public Mono remote() { return webClient.get() .uri("http://localhost:8080/") .httpRequest(request -> ((HttpClientRequest) request.getNativeRequest()) .responseTimeout(Duration.ofSeconds(1))) .retrieve() … } 6

Slide 97

Slide 97 text

Client Side - Response Timeout @GetMapping("/remote") public Mono 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

Slide 98

Slide 98 text

Client Side - Timeout for Mono/Flux @GetMapping("/remote") public Mono remote() { return webClient.get() .uri("http://localhost:8080/") .retrieve() … .timeout(…) } 98

Slide 99

Slide 99 text

Client Side - Timeout for Mono/Flux @GetMapping("/remote") public Mono remote() { return webClient.get() .uri("http://localhost:8080/") .retrieve() … .timeout(…) } Timeout for this Mono 99

Slide 100

Slide 100 text

● 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

Slide 101

Slide 101 text

Connection Closed

Slide 102

Slide 102 text

Network Latency ⏰ Read Timeout

Slide 103

Slide 103 text

Target Server - Read Timeout @Component public class MyNettyWebServerCustomizer implements WebServerFactoryCustomizer { @Override public void customize(NettyReactiveWebServerFactory factory) { factory.addServerCustomizers( server -> server.doOnConnection(conn -> conn.addHandlerFirst( new ReadTimeoutHandler(50, TimeUnit.MILLISECONDS)))); } } 103

Slide 104

Slide 104 text

Target Server - Read Timeout @Component public class MyNettyWebServerCustomizer implements WebServerFactoryCustomizer { @Override public void customize(NettyReactiveWebServerFactory factory) { factory.addServerCustomizers( server -> server.doOnConnection(conn -> conn.addHandlerFirst( new ReadTimeoutHandler(50, TimeUnit.MILLISECONDS)))); } } Read timeout (50ms) 104

Slide 105

Slide 105 text

Target Server - Read Timeout @PostMapping("/echo") public String echo(@RequestBody String body) { return body; } 105

Slide 106

Slide 106 text

106 Client - Read Timeout @GetMapping("/remote") public Mono 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

Slide 107

Slide 107 text

Client - Read Timeout @GetMapping("/remote") public Mono 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

Slide 108

Slide 108 text

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

Slide 109

Slide 109 text

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

Slide 110

Slide 110 text

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

Slide 111

Slide 111 text

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

Slide 112

Slide 112 text

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

Slide 113

Slide 113 text

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

Slide 114

Slide 114 text

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

Slide 115

Slide 115 text

Processing Latency ⏰ Read Timeout

Slide 116

Slide 116 text

116 Target Server - Read Timeout @Component public class MyNettyWebServerCustomizer implements WebServerFactoryCustomizer { @Override public void customize(NettyReactiveWebServerFactory factory) { factory.addServerCustomizers( server -> server.doOnConnection(conn -> conn.addHandlerFirst( new ReadTimeoutHandler(50, TimeUnit.MILLISECONDS)))); } } 6

Slide 117

Slide 117 text

Target Server - Read Timeout @Component public class MyNettyWebServerCustomizer implements WebServerFactoryCustomizer { @Override public void customize(NettyReactiveWebServerFactory factory) { factory.addServerCustomizers( server -> server.doOnConnection(conn -> conn.addHandlerFirst( new ReadTimeoutHandler(50, TimeUnit.MILLISECONDS)))); } } Read timeout (50ms) 117

Slide 118

Slide 118 text

Target Server - Read Timeout @PostMapping("/echo") public Mono echo(@RequestBody String body) { return Mono.just(body) .delayElement(Duration.ofMillis(100)); } 118

Slide 119

Slide 119 text

Target Server - Read Timeout @PostMapping("/echo") public Mono echo(@RequestBody String body) { return Mono.just(body) .delayElement(Duration.ofMillis(100)); } Simulate Processing Latency 119

Slide 120

Slide 120 text

Client - Read Timeout @GetMapping("/remote") public Mono 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

Slide 121

Slide 121 text

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

Slide 122

Slide 122 text

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

Slide 123

Slide 123 text

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

Slide 124

Slide 124 text

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

Slide 125

Slide 125 text

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

Slide 126

Slide 126 text

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

Slide 127

Slide 127 text

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

Slide 128

Slide 128 text

Keep Alive Timeout

Slide 129

Slide 129 text

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

Slide 130

Slide 130 text

Client - Connection Pool ● Max idle time ● Prefer LIFO vs. FIFO leasing strategy 130

Slide 131

Slide 131 text

Upload limit on the Target Server

Slide 132

Slide 132 text

Target Server - Upload Limit @Configuration public class WebConfig implements WebFluxConfigurer { @Override public void configureHttpMessageCodecs(ServerCodecConfigurer configurer) { configurer.defaultCodecs().maxInMemorySize(512); } } 132

Slide 133

Slide 133 text

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

Slide 134

Slide 134 text

Target Server - Upload Limit @PostMapping("/echo") public String echo(@RequestBody String body) { return body; } 134

Slide 135

Slide 135 text

Client - Upload Limit @GetMapping("/remote") public Mono 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

Slide 136

Slide 136 text

... [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

Slide 137

Slide 137 text

... [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

Slide 138

Slide 138 text

... [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

Slide 139

Slide 139 text

... [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

Slide 140

Slide 140 text

... [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

Slide 141

Slide 141 text

... [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

Slide 142

Slide 142 text

Connection Pool

Slide 143

Slide 143 text

Client Side - Connection Pool var provider = ConnectionProvider.create("demo", 1); var httpClient = HttpClient.create() .wiretap(true); WebClient.builder() .clientConnector(new ReactorClientHttpConnector(httpClient)) .build(); 143

Slide 144

Slide 144 text

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

Slide 145

Slide 145 text

Client Side - Connection Pool @GetMapping("/remote") public Mono remote() { Mono mono1 = webClient.get() .uri("https://example.com") .retrieve() .bodyToMono(String.class); Mono mono2 = webClient.get() .uri("https://httpbin.org/get") .retrieve() .bodyToMono(String.class); return Flux.merge(mono1, mono2).next(); } 145

Slide 146

Slide 146 text

146 Client Side - Connection Pool @GetMapping("/remote") public Mono remote() { Mono mono1 = webClient.get() .uri("https://example.com") .retrieve() .bodyToMono(String.class); Mono mono2 = webClient.get() .uri("https://httpbin.org/get") .retrieve() .bodyToMono(String.class); return Flux.merge(mono1, mono2).next(); } 6 Need only the first result

Slide 147

Slide 147 text

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

Slide 148

Slide 148 text

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

Slide 149

Slide 149 text

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

Slide 150

Slide 150 text

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

Slide 151

Slide 151 text

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

Slide 152

Slide 152 text

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

Slide 153

Slide 153 text

Key Takeaways

Slide 154

Slide 154 text

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

Slide 155

Slide 155 text

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

Slide 156

Slide 156 text

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