What is the cause of the "Stream already closed" message?

TonyV · Post by **TonyV** » Mon 26 Mar 2012 14:04

Our software is running on several devices in the field as part of our beta testing efforts. Everything is going very well, but a couple of the devices have generated the following error:

Code: Select all

2012-03-24 13:23:18,007 [45] FATAL LPRCore.Service [(null)] - UNHANDLED (Fatal): System.Data.EntityException: The underlying provider failed on Open. ---> Devart.Data.PostgreSql.PgSqlException: Stream already closed!!!

This is all the information we have right now. We don't know where the error is occurring in our code. The error is occurring in the one thread where we did not put any error handling, so it is killing our service process, which gets restarted automatically by Windows. We have added error handling to the thread so we'll be able to get more information should it happen again.

In the meantime, I can't find any documentation on this error message. My Google searches bring back results concerning the Oracle JDBC drivers, which don't apply.

What will cause this error to be generated?

Tony

Pinturiccio · Post by **Pinturiccio** » Mon 02 Apr 2012 13:23

The "Stream already closed!!!" exception can occur when using one connection in several threads. PgSqlConnection is not thread safe, so connection can be closed in one thread when it is used in another one.

TonyV · Post by **TonyV** » Mon 02 Apr 2012 13:48

We are not using the same PgSqlConnection object in multiple threads.

We are using Entity Framework 4. We create a new Entity Context object, open the connection, process, then close the context object in each operation. We do not keep a reference to a PgSqlConnection anywhere in our code.

We are using connection pooling, though. The error does go away if we turn off connection pooling, but this has a huge performance impact.

Is it possible for us to get this error message if a thread is using a connection from the pool and it performs an operation that takes longer to complete than the timeout is set to? Imagine this scenario:

1. A connection is taken from the pool. Call it "connection X".
2. A long running operation is started.
3. The command associated with the operation times out.
4. The context object is closed.
5. Connection X is returned to the connection pool.
6. Some time later another operation starts. This thread may or may not be in another thread.
7. This second operation ends up taking connection X from the pool.
8. The second operation starts some operation.

Would this cause the exception we are seeing?

Tony

Shalex · Post by **Shalex** » Tue 03 Apr 2012 14:50

1. Please make sure that the version of your dotConnect for PostgreSQL is 5.50.244 or higher because the bug with returning invalid connections to pool was fixed in 5.50.244 (revision history).
2. Try using the "Validate Connection=true;" connection string parameter.
3. If this doesn't help, try to localize the issue and send us a small test project with the corresponding DDL/DML script to reproduce the issue in our environment. Also specify your current version (x.xx.xxx) of dotConnect for PostgreSQL.

TonyV · Post by **TonyV** » Tue 03 Apr 2012 14:56

We are using the latest build, version 5.80.325.

We will try the Validate Connection=true connection string parameter and get back to you.

Incidentally, what happens if you have this property set to true and the connection is invalid?

Tony

Shalex · Post by **Shalex** » Wed 04 Apr 2012 15:04

Incidentally, what happens if you have this property set to true and the connection is invalid?

A new connection is created instead of using the one from pool.

TonyV · Post by **TonyV** » Thu 05 Apr 2012 13:14

We added the Validate Connection=true parameter to one of our beta sites that is having a really bad time of it and it made no difference.

We are checking to see if the database might be badly fragmented, which we think might be the cause.

TOny

Shalex · Post by **Shalex** » Fri 06 Apr 2012 11:37

TonyV wrote:We added the Validate Connection=true parameter to one of our beta sites that is having a really bad time of it and it made no difference.

Are you still getting "Stream already closed!!!" with "Validate Connection=true;"? Or there is no error but low performance?

TonyV · Post by **TonyV** » Fri 06 Apr 2012 16:55

We are still getting the "Stream already closed!!" message. We get it about every 30 seconds, give or take 20.

I have run VACUUM FULL ANALYZE on the database on my own development system and performance increased markedly when I did. I'm not getting the "Stream already closed!!!" message on my workstation, but we suspect that might be the cause.

We'll have more information next week. Our office is closed today (Good Friday).

Tony

Shalex · Post by **Shalex** » Mon 09 Apr 2012 11:56

TonyV wrote:We are still getting the "Stream already closed!!" message. We get it about every 30 seconds

30 seconds is a default value for the command timeout. If the problem comes back, try using the "Default Command Timeout=0;" (no time limit) connection string parameter.

TonyV wrote:I have run VACUUM FULL ANALYZE... I'm not getting the "Stream already closed!!!" message

We are glad to hear that the issue is solved.

TonyV · Post by **TonyV** » Thu 12 Apr 2012 14:23

Shalex:

Unfortunately, while the error is not occurring normally on my workstation, it is still happening on other machines. And we have devised a very simple test that can reliably reproduce the problem within a few minutes. And whatever the issue is, it has nothing to do with transactions or Entity Framework.

1. Set up a Unit Test with the following code:

Code: Select all

[TestCategory( "PubSubBufferPostrgres" ), TestMethod, Timeout( 600000 )]
public void TestPostgresPgSqlConnection() {
    while ( true ) {
        try {
            using ( PgSqlConnection connection = new PgSqlConnection( "User Id=CarSystem;Password=ELSAGelsag;Host=localhost;Database=CarSystem;Schema=security" ) ) {
                connection.Open();
            }
        } catch ( Exception e ) {
            if ( e.Message != "Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host." &&
                 e.Message != "Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host." &&
                 e.Message != "No connection could be made because the target machine actively refused it 127.0.0.1:5432" &&
                 e.Message != "the database system is starting up" &&
                 e.Message != "the database system is shutting down" &&
                 e.Message != "Transport channel is closed." )
                Console.WriteLine( "Crash!" );
        }
    }
}

2. Place a breakpoint on the line that outputs "Crash!" to the console.

3. Start the unit test running.

4. Make sure the test is running long enough for a connection to be added to the connection pool. You can do this by waiting for a minute after the test begins. Note that the problem will not occur at this point, no matter how long you wait.

5. Here's the step that will cause the problem to happen. Go into Control Panel, Windows Services, and stop the Postgres server. Wait a few seconds and restart it.

6. Within 10 minutes of restarting the server, you should hit the breakpoint.

At this point, if you were to run the unit test continuously, you will continue to get the error. The error is not generated on each iteration of the loop. And you will note that there is nothing multithreaded about this test.

We are not saying that the cause of the problem is that the Postgres server is going down and restarting on its own. Note that we are trapping the errors that are generated when the server does go down in our system and we know that the it's not going down in the field. It's some sort of issue with faulty connections in the connection pool. We don't know what's going on inside of the server or your code. We do know that this method will reliably produce the error within a very short time.

We are aiming for a June 15 release, and we really need this issue to be resolved. Whatever is causing the problem happens regularly on the test machines we have in the field and is causing them to be extremely unreliable. We can't release with the software this unreliable.

Tony

Shalex · Post by **Shalex** » Fri 13 Apr 2012 16:11

Thank you for your sample. We have reproduced the issue and are investigating it.

Shalex · Post by **Shalex** » Wed 18 Apr 2012 10:30

The bug with generating the "Stream already closed!!!" error when retrieving invalid connection from the pool is fixed. We will post here when the corresponding build of dotConnect for PostgreSQL is available for download.

TonyV · Post by **TonyV** » Wed 18 Apr 2012 12:32

Thank you! We look forward to hearing of the release.

Do you know what version of the software this bug was introduced in?

Will you be able to release the software sometime soon? Is there any way we can get a prerelease version to test the fix? We are hitting a hard deadline of a code freeze on May 15 and we have to have this fixed before that date.

Thanks

Tony

Shalex · Post by **Shalex** » Thu 19 Apr 2012 13:00

TonyV wrote:Do you know what version of the software this bug was introduced in?

We have not tested previous versions.

TonyV wrote:Will you be able to release the software sometime soon?

We are planning to release the next public build of dotConnect for PostgreSQL next week. If this timeframe suitable for you?