r2dbc-postgresql: Connection in unstable state when rollback after a failed commit

Bug Report

Versions

• Driver: 0.8.1.RELEASE
• Database: postgres v11
• Java: 11
• OS: ubuntu

Current Behavior

I have a query that fail on commit (due to pk issue). When the commit fail, r2dbc try to perform a rollback.

DEBUG [dd2c4c320c15cb04] o.s.d.r.c.R2dbcTransactionManager        Initiating transaction commit
DEBUG [dd2c4c320c15cb04] o.s.d.r.c.R2dbcTransactionManager        Committing R2DBC transaction on Connection [PooledConnection-proxy [PooledConnection[PostgresqlConnection{client=io.r2dbc.postgresql.client.ReactorNettyClient@368812cf, codecs=io.r2dbc.postgresql.codec.DefaultCodecs@3bd45442, forceBinary=false, portalNameSupplier=io.r2dbc.postgresql.DefaultPortalNameSupplier@77a49d3d, statementCache=IndefiniteStatementCache{cache={select count(1) from applied_message where id = $1 LIMIT 1={[I@419882ce=MonoLift}, select data from ... where customer_order_id = $1 and data->'holder'->>'type' = 'CUSTOMER_ORDER' LIMIT 1={[I@5dee73a4=MonoLift}, INSERT INTO applied_message (id, correlation_id, applied_at) VALUES ($1, $2, $3) RETURNING *={[I@432ae53c=MonoLift}, select data from ... where customer_order_id = $1 FOR UPDATE={[I@48d60596=MonoLift}}, client=io.r2dbc.postgresql.client.ReactorNettyClient@368812cf, counter=4}}]]]
DEBUG [dd2c4c320c15cb04] io.r2dbc.postgresql.QUERY                Executing query: COMMIT
DEBUG [f38d07efa5ddadb6] i.r.p.client.ReactorNettyClient          Request:  Query{query='COMMIT'}
DEBUG [f38d07efa5ddadb6] i.r.p.client.ReactorNettyClient          Response: BindComplete{}
DEBUG [f38d07efa5ddadb6] i.r.p.client.ReactorNettyClient          Response: RowDescription{fields=[Field{column=1, dataType=1043, dataTypeModifier=59, dataTypeSize=-1, format=FORMAT_TEXT, name='id', table=16404}, Field{column=2, dataType=1043, dataTypeModifier=59, dataTypeSize=-1, format=FORMAT_TEXT, name='correlation_id', table=16404}, Field{column=3, dataType=1114, dataTypeModifier=-1, dataTypeSize=8, format=FORMAT_TEXT, name='applied_at', table=16404}]}
DEBUG [f38d07efa5ddadb6] i.r.p.client.ReactorNettyClient          Response: ErrorResponse{fields=[Field{type=SEVERITY_LOCALIZED, value='ERROR'}, Field{type=SEVERITY_NON_LOCALIZED, value='ERROR'}, Field{type=CODE, value='23505'}, Field{type=MESSAGE, value='duplicate key value violates unique constraint "pk_applied_message"'}, Field{type=DETAIL, value='Key (id)=(gtirbvvcmukbimn) already exists.'}, Field{type=SCHEMA_NAME, value='...'}, Field{type=TABLE_NAME, value='applied_message'}, Field{type=CONSTRAINT_NAME, value='pk_applied_message'}, Field{type=FILE, value='nbtinsert.c'}, Field{type=LINE, value='570'}, Field{type=ROUTINE, value='_bt_check_unique'}]}
 WARN [f38d07efa5ddadb6] i.r.p.client.ReactorNettyClient          Error: SEVERITY_LOCALIZED=ERROR, SEVERITY_NON_LOCALIZED=ERROR, CODE=23505, MESSAGE=duplicate key value violates unique constraint "pk_applied_message", DETAIL=Key (id)=(gtirbvvcmukbimn) already exists., SCHEMA_NAME=..., TABLE_NAME=applied_message, CONSTRAINT_NAME=pk_applied_message, FILE=nbtinsert.c, LINE=570, ROUTINE=_bt_check_unique
DEBUG [b4b77d43edce3714] i.r.postgresql.util.FluxDiscardOnCancel  received cancel signal
DEBUG [b4b77d43edce3714] o.s.d.r.c.R2dbcTransactionManager        Initiating transaction rollback
DEBUG [b4b77d43edce3714] o.s.d.r.c.R2dbcTransactionManager        Rolling back R2DBC transaction on Connection [PooledConnection-proxy [PooledConnection[PostgresqlConnection{client=io.r2dbc.postgresql.client.ReactorNettyClient@368812cf, codecs=io.r2dbc.postgresql.codec.DefaultCodecs@3bd45442, forceBinary=false, portalNameSupplier=io.r2dbc.postgresql.DefaultPortalNameSupplier@77a49d3d, statementCache=IndefiniteStatementCache{cache={select count(1) from applied_message where id = $1 LIMIT 1={[I@419882ce=MonoLift}, select data from ... where customer_order_id = $1 and data->'holder'->>'type' = 'CUSTOMER_ORDER' LIMIT 1={[I@5dee73a4=MonoLift}, INSERT INTO applied_message (id, correlation_id, applied_at) VALUES ($1, $2, $3) RETURNING *={[I@432ae53c=MonoLift}, select data from ... where customer_order_id = $1 FOR UPDATE={[I@48d60596=MonoLift}}, client=io.r2dbc.postgresql.client.ReactorNettyClient@368812cf, counter=4}}]]]
DEBUG [b4b77d43edce3714] io.r2dbc.postgresql.QUERY                Executing query: ROLLBACK
DEBUG [f38d07efa5ddadb6] i.r.p.client.ReactorNettyClient          Request:  Query{query='ROLLBACK'}
DEBUG [f38d07efa5ddadb6] i.r.p.client.ReactorNettyClient          Response: ReadyForQuery{transactionStatus=ERROR}
DEBUG [f38d07efa5ddadb6] i.r.p.client.ReactorNettyClient          Response: ErrorResponse{fields=[Field{type=SEVERITY_LOCALIZED, value='ERROR'}, Field{type=SEVERITY_NON_LOCALIZED, value='ERROR'}, Field{type=CODE, value='25P02'}, Field{type=MESSAGE, value='current transaction is aborted, commands ignored until end of transaction block'}, Field{type=FILE, value='postgres.c'}, Field{type=LINE, value='1686'}, Field{type=ROUTINE, value='exec_bind_message'}]}
 WARN [f38d07efa5ddadb6] i.r.p.client.ReactorNettyClient          Error: SEVERITY_LOCALIZED=ERROR, SEVERITY_NON_LOCALIZED=ERROR, CODE=25P02, MESSAGE=current transaction is aborted, commands ignored until end of transaction block, FILE=postgres.c, LINE=1686, ROUTINE=exec_bind_message
DEBUG [c82bbc47b591b926] i.r.postgresql.util.FluxDiscardOnCancel  received cancel signal
DEBUG [c82bbc47b591b926] o.s.d.r.c.R2dbcTransactionManager        Initiating transaction rollback
DEBUG [c82bbc47b591b926] o.s.d.r.c.R2dbcTransactionManager        Rolling back R2DBC transaction on Connection [PooledConnection-proxy [PooledConnection[PostgresqlConnection{client=io.r2dbc.postgresql.client.ReactorNettyClient@368812cf, codecs=io.r2dbc.postgresql.codec.DefaultCodecs@3bd45442, forceBinary=false, portalNameSupplier=io.r2dbc.postgresql.DefaultPortalNameSupplier@77a49d3d, statementCache=IndefiniteStatementCache{cache={select count(1) from applied_message where id = $1 LIMIT 1={[I@419882ce=MonoLift}, select data from ... where customer_order_id = $1 and data->'holder'->>'type' = 'CUSTOMER_ORDER' LIMIT 1={[I@5dee73a4=MonoLift}, INSERT INTO applied_message (id, correlation_id, applied_at) VALUES ($1, $2, $3) RETURNING *={[I@432ae53c=MonoLift}, select data from ... where customer_order_id = $1 FOR UPDATE={[I@48d60596=MonoLift}}, client=io.r2dbc.postgresql.client.ReactorNettyClient@368812cf, counter=4}}]]]
DEBUG [c82bbc47b591b926] io.r2dbc.postgresql.QUERY                Executing query: ROLLBACK
DEBUG [f38d07efa5ddadb6] i.r.p.client.ReactorNettyClient          Request:  Query{query='ROLLBACK'}
DEBUG [f38d07efa5ddadb6] i.r.p.client.ReactorNettyClient          Response: ReadyForQuery{transactionStatus=ERROR}
DEBUG [f38d07efa5ddadb6] i.r.p.client.ReactorNettyClient          Response: ErrorResponse{fields=[Field{type=SEVERITY_LOCALIZED, value='ERROR'}, Field{type=SEVERITY_NON_LOCALIZED, value='ERROR'}, Field{type=CODE, value='25P02'}, Field{type=MESSAGE, value='current transaction is aborted, commands ignored until end of transaction block'}, Field{type=FILE, value='postgres.c'}, Field{type=LINE, value='1105'}, Field{type=ROUTINE, value='exec_simple_query'}]}
 WARN [f38d07efa5ddadb6] i.r.p.client.ReactorNettyClient          Error: SEVERITY_LOCALIZED=ERROR, SEVERITY_NON_LOCALIZED=ERROR, CODE=25P02, MESSAGE=current transaction is aborted, commands ignored until end of transaction block, FILE=postgres.c, LINE=1105, ROUTINE=exec_simple_query
DEBUG [23becfe529ea5ac2] i.r.postgresql.util.FluxDiscardOnCancel  received cancel signal
DEBUG [2cea38620b17253b] i.r.postgresql.util.FluxDiscardOnCancel  received cancel signal
DEBUG [2cea38620b17253b] i.r.postgresql.util.FluxDiscardOnCancel  received cancel signal
DEBUG [2cea38620b17253b] i.r.postgresql.util.FluxDiscardOnCancel  received cancel signal
DEBUG [2cea38620b17253b] o.s.d.r.c.R2dbcTransactionManager        Initiating transaction rollback
DEBUG [2cea38620b17253b] o.s.d.r.c.R2dbcTransactionManager        Rolling back R2DBC transaction on Connection [PooledConnection-proxy [PooledConnection[PostgresqlConnection{client=io.r2dbc.postgresql.client.ReactorNettyClient@368812cf, codecs=io.r2dbc.postgresql.codec.DefaultCodecs@3bd45442, forceBinary=false, portalNameSupplier=io.r2dbc.postgresql.DefaultPortalNameSupplier@77a49d3d, statementCache=IndefiniteStatementCache{cache={select count(1) from applied_message where id = $1 LIMIT 1={[I@419882ce=MonoLift}, select data from ... where customer_order_id = $1 and data->'holder'->>'type' = 'CUSTOMER_ORDER' LIMIT 1={[I@5dee73a4=MonoLift}, INSERT INTO applied_message (id, correlation_id, applied_at) VALUES ($1, $2, $3) RETURNING *={[I@432ae53c=MonoLift}, select data from ... where customer_order_id = $1 FOR UPDATE={[I@48d60596=MonoLift}}, client=io.r2dbc.postgresql.client.ReactorNettyClient@368812cf, counter=4}}]]]
DEBUG [2cea38620b17253b] io.r2dbc.postgresql.QUERY                Executing query: ROLLBACK
DEBUG [f38d07efa5ddadb6] i.r.p.client.ReactorNettyClient          Request:  Query{query='ROLLBACK'}
DEBUG [dd2c4c320c15cb04] i.r2dbc.postgresql.PostgresqlConnection  Setting auto-commit mode to [true]
DEBUG [dd2c4c320c15cb04] i.r2dbc.postgresql.PostgresqlConnection  Committing pending transactions
DEBUG [dd2c4c320c15cb04] i.r2dbc.postgresql.PostgresqlConnection  Skipping commit transaction because status is FAILED

By following trace f38d07efa5ddadb6, we can see that:

• commit has failed: pk error
• try to rollback: current transaction is aborted
• try to rollback…

Later on the log we can see that the connexion has been closed. and all next requests will fail.

Antoher question, If I fine understand the logs, Multiple transactions are commited/rollback on same time, while I only have one connection configured in my pool.

Steps to reproduce

I have not a simple project to reproduce the issue. I will try to do that.

Expected behavior/code

when commit fail, no rollback should be done.