Randomly getting InvalidOperationException: The connection was not closed

[dealdiane]

Seems to happen every now and then for the first few queries after launching an ASPNET5 website. Refreshing the page after crashing almost always sometimes rarely fixes it and I never had an instance where it crashed again after that. I'm using SQL2012. Could this be some sort of race condition?

I'll try my best to replicate the code I have that causes this exception but it's hard to give repro steps because this doesn't happen every time. It does happen about 40% of the time after the website is restarted though.

public class Pet
{
    public int Id { get; set; }
    public string Name { get; set; }
}

public class PagedPetResult
{
    public IAsyncEnumerable<Pet> Pets { get; set; }
    public Task<int> TotalPetCount { get; set; }
}

public PagedPetResult GetPets(int pageIndex, int pageSize)
{
    var pets = db.Set<Pet>()
                .Where(p => p.Id > 0);

    var pagedPets = pets
        .Skip(pageIndex * pageSize)
        .Take(pageSize);

    return new PagedPetResult
    {
        Pets = pagedPets.AsAsyncEnumerable(),
        TotalPetCount = pets.CountAsync()
    }
}

Now when I call GetPets using

var pagedPets = GetPets(0, 20);
var foo = new
{
    Pets = await pagedPets.Pets.ToList(),
    Count = await pagedPets.TotalPetCount,
};

this happens about half of the time. Interestingly, when I change it to:

var pagedPets = GetPets(0, 20);
var pets = await pagedPets.Pets.ToList();
var count = await pagedPets.TotalPetCount;

I haven't had it crash even once. Could be purely coincidental though..

Stack trace:

InvalidOperationException: The connection was not closed. The connection's current state is connecting.
    System.Data.ProviderBase.DbConnectionClosedConnecting.TryOpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
    System.Data.SqlClient.SqlConnection.TryOpenInner(TaskCompletionSource`1 retry)
    System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry)
    System.Data.SqlClient.SqlConnection.OpenAsync(CancellationToken cancellationToken)
    --- End of stack trace from previous location where exception was thrown ---
    System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
    System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
    Microsoft.Data.Entity.Storage.RelationalConnection.<OpenAsync>d__32.MoveNext()
    --- End of stack trace from previous location where exception was thrown ---
    System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
    System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
    Microsoft.Data.Entity.Query.Internal.AsyncQueryingEnumerable.AsyncEnumerator.<MoveNext>d__8.MoveNext()

This might be related to #3887

[dealdiane]

I hope this gets more attention. Our CI and smoke tests fail every now and then because of this problem. I'm attaching a detailed log. Notice how the connection was closed before iterating the results of the last command. Also notice that there are 2 queries there but the connection was only opened once for the first query.

Although this might be a little different than what I first reported, I am almost certain that they're caused by the same problem.

2015-12-02 12:16:34.9098 | Trace | Microsoft.Data.Entity.Storage.Internal.SqlServerConnection | Opening connection 'Server=WEBSERVER\SQL2012,10002;User=;Password=;Database=;MultipleActiveResultSets=True;'. | Trace | 
2015-12-02 12:16:34.9428 | Info | Microsoft.Data.Entity.Storage.Internal.RelationalCommandBuilderFactory | Executed DbCommand (2ms) [Parameters=[@__productId_0='?'], CommandType='Text', CommandTimeout='30']
SELECT [r].[Rating]
FROM [Review] AS [r]
WHERE [r].[ProductId] = @__productId_0 | Info | 
2015-12-02 12:16:34.9428 | Info | Microsoft.Data.Entity.Storage.Internal.RelationalCommandBuilderFactory | Executed DbCommand (2ms) [Parameters=[@__productId_0='?'], CommandType='Text', CommandTimeout='30']
SELECT COUNT(*)
FROM [Review] AS [r]
WHERE [r].[ProductId] = @__productId_0 | Info | 
2015-12-02 12:16:35.0235 | Trace | Microsoft.Data.Entity.Storage.Internal.SqlServerConnection | Closing connection 'Server=WEBSERVER\SQL2012,10002;User=;Password=;Database=;MultipleActiveResultSets=True;'. | Trace | 
2015-12-02 12:16:35.0235 | Info | Microsoft.Data.Entity.Storage.Internal.RelationalCommandBuilderFactory | Executed DbCommand (4ms) [Parameters=[@__productId_0='?', @__Empty_1='?', @__Empty_2='?'], CommandType='Text', CommandTimeout='30']
SELECT COUNT(*)
FROM [Review] AS [r]
WHERE ([r].[ProductId] = @__productId_0) AND ((COALESCE([r].[ReviewText], @__Empty_1) <> @__Empty_2) OR [r].[ReviewText] IS NULL) | Info | 
2015-12-02 12:16:35.1248 | Error | Microsoft.Data.Entity.Query.Internal.QueryCompiler | An exception occurred in the database while iterating the results of a query.
System.InvalidOperationException: Invalid attempt to call Read when reader is closed.
   at System.Data.SqlClient.SqlDataReader.TryReadInternal(Boolean setTimeout, Boolean& more)
   at System.Data.SqlClient.SqlDataReader.Read()
   at Microsoft.Data.Entity.Query.Internal.QueryingEnumerable.Enumerator.MoveNext() in \aspnet\EntityFramework.Relational\Query\Internal\QueryingEnumerable.cs:line 79
   at Microsoft.Data.Entity.Query.QueryMethodProvider.GetResult[TResult](IEnumerable`1 valueBuffers) in \aspnet\EntityFramework.Relational\Query\QueryMethodProvider.cs:line 62
   at lambda_method(Closure , QueryContext )
   at Microsoft.Data.Entity.Query.Internal.QueryCompiler.<>c__DisplayClass18_1`1.<CompileQuery>b__1(QueryContext qc) in \aspnet\EntityFramework.Core\Query\Internal\QueryCompiler.cs:line 153 | System.InvalidOperationException | 
2015-12-02 12:16:35.2335 | Error | Microsoft.AspNet.Diagnostics.DeveloperExceptionPageMiddleware | An unhandled exception has occurred while executing the request
System.InvalidOperationException: Invalid attempt to call Read when reader is closed.
   at System.Data.SqlClient.SqlDataReader.TryReadInternal(Boolean setTimeout, Boolean& more)
   at System.Data.SqlClient.SqlDataReader.Read()
   at Microsoft.Data.Entity.Query.Internal.QueryingEnumerable.Enumerator.MoveNext() in \aspnet\EntityFramework.Relational\Query\Internal\QueryingEnumerable.cs:line 79
   at Microsoft.Data.Entity.Query.QueryMethodProvider.GetResult[TResult](IEnumerable`1 valueBuffers) in \aspnet\EntityFramework.Relational\Query\QueryMethodProvider.cs:line 62
   at lambda_method(Closure , QueryContext )
   at Microsoft.Data.Entity.Query.Internal.QueryCompiler.<>c__DisplayClass18_1`1.<CompileQuery>b__1(QueryContext qc) in \aspnet\EntityFramework.Core\Query\Internal\QueryCompiler.cs:line 164
   at Microsoft.Data.Entity.Query.Internal.QueryCompiler.Execute[TResult](Expression query) in \aspnet\EntityFramework.Core\Query\Internal\QueryCompiler.cs:line 78
   at Microsoft.Data.Entity.Query.Internal.EntityQueryProvider.Execute[TResult](Expression expression) in \aspnet\EntityFramework.Core\Query\Internal\EntityQueryProvider.cs:line 37
   at System.Linq.Queryable.Count[TSource](IQueryable`1 source, Expression`1 predicate)

[rowanmiller]

Hey,

So looking at the original code, you are ending up with two async operations running against the same context at the same time. This is not supported as a DbContext instance is not thread safe. We have #3291 currently being worked on to provide a clear exception message when you do this.

The best rule of thumb to apply is to always await an async operation. Applying that rule, you should await the call to CountAsync in GetPets.

---

Here are some more details about what is causing the exception. This line of code in GetPets is kicking off the first async database operation:

TotalPetCount = pets.CountAsync()

Since the async call is not awaited, the code continues one and then the following line kicks of the second database operation.

Pets = await pagedPets.Pets.ToList(),

Since count is a pretty quick operation, it would be sporadic because sometimes the Count operation will complete before the second operation kicks off.

[rowanmiller]

BTW rather than AsAsyncEnumerable() and then ToList(), it is more common in EF code to just use ToListAsync() (which is an extension method in the System.Data.Entity namespace)

[dealdiane]

Yes, that's what I thought. I know that this has been a limitation of the previous versions of EF. I assumed this is no longer the case in EF7. Thanks for clearing that.

Was using AsAsyncEnumerable() because it is lazy (and because C#7 might support async enumerables thru this interface - so future proofing in another sense too). Do you think there are implications in using this? Also, because this is from a service that is heavily abstracted, we wanted to use interfaces as return types rather than a concrete List<T> type. If this will cause major problems when using EF7 though, then we might triage this and use List<T> because at this stage we are only using EF.

[rowanmiller]

@dealdiane this shouldn't be causing you any issues, it's not awaiting the call to CountAsync that is causing your problem. If you want to actually execute the query in GetPets (like you are for the pet count) then you could just use ToListAync there and use IEnumerable<T> as the property type. Or you could make the type of the property IQueryable<T> and use ToListAsync when you want the results.

[rowanmiller]

Just to be clear... using AsAsyncEnumerable as you are should be fine too though.

[dealdiane]

@rowanmiller Thanks. We'll stick with using AsAsyncEnumerable. As with changing the property type to something of collection type, will need a bit of discussion since IPagedResult is mainly used for geting paged sets. Without this interface means that calls to a method that returns a paged set (GetPets(pageIndex, pageSize)) will need to have a corresponding count method as well. GetPetCount(). The count method is required so we'll know whether there are more entities available and to determine how many pages are there. We have quite a few of these type of method calls so having this interface keeps everything in one block (ToList and Count) and reduces code duplication. The only downside is that I can't use async/await inside a method that returns an IAsyncEnumerable or IPagedResult. That's why I need to do the await in the calling method.

If I always await on the Count task first, then I think this will fix my problem (no?) as creating that Task object would've spun the thread already so calling ToListAsync first would cause exactly what you stated before.

On another note, if we can have OUTPUT parameters thru FromSql though. then I could further reduce the # of queries down to 1 I would assume. #245 (comment)

[rowanmiller]

@dealdiane yep, just await the CountAsync call and you should be fine.