TX management bug in certain cases: COMMIT PREPARED cannot run inside a transaction block #5246
Description
Steps to reproduce
using System.Transactions;
using Dapper;
using Npgsql;
namespace Tests
{
[TestClass]
public class NpgsqlTX
{
[TestMethod]
public void test()
{
using (var deleteTX = new TransactionScope())
{
var outerTX = Transaction.Current;
using (var copyTX = new TransactionScope(TransactionScopeOption.RequiresNew))
{
using (var deleteOuter = new TransactionScope(outerTX))
{
using (var delImidiate = new TransactionScope(TransactionScopeOption.RequiresNew))
{
var deleteNow = new NpgsqlConnection("Host=localhost;Port=5432;Database=db_name;Enlist=true;User ID=login;Password=123");
deleteNow.Open();
deleteNow.Execute("SELECT 'del_now'");
var deleteNow2 = new NpgsqlConnection("Host=localhost;Port=5432;Database=db_name;Enlist=true;User ID=login;Password=123");
deleteNow2.Open();
deleteNow2.Execute("SELECT 'del_now2'");
delImidiate.Complete();
}
var deleteConn = new NpgsqlConnection("Host=localhost;Port=5432;Database=db_name;Enlist=true;User ID=login;Password=123");
deleteConn.Open();
deleteConn.Execute("SELECT 'delete, this should commit last'");
deleteOuter.Complete();
}
var copyConn = new NpgsqlConnection("Host=localhost;Port=5432;Database=db2_name;Enlist=true;User ID=login;Password=123");
copyConn.Open();
copyConn.Execute("SELECT 'copy data. this should commit before delete'");
copyTX.Complete();
}
deleteTX.Complete();
}
}
}
}
This code could probably be simplified to reproduce a problem in its minimal way. But this is how it logically works in our project.
The issue
Code fails with error: COMMIT PREPARED cannot run inside a transaction block
As I understand the logic of Npgsql, for each TX, that is part of shared scope, when a TX ends it do 'prepare TX', then in 2nd phase, npgsql opens a new connection and do commit prepared
I did a lot of testing and Npgsql mostly works correct, but in some situations Npgsql for some reason do "BEGIN TRANSACTION" in connection that is supposed to do "COMMIT PREPARED" which should never happen.
Postgresql log:
2023-09-01 08:21:10.910 [12652] session:64f174c6.316c db:[unknown] tx:LOG: connection received: host=::1 port=60334
2023-09-01 08:21:10.942 [12652] session:64f174c6.316c db:db_name tx:12/10312LOG: connection authorized: user=login database=db_name
2023-09-01 08:21:10.978 [12652] session:64f174c6.316c db:db_name tx:12/10313LOG: statement: SELECT version();
2023-09-01 08:21:11.074 [12652] session:64f174c6.316c db:db_name tx:12/10314LOG: statement: BEGIN TRANSACTION ISOLATION LEVEL SERIALIZABLE
2023-09-01 08:21:11.074 [12652] session:64f174c6.316c db:db_name tx:12/10314LOG: execute <unnamed>: SELECT 'del_now'
2023-09-01 08:21:11.129 [11460] session:64f174c7.2cc4 db:[unknown] tx:LOG: connection received: host=::1 port=60336
2023-09-01 08:21:11.138 [11460] session:64f174c7.2cc4 db:db_name tx:13/74LOG: connection authorized: user=login database=db_name
2023-09-01 08:21:11.142 [11460] session:64f174c7.2cc4 db:db_name tx:13/75LOG: statement: BEGIN TRANSACTION ISOLATION LEVEL SERIALIZABLE
2023-09-01 08:21:11.143 [11460] session:64f174c7.2cc4 db:db_name tx:13/75LOG: execute <unnamed>: SELECT 'del_now2'
2023-09-01 08:21:11.146 [12652] session:64f174c6.316c db:db_name tx:12/10314LOG: statement: PREPARE TRANSACTION '00000000-0000-0000-0000-000000000000/12652'
2023-09-01 08:21:11.148 [11460] session:64f174c7.2cc4 db:db_name tx:13/75LOG: statement: PREPARE TRANSACTION '00000000-0000-0000-0000-000000000000/11460'
2023-09-01 08:21:11.191 [10648] session:64f174c7.2998 db:[unknown] tx:LOG: connection received: host=::1 port=60337
2023-09-01 08:21:11.203 [10648] session:64f174c7.2998 db:db_name tx:14/64LOG: connection authorized: user=login database=db_name
2023-09-01 08:21:11.207 [10648] session:64f174c7.2998 db:db_name tx:14/65LOG: statement: BEGIN TRANSACTION ISOLATION LEVEL SERIALIZABLE
2023-09-01 08:21:11.207 [10648] session:64f174c7.2998 db:db_name tx:14/65LOG: statement: COMMIT PREPARED '00000000-0000-0000-0000-000000000000/12652'
2023-09-01 08:21:11.207 [10648] session:64f174c7.2998 db:db_name tx:14/65ERROR: COMMIT PREPARED cannot run inside a transaction block
2023-09-01 08:21:11.207 [10648] session:64f174c7.2998 db:db_name tx:14/65STATEMENT: COMMIT PREPARED '00000000-0000-0000-0000-000000000000/12652'
2023-09-01 08:21:11.216 [10648] session:64f174c7.2998 db:db_name tx:14/0LOG: statement: COMMIT PREPARED '00000000-0000-0000-0000-000000000000/11460'
2023-09-01 08:21:11.216 [10648] session:64f174c7.2998 db:db_name tx:14/0ERROR: current transaction is aborted, commands ignored until end of transaction block
2023-09-01 08:21:11.216 [10648] session:64f174c7.2998 db:db_name tx:14/0STATEMENT: COMMIT PREPARED '00000000-0000-0000-0000-000000000000/11460'
2023-09-01 08:21:11.217 [10648] session:64f174c7.2998 db:db_name tx:14/0ERROR: current transaction is aborted, commands ignored until end of transaction block
2023-09-01 08:21:11.217 [10648] session:64f174c7.2998 db:db_name tx:14/0STATEMENT: SELECT 'delete, this should commit last'
2023-09-01 08:21:11.223 [10648] session:64f174c7.2998 db:db_name tx:14/0LOG: statement: ROLLBACK
Further technical details
Npgsql version: 7.0.4
PostgreSQL version: PostgreSQL 11
Operating system: Linux, Windows