Destructuring EntityFramework's DbUpdateException causes DB Queries #100
Labels
enhancement
Issues describing an enhancement or pull requests adding an enhancement.
help wanted
Help wanted from the community.
Comments
RehanSaeed
added
enhancement
|
I can submit a PR, but I don't know where to even start with writing tests for this. void Main()
{
string path = @"C:\\Temp\\TestUpdateExceptionLog.log";
ILogger logger = new LoggerConfiguration()
.Enrich.WithExceptionDetails(new DestructuringOptionsBuilder().WithDefaultDestructurers().WithDestructurers(new[] { new DbUpdateExceptionDestructurer() }))
.WriteTo.Console()
.WriteTo.RollingFile(new JsonFormatter(renderMessage: true), path)
.CreateLogger();
try
{
TestTestContext(logger);
TestException();
}
catch (Exception ex)
{
logger.Error(ex, "Error");
}
Log.CloseAndFlush();
}
public class DbUpdateExceptionDestructurer : ExceptionDestructurer
{
public override Type[] TargetTypes => new[] { typeof(DbUpdateException), typeof(DbUpdateConcurrencyException) };
public override void Destructure(Exception exception, IExceptionPropertiesBag propertiesBag, Func<Exception, IReadOnlyDictionary<string, object>> destructureException)
{
base.Destructure(exception, propertiesBag, destructureException);
var dbUpdateException = (DbUpdateException)exception;
propertiesBag.AddProperty(nameof(DbUpdateException.Entries), dbUpdateException.Entries?.Select(e => new
{
EntryProperties = e.Properties.Select(p => new
{
PropertyName = p.Metadata.Name,
p.OriginalValue,
p.CurrentValue,
p.IsTemporary,
p.IsModified
}),
e.State
}).ToList());
}
}
public void TestTestContext(ILogger logger)
{
var ctx = new TestContext();
ctx.Database.EnsureDeleted();
ctx.Database.EnsureCreated();
logger.Information("Get first UserRole {@UserRole}", ctx.UserRoles.First());
}
const string _UserId = "0f7183fd-94f6-40de-9ee4-e30f4d3b6167";
const string _PhoneNumber = "5551234567";
public void TestException()
{
var ctx = new TestContext();
// First update pending
var user = ctx.Users.First(u => u.UserId == _UserId);
user.PhoneNumber = user.PhoneNumber == _PhoneNumber ? "2221234567" : "5551234567";
// Second update pending
var role = ctx.Roles.First();
role.ConcurrencyStamp = Guid.NewGuid().ToString();
// Foreign key issue
for (int i = 0; i < 2; i++)
{
var userRole = new UserRole
{
UserId = _UserId,
RoleId = Guid.NewGuid().ToString() // this role ID is not valid
};
ctx.Add(userRole);
}
ctx.SaveChanges();
}
public class User
{
public User() => UserRoles = new List<UserRole>();
public string UserId { get; set; }
public string PhoneNumber { get; set; }
public List<UserRole> UserRoles { get; set; }
}
public class Role
{
public Role() => UserRoles = new List<UserRole>();
public string RoleId { get; set; }
public string ConcurrencyStamp { get; set; }
public List<UserRole> UserRoles { get; set; }
}
public class UserRole
{
public string UserRoleId { get; set; }
public string UserId { get; set; }
public string RoleId { get; set; }
public User User { get; set; }
public Role Role { get; set; }
}
public class TestContext : DbContext
{
protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
{
optionsBuilder.UseSqlServer(@"Server=localhost;Database=TestSerilogExceptions;Integrated Security=True");
}
protected override void OnModelCreating(ModelBuilder modelBuilder)
{
var users = new List<User>
{
new User
{
UserId = _UserId,
PhoneNumber = _PhoneNumber
}
};
for (int i = 0; i < 10; i++)
{
users.Add(new User
{
UserId = Guid.NewGuid().ToString(),
PhoneNumber = i.ToString()
});
}
var role = new Role
{
RoleId = Guid.NewGuid().ToString()
};
var userRole = new UserRole
{
UserRoleId = Guid.NewGuid().ToString(),
UserId = users[0].UserId,
RoleId = role.RoleId
};
modelBuilder.Entity<User>().HasData(users);
modelBuilder.Entity<Role>().HasData(role);
modelBuilder.Entity<UserRole>().HasData(userRole);
}
public DbSet<User> Users { get; set; }
public DbSet<Role> Roles { get; set; }
public DbSet<UserRole> UserRoles { get; set; }
}Here is the log output with
|
|
Thanks, that would be great! I'm wondering if we could we use the Entity Framework SQLite provider for the tests. |
joelweiss
pushed a commit
to joelweiss/Serilog.Exceptions
that referenced
this issue
Jun 28, 2019
joelweiss
pushed a commit
to joelweiss/Serilog.Exceptions
that referenced
this issue
Jun 28, 2019
The SQLite provider doesn't set the |
RehanSaeed
pushed a commit
that referenced
this issue
Jul 11, 2019
|
PR has been merged. New NuGet package will be released soon. Closing issue. |
|
@RehanSaeed Would there be a way to detect at runtime that Serilog.Exceptions.EntityFrameworkCore is not referenced, but the Serilog.Exceptions enricher is enabled? Maybe a warning-level log at initialization time, etc. After we upgraded from .Net Core 2.2 -> 3.1 (and all associated third-party packages), we spent a lot of time tracking down our apparently random "out-of-memory" crashes because we were not aware of the new required package. I'd love to save the next person in this situation some time. |
|
@lesscodetxm I think that's a good idea. It's there in the documentation but easy to miss. We'd need to have a think about how we could log a warning using Serilog. It's a bit weird that logging something would cause another log message to get logged. |
|
Well, I was thinking that the situation could be detected earlier than a logger call, maybe during |
|
We could look for the exception in the current assembly context on startup. However, we would take a slight performance hit. I'm not certain how much though. |
|
Right. I was thinking that maybe it would be enough to warn if, during |
|
Yes that makes sense. Want to submit a small PR with that if statement in it? |
|
I'll see if I can take a stab at it this week. |
|
Just ran into this, but thankfully not on production! 😛 I agree the developer should be informed, but not via a warning log - since this is a massive problem to have in production, it should crash the program on startup with an explanation and link to this issue. |
|
I just had this problem, and it took me hours to track down. @lesscodetxm did you ever get around to a PR? What can we do to fix this? My entire DB started getting tracked when SaveChanges() failed. It knocked out the server memory. |
Ha, struggled to track this bug down for days... Using https://www.nuget.org/packages/Serilog.Exceptions.EntityFrameworkCore/ (and https://www.nuget.org/packages/Serilog.Exceptions.SqlServer/ ) fixed the problem. |
|
Our project ran into this problem in production. It was not caught in testing because staging only had one instance whereas production had more than one which triggered the db conflict under load, specifically with data migration activities. We fixed this by adding If there is a reason to log the DbContext, an option would be to block the logging of DbSet, or IQueryable. public ReflectionInfoExtractor()
{
this.baseExceptionPropertiesForDestructuring = GetExceptionPropertiesForDestructuring(typeof(Exception));
this.blockedTypes.Add(typeof(IQueryable));
}
private ReflectionInfo GenerateReflectionInfoForType(Type valueType)
{
var properties = GetExceptionPropertiesForDestructuring(valueType);
var propertyInfos = properties
.Where(p => !this.blockedTypes.All(t => t.IsAssignableFrom(p.PropertyType)))
.Select(p => new ReflectionPropertyInfo(p.Name, p.DeclaringType, GenerateFastGetterForProperty(valueType, p)))
.ToArray(); |
|
The problem with this solution is that you need a type reference which
causes a dependency on efcore. The reflectionbased deconstructor could just
avoid dbcontext inherited and dbset based types (generic) by name, that
would help.
Adding the additional nuget package would lift the restriction and handle
these exceptions gracefully.
|
|
Not true @SeriousM. If I call The problem with requiring a separate nuget package is that it's so easy to miss. Also, there are also other implementations out there of IQueryable that is not tied to efcore. Execution of the underlying query provider can be an expensive operation, and I think it would make sense to block the serialization of any object that implements this interface, otherwise an expensive operation could be executed. |
|
Another option is to give special handling to |
|
Here is my other proposal. This only requires modification to private static object DestructureQueryable(IQueryable value) => value.Expression.ToString();
// DestructureValue
if (value is IQueryable queryable)
{
return DestructureQueryable(queryable);
}
else if (value is IEnumerable enumerable)
{
return this.DestructureValueEnumerable(enumerable, level, destructuredObjects, ref nextCyclicRefId);
} |
I like this solution as its a more general one as compared to special casing the exception in the core library. Thoughts @krajek? |
|
If anything, I consider this one unobscure, safe improvement. @almostchristian are you keen on providing the PR? Let me know, if you can't I think I can implement one this week. Note, that materialization of queries could be still present, for example in some getters' bodies. Then custom destructurers would be the only way to go. |
almostchristian
pushed a commit
to almostchristian/Serilog.Exceptions
that referenced
this issue
Nov 1, 2021
|
Do you have concerns with the destructuring of the IQueryable using |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
See dotnet/efcore#15214 for details. Would be willing to accept a PR for this work.
The text was updated successfully, but these errors were encountered: