Instead of just throwing, this common error hangs and causes a memory / CPU spike.

kinetiq commented 3 years ago

File a bug

In Production, a very normal String or binary data would be truncated error brought down our entire server, which is an Azure Service S2 with only 1.5g memory. To my surprise, I reproduced this on my local machine, and it seems that instead of just throwing an exception, it hangs. I was able to observe the iisprocess consuming a few gigs of memory before the exception finally throws.

In Production, it eventually timed out. The resources were not released and the server remained close to 100% utilization.

I tried updating to the latest EF, although I was already on 5.0.1 - no luck.

Any idea why this is happening and how I could avoid it?

Include your code

            // other fields removed for clarity
            var user = new User()
            {
                PhoneOffice = "intentionally long field; this field is varchar(12)"
            };

            Db.User.Add(user);
            Db.SaveChanges();

Include stack traces

Include the full exception message and stack trace for any exception you encounter.

Use triple-tick fences for stack traces. For example:

String or binary data would be truncated. The statement has been terminated.
   at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.Execute(IRelationalConnection connection)
   at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.Execute(IEnumerable`1 commandBatches, IRelationalConnection connection)
   at Microsoft.EntityFrameworkCore.Storage.RelationalDatabase.SaveChanges(IList`1 entries)
   at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChanges(IList`1 entriesToSave)
   at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChanges(DbContext _, Boolean acceptAllChangesOnSuccess)
   at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)
   at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChanges(Boolean acceptAllChangesOnSuccess)
   at Microsoft.EntityFrameworkCore.DbContext.SaveChanges(Boolean acceptAllChangesOnSuccess)
   at Microsoft.EntityFrameworkCore.DbContext.SaveChanges()
   at Keystone.Web.Controllers.AdminUser.Models.UserCreator.CreateKeystoneUser(String auth0UserId) in D:\Dev\Kinetiq\Keystone\Dev\Keystone.Web\Controllers\AdminUser\Models\UserCreator.cs:line 120
   at Keystone.Web.Controllers.AdminUser.Models.UserCreator.CreateNew(UserVM model) in D:\Dev\Kinetiq\Keystone\Dev\Keystone.Web\Controllers\AdminUser\Models\UserCreator.cs:line 51
   at Keystone.Web.Controllers.AdminUser.AdminUserController.Create(UserVM model) in D:\Dev\Kinetiq\Keystone\Dev\Keystone.Web\Controllers\AdminUser\AdminUserController.cs:line 95
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.SyncActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<<InvokeActionMethodAsync>g__Logged|12_1>d.MoveNext()

Include provider and version information

EF Core version: 5.0.1 and 5.0.2 Database provider: Microsoft.EntityFrameworkCore.SqlServer Target framework: net5.0 Operating system: Windows 10, and Azure Service IDE: Visual Studio 2019 16.8.4

roji commented 3 years ago

Hi @kinetiq, sorry it took a while to get back to you.

As you've said you can see this happening locally, I've tried to reproduce this against a local SQL Server and have not succeeded - please see my runnable code sample below.

Does this issue only occur when the server is SQL Azure, or are you able to see it happening also with a non-Azure SQL Server? Does my code sample below trigger it?

Attempted repro

```c# await using var ctx = new UserContext(); await ctx.Database.EnsureDeletedAsync(); await ctx.Database.EnsureCreatedAsync(); var user = new User() { PhoneOffice = "intentionally long field; this field is varchar(12)" }; ctx.User.Add(user); ctx.SaveChanges(); public class UserContext : DbContext { public DbSet User { 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") .EnableSensitiveDataLogging() .UseLoggerFactory(ContextLoggerFactory); } public class User { public int Id { get; set; } public string Name { get; set; } [Column(TypeName = "varchar(12)")] public string PhoneOffice { get; set; } } ```

kinetiq commented 3 years ago

@roji Sorry for the delay. We use SQL Azure both for dev and prod, so I do not have any way to test non-Azure SQL Server. However, it does occur in my dev environment for whatever that's worth.

I will run your code tomorrow and let you know how your repro performs.

kinetiq commented 3 years ago

@roji Okay, I ran this.

I did rename the User to Userxx just to quickly clear up a conflict.

I got this after a brief delay, which is what I would have expected:

SqlException: A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Microsoft.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, bool breakConnection, Action<Action> wrapCloseInAction)
Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, bool callerHasConnectionLock, bool asyncClose)
Microsoft.Data.SqlClient.TdsParser.Connect(ServerInfo serverInfo, SqlInternalConnectionTds connHandler, bool ignoreSniOpenTimeout, long timerExpire, bool encrypt, bool trustServerCert, bool integratedSecurity, bool withFailover, SqlAuthenticationMethod authType)
Microsoft.Data.SqlClient.SqlInternalConnectionTds.AttemptOneLogin(ServerInfo serverInfo, string newPassword, SecureString newSecurePassword, bool ignoreSniOpenTimeout, TimeoutTimer timeout, bool withFailover)
Microsoft.Data.SqlClient.SqlInternalConnectionTds.LoginNoFailover(ServerInfo serverInfo, string newPassword, SecureString newSecurePassword, bool redirectedUserInstance, SqlConnectionString connectionOptions, SqlCredential credential, TimeoutTimer timeout)
Microsoft.Data.SqlClient.SqlInternalConnectionTds.OpenLoginEnlist(TimeoutTimer timeout, SqlConnectionString connectionOptions, SqlCredential credential, string newPassword, SecureString newSecurePassword, bool redirectedUserInstance)
Microsoft.Data.SqlClient.SqlInternalConnectionTds..ctor(DbConnectionPoolIdentity identity, SqlConnectionString connectionOptions, SqlCredential credential, object providerInfo, string newPassword, SecureString newSecurePassword, bool redirectedUserInstance, SqlConnectionString userConnectionOptions, SessionData reconnectSessionData, bool applyTransientFaultHandling, string accessToken, DbConnectionPool pool)
Microsoft.Data.SqlClient.SqlConnectionFactory.CreateConnection(DbConnectionOptions options, DbConnectionPoolKey poolKey, object poolGroupProviderInfo, DbConnectionPool pool, DbConnection owningConnection, DbConnectionOptions userOptions)
Microsoft.Data.ProviderBase.DbConnectionFactory.CreatePooledConnection(DbConnectionPool pool, DbConnection owningObject, DbConnectionOptions options, DbConnectionPoolKey poolKey, DbConnectionOptions userOptions)
Microsoft.Data.ProviderBase.DbConnectionPool.CreateObject(DbConnection owningObject, DbConnectionOptions userOptions, DbConnectionInternal oldConnection)
Microsoft.Data.ProviderBase.DbConnectionPool.UserCreateRequest(DbConnection owningObject, DbConnectionOptions userOptions, DbConnectionInternal oldConnection)
Microsoft.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, uint waitForMultipleObjectsTimeout, bool allowCreate, bool onlyOneCheckConnection, DbConnectionOptions userOptions, out DbConnectionInternal connection)
Microsoft.Data.ProviderBase.DbConnectionPool.WaitForPendingOpen()
Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(bool errorsExpected, CancellationToken cancellationToken)
Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(bool errorsExpected, CancellationToken cancellationToken)
Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenAsync(CancellationToken cancellationToken, bool errorsExpected)
Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerDatabaseCreator+<>c__DisplayClass20_0+<<ExistsAsync>b__0>d.MoveNext()
Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerDatabaseCreator+<>c__DisplayClass20_0+<<ExistsAsync>b__0>d.MoveNext()
Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerDatabaseCreator+<>c__DisplayClass20_0+<<ExistsAsync>b__0>d.MoveNext()
Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync<TState, TResult>(TState state, Func<DbContext, TState, CancellationToken, Task<TResult>> operation, Func<DbContext, TState, CancellationToken, Task<ExecutionResult<TResult>>> verifySucceeded, CancellationToken cancellationToken)
Microsoft.EntityFrameworkCore.Storage.RelationalDatabaseCreator.EnsureDeletedAsync(CancellationToken cancellationToken)
Keystone.Web.Controllers.Bench.BenchController.Repro() in BenchController.cs
+
            await ctx.Database.EnsureDeletedAsync();
Keystone.Web.Controllers.Bench.BenchController.Repro() in BenchController.cs
+
            return Content("yay");
lambda_method1525(Closure , object )
Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor+TaskOfActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, object controller, object[] arguments)
System.Threading.Tasks.ValueTask<TResult>.get_Result()
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Logged|12_1(ControllerActionInvoker invoker)
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, object state, bool isCompleted)
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(ref State next, ref Scope scope, ref object state, ref bool isCompleted)
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, object state, bool isCompleted)
Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|24_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, object state, bool isCompleted)
Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)
Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(ref State next, ref Scope scope, ref object state, ref bool isCompleted)
Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, object state, bool isCompleted)
Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)
Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
Microsoft.AspNetCore.Authorization.Policy.AuthorizationMiddlewareResultHandler.HandleAsync(RequestDelegate next, HttpContext context, AuthorizationPolicy policy, PolicyAuthorizationResult authorizeResult)
Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.Invoke(HttpContext context)

roji commented 3 years ago

I did rename the User to Userxx just to quickly clear up a conflict.

I'm not sure what you're referring to exactly - is this an attempt to run my repro on your SQL Azure? The error seems to point at a wrong connection string or similar...

In any case, I spun up an instance of SQL Azure (single, non-managed), ran my repro against it and just got the exception as expected - no hang or visible memory/CPU spike. Can you please check again and see if the issue isn't in your application? If you're convinced there's an issue, can you please provide a runnable code sample?

kinetiq commented 3 years ago

@roji I ran your code as-is, and it includes an invalid connection string. I assumed you were trying to make an exception happen in dev (an environment that is experiencing the problem). Do you want me to modify your code to run against my own context and so on?

As for whether this is an issue with my application - it may be. But what could we have done that would cause this exception to hang and also cause a memory spike that takes down the server? I can share a bit of my configuration if that would help... The only thing I have that I would expect to be involved here is App Insights, which captures exceptions and logs them in Azure, in what I think is the normal way.

roji commented 3 years ago

@kinetiq my code has my own connection string - yes, you'd need to adapt it to run against your environment (it's very unlikely the original issue we're discussing has anything to do with the connection string). The point is to try to put together a minimal repro which reproduces the error, to help you pinpoint where the problem is coming from.

Regarding what may be wrong with your app - I can't really help with that since I have no idea what it's doing :) Maybe in the case of this exception, there's a code path where things go awry and do an endless loop or something... I'd recommend trying to narrow thing down, gradually excluding unrelated pieces of code until you either find the cause, or you have a minimal repro which you can submit to us for further investigation.

kinetiq commented 3 years ago

Ok, got it, thanks for the clarification, and thanks for sticking with me on this. I ran this again and made the necessary changes, touching as little as possible. I am running this in a controller action.

It crashed as expected, however, but it hung for 53 seconds. The exception looks normal to me (see below).

What should I try next? Maybe the same code in a new solution, and try to isolate what interaction may be causing this?

SqlException: String or binary data would be truncated in table 'KeystoneDev.dbo.User', column 'PhoneOffice'. Truncated value: 'intentionall'. The statement has been terminated.
Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, bool breakConnection, Action<Action> wrapCloseInAction)
Microsoft.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, bool breakConnection, Action<Action> wrapCloseInAction)
Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, bool callerHasConnectionLock, bool asyncClose)
Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, out bool dataReady)
Microsoft.Data.SqlClient.SqlDataReader.TryConsumeMetaData()
Microsoft.Data.SqlClient.SqlDataReader.get_MetaData()
Microsoft.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, string resetOptionsString, bool isInternal, bool forDescribeParameterEncryption, bool shouldCacheForAlwaysEncrypted)
Microsoft.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, bool returnStream, bool isAsync, int timeout, out Task task, bool asyncWrite, bool inRetry, SqlDataReader ds, bool describeParameterEncryptionRequest)
Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, bool returnStream, TaskCompletionSource<object> completion, int timeout, out Task task, out bool usedCache, bool asyncWrite, bool inRetry, string method)
Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, bool returnStream, string method)
Microsoft.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior)
Microsoft.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
System.Data.Common.DbCommand.ExecuteReader()
Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReader(RelationalCommandParameterObject parameterObject)
Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.Execute(IRelationalConnection connection)

roji commented 3 years ago

@kinetiq just to be sure we're on the same page, you're confirming that you ran my minimal repro code from here against SQL Azure - as a console program (without embedding it in a web project, IIS or anything else - and the console program hung for 53 seconds?

kinetiq commented 3 years ago

No, not in a new console program, I ran this in my existing app, in a controller action.

Want me to run it in a console program?

roji commented 3 years ago

Yes, that would tell us whether the problem is in your existing app or not. If the console program works correctly, the problem is somewhere in your application, probably in the way it handles exceptions or similar.

kinetiq commented 3 years ago

Ok, this actually fails pretty fast in both the console app and when running in my application.

The part that was probably taking awhile was where it dropped and re-created my dev database. Which, yes, did indeed happen... Working on restoring it. Now I know what EnsureDeletedAsync does.

What's next?

roji commented 3 years ago

I'm not sure I understand... are you saying that the long delay - which you originally opened this issue for - is because your dev database was being dropped? If so, then there doesn't seem to be an issue?

Otherwise, if you're still seeing an unexplained delay but the minimal code sample I provided does not reproduce the problem, you're going to have to work on a minimal code sample on your side. Start with your application as-is (which presumably is triggering the unexplained delay) and narrow things down until you've pinpointed the issue. There's a good chance that during that process you'll understand the cause.

kinetiq commented 3 years ago

No, this only pertains to your sample code. My application still has the original problem.

So, to recap, here's what I've tried:

I recreated the original problem from production in dev, and the slow-down still occurs.
I used the code you gave me as-is in dev, and that obviously results in a login failure, which makes sense because it contains your original credentials and so on. You told me to target my actual database server and to try it in a console application.
- I did so. Foolishly, I targeted my actual dev database, which was promptly dropped because that's what your code does. That is not great but it's recoverable. This operation took something like 40s, which is a long time, but I think most of that was due to dropping a SQL Azure database; MSSMS operations on SQL Azure tend to be very slow as well. As a test, I ran your code again without the line that drops the DB, and the failure occurred very quickly.
- So I ran this in the new console app, and also inside of a controller action in my dev project. Both throw very quickly and do not show signs of the slowdown/memory spike problem. So it seems to me we have now ruled out some possibilities, although I'm not sure exactly what those are or what the next steps should be for troubleshooting this.
- To be clear, the original problem still persists when using my normal context.

I hope that is clear, there's a lot going on now.

roji commented 3 years ago

Apologies for your dev database, I did not intend for that sample to be executed against a database with actual (important) contents.

I understand the situation. It seems that you have (a) my code running within your dev project, without any delay, and (b) other code running within that same project, producing the delay. At this point you'll need to find exactly what is happening in (b) to trigger the issue, likely by gradually removing parts of the code until you've isolated the issue.

kinetiq commented 3 years ago

Alright, I am in the long process of gradually ripping things out of this project... Stay tuned.

kinetiq commented 3 years ago

I absolutely gutted this solution, and eventually isolated the problem down to Serilog's exception enricher. Maybe my configuration has a problem, or maybe there's an issue with the enricher. I opened a ticket with them: https://github.com/RehanSaeed/Serilog.Exceptions/issues/295

Thanks for all the help! Looks like we can close this one.

ErikEJ commented 3 years ago

You need to install the serilog EF Core package.

roji commented 3 years ago

Duplicate of #15214

roji commented 3 years ago

@kinetiq this is a well-known problem, as @ErikEJ wrote you need to install Serilog.Exceptions.EntityFrameworkCore.

kinetiq commented 3 years ago

@roji @ErikEJ Thanks for the heads up on that. I didn't find it in my searches.

dotnet / efcore