[.NET 6 Preview 4] Command is already in progress error in Npgsql library

@dotnet-actwx-bot

Application Name: ComforDev
OS: Windows 10 RS5
CPU: X64
.NET Build Number: 6.0.100-preview.4.21226.5

Verify Scenarios:
1). Windows 10 RS5 X64 + 6.0.100-preview.5.21222.19 - main branch: PASS
2). Windows 10 RS5 X64 + 6.0.100-preview.4.21226.5 - Preview 4 branch: Fail

Repro steps & source: Check at https://devdiv.visualstudio.com/DevDiv/_workitems/edit/1319505

Repro steps:
1)Restore DB by psql -d ComfortDev -U postgres -f ComfortDevdb.sql
2 Start Api by dotnet ComfortDevApp\API\ComfortDev.API.dll
3) Start Client Console app to connect to API by : running ComfortDevApp\Client\ConsoleApp1.exe

Expected Result:
It should return db table record number

Actual Result:

Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware[1]
      An unhandled exception has occurred while executing the request.
      Npgsql.NpgsqlOperationInProgressException: A command is already in progress: SELECT t.id, t.question
      FROM test_questions AS t
         at Npgsql.NpgsqlConnector.<StartUserAction>g__DoStartUserAction|187_0(<>c__DisplayClass187_0& ) in Npgsql.dll:token 0x6000443+0x4c
         at Npgsql.NpgsqlConnector.StartUserAction(ConnectorState newState, NpgsqlCommand command) in Npgsql.dll:token 0x6000417+0x20
         at Npgsql.NpgsqlCommand.ExecuteReaderAsync(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken) in Npgsql.dll:token 0x60002a7+0x11
         at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior) in Npgsql.dll:token 0x60002a4+0x16
         at Npgsql.NpgsqlCommand.ExecuteDbDataReader(CommandBehavior behavior) in Npgsql.dll:token 0x60002a1+0x0
         at System.Data.Common.DbCommand.ExecuteReader() in System.Data.Common.dll:token 0x60015c6+0x0
         at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReader(RelationalCommandParameterObject parameterObject) in Microsoft.EntityFrameworkCore.Relational.dll:token 0x6000304+0x7a
         at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.Enumerator.InitializeReader(DbContext _, Boolean result) in Microsoft.EntityFrameworkCore.Relational.dll:token 0x6001121+0x50
         at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded) in Npgsql.EntityFrameworkCore.PostgreSQL.dll:token 0x60001de+0x0
         at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.Enumerator.MoveNext() in Microsoft.EntityFrameworkCore.Relational.dll:token 0x6001120+0x4a
         at Microsoft.EntityFrameworkCore.EntityFrameworkQueryableExtensions.Load[TSource](IQueryable`1 source) in Microsoft.EntityFrameworkCore.dll:token 0x6000203+0x13
         at Microsoft.EntityFrameworkCore.Internal.EntityFinder`1.Load(INavigation navigation, InternalEntityEntry entry) in Microsoft.EntityFrameworkCore.dll:token 0x6001326+0x2f
         at Microsoft.EntityFrameworkCore.ChangeTracking.NavigationEntry.Load() in Microsoft.EntityFrameworkCore.dll:token 0x6001724+0x8
         at Microsoft.EntityFrameworkCore.ChangeTracking.CollectionEntry.Load() in Microsoft.EntityFrameworkCore.dll:token 0x60016a9+0x6
         at Microsoft.EntityFrameworkCore.Internal.LazyLoader.Load(Object entity, String navigationName) in Microsoft.EntityFrameworkCore.dll:token 0x60013b2+0x24
         at Microsoft.EntityFrameworkCore.Proxies.Internal.LazyLoadingInterceptor.Intercept(IInvocation invocation) in Microsoft.EntityFrameworkCore.Proxies.dll:token 0x60000a3+0x7d
         at Castle.DynamicProxy.AbstractInvocation.Proceed() in Castle.Core.dll:token 0x600001c+0x50
         at Castle.Proxies.TestQuestionProxy.get_TestAnswers() in RefEmit_InMemoryManifestModule:token 0x6000051+0x24
         at System.Text.Json.Serialization.Metadata.JsonPropertyInfo`1.GetMemberAndWriteJson(Object obj, WriteStack& state, Utf8JsonWriter writer) in System.Text.Json.dll:token 0x60007b7+0x0
         at System.Text.Json.Serialization.Converters.ObjectDefaultConverter`1.OnTryWrite(Utf8JsonWriter writer, T value, JsonSerializerOptions options, WriteStack& state) in System.Text.Json.dll:token 0x60008d8+0x199
         at System.Text.Json.Serialization.JsonConverter`1.TryWrite(Utf8JsonWriter writer, T& value, JsonSerializerOptions options, WriteStack& state) in System.Text.Json.dll:token 0x60006f6+0x206
         at System.Text.Json.Serialization.Converters.IAsyncEnumerableOfTConverter`2.OnWriteResume(Utf8JsonWriter writer, TAsyncEnumerable value, JsonSerializerOptions options, WriteStack& state) in System.Text.Json.dll:token 0x600084c+0xb4
         at System.Text.Json.Serialization.Converters.IEnumerableDefaultConverter`2.OnTryWrite(Utf8JsonWriter writer, TCollection value, JsonSerializerOptions options, WriteStack& state) in System.Text.Json.dll:token 0x600087a+0x86
         at System.Text.Json.Serialization.Converters.IAsyncEnumerableOfTConverter`2.OnTryWrite(Utf8JsonWriter writer, TAsyncEnumerable value, JsonSerializerOptions options, WriteStack& state) in System.Text.Json.dll:token 0x600084b+0x14
         at System.Text.Json.Serialization.JsonConverter`1.TryWrite(Utf8JsonWriter writer, T& value, JsonSerializerOptions options, WriteStack& state) in System.Text.Json.dll:token 0x60006f6+0x206
         at System.Text.Json.Serialization.JsonConverter`1.WriteCore(Utf8JsonWriter writer, T& value, JsonSerializerOptions options, WriteStack& state) in System.Text.Json.dll:token 0x60006e1+0x0
         at System.Text.Json.Serialization.JsonConverter`1.WriteCoreAsObject(Utf8JsonWriter writer, Object value, JsonSerializerOptions options, WriteStack& state) in System.Text.Json.dll:token 0x60006e0+0x49
         at System.Text.Json.JsonSerializer.WriteCore[TValue](JsonConverter jsonConverter, Utf8JsonWriter writer, TValue& value, JsonSerializerOptions options, WriteStack& state) in System.Text.Json.dll:token 0x600035a+0x18
         at System.Text.Json.JsonSerializer.WriteAsyncCore[TValue](Stream utf8Json, TValue value, JsonTypeInfo jsonTypeInfo, CancellationToken cancellationToken) in System.Text.Json.dll:token 0x6000364+0xd4
         at System.Text.Json.JsonSerializer.WriteAsyncCore[TValue](Stream utf8Json, TValue value, JsonTypeInfo jsonTypeInfo, CancellationToken cancellationToken) in System.Text.Json.dll:token 0x6000364+0x1b5
         at System.Text.Json.JsonSerializer.WriteAsyncCore[TValue](Stream utf8Json, TValue value, JsonTypeInfo jsonTypeInfo, CancellationToken cancellationToken) in System.Text.Json.dll:token 0x6000364+0x38b
         at Microsoft.AspNetCore.Mvc.Formatters.SystemTextJsonOutputFormatter.WriteResponseBodyAsync(OutputFormatterWriteContext context, Encoding selectedEncoding) in Microsoft.AspNetCore.Mvc.Core.dll:token 0x6000b07+0x132
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResultFilterAsync>g__Awaited|30_0[TFilter,TFilterAsync](ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted) in Microsoft.AspNetCore.Mvc.Core.dll:token 0x6000a83+0x6a
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResultExecutedContextSealed context) in Microsoft.AspNetCore.Mvc.Core.dll:token 0x6000a76+0x15
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.ResultNext[TFilter,TFilterAsync](State& next, Scope& scope, Object& state, Boolean& isCompleted) in Microsoft.AspNetCore.Mvc.Core.dll:token 0x6000a71+0x3dc
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeResultFilters>g__Awaited|28_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted) in Microsoft.AspNetCore.Mvc.Core.dll:token 0x6000a82+0x6e
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|20_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted) in Microsoft.AspNetCore.Mvc.Core.dll:token 0x6000a7b+0x65
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker) in Microsoft.AspNetCore.Mvc.Core.dll:token 0x6000a78+0x172
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker) in Microsoft.AspNetCore.Mvc.Core.dll:token 0x6000a78+0x21d
         at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger) in Microsoft.AspNetCore.Routing.dll:token 0x60000aa+0x5e
         at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context) in Microsoft.AspNetCore.Authorization.Policy.dll:token 0x600000b+0x16b
         at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context) in Microsoft.AspNetCore.Authentication.dll:token 0x6000044+0x384
         at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.Invoke(HttpContext context) in Microsoft.AspNetCore.Diagnostics.dll:token 0x60000aa+0x82
warn: Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware[2]
      The response has already started, the error page middleware will not be executed.

Findings :
This issue occurs when UseLazyLoadingProxies is enabled.
We couldn't repro this issue when using Sql Server, this could only be in postgres.

In Api, we are trying to get data from a table and also its related data with LazyLoading enabled ,

   public IEnumerable<TestQuestion> GetTest()

        {
            return database.TestQuestions.GetAll();
        }

In Client Side , we call API :

private static async Task<IEnumerable<Question>> GetDataAsnyc()

{
try
{
using var client = new HttpClient();
var streamTask = client.GetStreamAsync("https://localhost:5001/api/test");
var serializer = new DataContractJsonSerializer(typeof(IEnumerable<Question>));
var questions = serializer.ReadObject(await streamTask) as IEnumerable<Question>;
return questions;
}
catch (Exception ex)
{
   return null;
}
}

@dotnet-actwx-bot @dotnet/compat

@ajcvickers

@ajcvickers Could you please help to take a look on this to see if this belongs to system.data?

@jiangzeng01

@jiangzeng01 I wasn't able to reproduce the error with the repro, with the following steps:

Copy the application source to a local drive (from ComforDev2\ComfortDev)
Create a blank database and apply ComfortDevdb.sql to it (from ComfortDevApp\DB)
Modify ComfortDev.Common\Secret.cs to make the connection string point to the populated database
Install .NET SDK 6.0.100-preview.4.21226.5 with dotnet-install.ps1
Execute dotnet run under ComfortDev\ComfortDev.API
Access https://localhost:5001/api/test with the browser (note that the source code for the client applicaiton does seem to be provided above, so I just accessed the API directly)

Result: I get a proper JSON response with all the data.

Note that the error you're seeing - a command is already in progress - is quite common, and especially when using lazy loading. The following snippet demonstrates it well:

foreach (var blog in context.Blogs)
{
    foreach (var post in blog.Posts)
    {
        Console.WriteLine(post.Name);     
    }
}

In this code snippet, a command is started to fetch all the blogs. Then, before that command completes, another command is started to fetch the posts for a given blog, but two commands aren't allowed concurrently in Npgsql. This code will work on SQL Server if MARS is enabled on your connection string, which could explain why your code works on SQL Server but not on PostgreSQL. A possible workaround is to add .ToList() after context.Blogs - this makes EF Core load all blogs into memory and close the first command before proceeding to load posts.

Other unrelated comments:

The API project currently targets netcoreapp3.0, which has reached its end of life, and is not supported. It's strongly recommended to upgrade to at least netcoreapp3.1.
Having a Secrets.cs file is extremely problematic from a security point of view, and can very easily lead to secret leak. You probably want to look at better secret management (this can be a good starting point).

One additional note - the Npgsql EF Core provider is managed in this repo, while the ADO.NET provider is managed in this one. Neither are part of System.Data.

@roji

@roji I'm from AppCompat team and doing third-party apps runtime combability validation with .NET 6 Preview 4 now.
We are running .NET Core 2.x/3.x/5.0/6.0 apps against .NET 6 Preview 4 latest SDK to find Runtime Compatibility issues.

According to your steps, I think you have lower versions of SDK (like .NET Core 3.1 or .NET 5.0) installed in the machine, so if you do "dotnet run", app won't run on .NET 6 because it is targeting .NET Core 3.0.

I think you can first do "dotnet build" under ComfortDev\ComfortDev.API and update the file ComfortDev.API.runtimeconfig under bin folder by changing "runtimeOptions" version to "6.0.0-preview.4.21222.16", then go to bin folder and "dotnet ComfortDev.API.dll". It will repro.

Steps would be:

1. Copy the application source to a local drive (from ComforDev2\ComfortDev)
2. Create a blank database and apply ComfortDevdb.sql to it (from ComfortDevApp\DB)
3. Modify ComfortDev.Common\Secret.cs to make the connection string point to the populated database
4. Install .NET SDK 6.0.100-preview.4.21226.5 with dotnet-install.ps1
5. "dotnet build" under ComfortDev\ComfortDev.API and update the file ComfortDev.API.runtimeconfig under bin folder by changing "runtimeOptions" version to "6.0.0-preview.4.21222.16", then go to bin folder and "dotnet ComfortDev.API.dll"
6. Access https://localhost:5001/api/test with the browser (note that the source code for the client applicaiton does seem to be provided above, so I just accessed the API directly)

This issue does not happen in main branch SDKs, but fails with Preview 4 branch SDKs. So something should be changed in Preview 4 to make it fail.

@jiangzeng01

Thanks for the tip @jiangzeng01, I can indeed repro this now (switching the TFM to net6.0 also works). Thanks also for providing the context, I mistakenly thought this was an actual user app.

It seems like when serializing the resulting IEnumerable<TestQuestion> into JSON, the JSON serialization walks the object graph, and triggers lazy loading to load the related entities; see the minimal console app below which shows this happening outside of ASP.NET. What I'm not sure about, is exactly how this is working before (or after) preview4 - unless the JSON serializer consumes and buffers all results before starting to look at references to other objects, it would be fundamentally incompatible with lazy loading.

In any case, some sort of change either in System.Text.Json or in how ASP.NET Core uses it should explain this. Before digging too deeply, @davidfowl @ajcvickers does this ring any bells?

Minimal error demo with lazy loading

await using (var ctx = new BlogContext())
{
    await ctx.Database.EnsureDeletedAsync();
    await ctx.Database.EnsureCreatedAsync();

    ctx.Blogs.Add(new()
    {
        Name = "Blog1",
        Posts = new()
        {
            new() { Title = "Post1" },
            new() { Title = "Post2" }
        }
    });
    await ctx.SaveChangesAsync();
}

await using (var ctx = new BlogContext())
{
    await JsonSerializer.SerializeAsync(new MemoryStream(), ctx.Blogs);
}

public class BlogContext : DbContext
{
    public DbSet<Blog> Blogs { get; set; }

    static ILoggerFactory ContextLoggerFactory
        => LoggerFactory.Create(b => b.AddConsole().AddFilter("", LogLevel.Information));

    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
        => optionsBuilder
            .UseSqlServer(@"Server=localhost;Database=test;User=SA;Password=Abcd5678;Connect Timeout=60;ConnectRetryCount=0")
            // .UseNpgsql(@"Host=localhost;Username=test;Password=test")
            .UseLazyLoadingProxies()
            .EnableSensitiveDataLogging()
            .UseLoggerFactory(ContextLoggerFactory);
}

public class Blog
{
    public int Id { get; set; }
    public string Name { get; set; }
    public virtual List<Post> Posts { get; set; }
}

public class Post
{
    public int Id { get; set; }
    public string Title { get; set; }
    [JsonIgnore]
    public virtual Blog Blog { get; set; }
}

@roji

The repro code that @roji posted above fails for me targeting .NET 5 with EF Core 5. I can't see a way it could ever have behaved differently.

@ajcvickers

@ajcvickers yeah - the minimal code snippet I posted fails for me too, regardless of .NET version. However, the original repro with ASP.NET does work (except on preview4), although it seems like it should fail in the same way...

@mkArtakMSFT

Some ideas. If the list is materialized before streaming, then this works*:

await using (var ctx = new BlogContext())
{
    var blogs = ctx.Blogs.ToList();
    await JsonSerializer.SerializeAsync(new MemoryStream(), blogs);
}

This is because now the lazy loading query is not interleaved with the regular query. So if something has changed in ASP.NET that would cause the query to be streaming now, when before it was pre-executed, then this could account for the behavior change.

@mkArtakMSFT Any ideas?

*When I said "works" before, I should point how that it still doesn't do what it should do, because serialization of a lazy-loading graph is a fundamentally flawed thing to do since can cause lots of additional queries to the database and a massive payload with lots of additional data loaded.

@pranavkm

@pranavkm this might be the IAsyncEnumerable<T> changes that went into MVC.

@pranavkm

Thanks all for you investigation and updates!
@pranavkm We are in Preview 4 release validation now, and sign off date is before noon of 4/29. Can you help to check and see if it is a blocking issue for Preview 4?

@eiriktsarpalis

Actually it's likely this change dotnet/runtime#50778

cc @eiriktsarpalis

@davidfowl

@davidfowl @pranavkm We just tried with latest main branch sdk, it also fails now.
Now it fails on both Preview 4 branch & main branch.

6.0.100-preview.5.21222.19 (main branch build 2 days ago) - PASS
6.0.100-preview.5.21228.11 (latest main branch) - FAIL

@eiriktsarpalis

@eiriktsarpalis off the top of my hand, I'm not sure why a switch from serializing IEnumerable to IAsyncEnumerable would be important here; when lazy loading is enabled, both modes would cause additional queries to be sent when internal properties are accessed, while the main enumeration is still active (so multiple commands on the same connection at the same time, which isn't allowed).

Any chance you could take a look at the code sample I posted above - which always fails - and see how it's different from what ASP.NET does when serializing? How everything was fully working pre-preview4 is probably something we need to understand (could be @ajcvickers explanation here).

In 5.0, MVC buffered IAsyncEnumerable instances, effectively calling ToListAsync() on the user's behalf. At that point, it would exhaust the enumerable before beginning to serialize individual items that would result in lazy loading. In 6.0-p4, the buffering was removed in lieu of directly invoking the serializer. This now results in the simultaneous enumeration of the IAsyncEnumerable as well as accessing the lazy loaded property as part of the serialization of individual items, resulting in this issue.

If we think this was a problematic pattern to start with, I think documenting the breaking behavior change and providing users correct guidance on how to do it right way would be the way to go.

Btw, it's really cool we're discovering all these fun issues as part of release validation. 👍🏽

@pranavkm

@pranavkm then yeah, makes sense and sounds pretty much like what @ajcvickers described above; the thing is less related to sync/async and more to whether ASP.NET buffers everything before the JSON serializer starts to drill into the object graph (and triggers additional queries because of lazy loading).

Removing the buffering behavior sounds like the right thing, and FWIW we don't recommend using lazy loading in this way (or at all, actually...), so IMHO documenting this as a breaking change is the way to go. @ajcvickers what do you think?

I think this is something ASP.NET should document as a breaking change. The lazy-loading case here is really an anti-pattern (as I mentioned above) so this failure is perhaps not very interesting. However, changing where streaming happens means that the DbContext is now used at a later point it was before. This will break if the context is disposed after where it was used before, but before where it is used now. This typically isn't a problem when the context is scoped to the request, but more and more people are using DbContextFactory, in which case the context is often disposed sooner. Likely people will now need to do their own buffering in these cases, whereas before ASP.NET was doing it for them.

I agree, it is a breaking change (didn't we mark it as such?).

Likely people will now need to do their own buffering in these cases, whereas before ASP.NET was doing it for them.

This is worth a discussion I think.

@ajcvickers

This typically isn't a problem when the context is scoped to the request, but more and more people are using DbContextFactory, in which case the context is often disposed sooner.

@ajcvickers in this case, don't people have to dispose the context before the controller method returns, so they already have to buffer themselves in the controller? i.e. for this particular scenario I'm not sure there's a breaking change...

@roji

@roji That's possible.

Btw, it's really cool we're discovering all these fun issues as part of release validation. 👍🏽
I am glad the investments made in AppCompat are adding value. 3rd Party apps provide insights into interesting customer usage scenarios that might not be caught as part of unit/functional testing.

I see that this issue has been moved to next sprint planning. In the interim, what is the plan for Preview 4? Can you please confirm whether ASPNET Core team will be creating a breaking change announcement for this or a known issue if you will decide later after investigation whether this change is by design or not?

Breaking change announcement: aspnet/Announcements#463

Navigation Menu

Repository navigation

[.NET 6 Preview 4] Command is already in progress error in Npgsql library #32254

1 remaining item

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[.NET 6 Preview 4] Command is already in progress error in Npgsql library #32254

Description

Activity

jiangzeng01 commented on Apr 27, 2021

roji commented on Apr 27, 2021

roji commented on Apr 27, 2021

jiangzeng01 commented on Apr 28, 2021

roji commented on Apr 28, 2021

ajcvickers commented on Apr 28, 2021

roji commented on Apr 28, 2021

ajcvickers commented on Apr 28, 2021

davidfowl commented on Apr 28, 2021

jiangzeng01 commented on Apr 29, 2021

davidfowl commented on Apr 29, 2021

jiangzeng01 commented on Apr 29, 2021

1 remaining item

roji commented on Apr 29, 2021

pranavkm commented on Apr 29, 2021

roji commented on Apr 29, 2021

ajcvickers commented on Apr 29, 2021

davidfowl commented on Apr 29, 2021

roji commented on Apr 29, 2021

ajcvickers commented on Apr 29, 2021

PriyaPurkayastha commented on Apr 29, 2021

pranavkm commented on May 6, 2021

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions