Efcore: Enhance logging for "More than twenty 'IServiceProvider' instances warning" scenarios

[kieronlanning]

When using EF Core 2.1.1 after a number of calls into my service I start seeing the following warning:

More than twenty 'IServiceProvider' instances have been created for internal use by Entity Framework. This is commonly caused by injection of a new singleton service instance into every DbContext instance. For example, calling UseLoggerFactory passing in a new instance each time--see https://go.microsoft.com/fwlink/?linkid=869049 for more details. Consider reviewing calls on 'DbContextOptionsBuilder' that may require new service providers to be built.

I've followed the instructions details in the link in the warning, and from Issue #10235 but still the warning occurs.

The contexts all use the same ILoggerFactory by using the UseLoggerFactory extension:

services.AddDbContext<ApplicationDbContext>(
    builder =>
        {
            builder
                .UseLoggerFactory(LoggerFactory)  // <-- Passed in during App class start-up in the constructor.
                .UseSqlServer(defaultSqlConnectionString, options => options.MigrationsAssembly(migrationsAssembly));
        });

EF Core version: 2.1.1
Database Provider: Microsoft.EntityFrameworkCore.SqlServer

[ajcvickers]

@kieronlanning Can you post the full code for your AddDbContext call?

[kieronlanning]

@ajcvickers Hi, that's it above... although I have raised a similar issue with the IdSrv4 teams because on further inspection I noticed that it only happens in that service, not any others. So I think it maybe an issue with their internal registration system for their DbContexts.

I'll keep this post updated as I find more out from there.

[ajcvickers]

EF Team Triage: Closing this issue as the requested additional details have not been provided and we have been unable to reproduce it.

BTW this is a canned response and may have info or details that do not directly apply to this particular issue. While we'd like to spend the time to uniquely address every incoming issue, we get a lot traffic on the EF projects and that is not practical. To ensure we maximize the time we have to work on fixing bugs, implementing new features, etc. we use canned responses for common triage decisions.

[felixhayashi]

@kieronlanning I am currently having the same issue in my ASP.NET Core 2.1 MVC project (running in docker) and I am not using the "IdentityServer4" and instead rely on .NET Core Identity.

My setup also involves autofac, so I am really curious to see whether your demo-project with autofac that you mentioned over here is responsible for the piling up of IServiceProviders (which is slowly eating up my memory).

I have not registered a logger so far so the (otherwise helpful) error message appendix....

This is commonly caused by injection of a new singleton service instance into every DbContext instance. For example, calling UseLoggerFactory passing in a new instance each time"

...cannot be the cause in my case.

My Startup.cs includes this setup in ConfigureServices:

services.AddDbContext<AppDbContext>(
  options => {
    options.UseMySql(
      this.config.GetConnectionString("db1"),
      mysqlOptions => {
        mysqlOptions.ServerVersion(new Version(5, 7), ServerType.MySql)
      }
    );
  }
);
services.AddIdentity<User, Role>(config => {
  config.SignIn.RequireConfirmedEmail = true;
})

...and my AppDbContext constructor is clearly not getting anything injected but the config:

public class AppDbContext : IdentityDbContext<User, Role, int>
{
  public AppDbContext(DbContextOptions<AppDbContext> options) : base(options)
  { }

@ajcvickers do you have any idea where else I should look to find out who is injecting a singleton into my db contect instances? Or is there any related bugticket or issue I can check out? I would really appreciate your feedback. Thanks in advance.

Best wishes
Felix

P.S. I am also trying to narrow this down by setting up a demo project.

[felixhayashi]

@kieronlanning I removed autofac and it seems that the error is gone then! Can you please confirm? If yes, we should probably create a new ticket at the autofac repo.

[kieronlanning]

@felixhayashi I'm not confirming 100% as yet, but it certainly seems to be the case that removing Autofac has solved the issue.

I have lots of testing milage to complete right now, but my current status looks something like this:

• The demo was not using Autofac, and I couldn't replicate the problem.
• My primary solution was Autofac based, and spans 8 executable projects, and many other project references - all with their own IoC modules - so there has been a lot of refactoring to make sure the project still works.
• The refactoring started as a quick 'remove' Autofac, but as it's a part-time project, ended up being a lot more than just removing Autofac (lots of technical debt was accrued: https://twitter.com/b33rdy/status/1031309861173305345)

I'll update the issue on the Id4 group when I've completed my testing: https://github.com/IdentityServer/IdentityServer4/issues/2531

[felixhayashi]

okay, I understand @kieronlanning, many thanks. Looking forward to hearing about your progress! If there are any new discoveries from my side, I'll keep you posted.

[ajcvickers]

@kieronlanning @felixhayashi Would be very interested to hear what you find.

Reopening for triage: we should add some additional logging around service provider creation to make debugging these things easier.

[kieronlanning]

@ajcvickers Personally I've found this incredibly difficult to track down. Days of playing around and trying things.

It wasn't until creating a new test project that I chanced upon what could, maybe, possibly have been the issue. So any additional logging would be greatly received!

[ajcvickers]

Triage: we will enhance the logging here for 2.2, and do it soon so that nightly builds and 2.2 previews will be able to use it to help debugging.

[felixhayashi]

@ajcvickers that's great. many thanks for your support.

Meanwhile I discovered that I must have been to fast blaming autofac. Seems that the night I tested it, I used the wrong controller which had no db context injected so the warning naturally disappeared, sorry for that misleading post :( . So now I retested it with autofac in use and also with autofac disabled and native DI enabled and in both cases the warning about the 20+ instances occured. I also disabled "Identity" user management and still got the same result.

What is striking me now is that if I switch from mysql db driver (pomelo) to an mssql db setup then the warning seems to be gone.

This has led me to this https://github.com/PomeloFoundation/Pomelo.EntityFrameworkCore.MySql/issues/668 and this https://github.com/PomeloFoundation/Pomelo.EntityFrameworkCore.MySql/issues/619 ticket.

So indeed, when removing

.CharSetBehavior(CharSetBehavior.AppendToAllColumns)
.AnsiCharSet(CharSet.Latin1)
.UnicodeCharSet(CharSet.Utf8mb4);

from the mysqlOptions the leak seems to be gone. I will double check this tomorrow as it is getting late again and I hope I am not seeing ghosts again but this time I am quite confident that this is the reason.

@kieronlanning you are not by any chance using Pomelo.EntityFrameworkCore.MySql with these options enabled?

[ajcvickers]

@felixhayashi I was going to suggest this might be a culprit if working with MySQL, but the AutoFac comments lead me to believe this was something else.

[kieronlanning]

@ajcvickers @felixhayashi No Pomelo.EntityFrameworkCore.MySql here...

Mine was purely EF with MS SQL.

[PhilippeCamou]

I had this issue since long and as time to go in production came we had to find a fix.
We use Asp Net Core 2.1.1, EF 2.1.1, Autofac , Oracle and Devart provider.
Warnings is there since start and sure 2.0 first stable release 08/2017.

For us it was clear it was not the logging factory issue as already a singleton since start.
Then turning around and really really turning around I fixed it.

Below is how dbcontexts was declared and warnings appeared after about 10 calls :
services.AddDbContext((serviceProvider, optionsBuilder) =>
{
var connectionString = serviceProvider.GetRequiredService().GetSettings(DataSourceType.SecurityModel,typeof(MyDbContext)).ConnectionString;
optionsBuilder.UseOracle(connectionString);
});

What fixed issue :
1 - reference all dbcontext without any options in startup.cs as bellow :
services.AddDbContext();
2 - rather than using serviceprovider as before i injected our multitenant datasource setting provider directly in DbContext constructor using DI.
3 - And finally use overrided OnConfiguring method to pass connectionstring retrieved from multitenancy interface.

And after that I said "bye bye warnings we will miss you" and went peacefull in production.
May be the issue is somewhere else but if it can help EF Team to diagnose.

[kieronlanning]

@PhilippeCamou That's a great write up, thanks.

In removing Autofac completely, the problem has gone away for me. I wish I'd know this prior to embarking on a IoC refactor.

Post-Autofac, a lot of the scoped vs. singleton references were breaking the app, so I feel happier with the solution now at least.

[joshmouch]

@ajcvickers Sorry for the dumb question, but how do you enable this additional logging?

[ajcvickers]

@joshmouch Enable in what way? It is just additional log messages logged in the same way as other log messages. There is nothing to explicitly enable it in application code. However, the database provider needs to be updated to support it. SQL Server, SQLite, and In-memory have been updated. Not sure which third-party provides have been updated yet.

[ErikEJ]

Fixed in SQL CE provider 2.2.0.2

[laksh-parab]

I am still noticing the issue with .Net Core 3.1 Here is .NET Fiddle

[kieronlanning]

@laksh-parab That example is wrong I think.

Move the call to BuildServiceProvider outside of your loop.

[laksh-parab]

Original question is actually posted on SO