search

pgjdbc / r2dbc-postgresql

Postgresql R2DBC Driver
https://r2dbc.io
Apache License 2.0
1.01k stars 177 forks source link

R2DBC Postgresql: Creating new Transactions org.springframework.transaction.reactive.AbstractReactiveTransactionManager Struck #531

Open madhav1306 opened 2 years ago

madhav1306 commented 2 years ago

With the recent upgrade of sprint boot version 2.7.1, we are unable to obtain the database connection from the r2dbc pool. The code strucks at the below line until we restart. Once restarted, the issues occurrence takes 2 to 3 days. No detailed logs printed

DEBUG o.s.t.r.AbstractReactiveTransactionManager [reactor-http-nio-4] Creating new transaction with name [com.authenticate.service.UserService.fetchUserWithRoles]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly

application.properties

Below is the db connection pool configuration

spring.r2dbc.pool.enabled=true spring.r2dbc.pool.initial-size=5 spring.r2dbc.pool.max-size=10 spring.r2dbc.pool.max-idle-time=10m spring.r2dbc.pool.max-acquire-time=30s spring.r2dbc.pool.max-create-connection-time=30s spring.r2dbc.pool.validation-query=SELECT 1

application.yml

spring: config: activate: on-profile: local r2dbc: url: r2dbc:postgresql://localhost:5432/mydb username: postgres

mp911de commented 2 years ago

We need a bit more context to diagnose the issue. Can you provide a connection list as seen from the database server and provide pool metrics (allocation, idle, active sizes)?

madhav1306 commented 2 years ago

Now the application is idle more than 2 hours. No active db connections founds

Snap from postgres db image

Snap from application server image

I tried to login into the application. Now the connection was established with the database

Snap from application server

image

Snap from database server image

Please let me know if you need further details. Successful DB connection flow log information

2022-07-19 09:19:53,994 DEBUG o.s.t.r.AbstractReactiveTransactionManager [reactor-http-nio-2] Creating new transaction with name [com.authenticate.service.UserService.fetchUserWithRoles]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly 2022-07-19 09:19:53,995 DEBUG r.u.Loggers$Slf4JLogger [reactor-http-nio-2] should warm up 1 extra resources 2022-07-19 09:19:53,995 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [1160f5b6] Initialized pipeline DefaultChannelPipeline{(reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)} 2022-07-19 09:19:53,996 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [1160f5b6] Connecting to [/xxx.31.16.14:3290]. 2022-07-19 09:19:53,996 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [1160f5b6, L:/xxx.31.34.19:50892 - R:/xxx.31.16.14:3290] Connected new channel 2022-07-19 09:19:53,996 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [1160f5b6, L:/xxx.31.34.19:50892 - R:/xxx.31.16.14:3290] onStateChange([connected], SimpleConnection{channel=[id: 0x1160f5b6, L:/xxx.31.34.19:50892 - R:/xxx.31.16.14:3290]}) 2022-07-19 09:19:53,997 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [1160f5b6, L:/xxx.31.34.19:50892 - R:/xxx.31.16.14:3290] onStateChange([configured], ChannelOperations{SimpleConnection{channel=[id: 0x1160f5b6, L:/xxx.31.34.19:50892 - R:/xxx.31.16.14:3290]}}) 2022-07-19 09:19:53,997 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [1160f5b6, L:/xxx.31.34.19:50892 - R:/xxx.31.16.14:3290] Added decoder [LengthFieldBasedFrameDecoder] at the end of the user pipeline, full pipeline: [LengthFieldBasedFrameDecoder, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0] 2022-07-19 09:19:53,997 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [1160f5b6, L:/xxx.31.34.19:50892 - R:/xxx.31.16.14:3290] Added encoder [EnsureSubscribersCompleteChannelHandler] at the beginning of the user pipeline, full pipeline: [EnsureSubscribersCompleteChannelHandler, LengthFieldBasedFrameDecoder, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0] 2022-07-19 09:19:53,997 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [1160f5b6, L:/xxx.31.34.19:50892 - R:/xxx.31.16.14:3290] FluxReceive{pending=0, cancelled=false, inboundDone=false, inboundError=null}: subscribing inbound receiver 2022-07-19 09:19:53,998 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b] Request: StartupMessage{applicationName='r2dbc-postgresql', database='app_name_01', username='app_name', options='{}'} 2022-07-19 09:19:53,999 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b] Response: AuthenticationCleartextPassword{} 2022-07-19 09:19:53,999 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b] Request: PasswordMessage{password='...'} 2022-07-19 09:19:54,001 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b] Response: AuthenticationOk{} 2022-07-19 09:19:54,001 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b] Response: ParameterStatus{name='application_name', value='r2dbc-postgresql'} 2022-07-19 09:19:54,001 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b] Response: ParameterStatus{name='client_encoding', value='UTF8'} 2022-07-19 09:19:54,001 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b] Response: ParameterStatus{name='DateStyle', value='ISO, MDY'} 2022-07-19 09:19:54,001 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b] Response: ParameterStatus{name='integer_datetimes', value='on'} 2022-07-19 09:19:54,001 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b] Response: ParameterStatus{name='IntervalStyle', value='postgres'} 2022-07-19 09:19:54,001 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b] Response: ParameterStatus{name='is_superuser', value='off'} 2022-07-19 09:19:54,001 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b] Response: ParameterStatus{name='server_encoding', value='UTF8'} 2022-07-19 09:19:54,001 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b] Response: ParameterStatus{name='server_version', value='13.3'} 2022-07-19 09:19:54,002 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b] Response: ParameterStatus{name='session_authorization', value='app_name'} 2022-07-19 09:19:54,002 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b] Response: ParameterStatus{name='standard_conforming_strings', value='on'} 2022-07-19 09:19:54,002 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b] Response: ParameterStatus{name='TimeZone', value='UTC'} 2022-07-19 09:19:54,002 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b] Response: BackendKeyData{processId=3781, secretKey=-21480597} 2022-07-19 09:19:54,002 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: ReadyForQuery{transactionStatus=IDLE} 2022-07-19 09:19:54,004 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Executing query: SHOW TRANSACTION ISOLATION LEVEL 2022-07-19 09:19:54,004 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Request: Query{query='SHOW TRANSACTION ISOLATION LEVEL'} 2022-07-19 09:19:54,005 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: RowDescription{fields=[Field{column=0, dataType=25, dataTypeModifier=-1, dataTypeSize=-1, format=FORMAT_TEXT, name='transaction_isolation', table=0}]} 2022-07-19 09:19:54,006 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: DataRow{columns=[PooledSlicedByteBuf(ridx: 0, widx: 14, cap: 14/14, unwrapped: PooledUnsafeDirectByteBuf(ridx: 72, widx: 88, cap: 1024))]} 2022-07-19 09:19:54,006 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: CommandComplete{command=SHOW, rowId=null, rows=null} 2022-07-19 09:19:54,006 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: ReadyForQuery{transactionStatus=IDLE} 2022-07-19 09:19:54,007 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Executing query: SELECT oid, typname FROM pg_catalog.pg_type WHERE typname IN ('hstore','geometry') 2022-07-19 09:19:54,008 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Request: Query{query='SELECT oid, typname FROM pg_catalog.pg_type WHERE typname IN ('hstore','geometry')'} 2022-07-19 09:19:54,009 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: RowDescription{fields=[Field{column=1, dataType=26, dataTypeModifier=-1, dataTypeSize=4, format=FORMAT_TEXT, name='oid', table=1247}, Field{column=2, dataType=19, dataTypeModifier=-1, dataTypeSize=64, format=FORMAT_TEXT, name='typname', table=1247}]} 2022-07-19 09:19:54,010 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: CommandComplete{command=SELECT, rowId=null, rows=0} 2022-07-19 09:19:54,010 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: ReadyForQuery{transactionStatus=IDLE} 2022-07-19 09:19:54,010 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] Obtaining new connection from the pool 2022-07-19 09:19:54,011 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Executing query: SELECT 1 2022-07-19 09:19:54,011 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Request: Query{query='SELECT 1'} 2022-07-19 09:19:54,012 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [7c541894] Initialized pipeline DefaultChannelPipeline{(reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)} 2022-07-19 09:19:54,012 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [7c541894] Connecting to [/xxx.31.16.14:3290]. 2022-07-19 09:19:54,012 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: RowDescription{fields=[Field{column=0, dataType=23, dataTypeModifier=-1, dataTypeSize=4, format=FORMAT_TEXT, name='?column?', table=0}]} 2022-07-19 09:19:54,013 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: DataRow{columns=[PooledSlicedByteBuf(ridx: 0, widx: 1, cap: 1/1, unwrapped: PooledUnsafeDirectByteBuf(ridx: 46, widx: 66, cap: 512))]} 2022-07-19 09:19:54,013 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: CommandComplete{command=SELECT, rowId=null, rows=1} 2022-07-19 09:19:54,013 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: ReadyForQuery{transactionStatus=IDLE} 2022-07-19 09:19:54,013 DEBUG o.s.r.c.R2dbcTransactionManager [reactor-tcp-nio-1] Acquired Connection [MonoRetry] for R2DBC transaction 2022-07-19 09:19:54,013 DEBUG o.s.r.c.R2dbcTransactionManager [reactor-tcp-nio-1] Switching R2DBC Connection [PooledConnection[PostgresqlConnection{client=io.r2dbc.postgresql.client.ReactorNettyClient@4372abf9, codecs=io.r2dbc.postgresql.codec.DefaultCodecs@dadfd27}]] to manual commit 2022-07-19 09:19:54,013 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Setting auto-commit mode to [false] 2022-07-19 09:19:54,013 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Beginning transaction 2022-07-19 09:19:54,013 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Executing query: BEGIN 2022-07-19 09:19:54,014 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Request: Query{query='BEGIN'} 2022-07-19 09:19:54,014 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [7c541894, L:/xxx.31.34.19:50894 - R:/xxx.31.16.14:3290] Connected new channel 2022-07-19 09:19:54,014 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [7c541894, L:/xxx.31.34.19:50894 - R:/xxx.31.16.14:3290] onStateChange([connected], SimpleConnection{channel=[id: 0x7c541894, L:/xxx.31.34.19:50894 - R:/xxx.31.16.14:3290]}) 2022-07-19 09:19:54,014 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [7c541894, L:/xxx.31.34.19:50894 - R:/xxx.31.16.14:3290] onStateChange([configured], ChannelOperations{SimpleConnection{channel=[id: 0x7c541894, L:/xxx.31.34.19:50894 - R:/xxx.31.16.14:3290]}}) 2022-07-19 09:19:54,014 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [7c541894, L:/xxx.31.34.19:50894 - R:/xxx.31.16.14:3290] Added decoder [LengthFieldBasedFrameDecoder] at the end of the user pipeline, full pipeline: [LengthFieldBasedFrameDecoder, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0] 2022-07-19 09:19:54,015 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [7c541894, L:/xxx.31.34.19:50894 - R:/xxx.31.16.14:3290] Added encoder [EnsureSubscribersCompleteChannelHandler] at the beginning of the user pipeline, full pipeline: [EnsureSubscribersCompleteChannelHandler, LengthFieldBasedFrameDecoder, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0] 2022-07-19 09:19:54,015 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [7c541894, L:/xxx.31.34.19:50894 - R:/xxx.31.16.14:3290] FluxReceive{pending=0, cancelled=false, inboundDone=false, inboundError=null}: subscribing inbound receiver 2022-07-19 09:19:54,017 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c] Request: StartupMessage{applicationName='r2dbc-postgresql', database='app_name_01', username='app_name', options='{}'} 2022-07-19 09:19:54,019 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: CommandComplete{command=BEGIN, rowId=null, rows=null} 2022-07-19 09:19:54,019 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: ReadyForQuery{transactionStatus=TRANSACTION} 2022-07-19 09:19:54,019 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Skipping begin transaction because status is OPEN 2022-07-19 09:19:54,020 DEBUG o.s.r.c.DefaultDatabaseClient$DefaultGenericExecuteSpec [reactor-tcp-nio-1] Executing SQL statement [] 2022-07-19 09:19:54,021 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Bind parameter [0] to: xxxxxxxxxxx 2022-07-19 09:19:54,021 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Executing query: 2022-07-19 09:19:54,021 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Request: [Parse{name='S_0', parameters=[1043], query='$1'}, Bind{name='B_101', parameterFormats=[FORMAT_TEXT], parameters=[CompositeByteBuf(ridx: 0, widx: 10, cap: 10, components=1)], resultFormats=[], source='S_0'}, Describe{name='B_101', type=PORTAL}, Execute{name='B_101', rows=0}, Close{name='B_101', type=PORTAL}, Sync{}] 2022-07-19 09:19:54,022 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c] Response: AuthenticationCleartextPassword{} 2022-07-19 09:19:54,022 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c] Request: PasswordMessage{password='...'} 2022-07-19 09:19:54,023 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: ParseComplete{} 2022-07-19 09:19:54,023 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: BindComplete{} 2022-07-19 09:19:54,024 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: RowDescription{fields=[Field{column=2, }]} 2022-07-19 09:19:54,024 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: DataRow{columns=[PooledSlicedByteBuf(ridx: 0, widx: 10, cap: 10/10, unwrapped: PooledUnsafeDirectByteBuf(ridx: 418, widx: 443, cap: 496)), PooledSlicedByteBuf(ridx: 0, widx: 80, cap: 80/80, unwrapped: PooledUnsafeDirectByteBuf(ridx: 418, widx: 443, cap: 496)), PooledSlicedByteBuf(ridx: 0, widx: 1, cap: 1/1, unwrapped: PooledUnsafeDirectByteBuf(ridx: 418, widx: 443, cap: 496)), PooledSlicedByteBuf(ridx: 0, widx: 1, cap: 1/1, unwrapped: PooledUnsafeDirectByteBuf(ridx: 418, widx: 443, cap: 496)), PooledSlicedByteBuf(ridx: 0, widx: 26, cap: 26/26, unwrapped: PooledUnsafeDirectByteBuf(ridx: 418, widx: 443, cap: 496)), PooledSlicedByteBuf(ridx: 0, widx: 1, cap: 1/1, unwrapped: PooledUnsafeDirectByteBuf(ridx: 418, widx: 443, cap: 496)), PooledSlicedByteBuf(ridx: 0, widx: 26, cap: 26/26, unwrapped: PooledUnsafeDirectByteBuf(ridx: 418, widx: 443, cap: 496)), PooledSlicedByteBuf(ridx: 0, widx: 1, cap: 1/1, unwrapped: PooledUnsafeDirectByteBuf(ridx: 418, widx: 443, cap: 496))]} 2022-07-19 09:19:54,024 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: CommandComplete{command=SELECT, rowId=null, rows=1} 2022-07-19 09:19:54,025 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: CloseComplete{} 2022-07-19 09:19:54,025 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: ReadyForQuery{transactionStatus=TRANSACTION} 2022-07-19 09:19:54,026 DEBUG o.s.d.r.c.NamedParameterExpander [reactor-tcp-nio-1] Expanding SQL statement [] 2022-07-19 09:19:54,026 DEBUG o.s.r.c.DefaultDatabaseClient$DefaultGenericExecuteSpec [reactor-tcp-nio-1] Executing SQL statement [] 2022-07-19 09:19:54,026 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Bind parameter [0] to: 2 2022-07-19 09:19:54,027 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Executing query: s 2022-07-19 09:19:54,027 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Request: [Parse{name='S_1', parameters=[20], query='s}, Bind{name='B_102', parameterFormats=[FORMAT_BINARY], parameters=[CompositeByteBuf(ridx: 0, widx: 8, cap: 8, components=1)], resultFormats=[], source='S_1'}, Describe{name='B_102', type=PORTAL}, Execute{name='B_102', rows=0}, Close{name='B_102', type=PORTAL}, Sync{}] 2022-07-19 09:19:54,027 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c] Response: AuthenticationOk{} 2022-07-19 09:19:54,028 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c] Response: ParameterStatus{name='application_name', value='r2dbc-postgresql'} 2022-07-19 09:19:54,028 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c] Response: ParameterStatus{name='client_encoding', value='UTF8'} 2022-07-19 09:19:54,028 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c] Response: ParameterStatus{name='DateStyle', value='ISO, MDY'} 2022-07-19 09:19:54,028 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c] Response: ParameterStatus{name='integer_datetimes', value='on'} 2022-07-19 09:19:54,028 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c] Response: ParameterStatus{name='IntervalStyle', value='postgres'} 2022-07-19 09:19:54,028 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c] Response: ParameterStatus{name='is_superuser', value='off'} 2022-07-19 09:19:54,029 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c] Response: ParameterStatus{name='server_encoding', value='UTF8'} 2022-07-19 09:19:54,029 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c] Response: ParameterStatus{name='server_version', value='13.3'} 2022-07-19 09:19:54,029 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c] Response: ParameterStatus{name='session_authorization', value='app_name'} 2022-07-19 09:19:54,029 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c] Response: ParameterStatus{name='standard_conforming_strings', value='on'} 2022-07-19 09:19:54,029 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c] Response: ParameterStatus{name='TimeZone', value='UTC'} 2022-07-19 09:19:54,029 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c] Response: BackendKeyData{processId=3782, secretKey=-689945242} 2022-07-19 09:19:54,030 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c][pid: 3782] Response: ReadyForQuery{transactionStatus=IDLE} 2022-07-19 09:19:54,032 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c][pid: 3782] Executing query: SHOW TRANSACTION ISOLATION LEVEL 2022-07-19 09:19:54,032 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c][pid: 3782] Request: Query{query='SHOW TRANSACTION ISOLATION LEVEL'} 2022-07-19 09:19:54,033 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: ParseComplete{} 2022-07-19 09:19:54,033 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: BindComplete{} 2022-07-19 09:19:54,033 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: RowDescription{fields=[Field{column=1, ]} 2022-07-19 09:19:54,034 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: DataRow{columns=[PooledSlicedByteBuf(ridx: 0, widx: 1, cap: 1/1, unwrapped: PooledUnsafeDirectByteBuf(ridx: 415, widx: 440, cap: 496)), PooledSlicedByteBuf(ridx: 0, widx: 5, cap: 5/5, unwrapped: PooledUnsafeDirectByteBuf(ridx: 415, widx: 440, cap: 496)), PooledSlicedByteBuf(ridx: 0, widx: 3, cap: 3/3, unwrapped: PooledUnsafeDirectByteBuf(ridx: 415, widx: 440, cap: 496)), null, PooledSlicedByteBuf(ridx: 0, widx: 1, cap: 1/1, unwrapped: PooledUnsafeDirectByteBuf(ridx: 415, widx: 440, cap: 496)), PooledSlicedByteBuf(ridx: 0, widx: 17, cap: 17/17, unwrapped: PooledUnsafeDirectByteBuf(ridx: 415, widx: 440, cap: 496)), PooledSlicedByteBuf(ridx: 0, widx: 26, cap: 26/26, unwrapped: PooledUnsafeDirectByteBuf(ridx: 415, widx: 440, cap: 496)), PooledSlicedByteBuf(ridx: 0, widx: 1, cap: 1/1, unwrapped: PooledUnsafeDirectByteBuf(ridx: 415, widx: 440, cap: 496)), PooledSlicedByteBuf(ridx: 0, widx: 26, cap: 26/26, unwrapped: PooledUnsafeDirectByteBuf(ridx: 415, widx: 440, cap: 496)), PooledSlicedByteBuf(ridx: 0, widx: 1, cap: 1/1, unwrapped: PooledUnsafeDirectByteBuf(ridx: 415, widx: 440, cap: 496))]} 2022-07-19 09:19:54,034 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: CommandComplete{command=SELECT, rowId=null, rows=1} 2022-07-19 09:19:54,034 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: CloseComplete{} 2022-07-19 09:19:54,034 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: ReadyForQuery{transactionStatus=TRANSACTION} 2022-07-19 09:19:54,035 DEBUG o.s.t.r.AbstractReactiveTransactionManager [reactor-tcp-nio-1] Initiating transaction commit 2022-07-19 09:19:54,035 DEBUG o.s.r.c.R2dbcTransactionManager [reactor-tcp-nio-1] Committing R2DBC transaction on Connection [PooledConnection[PostgresqlConnection{client=io.r2dbc.postgresql.client.ReactorNettyClient@4372abf9, codecs=io.r2dbc.postgresql.codec.DefaultCodecs@dadfd27}]] 2022-07-19 09:19:54,035 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Executing query: COMMIT 2022-07-19 09:19:54,035 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Request: Query{query='COMMIT'} 2022-07-19 09:19:54,036 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c][pid: 3782] Response: RowDescription{fields=[Field{column=0, dataType=25, dataTypeModifier=-1, dataTypeSize=-1, format=FORMAT_TEXT, name='transaction_isolation', table=0}]} 2022-07-19 09:19:54,036 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c][pid: 3782] Response: DataRow{columns=[PooledSlicedByteBuf(ridx: 0, widx: 14, cap: 14/14, unwrapped: PooledUnsafeDirectByteBuf(ridx: 72, widx: 88, cap: 1024))]} 2022-07-19 09:19:54,036 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c][pid: 3782] Response: CommandComplete{command=SHOW, rowId=null, rows=null} 2022-07-19 09:19:54,036 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c][pid: 3782] Response: ReadyForQuery{transactionStatus=IDLE} 2022-07-19 09:19:54,037 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c][pid: 3782] Executing query: SELECT oid, typname FROM pg_catalog.pg_type WHERE typname IN ('hstore','geometry') 2022-07-19 09:19:54,037 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c][pid: 3782] Request: Query{query='SELECT oid, typname FROM pg_catalog.pg_type WHERE typname IN ('hstore','geometry')'} 2022-07-19 09:19:54,037 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: CommandComplete{command=COMMIT, rowId=null, rows=null} 2022-07-19 09:19:54,037 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Response: ReadyForQuery{transactionStatus=IDLE} 2022-07-19 09:19:54,038 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Setting auto-commit mode to [true] 2022-07-19 09:19:54,038 DEBUG o.s.r.c.R2dbcTransactionManager [reactor-tcp-nio-1] Releasing R2DBC Connection [PooledConnection[PostgresqlConnection{client=io.r2dbc.postgresql.client.ReactorNettyClient@4372abf9, codecs=io.r2dbc.postgresql.codec.DefaultCodecs@dadfd27}]] after transaction 2022-07-19 09:19:54,038 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] Releasing connection 2022-07-19 09:19:54,038 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1b][pid: 3781] Request: Terminate{} 2022-07-19 09:19:54,039 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [1160f5b6, L:/xxx.31.34.19:50892 ! R:/xxx.31.16.14:3290] Non Removed handler: LengthFieldBasedFrameDecoder, context: ChannelHandlerContext(LengthFieldBasedFrameDecoder, [id: 0x1160f5b6, L:/xxx.31.34.19:50892 ! R:/xxx.31.16.14:3290]), pipeline: DefaultChannelPipeline{(EnsureSubscribersCompleteChannelHandler = io.r2dbc.postgresql.client.ReactorNettyClient$EnsureSubscribersCompleteChannelHandler), (LengthFieldBasedFrameDecoder = io.netty.handler.codec.LengthFieldBasedFrameDecoder), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)} 2022-07-19 09:19:54,039 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [1160f5b6, L:/xxx.31.34.19:50892 ! R:/xxx.31.16.14:3290] Non Removed handler: EnsureSubscribersCompleteChannelHandler, context: ChannelHandlerContext(EnsureSubscribersCompleteChannelHandler, [id: 0x1160f5b6, L:/xxx.31.34.19:50892 ! R:/xxx.31.16.14:3290]), pipeline: DefaultChannelPipeline{(EnsureSubscribersCompleteChannelHandler = io.r2dbc.postgresql.client.ReactorNettyClient$EnsureSubscribersCompleteChannelHandler), (LengthFieldBasedFrameDecoder = io.netty.handler.codec.LengthFieldBasedFrameDecoder), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)} 2022-07-19 09:19:54,039 INFO c.a.s.AuthenticationService [reactor-tcp-nio-1] UserName: 2022-07-19 09:19:54,039 INFO c.a.s.AuthenticationService [reactor-tcp-nio-1] Password: 2022-07-19 09:19:54,041 DEBUG o.s.w.r.r.HandlerResultHandlerSupport [reactor-tcp-nio-1] [bc11bb29-17] Using 'application/json' given [application/json, text/plain, /] and supported [application/json, application/*+json, application/x-ndjson, text/event-stream] 2022-07-19 09:19:54,041 DEBUG o.s.w.r.r.m.a.AbstractMessageWriterResultHandler [reactor-tcp-nio-1] [bc11bb29-17] 0..1 [com.authenticate.model.auth.AuthResponse] 2022-07-19 09:19:54,042 DEBUG o.s.c.l.CompositeLog [reactor-tcp-nio-1] [bc11bb29-17] Encoding [AuthResponse(token=null)] 2022-07-19 09:19:54,042 DEBUG r.u.Loggers$Slf4JLogger [reactor-http-nio-2] [bc11bb29-1, L:/127.0.0.1:8082 - R:/127.0.0.1:36548] Detected non persistent http connection, preparing to close 2022-07-19 09:19:54,043 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [1160f5b6, L:/xxx.31.34.19:50892 ! R:/xxx.31.16.14:3290] onStateChange([disconnecting], ChannelOperations{SimpleConnection{channel=[id: 0x1160f5b6, L:/xxx.31.34.19:50892 ! R:/xxx.31.16.14:3290]}}) 2022-07-19 09:19:54,043 DEBUG r.u.Loggers$Slf4JLogger [reactor-http-nio-2] [bc11bb29-1, L:/127.0.0.1:8082 - R:/127.0.0.1:36548] Last HTTP response frame 2022-07-19 09:19:54,043 DEBUG r.u.Loggers$Slf4JLogger [reactor-http-nio-2] [bc11bb29-1, L:/127.0.0.1:8082 - R:/127.0.0.1:36548] Last HTTP packet was sent, terminating the channel 2022-07-19 09:19:54,043 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c][pid: 3782] Response: RowDescription{fields=[Field{column=1, dataType=26, dataTypeModifier=-1, dataTypeSize=4, format=FORMAT_TEXT, name='oid', table=1247}, Field{column=2, dataType=19, dataTypeModifier=-1, dataTypeSize=64, format=FORMAT_TEXT, name='typname', table=1247}]} 2022-07-19 09:19:54,043 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c][pid: 3782] Response: CommandComplete{command=SELECT, rowId=null, rows=0} 2022-07-19 09:19:54,043 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] [cid: 0x1c][pid: 3782] Response: ReadyForQuery{transactionStatus=IDLE} 2022-07-19 09:19:54,044 DEBUG r.u.Loggers$Slf4JLogger [reactor-tcp-nio-1] warmed up extra resource 1/1

immmus commented 1 year ago

I have the same problem

sonallux commented 1 year ago

@mp911de We also have this problem, that our application is unable to obtain database connections from the connection pool. The PostgreSQL database does not see any open connections. We are using Spring Boot 3.0.2.

Our r2dbc pool metrics are: