search

reactor / reactor-netty

TCP/HTTP/UDP/QUIC client/server with Reactor over Netty
https://projectreactor.io
Apache License 2.0
2.58k stars 645 forks source link

Increased latency while calling api using webclient with connection pool #3392

Closed guptapcam6 closed 1 month ago

guptapcam6 commented 2 months ago

Can you please help to find why there is difference of 9 seconds between the two logs (Row 28&29/highlighted in Bold/Italic). It is causing latency issues for some requests.

<html xmlns:v="urn:schemas-microsoft-com:vml" xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:x="urn:schemas-microsoft-com:office:excel" xmlns="http://www.w3.org/TR/REC-html40">

RowNo | jsonPayload.class | jsonPayload.logtimestamp | jsonPayload.message | jsonPayload.thread_instance -- | -- | -- | -- | -- 1 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.312 | [f7269677-4, L:/300.300.2.2:71 - R:publisher-uc.a.run.app/200.200.1.9:443] Received last HTTP packet | [or-http-epoll-4] 2 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.311 | [f7269677-4, L:/300.300.2.2:71 - R:publisher-uc.a.run.app/200.200.1.9:443] [terminated=false, cancelled=false, pending=0, error=null]: subscribing inbound receiver | [or-http-epoll-4] 3 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.311 | [f7269677-4, L:/300.300.2.2:71 - R:publisher-uc.a.run.app/200.200.1.9:443] onStateChange(POST{uri=/api/publish, connection=PooledConnection{channel=[id: 0xf7269677, L:/300.300.2.2:71 - R:publisher-uc.a.run.app/200.200.1.9:443]}}, [response_received]) | [or-http-epoll-4] 4 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.311 | [f7269677-4, L:/300.300.2.2:71 - R:publisher-uc.a.run.app/200.200.1.9:443] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1).HTTP/1.1 200 OK.x-request-info: .x-application-info: .x-content-type-options: .x-xss-protection: .cache-control: .pragma: .expires: .x-frame-options: .content-type: .Transfer-Encoding: .Date: .Server: | [or-http-epoll-4] 5 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.296 | [f7269677-4, L:/300.300.2.2:71 - R:publisher-uc.a.run.app/200.200.1.9:443] onStateChange(POST{uri=/api/publish, connection=PooledConnection{channel=[id: 0xf7269677, L:/300.300.2.2:71 - R:publisher-uc.a.run.app/200.200.1.9:443]}}, [request_sent]) | [or-http-epoll-4] 6 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.295 | [f7269677-4, L:/300.300.2.2:71 - R:publisher-uc.a.run.app/200.200.1.9:443] onStateChange(POST{uri=/api/publish, connection=PooledConnection{channel=[id: 0xf7269677, L:/300.300.2.2:71 - R:publisher-uc.a.run.app/200.200.1.9:443]}}, [request_prepared]) | [or-http-epoll-4] 7 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.295 | [f7269677-4, L:/300.300.2.2:71 - R:publisher-uc.a.run.app/200.200.1.9:443] Handler is being applied: {uri=https://publisher-uc.a.run.app/api/publish, method=POST} | [or-http-epoll-4] 8 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.295 | [f7269677, L:/300.300.2.2:71 - R:publisher-uc.a.run.app/200.200.1.9:443] Channel acquired, now: 1 active connections, 1 inactive connections and 0 pending acquire requests. | [or-http-epoll-4] 9 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.285 | [f7269677, L:/300.300.2.2:71 - R:publisher-uc.a.run.app/200.200.1.9:443] Channel cleaned, now: 1 active connections, 1 inactive connections and 0 pending acquire requests. | [or-http-epoll-4] 10 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.285 | [f7269677, L:/300.300.2.2:71 - R:publisher-uc.a.run.app/200.200.1.9:443] Releasing channel | [or-http-epoll-4] 11 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.285 | [f7269677, L:/300.300.2.2:71 - R:publisher-uc.a.run.app/200.200.1.9:443] onStateChange(POST{uri=/api/publish, connection=PooledConnection{channel=[id: 0xf7269677, L:/300.300.2.2:71 - R:publisher-uc.a.run.app/200.200.1.9:443]}}, [disconnecting]) | [or-http-epoll-4] 12 | c.c.Controller$processRequest$3 | 2024-08-0815:32:58.285 | Completed async Processing for: TriggeredAlert | [atcher-worker-2] 13 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.285 | [f7269677, L:/300.300.2.2:71 - R:publisher-uc.a.run.app/200.200.1.9:443] onStateChange(POST{uri=/api/publish, connection=PooledConnection{channel=[id: 0xf7269677, L:/300.300.2.2:71 - R:publisher-uc.a.run.app/200.200.1.9:443]}}, [response_completed]) | [or-http-epoll-4] 14 | c.s.n.P&MService$processPAndMCResponse$2$3 | 2024-08-0815:32:58.285 | Publishing to Publisher is successful for the vin: 27862 | [or-http-epoll-4] 15 | c.s.n.P&MService$processPAndMCResponse$2$3 | 2024-08-0815:32:58.285 | Published to Publisher with code: 0 + description: Notification Request has been accepted.+ messageName: TriggeredAlert | [or-http-epoll-4] 16 | c.a.PublisherAdapter | 2024-08-0815:32:58.284 | Successfully publish to Publisher response: true | [or-http-epoll-4] 17 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.265 | [0ecc10bd-1, L:/400.400.8.1:63 - R:api.stg.com/500.500.68.21:443] Received last HTTP packet | [or-http-epoll-3] 18 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.265 | [0ecc10bd-1, L:/400.400.8.1:63 - R:api.stg.com/500.500.68.21:443] [terminated=false, cancelled=false, pending=0, error=null]: subscribing inbound receiver | [or-http-epoll-3] 19 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.264 | [0ecc10bd-1, L:/400.400.8.1:63 - R:api.stg.com/500.500.68.21:443] onStateChange(POST{uri=/api/add, connection=PooledConnection{channel=[id: 0x0ecc10bd, L:/400.400.8.1:63 - R:api.stg.com/500.500.68.21:443]}}, [response_received]) | [or-http-epoll-3] 20 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.264 | [0ecc10bd-1, L:/400.400.8.1:63 - R:api.stg.com/500.500.68.21:443] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1).HTTP/1.1 200 OK.vary: .x-request-id: .traceparent: .traceid: .x-b3-traceid: .spanid: .x-b3-spanid: .x-rate-limit-remaining: .x-content-type-options: .x-xss-protection: .cache-control: .pragma: .expires: .x-frame-options: .content-type: .date: .via: .transfer-encoding: | [or-http-epoll-3] 21 | c.a.PublisherAdapter | 2024-08-0815:32:58.258 | Publishing to request/response topic : | [atcher-worker-2] 22 | c.a.PublisherAdapter | 2024-08-0815:32:58.243 | Entered publishMessage Method with: | [atcher-worker-2] 23 | c.s.n.P&MService$externalTemplateProcess$3 | 2024-08-0815:32:58.243 | External add process | [atcher-worker-2] 24 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.242 | [f35d8042, L:/600.600.8.1:43 - R:api.stg.com/500.500.68.21:443] Channel cleaned, now: 4 active connections, 3 inactive connections and 0 pending acquire requests. | [or-http-epoll-3] 25 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.242 | [f35d8042, L:/600.600.8.1:43 - R:api.stg.com/500.500.68.21:443] Releasing channel | [or-http-epoll-3] 26 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.241 | [f35d8042, L:/600.600.8.1:43 - R:api.stg.com/500.500.68.21:443] onStateChange(POST{uri=/api/add, connection=PooledConnection{channel=[id: 0xf35d8042, L:/600.600.8.1:43 - R:api.stg.com/500.500.68.21:443]}}, [disconnecting]) | [or-http-epoll-3] 27 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:58.241 | [f35d8042, L:/600.600.8.1:43 - R:api.stg.com/500.500.68.21:443] onStateChange(POST{uri=/api/add, connection=PooledConnection{channel=[id: 0xf35d8042, L:/600.600.8.1:43 - R:api.stg.com/500.500.68.21:443]}}, [response_completed]) | [or-http-epoll-3] 28 | c.a.PandMCNotificationAdapter | **_2024-08-0815:32:58.241_** | Message response sent to channel | [or-http-epoll-3] 29 | reactor.util.Loggers$Slf4JLogger | **_2024-08-0815:32:49.134_** | [39689d01-1, L:/700.700.169.2:80 - R:/800.800.19.26:51] [terminated=true, cancelled=false, pending=1, error=null]: subscribing inbound receiver | [or-http-epoll-4] 30 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:49.132 | [39689d01-1, L:/700.700.169.2:80 - R:/800.800.19.26:51] Non Removed handler: reactor.left.readTimeoutHandler, context: null, pipeline: DefaultChannelPipeline{(reactor.left.httpCodec = io.netty.handler.codec.http.HttpServerCodec), (reactor.left.httpTrafficHandler = reactor.netty.http.server.HttpTrafficHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)} | [or-http-epoll-4] 31 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:49.130 | [39689d01-1, L:/700.700.169.2:80 - R:/800.800.19.26:51] Handler is being applied: org.springframework.http.server.reactive.ReactorHttpHandlerAdapter@3a563661 | [or-http-epoll-4] 32 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:49.130 | [39689d01, L:/700.700.169.2:80 - R:/800.800.19.26:51] Increasing pending responses, now 1 | [or-http-epoll-4] 33 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:49.129 | [39689d01, L:/700.700.169.2:80 - R:/800.800.19.26:51] Initialized pipeline DefaultChannelPipeline{(reactor.left.httpCodec = io.netty.handler.codec.http.HttpServerCodec), (reactor.left.httpTrafficHandler = reactor.netty.http.server.HttpTrafficHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)} | [or-http-epoll-4] 34 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:49.129 | [39689d01, L:/700.700.169.2:80 - R:/800.800.19.26:51] New http connection, requesting read | [or-http-epoll-4] 35 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:48.954 | [630b767f-2, L:/900.900.8.1:53 - R:api.stg.com/500.500.68.21:443] onStateChange(POST{uri=/api/add, connection=PooledConnection{channel=[id: 0x630b767f, L:/900.900.8.1:53 - R:api.stg.com/500.500.68.21:443]}}, [request_sent]) | [or-http-epoll-4] 36 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:48.953 | [630b767f-2, L:/900.900.8.1:53 - R:api.stg.com/500.500.68.21:443] onStateChange(POST{uri=/api/add, connection=PooledConnection{channel=[id: 0x630b767f, L:/900.900.8.1:53 - R:api.stg.com/500.500.68.21:443]}}, [request_prepared]) | [or-http-epoll-4] 37 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:48.953 | [630b767f-2, L:/900.900.8.1:53 - R:api.stg.com/500.500.68.21:443] Handler is being applied: {uri=https://api.stg.com/api/add, method=POST} | [or-http-epoll-4] 38 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:48.953 | [630b767f, L:/900.900.8.1:53 - R:api.stg.com/500.500.68.21:443] Channel acquired, now: 1 active connections, 2 inactive connections and 0 pending acquire requests. | [or-http-epoll-4] 39 | c.adapters.AdapterBase | 2024-08-0815:32:48.951 | Token found in cache for resource: b3c7fd16-77e6-4375-b02c | [atcher-worker-1] 40 | c.adapters.AdapterBase | 2024-08-0815:32:48.951 | proxy settings:*.google.internal\|*.run.app | [atcher-worker-1] 41 | c.a.PandMCNotificationAdapter | 2024-08-0815:32:48.951 | PushAndMessageCenter Adapter request. | [atcher-worker-1] 42 | c.s.n.P&MService | 2024-08-0815:32:48.951 | ContentValue | [atcher-worker-1] 43 | c.s.n.P&MService | 2024-08-0815:32:48.951 | ContentParameters [alarmTimestamp] . | [atcher-worker-1] 44 | c.s.n.P&MService | 2024-08-0815:32:48.950 | End of method | [atcher-worker-1] 45 | c.utils.TimezoneUtil | 2024-08-0815:32:48.949 | Original Timestamp: 2024-08-09T14:13:58.551000Z Converted Timestamp: 09/08/2024 10:13:58 | [atcher-worker-1] 46 | c.utils.TimezoneUtil | 2024-08-0815:32:48.949 | Local Zone Id from TimezoneConversion | [atcher-worker-1] 47 | c.s.n.P&MService | 2024-08-0815:32:48.946 | requestParameterValue | [atcher-worker-1] 48 | c.s.n.P&MService | 2024-08-0815:32:48.946 | notification properties: | [atcher-worker-1] 49 | c.s.n.P&MService | 2024-08-0815:32:48.946 | Processing CenterNotification in P&MService. | [atcher-worker-1] 50 | c.service.GatewayService | 2024-08-0815:32:48.946 | Push and MessageCenter sending notification for TriggeredAlert | [atcher-worker-1] 51 | c.service.GatewayService | 2024-08-0815:32:48.946 | Country USA and Local | [atcher-worker-1] 52 | c.adapters.AdapterBase | 2024-08-0815:32:48.616 | Token found in cache for resource: b3c7fd16-77e6-4375-b02c | [atcher-worker-2] 53 | c.adapters.AdapterBase | 2024-08-0815:32:48.615 | proxy settings:*.google.internal\|*.run.app | [atcher-worker-2] 54 | c.adapters.UPAdapter | 2024-08-0815:32:48.615 | Start of method get UP. +Going to org.springframework.web.reactive.function.client.DefaultWebClient$DefaultRequestBodyUriSpec@768e28af | [atcher-worker-2] 55 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:48.194 | [ca242470-6, L:/100.100.8.1:42 - R:api.stg.com/500.500.68.21:443] Received last HTTP packet | [or-http-epoll-2] 56 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:48.194 | [ca242470-6, L:/100.100.8.1:42 - R:api.stg.com/500.500.68.21:443] [terminated=false, cancelled=false, pending=0, error=null]: subscribing inbound receiver | [or-http-epoll-2] 57 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:48.193 | [ca242470-6, L:/100.100.8.1:42 - R:api.stg.com/500.500.68.21:443] onStateChange(GET{uri=/api/getUsersByVin/27862, connection=PooledConnection{channel=[id: 0xca242470, L:/100.100.8.1:42 - R:api.stg.com/500.500.68.21:443]}}, [response_received]) | [or-http-epoll-2] 58 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:48.193 | [ca242470-6, L:/100.100.8.1:42 - R:api.stg.com/500.500.68.21:443] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1).HTTP/1.1 200 OK.date: .content-type: .vary: .x-content-type-options: .x-xss-protection: .cache-control: .pragma: .expires: .strict-transport-security: .x-frame-options: .x-request-id: .via: .transfer-encoding: | [or-http-epoll-2] 59 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:48.155 | [ca242470-6, L:/100.100.8.1:42 - R:api.stg.com/500.500.68.21:443] onStateChange(GET{uri=/api/getUsersByVin/27862, connection=PooledConnection{channel=[id: 0xca242470, L:/100.100.8.1:42 - R:api.stg.com/500.500.68.21:443]}}, [request_sent]) | [or-http-epoll-2] 60 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:48.154 | [ca242470-6, L:/100.100.8.1:42 - R:api.stg.com/500.500.68.21:443] onStateChange(GET{uri=/api/getUsersByVin/27862, connection=PooledConnection{channel=[id: 0xca242470, L:/100.100.8.1:42 - R:api.stg.com/500.500.68.21:443]}}, [request_prepared]) | [or-http-epoll-2] 61 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:48.154 | [ca242470-6, L:/100.100.8.1:42 - R:api.stg.com/500.500.68.21:443] Handler is being applied: {uri=https://api.stg.com/api/getUsersByVin/27862, method=GET} | [or-http-epoll-2] 62 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:48.153 | [ca242470, L:/100.100.8.1:42 - R:api.stg.com/500.500.68.21:443] Channel acquired, now: 1 active connections, 0 inactive connections and 0 pending acquire requests. | [or-http-epoll-2] 63 | c.adapters.AdapterBase | 2024-08-0815:32:48.148 | Token found in cache for resource: b3c7fd16-77e6-4375-b02c | [atcher-worker-2] 64 | c.adapters.AdapterBase | 2024-08-0815:32:48.148 | proxy settings:*.google.internal\|*.run.app | [atcher-worker-2] 65 | c.adapters.UPAdapter | 2024-08-0815:32:48.147 | Start of method getUserProfile in UPAdapter for Id 7f737d11-6cc8, VIN: 27862. +Going to org.springframework.web.reactive.function.client.DefaultWebClient$DefaultRequestBodyUriSpec@10a04cbe | [atcher-worker-2] 66 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:47.746 | [5fa800b2-1, L:/700.700.169.2:80 - R:/201.201.169.16:290] Last HTTP packet was sent, terminating the channel | [or-http-epoll-4] 67 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:47.746 | [5fa800b2-1, L:/700.700.169.2:80 - R:/201.201.169.16:290] [HttpServer] Channel inbound receiver cancelled (subscription disposed). | [or-http-epoll-4] 68 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:47.746 | [5fa800b2-1, L:/700.700.169.2:80 - R:/201.201.169.16:290] Last HTTP response frame | [or-http-epoll-4] 69 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:47.745 | [5fa800b2-1, L:/700.700.169.2:80 - R:/201.201.169.16:290] Decreasing pending responses, now 0 | [or-http-epoll-4] 70 | c.adapters.AdapterBase | 2024-08-0815:32:47.741 | Token found in cache for resource: b3c7fd16-77e6-4375-b02c | [atcher-worker-1] 71 | c.adapters.AdapterBase | 2024-08-0815:32:47.741 | proxy settings:*.google.internal\|*.run.app | [atcher-worker-1] 72 | c.adapters.UPAdapter | 2024-08-0815:32:47.741 | Start of method getUserProfile in UPAdapter for Id 58076992-5ec6, VIN: 27862. +Going to org.springframework.web.reactive.function.client.DefaultWebClient$DefaultRequestBodyUriSpec@de0486 | [atcher-worker-1] 73 | c.service.GatewayService | 2024-08-0815:32:47.741 | Message is AlarmTriggeredAlert or AlarmActivatedAlert - Internal Template: TriggeredAlert | [atcher-worker-1] 74 | c.s.n.P&MService | 2024-08-0815:32:47.741 | AppGroupIds: [AppGroup] | [atcher-worker-1] 75 | c.service.GatewayService | 2024-08-0815:32:47.741 | Check to see if we're internal for TriggeredAlert | [atcher-worker-1] 76 | c.c.Controller$processRequest$3 | 2024-08-0815:32:47.741 | ProcessModel | [atcher-worker-1] 77 | c.c.Controller$processRequest$3 | 2024-08-0815:32:47.741 | Beginning async work in the Controller | [atcher-worker-1] 78 | c.c.Controller | 2024-08-0815:32:47.739 | Processed Response: | [atcher-worker-1] 79 | c.c.Controller$processRequest$2 | 2024-08-0815:32:47.739 | UserIds to be used are: [58076992-5ec6, 7f737d11-6cc8, b513f38f-8f55] | [atcher-worker-1] 80 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:47.738 | [ca242470, L:/100.100.8.1:42 - R:api.stg.com/500.500.68.21:443] Channel cleaned, now: 0 active connections, 1 inactive connections and 0 pending acquire requests. | [or-http-epoll-2] 81 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:47.738 | [ca242470, L:/100.100.8.1:42 - R:api.stg.com/500.500.68.21:443] Releasing channel | [or-http-epoll-2] 82 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:47.738 | [ca242470, L:/100.100.8.1:42 - R:api.stg.com/500.500.68.21:443] onStateChange(GET{uri=/api/getUsersByVin/27862, connection=PooledConnection{channel=[id: 0xca242470, L:/100.100.8.1:42 - R:api.stg.com/500.500.68.21:443]}}, [disconnecting]) | [or-http-epoll-2] 83 | reactor.util.Loggers$Slf4JLogger | 2024-08-0815:32:47.738 | [ca242470, L:/100.100.8.1:42 - R:api.stg.com/500.500.68.21:443] onStateChange(GET{uri=/api/getUsersByVin/27862, connection=PooledConnection{channel=[id: 0xca242470, L:/100.100.8.1:42 - R:api.stg.com/500.500.68.21:443]}}, [response_completed]) | [or-http-epoll-2] 84 | c.s.d.vasService$getUsers$2$1 | 2024-08-0815:32:47.738 | process model recipient user ids:)] | [or-http-epoll-2] 85 | c.adapters.vasAdapter | 2024-08-0815:32:47.737 | Successfully retrieved authorized users for vin: 27862 | [or-http-epoll-2] 86 | c.adapters.AdapterBase | 2024-08-0815:32:47.701 | Token found in cache for resource: | [atcher-worker-1] 87 | c.adapters.AdapterBase | 2024-08-0815:32:47.701 | proxy settings:*.google.internal\|*.run.app | [atcher-worker-1] 88 | c.c.Controller | 2024-08-0815:32:47.700 | V3 Request received | [or-http-epoll-4]

Connection pool :

 var provider = ConnectionProvider.builder("custom")
        .maxConnections(50)
        .maxIdleTime(Duration.ofSeconds(20))
        .maxLifeTime(Duration.ofSeconds(60))
        .pendingAcquireTimeout(Duration.ofSeconds(60))
        .evictInBackground(Duration.ofSeconds(120))
        .build()

Web client code 

 webClient.post()
                .uri { uriBuilder ->
                    val x = uriBuilder.path(url)
                        .build()
                    x
                }  
                .header(ServiceConstants.AUTHORIZATION, "${ServiceConstants.BEARER}$token")
                .contentType(MediaType.APPLICATION_JSON)
                .accept(MediaType.APPLICATION_JSON)
                .body(Mono.just(RequestModel!!), RequestModel::class.java)
                .retrieve()
                .retryFor5xx()
                    .toEntity<ResponseModel>().flatMap {
                        response ->
                            Mono.just(response.body!!).flatMap {
                            res -> if (response.statusCode.value().equals(HttpStatus.MULTI_STATUS.value())  && !hasNon500Errors(res.result?.messages!!)){
                                        return@flatMap Mono.error<RetryableApiCall>(RetryableApiCall())
                                    } else {
                                        res.status = response.statusCode.value()
                                        return@flatMap Mono.just(res)
                                    }
                        }
                    }
                    .timeout(Duration.ofSeconds(commonConfigs.ConnectionTimeoutDuration()))
                .retryTemplate( processModel.vin, "PushAndMessageCenter", recoveryMethod = {retryBackoffSpec, retrySignal ->
                    recoveryMethod(
                        retryBackoffSpec,
                        retrySignal,
                        commonConfigs.maxRetryAttempts.toLong(),
                        processModel.vin)})
                .doOnError {
                    MDC.setContextMap(processModel.mdcMap)
                    log.error { "DoOnError Exception while sending processing for for ${processModel.vin}, $it" }
                    val response =ResponseModel().apply {
                        this.status = 500
                    }
                    instructions(response)
                }
                .doOnSuccess { response ->
                    val response1 = response as ResponseModel
                    MDC.setContextMap(processModel.mdcMap)
                    log.info("Message response sent to channel with messages $response1")
                    instructions(response)
                }
                .subscribe()
violetagg commented 2 months ago

@guptapcam6 Without knowing the exact connection it is hard to say. How do you correlate this message Message response sent to channel to some connection?

guptapcam6 commented 2 months ago

@violetagg Message response sent to channel is log in webservice after getting the response for api call, as you can see in the code snippet provided above, this log is printed in doOnSuccess block.

Currently to print connection related logs we are doing two things :

  1. Enabling DEBUG for reactor.netty by doing logging.level.reactor.netty = DEBUG
  2. Using meterRegistry to print the logs for connection every 15 seconds 
class MetricsPrinter(private val meterRegistry: MeterRegistry) {

    private val log = KotlinLogging.logger {}
    private val scope = CoroutineScope(Dispatchers.Default)

    private val selectedMetrics = listOf(
        "reactor.netty.connection.provider.total.connections",
        "reactor.netty.connection.provider.active.connections",
        "reactor.netty.connection.provider.max.connections",
        "reactor.netty.connection.provider.idle.connections",
        "reactor.netty.connection.provider.pending.connections",
        "reactor.netty.connection.provider.pending.connections.time",
        "reactor.netty.connection.provider.max.pending.connections",
        "http.server.requests"
        // Add more metric names as needed
    )

    @PostConstruct
    fun init() {
        scope.launch {
            while (true) {
                printMetrics()
                delay(15000)
            }
        }
    }

    private fun printMetrics() {
        log.info {"########################################################Logging starts########################################################"}
        meterRegistry.forEachMeter { meter ->
            if (meter.id.name in selectedMetrics) {
                log.info {"Logging : ${meter.id}: ${meter.measure()}"}
            }

        }
        log.info {"########################################################Logging ends########################################################"}
    }
}

Can you please let us know if there is any better way to log connection details associated with any message ?

violetagg commented 2 months ago

@guptapcam6 Please use the spring webflux log prefix, it is based on the connection id - https://docs.spring.io/spring-framework/docs/current/javadoc-api/org/springframework/web/server/ServerWebExchange.html#getLogPrefix()

github-actions[bot] commented 1 month ago

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.

github-actions[bot] commented 1 month ago

Closing due to lack of requested feedback. If you would like us to look at this issue, please provide the requested information and we will re-open.