Connection closing on its own?

Discussion of open issues, suggestions and bugs regarding ADO.NET provider for PostgreSQL
Post Reply
TonyV
Posts: 74
Joined: Wed 25 May 2011 15:03

Connection closing on its own?

Post by TonyV » Sat 10 Mar 2012 03:44

I've got a PostgreSQL 9.1 database and I've build an Entity Framework 4 model using Entity Developer. I'm using the Postgresql large objects table to hold jpeg images. The OID of the large object for each image is stored in a column in a table called Images.

I've got a module which is designed to run periodically and purge old data. The module uses the entity model for most of its work. However, when I get to purging the Images table, I have to do the work through the PgSqlLargeObject object (which is what I use to put the image bytes into the large objects table and retrieve them from it).

In the purge method, I perform the following

Code: Select all


IQueryable images = from image in context.Images . . .;
PgSqlConnection connection = ((EntityConnection) context.Connection).StoreConnecton;
if ( connection.State != ConnectionState.Open ) {
    connection.Open();
}

using ( PgSqlTransaction transaction = connection.BeginTransaction() {
    try {
        foreach ( Image image in images ) {
            if ( image.ImageOid != null ) {   // the ImageOid column is nullable
                PgSqlLargeObject lo = new PgSqlLargeObject( connection );
                lo.Open();
                if ( lo.CanWrite ) {
                    lo.Remove();
                }
                lo.Close();
            }

            context.Images.DeleteObject( image );
        }
    } catch ( Exception ex ) {
        // Log the message here
        transaction.Rollback();
    }
    transaction.Commit();
}
There's more code for related tables, but this is the gist.

This method is called from the main method of a thread. The context object is created in there, and I also create a transaction at that level using the same code so I can roll everything back should something go wrong elsewhere in the process.

The problem is that when the method I've shown the code for above exits, the connection is closed. The outer transaction's Rollback & Commit calls throws a PgSqlException saying that the connection must be open.

I'm not closing the connection, and I'm not getting it in a using statement. I've done some debugging and the transaction doesn't close until just before the method returns.

What is closing the connection? How do I keep it from closing automatically?

Tony

Shalex
Site Admin
Posts: 9543
Joined: Thu 14 Aug 2008 12:44

Post by Shalex » Wed 14 Mar 2012 14:38

Connection should not be closed automatically. Please make sure that connection to your PostgreSQL server is stable (in the opposite, this can be the reason of the problem). If this is not the case, please send us a small test project with the corresponding DDL/DML script to reproduce the issue in our environment. Also tell us the exact (9.1.x) version of your PostgreSQL server.

TonyV
Posts: 74
Joined: Wed 25 May 2011 15:03

More detail

Post by TonyV » Wed 14 Mar 2012 21:23

Shalex:

The problem is not what it seems. This is partly because of the way the Devart library is reporting the error that occurs in Postgres.

To try to figure out what is happening, we prepared three unit tests. Each one creates an Entity Framework object context, then inserts a single row into one of our tables using the object context. It then calls context.SaveChanges().

In the first test, we used a TransactionScope to surround the insert. Here is the code for this test:

Code: Select all

[TestCategory( "PubSubBufferPostrgres" ), TestMethod, Timeout( 600000 )]
public void TestPostgresConcurrancy_TransactionScope() {
	using ( CarSystemEntities context = new CarSystemEntities() )
	using ( TransactionScope tran = new TransactionScope() ) {
		CarSystem.List l = new CarSystem.List();
		l.ListId = Guid.NewGuid();
		l.ListName = "test";
		l.ListTypeId = 1;
		l.DomainId = 1;

		context.AddToLists( l );
		context.SaveChanges( System.Data.Objects.SaveOptions.AcceptAllChangesAfterSave );

		tran.Complete();
	}
}
In the second, we created a DbTransaction using the EntityConnection in the context. Here's that code:

Code: Select all

[TestCategory( "PubSubBufferPostrgres" ), TestMethod, Timeout( 600000 )]
public void TestPostgresConcurrancy_DbTransaction() {
	using ( CarSystemEntities context = new CarSystemEntities() ) {
		if ( context.Connection.State != ConnectionState.Open ) {
			context.Connection.Open();
		}

		using ( DbTransaction tran = context.Connection.BeginTransaction() ) {
			CarSystem.List l = new CarSystem.List();
			l.ListId = Guid.NewGuid();
			l.ListName = "test";
			l.ListTypeId = 1;
			l.DomainId = 1;
				
			context.AddToLists( l );
			context.SaveChanges( System.Data.Objects.SaveOptions.AcceptAllChangesAfterSave );

			tran.Commit();
		}
	}
}
In the third, we created a PgSqlTransaction by referencing the StoreConnection in the EntityConnection. Here's that code:

Code: Select all

[TestCategory( "PubSubBufferPostrgres" ), TestMethod, Timeout( 600000 )]
public void TestPostgresConcurrancy_PgSqlTransaction() {
	using ( CarSystemEntities context = new CarSystemEntities() ) {
		PgSqlConnection connection = ( (EntityConnection) context.Connection ).StoreConnection as PgSqlConnection;
		if ( connection.State != ConnectionState.Open ) {
			connection.Open();
		}

		using ( PgSqlTransaction tran = connection.BeginTransaction() ) {
			CarSystem.List l = new CarSystem.List();
			l.ListId = Guid.NewGuid();
			l.ListName = "test";
			l.ListTypeId = 1;
			l.DomainId = 1;
				
			context.AddToLists( l );
			context.SaveChanges( System.Data.Objects.SaveOptions.AcceptAllChangesAfterSave );

			tran.Commit();
		}
	}
}
We turned on verbose logging on one of our servers. This let us see that the issue in the TransactionScope test was caused by our not having prepared transactions turned on at the server. We then turned on prepared transactions and ran our unit tests again.

3/15/2012: Edits begin:

Here are the log entries from the first test:

Code: Select all

TransactionScope: NO ERROR, data is written
Information,3/14/2012 5:24:35 PM,PostgreSQL,0,None,LOG:  statement: SET TRANSACTION ISOLATION LEVEL SERIALIZABLE
Information,3/14/2012 5:24:35 PM,PostgreSQL,0,None,LOG:  statement: BEGIN
Information,3/14/2012 5:24:35 PM,PostgreSQL,0,None,"LOG:  statement: SET search_path TO ""CarSystem"";
Information,3/14/2012 5:24:36 PM,PostgreSQL,0,None,"LOG:  execute PRSTMT1639816908436919862/PORTAL1639816908436919862: INSERT INTO ""CarSystem"".""Lists""(""ListId"", ""ListName"", ""ListTypeId"", ""DomainId"", ""Geofencing"", ""Salt"", ""WhiteListAlarmClassId"", ""CreatedDate"", i_active, ""ModifyDate"", ""LastUpdate"") VALUES ($1, $2, $3, $4, NULL, NULL, NULL, $5, $6, NULL, NULL)
ETAIL:  parameters: $1 = '8fb84653-f72a-416d-b634-31e4d25c3dae', $2 = 'test', $3 = '1', $4 = '1', $5 = '0001-01-01 00:03:58-04:56:02', $6 = '1'
Information,3/14/2012 5:24:36 PM,PostgreSQL,0,None,LOG:  statement: PREPARE TRANSACTION 'bbdf3449-e299-4252-9755-9def4ef355f7'
Information,3/14/2012 5:24:36 PM,PostgreSQL,0,None,LOG:  statement: COMMIT PREPARED 'bbdf3449-e299-4252-9755-9def4ef355f7'
Information,3/14/2012 5:24:36 PM,PostgreSQL,0,None,LOG:  statement: COMMIT
Warning,3/14/2012 5:24:36 PM,PostgreSQL,0,None,WARNING:  there is no transaction in progress
As you can see, a transaction is started, the insert occurs without error, a prepared tranaction is then begun and committed, and the original transaction committed. Postgres issues a warning, and Devart does not throw an exception.

Here is the log from the DbTransaction test:

Code: Select all

DbTransaction: NO ERROR, data is written
Information,3/14/2012 6:07:02 PM,PostgreSQL,0,None,"LOG:  statement: SET search_path TO ""CarSystem"";
Information,3/14/2012 6:07:02 PM,PostgreSQL,0,None,LOG:  execute PRSTMT1195684527439466064/PORTAL1195684527439466064: BEGIN
Information,3/14/2012 6:07:02 PM,PostgreSQL,0,None,"LOG:  execute PRSTMT1582115622439466376/PORTAL1582115622439466376: INSERT INTO ""CarSystem"".""Lists""(""ListId"", ""ListName"", ""ListTypeId"", ""DomainId"", ""Geofencing"", ""Salt"", ""WhiteListAlarmClassId"", ""CreatedDate"", i_active, ""ModifyDate"", ""LastUpdate"") VALUES ($1, $2, $3, $4, NULL, NULL, NULL, $5, $6, NULL, NULL)
DETAIL:  parameters: $1 = '775ab696-2504-4e82-b4d5-2de6a4a983b0', $2 = 'test', $3 = '1', $4 = '1', $5 = '0001-01-01 00:03:58-04:56:02', $6 = '1'
Information,3/14/2012 6:07:02 PM,PostgreSQL,0,None,LOG:  execute PRSTMT869502152439466407/PORTAL869502152439466407: COMMIT
Information,3/14/2012 6:07:02 PM,PostgreSQL,0,None,LOG:  statement: ROLLBACK
Information,3/14/2012 6:07:02 PM,PostgreSQL,0,None,"LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.
As you can see, in this case a transaction is started, the insert is made, the transaction is committed, and then a ROLLBACK is issues. Postgres then issues the error message, "could not receive data from client: No connection could be made because the target machine actively refused it."

Finally, here is the log from the last test using PgSqlTransaction:

Code: Select all

PgSQLTransaction: Error on commit: Connection must be opened, data is written
Information,3/14/2012 5:29:43 PM,PostgreSQL,0,None,"LOG:  statement: SET search_path TO ""CarSystem"";
Information,3/14/2012 5:29:43 PM,PostgreSQL,0,None,LOG:  execute PRSTMT1172646091437226700/PORTAL1172646091437226700: BEGIN
Information,3/14/2012 5:29:43 PM,PostgreSQL,0,None,LOG:  execute PRSTMT1191317911437226997/PORTAL1191317911437226997: BEGIN
Warning,3/14/2012 5:29:43 PM,PostgreSQL,0,None,WARNING:  there is already a transaction in progress
Information,3/14/2012 5:29:43 PM,PostgreSQL,0,None,"LOG:  execute PRSTMT1584267521437227387/PORTAL1584267521437227387: INSERT INTO ""CarSystem"".""Lists""(""ListId"", ""ListName"", ""ListTypeId"", ""DomainId"", ""Geofencing"", ""Salt"", ""WhiteListAlarmClassId"", ""CreatedDate"", i_active, ""ModifyDate"", ""LastUpdate"")
VALUES ($1, $2, $3, $4, NULL, NULL, NULL, $5, $6, NULL, NULL)
DETAIL:  parameters: $1 = '521d753d-f719-4aca-960d-edec36abbb6f', $2 = 'test', $3 = '1', $4 = '1', $5 = '0001-01-01 00:03:58-04:56:02', $6 = '1'
Information,3/14/2012 5:29:43 PM,PostgreSQL,0,None,LOG:  execute PRSTMT925051539437227418/PORTAL925051539437227418: COMMIT
Information,3/14/2012 5:29:43 PM,PostgreSQL,0,None,LOG:  statement: ROLLBACK
In this case, a transaction is started. The insert is made, and then the transaction is committed. This is followed with a ROLLBACK. On the C# side, we get a PgSqlException with the message reading "Connection must be opened."

It appears that in all cases the data is written to the database.

In the past, we've seen the DbTransaction case return "Connection must be opened" errors, put we were using PgSqlTransactions in some code that accesses the Large Objects table using the PgSqlLargeObject class. We've since removed those inner transactions, but these tests don't exercise that code. We'll have to do more testing.

Edits end;

We then decided to rewrite our software so it would use the TransactionScope, as this seemed to be the only case that would work. There turned out to be another issue with our database that prevented this from working.

It turns out that we have three different tables that have INSERT OR UPDATE triggers on them. The triggers use the Postgres NOTIFY construct to signal another process. The error we get back from the Devart library indicates that the transaction was aborted, which I guess it was, but the error reported by Postgres reads:

Code: Select all

ERROR:  cannot PREPARE a transaction that has executed LISTEN, UNLISTEN or NOTIFY STATEMENT:  PREPARE TRANSACTION '9a171233-8ce3-46de-babc-87ee537d7f0f'
No where was this information to be found except in the event log after we turned on verbose logging on the server.

So our questions for you now are:

1. Is there any way to create a TransactionScope that doesn't use prepared transctions? We don't need prepared transactions, we just need a normal transaction that is going to work and not lose data.

2. Can you fix the error reporting so it's clearer that the problem is that prepared transactions are turned off in that particular case?

Incidentally, it doesn't matter what is in the entity model. The problem is related to transaction handling and not the model itself.

Tony

TonyV
Posts: 74
Joined: Wed 25 May 2011 15:03

Resolved!

Post by TonyV » Wed 21 Mar 2012 20:41

We have figured out what was going on in our application and we want to report our results to you.

First, we were using version 5.50.214.0 of the Devart library. We reviewed the release notes and upgraded to the current release, 5.80.325.0. A number of the issues we were having were apparently fixed between the two releases. The update by itself, however, did not resolve all of our problems.

After extensive testing and watching the server's status console for a couple of days, we figured out a few things:

1. Some of our queries were taking longer than the default timeout interval to execute. In this case, the code in the Devart library would give up and throw an exception, but the server process running the query was left orphaned. That is, it was still running and locking resources.

At that point, our code would restart and end up retrying the same operation again. The orphaned server process still had the resources locked, and would block the second instance. As time went on, the second query would time out. This sequence would repeat many times, and each time the server's performance would get worse and worse until finally we intervened.

To test this for yourself, run the following code against one of your postgres servers:

Code: Select all

try {
    using (CarSystemEntities context = new CarSystemEntities()) {
        if (context.Connection.State != ConnectionState.Open) context.Connection.Open(); 
        //using (DbTransaction tran = context.Connection.BeginTransaction()) {
            context.ExecuteStoreCommand(@"DO LANGUAGE PlPgSql $Outer$ BEGIN LOOP END LOOP; END;$Outer$;");
        //}
    }
} catch (Exception e) {
    Console.WriteLine("Fubar query aborted with exception: " + e);
}
If you wait the 30 seconds for the timeout to occur, and check your server's status console, you'll see that the server fork processing the query is still running even though the entity context is no longer listening for a response.

Another interesting thing we found is that the query apparently waits forever if you try the above code with the using DbTransaction statement uncommented. We didn't wait more than 3 - 5 minutes for this process, so we don't know if it would eventually time out or not.

To fix this problem, we set the context object's CommandTimeout property to 0 and put all of our code into DbTransactions. Now the connetction between entity framework and the server process running the query is never lost.

2. Some of your TransactionScope code is broken. The code below will crash the program:

Code: Select all

try {
    using (CarSystemEntities context = new CarSystemEntities()) {
        if (context.Connection.State != ConnectionState.Open) context.Connection.Open();
        context.ExecuteStoreCommand(@"DO LANGUAGE PlPgSql $Outer$ BEGIN LOOP END LOOP; END;$Outer$;");
    }
} catch { }
We also found a race condition leading to deadlock in our code. This had nothing to do with any problems in your library, but it wasn't helping any. That has been fixed and now the database is running like a well oiled machine.

Tony

Shalex
Site Admin
Posts: 9543
Joined: Thu 14 Aug 2008 12:44

Post by Shalex » Fri 23 Mar 2012 17:33

We have reproduced the issue when server resources are left locked after application has finished its work. We will investigate the issue and notify you about the results.

Shalex
Site Admin
Posts: 9543
Joined: Thu 14 Aug 2008 12:44

Post by Shalex » Tue 27 Mar 2012 14:46

We have reproduced and fixed the bug with generating the "Connection must be opened." error when trying to commit/roll back transaction after expiration of command timeout. We will post here when the corresponding build of dotConnect for PosgreSQL is available for download.
TonyV wrote:Some of our queries were taking longer than the default timeout interval to execute. In this case, the code in the Devart library would give up and throw an exception, but the server process running the query was left orphaned. That is, it was still running and locking resources.
This is a designed behaviour. You should stop your queries yourself:
http://archives.postgresql.org/pgsql-ad ... g00229.php
http://postgresql.1045698.n5.nabble.com ... 24086.html

Shalex
Site Admin
Posts: 9543
Joined: Thu 14 Aug 2008 12:44

Post by Shalex » Thu 29 Mar 2012 16:00

New build of dotConnect for PostgreSQL 5.80.332 is available for download now!
It can be downloaded from http://www.devart.com/dotconnect/postgr ... nload.html (trial version) or from Registered Users' Area (for users with active subscription only).
For more information, please refer to http://www.devart.com/forums/viewtopic.php?t=23777 .

Post Reply