Connection in unstable state when rollback after a failed commit

[deblockt]

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.

[Squiry]

I don't think that r2dbc-postgres really does some tx-management. As I can see in log all this rolling-back-failed-to-commit-tx logic is in R2dbcTransactionManager and that's a part of spring-data-r2dbc.
@mp911de please correct me if I'm wrong.

[mp911de]

What @Squiry said. I'm worried about the rollback()/setAutoCommit(true) sequence. The rollback doesn't seem to have any effect as setAutoCommit(…) tries to issue a commit:

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

I need to look into it what's going on.

[mp911de]

I have only a partial explanation on what happens. For some reason, the ROLLBACK statement fails. As part of the transaction cleanup, auto-commit gets restored and enabling auto-commit sees that there is an unfinished transaction that issues a commit.

We require a reproducer to further investigate what's happening.

[deblockt]

I'm trying to reproduce the issue on a sample, but without success.
The main difference that I can not see that on my reproduction logs DEBUG [b4b77d43edce3714] i.r.postgresql.util.FluxDiscardOnCancel received cancel signal .
Do you know what is done by this class?

[mp911de]

FluxDiscardOnCancel gets activated if you cancel the result consumption before consuming all results from the statement execution. You should be able to reproduce it via statement.execute().flatMap(result -> result.map(...)).take(1) assuming that the statement creates more than one row.

[deblockt]

Hi, I created a project to reproduce the issue: https://github.com/deblockt/r2dbc-issue-reproducer

I doesn't have the same log, but I have the same issue finally (a closed connecton)

[deblockt]

It seem that with Arabba-SR4 I don't reproduce the issue on my sample project. Do you know if something on this version can fix the issue?
I will try to reproduce on my real project.

[deblockt]

I have test on my real case application, Have the issue change using Arabba-SR4 When an error occurs, The mono is "blocked"; the connection is not released and nothing happen.
All is unblocked when I kill the application, on shutdown connection are released and errors are shown

[mp911de]

0.8.3 ships with mostly dependency upgrades and smaller improvements and there aren't really bugfixes. Let me have a look at the provided sample.

[mp911de]

I was able to get all sorts of exceptions with version 0.8.1 (Arabba-SR2). Version 0.8.2 contained some significant changes to cancellation and event dispatching so I expect 0.8.2 is really the version that fixed a few things.

Let me know if the issue persists or has changed so that we can either continue the investigation or that we can close this ticket.

[deblockt]

With the last version when an error occurs, the rollback start, but the mono is never completed.

[mp911de]

We fixed today an issue where publishers never complete due to a bug in handling reentrant calls. Care to retest the issue against 0.8.4.BUILD-SNAPSHOT?

[deblockt]

Is there a bom ton instal this version?

[mp911de]

Typically, you specify the version number in your build config. See https://github.com/pgjdbc/r2dbc-postgresql/tree/0.8.x#maven-configuration for a Maven example.

[davecramer]

FYI, there are challenges with this scenario due to the way postgres handles transactions. No error message is emitted if you commit transaction in an error state. Instead Postgres responds to commit with rollback. There is a thread https://www.postgresql.org/message-id/b9fb50dc-0f6e-15fb-6555-8ddb86f4aa71%40postgresfriends.org feel free to voice your opinion. The jdbc driver now checks for rollback as a response to commit and throws and exception if this happens

[deblockt]

I have try with the 0.8.4 version, but now some request are not executed. I will retry later.

[mp911de]

We're going to fix in 0.8.x the issue that commitTransaction ignores failed transactions so COMMIT ensures a proper transaction cleanup. For 0.9.x, we're going to align with PGJDBC, so that we throw a rollback exception on silent rollbacks.