Efcore.pg: 5.0.0: Npgsql.NpgsqlException (0x80004005): Exception while reading from stream

[asadcr]

Hello,
after upgrading to 5.0.0 version, this is the error i get for long queries. Long queries get timeout. Happens only on 5.0.0.
The same queries / codebase works fine with V3.1.2 or when connected with any local sql client to the same database.

The following is the exception
```c#
System.InvalidOperationException
An exception has been raised that is likely due to a transient failure.

System.InvalidOperationException: An exception has been raised that is likely due to a transient failure.
---> Npgsql.NpgsqlException (0x80004005): Exception while reading from stream
---> System.TimeoutException: Timeout during reading attempt
at Npgsql.NpgsqlConnector.g__ReadMessageLong|194_0(NpgsqlConnector connector, Boolean async, DataRowLoadingMode dataRowLoadingMode, Boolean readingNotifications, Boolean isReadingPrependedMessage)
at Npgsql.NpgsqlDataReader.NextResult(Boolean async, Boolean isConsuming, CancellationToken cancellationToken)
at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken)
at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken)
at Npgsql.NpgsqlCommand.ExecuteDbDataReaderAsync(CommandBehavior behavior, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable1.AsyncEnumerator.InitializeReaderAsync(DbContext _, Boolean result, CancellationToken cancellationToken) at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func4 operation, Func4 verifySucceeded, CancellationToken cancellationToken) --- End of inner exception stack trace --- at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func4 operation, Func4 verifySucceeded, CancellationToken cancellationToken) at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable1.AsyncEnumerator.MoveNextAsync()
at Microsoft.EntityFrameworkCore.Query.ShapedQueryCompilingExpressionVisitor.SingleAsyncTSource
```

[roji]

There have been many changes around the timeout logic in Npgsql 5.0.0, so it's possible that some sort of bug slipped in. But it's going to be very difficult for us to do any investigation without some sort of runnable code sample - can you please try to put something together?

[vonzshik]

@roji did 3.1.2 support an async timeout?

[vonzshik]

Also, might be npgsql/npgsql#3379

[roji]

Good catch @vonzshik. @asadcr consider that you may be encountering a genuine case of timeout which was simply not flagged before, because async timeouts weren't implemented.

[asadcr]

@roji Setting a Command Timeout=0 still does not fix the issue. I will try to compile a runnable sample hopefully. if there is something else you would like me to try, that would be helpful.

[vonzshik]

I recommend to test with a 5.0.1 CI version. Pretty sure there was a tutorial somewhere around here. @roji ?

[timbze]

I have this same issue using Dapper with Npgsql, so I think it's not related to efcore. For me it happens when the data set gets too big. I will try to get some logs

Did a downgrade to 3.1 and everything worked

[etiennecl]

I'm currently getting this behaviour inside my integration testing setup using xUnit. I'm using a CustomwebapplicationFactory where I initialize a test database without any data:

builder.ConfigureTestContainer<ContainerBuilder>(containerBuilder =>
{
    containerBuilder.RegisterBuildCallback(c =>
    {
        var dbContext = c.Resolve<DbContext>();
        dbContext.Database.EnsureDeleted();
        dbContext.Database.Migrate();
    });
});

I've then created a test class that uses the CustomWebApplicationFactoryFixture as a collection and a ClassFixture to initialize all the test cases with some initial data:

public class ClassFixture: IAsyncLifetime
{
    public ClassFixture(CustomWebApplicationFactoryFixture fixture)
    {
        Fixture = fixture;
    }

    public CustomWebApplicationFactoryFixture Fixture { get; }

    public async Task InitializeAsync()
    {
        using var scope = Fixture.Services.CreateScope();
        var sp = scope.ServiceProvider;

        var dbContext = sp.GetRequiredService<DbContext>();
        await Seeder.SeedAsync(dbContext); // When calling SaveChanges, it results in a exception while reading from stream
    }

    public Task DisposeAsync()
    {
        return Task.CompletedTask;
    }
}

As a reference both are then used inside my test class like so:

[Collection(CollectionFixture.Name)]
public class TestClass : IClassFixture<ClassFixture>, IDisposable
{
    public CreateEntryGrpcEndpointTest(CollectionFixture fixture, ITestOutputHelper outputHelper)
    {}

    ...
}

Note that I've also tried to modify the Class Fixture to use only sync code as I know there might be an issue with how xUnit handles parralelizm, but without any success.

[timbze]

@etiennecl There is a similar issue here (https://github.com/npgsql/npgsql/issues/3403) that has been fixed in branch, but it's not released as stable yet. You can get it in 5.0.2-ci version here

[etiennecl]

The new version from myget didn't resolve the issue.

[vonzshik]

@etiennecl
1) Could you please provide the exact exception with a stacktrace?
2) Does it fail immediately or it takes some time to fail?
3) Does raising the CommandTimeout property in the connection string helps?

[etiennecl]

1. Here is the stack trace:

System.InvalidOperationException: An exception has been raised that is likely due to a transient failure.

System.InvalidOperationException
An exception has been raised that is likely due to a transient failure.
   at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
   at Clinia.MultiTenant.MultiTenantDbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
   at Clinia.Directory.Infrastructure.Specification.Data.DirectorySpecificationDbContextSeed.SeedAsync(DirectorySpecificationDbContext dbContext, IMultiTenantContextAccessor`1 tenantContextAccessor) in /Users/etienne/Projects/clinia-workspace/client-solution-backend/src/Directory/src/Directory.Infrastructure/Specification/Data/DirectorySpecificationDbContextSeed.cs:line 84
   at Directory.Grpc.IntegrationTest.Entries.CreateEntryGrpcEndpointFixture.InitializeAsync() in /Users/etienne/Projects/clinia-workspace/client-solution-backend/src/Directory/test/Directory.Grpc.IntegrationTest/Entries/CreateEntryGrpcEndpointFixture.cs:line 31
   at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in C:\Dev\xunit\xunit\src\xunit.core\Sdk\ExceptionAggregator.cs:line 90

Npgsql.NpgsqlException
Exception while reading from stream
   at Npgsql.NpgsqlReadBuffer.<Ensure>g__EnsureLong|40_0(NpgsqlReadBuffer buffer, Int32 count, Boolean async, Boolean readingNotifications)
   at Npgsql.NpgsqlConnector.<ReadMessage>g__ReadMessageLong|194_0(NpgsqlConnector connector, Boolean async, DataRowLoadingMode dataRowLoadingMode, Boolean readingNotifications, Boolean isReadingPrependedMessage)
   at Npgsql.NpgsqlConnector.ExecuteInternalCommand(Byte[] data, Boolean async, CancellationToken cancellationToken)
   at Npgsql.NpgsqlConnector.Rollback(Boolean async, CancellationToken cancellationToken)
   at Npgsql.NpgsqlTransaction.<DisposeAsync>g__DisposeAsyncInternal|30_0()
   at Microsoft.EntityFrameworkCore.Storage.RelationalTransaction.DisposeAsync()
   at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(IList`1 entriesToSave, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(DbContext _, Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
   at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)

System.TimeoutException
Timeout during reading attempt
  Exception doesn't have a stacktrace

1. It take some time to fail
2. Changes nothing

[PatrikBak]

I've been having the same problem. Any query that transfers a larger amount of data fails at random and quite often. The only thing that helped me was a downgrade to 3.1.4.

[etiennecl]

This is unfortunate as we rely on the new many-many capabilities of ef core 5.0

[etiennecl]

@vonzshik I've managed to debug this a bit further and it appears the real exception is happening inside the BatchExecutor claiming that there is not enough space left on the buffer when using JsonHandler.

Microsoft.EntityFrameworkCore.DbUpdateException: An error occurred while updating the entries. See the inner exception for details.
 ---> System.InvalidOperationException: There is not enough space left in the buffer.
   at Npgsql.NpgsqlWriteBuffer.ThrowNotSpaceLeft()
   at Npgsql.TypeHandlers.JsonHandler.WriteWithLength[TAny](TAny value, NpgsqlWriteBuffer buf, NpgsqlLengthCache lengthCache, NpgsqlParameter parameter, Boolean async, CancellationToken cancellationToken)
   at Npgsql.NpgsqlConnector.WriteBind(List`1 inputParameters, String portal, String statement, Boolean allResultTypesAreUnknown, Boolean[] unknownResultTypeList, Boolean async, CancellationToken cancellationToken)
   at Npgsql.NpgsqlCommand.<>c__DisplayClass86_0.<<Write>g__WriteExecute|0>d.MoveNext()
--- End of stack trace from previous location ---
   at Npgsql.NpgsqlCommand.<ExecuteReader>g__NonMultiplexingWriteWrapper|105_0(NpgsqlConnector connector, Boolean async, CancellationToken cancellationToken2)
   at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken)
   at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken)
   at Npgsql.NpgsqlCommand.ExecuteDbDataReaderAsync(CommandBehavior behavior, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)

using version 5.0.2-ci.20210117T173439

---

Inside the batch executor inside the finally block it then tries to dispose the transaction, which gives a timeout exception:

finally
{
    if (beganTransaction)
    {
        await transaction.DisposeAsync().ConfigureAwait(false); // here
    }
}

[vonzshik]

@etiennecl are you using Npgsql.Json.NET plugin?

[etiennecl]

yes!

[vonzshik]

In this case, good news: I've been able to repeat this error.

public class BugClass
{
    public string? SomeString { get; set; }
}

[Test]
public void Bug1599()
{
    var expected = new BugClass { SomeString = new string('5', 8174) };
    using (var conn = OpenConnection())
    using (var cmd = new NpgsqlCommand(@"SELECT @p1, @p2", conn))
    {
        conn.TypeMapper.UseJsonNet(new[] { typeof(BugClass) });

        cmd.Parameters.AddWithValue("p1", expected);
        cmd.Parameters.AddWithValue("p2", expected);
        using (var reader = cmd.ExecuteReader()) { }
    }
}

Right now, @YohDeadfall is taking a look.

[roji]

@YohDeadfall this should be closed as a duplicate of https://github.com/npgsql/npgsql/issues/3464 right?

[YohDeadfall]

@etiennecl's problem was moved to the new issue, but it's hard to say what was here. Let's wait a week for @asadcr and close the issue in case of no response. Otherwise, we can close it right now and reopen later.