Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
madhav1306 opened this issue Jul 19, 2022 · 4 comments
Open

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

madhav1306 opened this issue Jul 19, 2022 · 4 comments
Labels
status: waiting-for-feedback We need additional information before we can continue status: waiting-for-triage An issue we've not yet triaged

Comments

@madhav1306
Copy link

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
@madhav1306 madhav1306 added the status: waiting-for-triage An issue we've not yet triaged label Jul 19, 2022
@mp911de
Copy link
Collaborator

mp911de commented Jul 19, 2022

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)?

@mp911de mp911de added the status: waiting-for-feedback We need additional information before we can continue label Jul 19, 2022
@madhav1306
Copy link
Author

madhav1306 commented Jul 19, 2022 •
edited

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
Copy link

immmus commented Jan 17, 2023

I have the same problem

@sonallux
Copy link

@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:

  • r2dbc.pool.acquired: 0
  • r2dbc.pool.allocated: 15
  • r2dbc.pool.idle: 0
  • r2dbc.pool.max.allocated: 15
  • r2dbc.pool.max.pending: 2.147483647E9
  • r2dbc.pool.pending: 400120.0

@anschnapp anschnapp mentioned this issue Mar 18, 2024
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
status: waiting-for-feedback We need additional information before we can continue status: waiting-for-triage An issue we've not yet triaged
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@mp911de @madhav1306 @sonallux @immmus