7

Despite there are many results for this question none have really given me a clear answer.

Every time I try to insert faulty data such as a duplicate primary key, via the AddAsync and SaveChangesAsync methods, I see this log: Failed executing DbCommand (15ms)

I also see the error on the SQL PROFILER and it very clear it's a primary key conflict. In these cases the SaveChangesAsync does not throw any error! It just hangs indefinitely causing a memory leak and eventually the app crashes. I tried wrapping the savechanges with a try catch to no avail, and even added a cancellation token to auto cancel after 2 seconds and even that did not stop the hang. The result is always a never ending HTTP request that never returns a response to the client. *I also tried running the savechangesasync without the configure await and the result is the same.

DI for context and repository:

        services.AddDbContext<SalesDBContext>(o => 
            o.UseSqlServer(appSettings.ConnectionString)
            .EnableDetailedErrors(true)
            .EnableSensitiveDataLogging()
        , ServiceLifetime.Scoped);

services.AddScoped<IRepository, EfRepository>();

The Controller Method:

[HttpPost]
public async Task<IActionResult> Post([FromBody] SomeRequest request)
{
    if (ModelState.IsValid)
    {
        var data = await _service.AddAsync(request);
        return Ok(data);
    }
    return BadRequest(ModelState.Values);
}

The addasync is the caller:

public class EfRepository : IRepository
{
    private readonly SalesDBContext _dbContext;

    public EfRepository(SalesDBContext dbContext)
    {
        _dbContext = dbContext;
    }

    public async Task<int> AddAsync<T>(T entity) where T : Entity
    {
        _dbContext.Set<T>().Add(entity);
        return await _dbContext.SaveChangesAsync();
    }
}

I fixed the issue by checking there are no violations, but this does not solve the root problem that currently it is impossible for me to log these errors and if this happens again somewhere it will destroy the website.

As per request: The entire context class:

    public class SalesDBContext : DbContext
{
    public DbSet<Entity> Entities { get; set; }


    public SalesDBContext(DbContextOptions<SalesDBContext> options) : base(options)
    {

    }

    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    {
        base.OnConfiguring(optionsBuilder);
    }
    protected override void OnModelCreating(ModelBuilder modelBuilder)
    {
        base.OnModelCreating(modelBuilder);

        modelBuilder.ApplyConfigurationsFromAssembly(System.Reflection.Assembly.GetExecutingAssembly());

        foreach (var relationship in modelBuilder.Model.GetEntityTypes().SelectMany(e => e.GetForeignKeys()))
        {
            relationship.DeleteBehavior = DeleteBehavior.Restrict;
        }
    }
    //This is the savechanges being called.
    public override async Task<int> SaveChangesAsync(CancellationToken cancellationToken = default)
    {
        int result = await base.SaveChangesAsync(cancellationToken); 
        //Hangs here on primary key conflict error
        return result;
    }
}

*The lifetime of the context probably has nothing to do with it, I reproduced the issue with every lifetime.

Here is the callstack: Call stack

*More information: The hang occurs also when saving with the non Async method. When manually throwing an error in the savechanges it bubbles up correctly. In another project that shares the same DLLs, the SaveChanges throws an error that bubbles up correctly, also in Async methods.

jps
  • 20,041
  • 15
  • 75
  • 79
Bodokh
  • 976
  • 4
  • 15
  • 34
  • This is probably a deadlock - check this out: https://stackoverflow.com/questions/25588659/deadlock-even-after-using-configureawaitfalse-in-asp-net-flow – Dominik Mar 09 '21 at 12:27
  • 1
    I think in ASP.NET Core the ConfigureAwait is not even needed anymore so I don't think this is the issue ? https://stackoverflow.com/questions/42053135/configureawaitfalse-relevant-in-asp-net-core – Arcord Mar 09 '21 at 12:31
  • I also tried saving without the configure await but the result is the same. I don't understand why a deadlock is occurring. All i want to do is capture the Key conflict exception – Bodokh Mar 09 '21 at 12:50
  • Can you try to use the SaveChanges not async? – Arcord Mar 09 '21 at 12:52
  • @Arcord I haven't tried because currently the entire code is Asynchronous and i don't know how a change like this will affect the entire system – Bodokh Mar 09 '21 at 13:05
  • It's not a solution I proposed, just something you could try to ensure if it's or not a deadlock issue :-) – Arcord Mar 09 '21 at 13:19
  • `SaveChangesAsync` does *not* hang on errors. It's the rest of the code, which wasn't posted, that caused blocking or deadlocks. If you use the "generic repository" **anti**pattern and call `SaveChangesAsync` for every change, you're probably using an external transaction needlessly, and face delays because of the networking overhead. If you try to "speed up" slow operations by using multiple DbContext instances, you end up with multiple competing connections. – Panagiotis Kanavos Mar 30 '21 at 09:01
  • @PanagiotisKanavos This save request is the only request. There are no other requests and I have tested the case with only one running instance of the dbcontext. No deadlocks. And I see the primary key error in the Profiler. If I run the same request exactly with different parameters everything works fine! It just fails silently everytime it encounters a duplicate primary key error. – Bodokh Mar 30 '21 at 09:05
  • The code you posted has no effect other than *add* some delay - `ConfigureAwait` affects the *await* operation, not the asynchronous operation. The method that calls your `SaveChangesAsync` would have to use `ConfigureAwait` itself to avoid returning to the original sync context. ASP.NET Core has no sync context, so `ConfigureAwait` isn't needed. In ASP.NET Old `ConfigureAwait` isn't needed unless something blocks the original request thread – Panagiotis Kanavos Mar 30 '21 at 09:05
  • @PanagiotisKanavos I know the configureawait is useless but I just desperately tried every possible solution I could find to no avail... – Bodokh Mar 30 '21 at 09:06
  • @Bodokh post your code. Don't assume you discovered a error in a common scenario missed by hundreds of thousands of developers over almost 10 years. – Panagiotis Kanavos Mar 30 '21 at 09:07
  • @PanagiotisKanavos I added the code that calls the savechanges, I'm not assuming I discovered something I just want to know what I'm missing! I have dealt with EF before and I have never encountered an error of this sort. – Bodokh Mar 30 '21 at 09:10
  • The code you posted is a no-op essentially. It's little different than returning the `Task` generated by `SaveChangesAsync`, except the compiler generates a state machine for *that await only*. I bet VS or Resharper already proposes removing `await`. Post the *rest* of the code – Panagiotis Kanavos Mar 30 '21 at 09:12
  • @PanagiotisKanavos Gladly, which part exactly of the code? The method that calls the AddAsync? – Bodokh Mar 30 '21 at 09:13
  • The code that causes the problem. Post enough code to reproduce the problem. – Panagiotis Kanavos Mar 30 '21 at 09:14
  • @PanagiotisKanavos I don't know what else to post.. This is the code. I add the dbcontext as a transient dependency with detailed errors and sensitive data logging enabled, and I just add any entity that must be unique. Doesn't matter what. Any entity that I insert that should throw a duplicate exception just fails silently. – Bodokh Mar 30 '21 at 09:23
  • In this single request test case,1. the injected dbcontext is used before or after this add? 2. Do you consume directly the dbcontext dependency or you consume a dependecy from wich you then get the db context? 3. Why you inject the dbcontext as transient? You have a specific need for this? – david-ao Mar 30 '21 at 11:52
  • Mmm you are using repositry pattern, so you consume your repository, not the db context, I'll add my educated guess as an answer – david-ao Mar 30 '21 at 11:55
  • Can I see the whole classes for both codeblocks. There are possible reasons for EF not giving you feedback in exact time. Please share the whole two classes. – Bahtiyar Özdere Mar 30 '21 at 13:09
  • @BahtiyarÖzdere I have added the codeblocks. – Bodokh Mar 30 '21 at 14:29
  • The issue will be with what code calls you Reposiitory.AddAsync method... How is it handling exceptions? Is it handling exceptions? Specifically the AgregateException? If nothing is explicitly handling exceptions then it would default to the configured global exception policy. The awaited SaveChangesAsync does not *hang* with an exception, the exception will be handled up the chain or the app terminates. Your DbContext will be "polluted" at this point so code such as a Logging attempt using the same DbContext can easily get caught up in an infinite loop due to invalid tracked entities. – Steve Py Mar 31 '21 at 23:58
  • @StevePy I have a try catch at the controller method level, and i also tried adding try catch blocks to every call in the tree, but no exceptions are ever caught, and in debug mode the hang always happens at the SaveChanges. – Bodokh Apr 01 '21 at 08:48
  • When you experience this problem you have something like SqlManagement studio/Oracle developer/DbBeaver etc open? – david-ao Apr 01 '21 at 11:54
  • @david-ao I have SQL Management Studio open. If I run the translated SQL from the SaveChanges I get a primary key exception, or for that matter, any exception thrown from SQL causes the request to hang. Even when I wrap the savechanges with a try catch it does not catch the exception and the request hangs. – Bodokh Apr 01 '21 at 12:11
  • Could it be you are locking the table with your management studio connection? Do you have an open transaction? This happened to me years ago with OracleDeveloper...It took me hours to understand that I was locking the table so my app could not do it's job... – david-ao Apr 01 '21 at 13:33
  • 1
    And where are you calling this from. I think we should check the calling action and dependency injection registering place too just in case. Can you share the calling action too pls? I also suggest to write a test for Repository action you are trying to achieve the error. If you can get error by calling it from test, you shold check your controller/action calling the repository. – Bahtiyar Özdere Apr 02 '21 at 08:26
  • What's the command timeout? If that is limited you should get a timout exception if the stall has to do with SQL. Since timeout is rarely unlimited it's likely that the code itself hangs, probably in the middleware. – Gert Arnold Apr 04 '21 at 08:43
  • I have added the controller method and the dependecy injection, I did not set a command timeout so it is probable default. – Bodokh Apr 04 '21 at 10:37
  • Can you reproduce when running locally with a single request? – tymtam Apr 05 '21 at 08:04
  • @tymtam Yes it's I can reproduce it easily in all environments. I think the issue lies in the dependency configuration somehow. I have another project, that uses the same dbContext and it is injected in the exact same manner, but in that project the exceptions bubble up. For some reason this does not happen here. The other project is a console applicatoin. – Bodokh Apr 05 '21 at 09:02
  • @Bodokh Can you share the class for the object you are trying to insert? And also the EF Core configuration for that class, if any? – sveinungf Apr 05 '21 at 16:46
  • Hi 1. please test with non async variant as previously kindly asked. 2. please add explicit `throw new Exception("test123");` instead `int result = await base.SaveChangesAsync(cancellationToken); ` and observe if you get the same behavior. The single await we are looking unwraps the Task "just" at that method level, the aggregate excp should be at the top somewhere in a middleware, the try / catch is of no effect if you face a deadlock scenario. The explicit throws will tell you if you are facing an EF issue or async / await one. 3. We would benefit if we saw the *whole* call stack of methods. – Vedran Mandić Apr 05 '21 at 18:14
  • In the EfRespository class you are using the "Add" method. Are you able to change this for the "AddOrUpdate" method instead? something like: _dbContext.Set().AddOrUpdate(entity); Since you are having a Primary Key conflict it means you are updating existing records and not inserting new. I think the "Add" method will always try to insert new records but if your entity has the Primary Key field populated the DB cannot insert a new record with the same key. In this case method "AddOrUpdate" should work for both scenarios. – Georgggg Apr 06 '21 at 04:41
  • See for reference: https://learn.microsoft.com/en-us/dotnet/api/system.data.entity.migrations.dbsetmigrationsextensions.addorupdate?view=entity-framework-6.2.0#System_Data_Entity_Migrations_DbSetMigrationsExtensions_AddOrUpdate__1_System_Data_Entity_IDbSet___0____0___ – Georgggg Apr 06 '21 at 04:42
  • @VedranMandić Hey, I tested as you asked. The exception bubbles up with no problem, and I also tried saving using the Non Async method and the result is the same. Adding the call stack now, I hope it's enough information – Bodokh Apr 06 '21 at 08:09

2 Answers2

6

I have finally found the Issue!! I sat down and just started removing code one line at a time until I found the culprit!

.UseSerilog((hostingContext, loggerConfiguration) => {
    loggerConfiguration
    .ReadFrom.Configuration(hostingContext.Configuration)
    .Enrich.FromLogContext()
    .Enrich.WithProperty("ApplicationName", typeof(Program).Assembly.GetName().Name)
    .Enrich.WithProperty("Environment", hostingContext.HostingEnvironment);
#if DEBUG
    loggerConfiguration.Enrich.WithProperty("DebuggerAttached", Debugger.IsAttached);
#endif
});

Serilog has been giving me the hard time all along. There were no errors pointing in the direction that something is wrong with the logging because all the logs were functional. So I just removed lines of code one after another until I removed this and the hanging stopped and exceptions started to bubble up.

Thank you for every one who commented and tried to help me, it is much appreciated!

I ended up ditching Serilog and using Seq directly with ILogging extension and everything works fine now!

Bodokh
  • 976
  • 4
  • 15
  • 34
  • Great that you were able to find a way forwards. Is there any other clue that Serilog is involved, e.g. is any logging code on the call stack, or being awaited (somehow) in the base context's `SaveChangesAsync()`? – Nicholas Blumhardt Apr 12 '21 at 23:00
  • @NicholasBlumhardt None at all! No error thrown whatsoever and no clue at all that points to Serilog as the culprit. Also, I changes the Serilog settings to only log to the console instead of Seq, and the issue still happens. So it's definitely Serilog and not the one of the Sinks. – Bodokh Apr 13 '21 at 08:51
  • 1
    Rather than it being Serilog, it could also be assumptions that EF is making about which logging provider is behind its `ILogger`s, or some side-effect (e.g. assembly loading?) - TBH it doesn't sound like a Serilog issue to me, but it also seems like it'll be tricky to pin down :-) – Nicholas Blumhardt Apr 14 '21 at 22:13
  • 1
    I had this exact same issue, this is due to https://github.com/RehanSaeed/Serilog.Exceptions/issues/100 – Victorio Berra Aug 06 '21 at 18:17
  • Yes, Serilog.Exception is the culprit !!! Thanks a lot man. – Sukhdevsinh Zala Mar 30 '22 at 16:55
  • Thank you! I have been trying to diagnose this for way too long – Justin Morrison May 31 '22 at 14:27
  • We had the exact same problem, and this did the trick, thank you! – uvr Aug 30 '22 at 18:33
-1

In the comments you say that you inject your db context as transient. I would suggest to inject it as scoped, this would ensure you are using the "same" dbcontext per request in your whole data flow.

Using different dbcontext, as it would be if using transient lifetime, in different consumers in the same request for your data access flow could lead to strange behaviours, like this

david-ao
  • 3,000
  • 5
  • 12
  • 1
    I am aware of the behavior differences, and I reproduced the error on all lifetimes. – Bodokh Mar 30 '21 at 14:21
  • I see, then I would suggest to check the unchecked, by the look of it the code seems ok like it is – david-ao Mar 30 '21 at 14:23
  • I don't see any basis for this claim, unless you provide more context. In fact I would argue the opposite. Entity Framework does not support multiple concurrent requests made from the same connection. Meaning if you registered the context as `Scoped`, and make an async call without awaiting, and in a separate entity (who also has a dependency on the same context) make an async call without awaiting, you will run into concurrency errors. – johnny 5 Apr 05 '21 at 13:18
  • I am not talking about not awaiting, i am talking about dependecies. – david-ao Apr 05 '21 at 13:58
  • I am not talking about not awaiting, i am talking about dependecies. If A depends on B and the DbContext, and B depends on the db context, if you add as scoped you are sure, that in the same request, the dbcontext in place is the same, so if B does something that starts some tracking for example then A will work with that tracking in place. If added as transient there will be 2 different instances that do not share a common state. Depending on your needs you have to add it as transient or scoped. – david-ao Apr 05 '21 at 14:06