NullReferenceException in Npgsql.NpgsqlConnector.StartUserAction

[sampalmer]

Background

Since upgrading from Npgsql 2 to Npgsql 3, I started getting EndOfStreamExceptions every now and then:

Message:
Name: EndOfStreamException
Message: Attempted to read past the end of the stream.
Source: Npgsql

Properties:
TargetSite = Void Ensure(Int32)
HResult = -2147024858

Stack Trace:
   at Npgsql.NpgsqlBuffer.Ensure(Int32 count)
   at Npgsql.NpgsqlConnector.DoReadSingleMessage(DataRowLoadingMode dataRowLoadingMode, Boolean returnNullForAsyncMessage, Boolean isPrependedMessage)
   at Npgsql.NpgsqlConnector.ReadSingleMessage(DataRowLoadingMode dataRowLoadingMode, Boolean returnNullForAsyncMessage)
   at Npgsql.NpgsqlCommand.Execute(CommandBehavior behavior)
   at Npgsql.NpgsqlCommand.ExecuteDbDataReaderInternal(CommandBehavior behavior)

• It seems to happen if I don't do anything in the application (no PostgreSQL activity) but then come back and do something (triggering a new PostgreSQL query) after maybe 15 or 20 minutes.
• This happens when I run cmd.ExecuteReader().
• The connection string looks like Server=REMOVED;Port=REMOVED;User Id=REMOVED;Password=REMOVED;Database=REMOVED;SSL Mode=Require;
• Running SELECT VERSION() produces PostgreSQL 9.3.10 on x86_64-unknown-linux-gnu, compiled by gcc (Ubuntu 4.8.2-19ubuntu1) 4.8.2, 64-bit.
• The problem didn't seem to happen in Npgsql 2.1.2 or 2.2.7 when I tested, but it did happen in 3.0.0, 3.0.5 and 3.1.0-alpha6.

Similarly, when I use pgAdmin III to connect to the same database, it produces an EOF (end-of-file) error if I haven't done anything with the connection for about 15 minutes. So I believe this problem is caused by some sort of connection timeout (15 minutes) between my computer and the database server.

Not sure why the problem only started happening in Npgsql 3. My DB commands and queries don't run for 15 minutes, so maybe it's because of connection pooling behaviour in Npgsql 3?

I worked around this in Npgsql 3 by enabling a 10-minute keep-alive in the connection string (Keepalive=600). So far so good.

NullReferenceException

Since applying the Keepalive workaround shown above, things have been mostly fine. However, I once ran into the following exception using Npgsql 3.0.5 after not doing anything in the application for a while again:

Name: NullReferenceException
Message: Object reference not set to an instance of an object.
Source: Npgsql

Properties:
TargetSite = System.IDisposable StartUserAction(Npgsql.ConnectorState)
HResult = -2147467261

Stack Trace:
   at Npgsql.NpgsqlConnector.StartUserAction(ConnectorState newState)
   at Npgsql.NpgsqlCommand.ExecuteDbDataReaderInternal(CommandBehavior behavior)

I haven't been able to reproduce it again. I'm guessing this could be an Npgsql bug since NullReferenceException isn't really meaningful to users of the library.

[roji]

Sorry for taking so long to respond to this.

I've looked hard at the code and it seems that it's possible for StartUserAction to throw a NullReferenceException when a subtle race condition occurs: if a keepalive request fails for some reason (broken connection), it cleans up connector state, setting many fields to null. If the user happens to start some operation at precisely that point, the locks may have already been set to null as StartUserAction is trying to take them.

This would be quite a rare issue, requiring very precise timing - but it's there and needs to be fixed.

[sampalmer]

No problem!

I don't recall experiencing this issue any more since I created this issue, so the Keepalive workaround I'm using seems good enough for the time being.

[roji]

@sampalmer you may want to look into what's requiring you to have keepalive - are you connecting through pgbouncer or some other proxy which closes idle connections? Is it some sort of networking issue? AFAIK in a regular setup you're not supposed to need a keepalive.

[sampalmer]

@roji, it would be good to get to the bottom of it, but unfortunately I don't have the time! The database server is hosted externally, so there are probably a bunch of different things that could be going wrong between my end and it.

Thanks for your help, though.

[roji]

OK, I've done a pretty serious concurrency pass and fixed quite a few edge cases, this should be gone now.

[treyhard]

Hi @roji, this problem still occurred in 4.0.2 version.
Could you take a look at that one more time?
I am using keepalive parameter set to 60, and a lot of threads which every has a different session of course.

System.NullReferenceException: Object reference not set to an instance of an object.
at Npgsql.NpgsqlConnector.StartUserAction(ConnectorState newState, NpgsqlCommand command)
at Npgsql.NpgsqlCommand.d__100.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Npgsql.NpgsqlCommand.d__92.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Npgsql.NpgsqlCommand.ExecuteNonQuery()

I disabled keepalive parameter and right now there is no problems with that, I hope so that it will help you to find that problem.

[roji]

@treyhard can you please open a new issue for this? I think it may still be possible for this to happen if a user command starts executing exactly as a keepalive encountered a an error (e.g. connection broken). However, in this case you Npgsql should be outputting log messages to let you know about it, can you please confirm whether you have enabled logging and can see these messages?

[treyhard]

@roji I opened an new issue. Right now I cannot swith keepalive parameter because system has to be stable. If I will have that chance I will do that and if I will get a better message I will add it to a new issue that I created: #2367