SaveChangesAsync called in an infinite loop with invalid data

[tessierp]

Hi,

I have found a bug where, if I am passing a model that has a foreign key dependency and that foreign key is invalid (doesn't exist), I would expect a DbUpdateException to be thrown but what happens instead is that SaveChangedAsync is called in a loop over and over again which causes the database volume to increase until the application stops.

The implementation I went for is the one with the DbContextHelper which is very close to what is detailed here : https://github.com/thepirat000/Audit.NET/blob/master/src/Audit.EntityFramework/README.md#entity-framework-data-provider

If I try to save data that is valid, everything happens without any issues, I will get an Audit record and the data will be written to the database, otherwise, upon calling SaveChangesAsync, the helper seems to call SaveChangesAsync over and over.

I disabled Audit.NET to see if it was an issue with my implementation and send invalid data again and I do get DbUpdateException thrown and I'm able to log the error and exits without an issue.

[thepirat000]

Can you share the affected model classes and its EF configuration, so I can try to reproduce ?

[tessierp]

Here is the class I use where all the database code resides :

    public abstract class SqlDbContextAuditNetBase : SqlDbContextBase
    {
        private static DbContextHelper _helper = new();
        private readonly IAuditDbContext _auditContext;

        #region Initializers

        public SqlDbContextAuditNetBase() { }

        public SqlDbContextAuditNetBase(DbContextOptions options)
            : base(options)
        {
            _auditContext = new DefaultAuditContext(this);
            _helper.SetConfig(_auditContext);
        }

        public SqlDbContextAuditNetBase(
            DbContextOptions options,
            bool enableAuditTrails,
            string defaultSchema = "")
            : this(options)
        {
            EnableAuditTrails = enableAuditTrails;
            DefaultSchema = defaultSchema;
        }

        #endregion

        #region Properties

        public bool EnableAuditTrails { get; private set; } = false;

        #endregion

        #region Overrides

        public override async Task<int> SaveChangesAsync(bool acceptAllChangesOnSuccess, CancellationToken cancellationToken = default)
        {
            try
            {
                if (EnableAuditTrails)
                {
                    ChangeTracker.DetectChanges();
                    return await _helper.SaveChangesAsync(_auditContext, async () =>
                    {
                        return await base.SaveChangesAsync(acceptAllChangesOnSuccess, cancellationToken);
                    });
                }

                return await base.SaveChangesAsync(acceptAllChangesOnSuccess, cancellationToken);
            }
            catch (DbException)
            {
                throw;
            }
            catch (DbUpdateException)
            {
                throw;
            }
        }

        public override async Task<int> SaveChangesAsync(CancellationToken cancellationToken = default)
        {
            try
            {
                if (EnableAuditTrails)
                {
                    ChangeTracker.DetectChanges();
                    return await _helper.SaveChangesAsync(_auditContext, async () =>
                    {
                        try
                        {
                            return await base.SaveChangesAsync(cancellationToken);
                        }
                        catch(DbUpdateException)
                        {
                            throw;
                        }
                    });
                }

                return await base.SaveChangesAsync(cancellationToken);
            }
            catch (DbException)
            {
                throw;
            }
            catch (DbUpdateException)
            {
                throw;
            }
        }

        public override int SaveChanges(bool acceptAllChangesOnSuccess)
        {
            try
            {
                if (EnableAuditTrails)
                {
                    ChangeTracker.DetectChanges();
                    return _helper.SaveChanges(_auditContext, () => base.SaveChanges(acceptAllChangesOnSuccess));
                }

                return base.SaveChanges(acceptAllChangesOnSuccess);
            }
            catch (DbException)
            {
                throw;
            }
            catch (DbUpdateException)
            {
                throw;
            }

        }

        public override int SaveChanges()
        {
            try
            {
                if (EnableAuditTrails)
                {
                    ChangeTracker.DetectChanges();
                    return _helper.SaveChanges(_auditContext, () => base.SaveChanges());
                }

                return base.SaveChanges();
            }
            catch (DbException)
            {
                throw;
            }
            catch (DbUpdateException)
            {
                throw;
            }

        }

        #endregion

        #region Protected Methods

        protected override void OnModelCreating(ModelBuilder modelBuilder)
        {
            base.OnModelCreating(modelBuilder);

            if (EnableAuditTrails)
            {
                modelBuilder.Entity<AuditLog>(e =>
                {
                    e.HasKey(a => a.AuditId);
                });
            }
        }

        #endregion
    }

SqlDbContextBase derives from DbContext and have no overrides of the save functions you see in here, this was created only for projects where I do need to use some form of audits. The catches were added to make sure they were thrown which they are.

This is the AuditLog model :

    [AuditIgnore]
    public class AuditLog
    {
        [Required]
        public Guid AuditId { get; set; }
        [Required]
        [MaxLength(AuditConstraints.TableNameMaxLength)]
        public string TableName { get; set; }
        public long Timestamp { get; set; }
        [Required]
        public string OperationData { get; set; }
        public string Operation { get; set; }
        public string OperationPerformedBy { get; set; }
        [MaxLength(AuditConstraints.NameOfAssemblyMaxLength)]
        public string NameOfAssembly { get; set; }
        [MaxLength(AuditConstraints.VersionOfAssemblyMaxLength)]
        public string VersionOfAssembly { get; set; }
    }

This helper class is what I use to setup the audit and also to add an audit scope right before performing an operation :

    public static class SqlAuditNetHelper
    {
        public static void SetupAuditNetLog(Assembly modelsAssembly)
        {
            Configuration.Setup()
                .UseEntityFramework(_ => _
                    .AuditTypeMapper(t => typeof(AuditLog))
                    .AuditEntityAction<AuditLog>((ev, entry, entity) =>
                    {
                        var assemblyName = modelsAssembly.GetName();

                        entity.AuditId = Guid.NewGuid();
                        entity.Timestamp = DateTimeUtilities.GetUnixTimeSeconds(DateTime.UtcNow);
                        entity.TableName = entry.EntityType.Name;
                        entity.OperationData = entry.ToJson();
                        entity.Operation = entry.Action;
                        entity.OperationPerformedBy = ev.Environment.CustomFields["UserId"] as string;
                        entity.NameOfAssembly = assemblyName.Name;
                        entity.VersionOfAssembly = assemblyName.Version.ToString();
                    })
                .IgnoreMatchedProperties(true));
        }

        public static void AddAuditScope(string userId)
        {
            Configuration.AddCustomAction(ActionType.OnScopeCreated, scope =>
            {
                scope.Event.Environment.CustomFields["UserId"] = userId;
            });
        }
    }

The model I push to the database to be persisted is very basic, contains a GUID primary key with a GUID as a foreign key (which doesn't exist in the other table) and some data (whatever you want it to be that looks something like this :

    public class Facility : TranslatableBase
    {
        [GuidNotEmptyValidation]
        [TranslatableId]
        public Guid FacilityId { get; set; }

        public Guid? FacilityTypeId { get; set; }

        [Required]
        [MaxLength(FacilityConstraints.FacilityNameMaxLength)]
        [TranslatableData]
        public string Name { get; set; }
    }

TranslatableBase is just a mechanism I use to support translation tables (just to give you some context), but this is not what is causing the issue and you don't have to create anything similar. Basically it adds more fields.

Like I was saying before, everything works fine if everything is valid, but as soon as I try to push an invalid foreign key and as soon as it hits the helper's SaveChangesAsync, it will raise the exception and call itself again. I did make sure it was not something I did that prevented the base class from reaching DbContext and did check that DbContext was being called which is what the helper is being passed as an argument.

If I disable the Audit, the exception is thrown normally without any issues.

[thepirat000]

Please check this #168 (comment)

Say you are saving a change on your context. If the change fails (i.e. DbUpdateException) then the framework still tries to save the audit before throwing the exception, but since you use the exact same context for saving audits, the audit saving fails because the context detects the previous change and try to re-apply it.

I guess it's the same issue, could you apply the suggested workaround and re-test?

[thepirat000]

Also I'm pretty sure the call to ChangeTracker.DetectChanges(); will be a problem, since even if you use a different DbContext instance for the audit saving after an exception on the entity saving, the DetectChanges() will detect the change from the original dbcontext and try to re-apply it.

So you probably need to remove that DetectChanges() call, or implement IAuditBypass on your dbcontext, so the internal call to Save Changes that the library makes, will be to that SaveChangesBypassAudit* instead:

public class SqlDbContextAuditNetBase : DbContext, IAuditBypass
{
    public int SaveChangesBypassAudit()
    {
        return base.SaveChanges();
    }

    public Task<int> SaveChangesBypassAuditAsync()
    {
        return base.SaveChangesAsync();
    }
}

[tessierp]

It seems that removing DetectChanges doesn't change anything. I did try the IAuditBypass and that worked. I'm just trying to evaluate the consequences of going that route if there are any. I didn't get the chance to look at the other issue yet but from the small resume there is there, it does seem very similar.

[tessierp]

So I was able to fix it with using the IAuditBypass and also by adding the right context to use during the setup as you proposed in this issue #168 (comment)

        public static void SetupAuditNetLog(Assembly modelsAssembly)
        {
            Configuration.Setup()
                .UseEntityFramework(_ => _
                    .UseDbContext<SqlDbContextAuditNetBase>()
                    .AuditTypeMapper(t => typeof(AuditLog))
                    .AuditEntityAction<AuditLog>((ev, entry, entity) =>
                    {
                        var assemblyName = modelsAssembly.GetName();

                        entity.AuditId = Guid.NewGuid();
                        entity.Timestamp = DateTimeUtilities.GetUnixTimeSeconds(DateTime.UtcNow);
                        entity.TableName = entry.EntityType.Name;
                        entity.OperationData = entry.ToJson();
                        entity.Operation = entry.Action;
                        entity.OperationPerformedBy = ev.Environment.CustomFields["UserId"] as string;
                        entity.NameOfAssembly = assemblyName.Name;
                        entity.VersionOfAssembly = assemblyName.Version.ToString();
                    })
                .IgnoreMatchedProperties(true));
        }

Thank you very much, problem is fixed!

[tessierp]

I guess I was too quick. While an error is thrown now when there is an error and exists gracefully, when I am trying to insert valid data, I get this error by adding .UseDbContext()

An error occured while processing request : One or more errors occurred. (Cannot create an abstract class.)

And indeed, my base class is abstract as I do not want ANYONE to use it since it is useless anyone without adding the specific code to create models, etc.

And then I did tried to use my top level context, the one where I have all the fluent API Definitions and I get this : An error occured while processing request : One or more errors occurred. (No database provider has been configured for this DbContext. A provider can be configured by overriding the 'DbContext.OnConfiguring' method or by using 'AddDbContext' on the application service provider. If 'AddDbContext' is used, then also ensure that your DbContext type accepts a DbContextOptions object in its constructor and passes it to the base constructor for DbContext.)

which is strange since the provider is defined. I'm not sure what is going on.

        public static void SetupAuditNetLog<TDbContext>(Assembly modelsAssembly) where TDbContext : DbContext
        {
            Configuration.Setup()
                .UseEntityFramework(_ => _
                    .UseDbContext<TDbContext>()
                    .AuditTypeMapper(t => typeof(AuditLog))
                    .AuditEntityAction<AuditLog>((ev, entry, entity) =>
                    {
                        var assemblyName = modelsAssembly.GetName();

                        entity.AuditId = Guid.NewGuid();
                        entity.Timestamp = DateTimeUtilities.GetUnixTimeSeconds(DateTime.UtcNow);
                        entity.TableName = entry.EntityType.Name;
                        entity.OperationData = entry.ToJson();
                        entity.Operation = entry.Action;
                        entity.OperationPerformedBy = ev.Environment.CustomFields["UserId"] as string;
                        entity.NameOfAssembly = assemblyName.Name;
                        entity.VersionOfAssembly = assemblyName.Version.ToString();
                    })
                .IgnoreMatchedProperties(true));
        }

Any clues? I think the problem is the where clause. If that is the case then I'll probably have no choice but the use the Bypass...

The solution proposed by the error is not something I can use since I am using a DbContext factory where the provider is defined.. So the error really doesn't make any sense to me.

[thepirat000]

When you use the parameterless UseDbContext<T>() overload, you are telling the framework to instantiate a new T DbContext for each audit, and it will try to create the type T by calling the T constructor without parameters.

So if you pass the abstract class as the generic type, it will fail when trying to create an instance of that type.

You need to pass the concrete implementation type, and if you need to pass arguments to the constructor you can use the overload UseDbContext<T>(params object[] constructorArgs), for example:

.UseDbContext<SqlDbContextConcrete>(new DbContextOptionsBuilder<SqlDbContextConcrete>().UseSqlServer("connection string..").Options)

Or you can pass a lambda function like a factory that returns the audit context with the overload
UseDbContext(Func<AuditEventEntityFramework, DbContext> dbContextBuilder), for example:

.UseDbContext(ev => 
{ 
  return contextAccessor.HttpContext.RequestServices.GetService<SqlDbContextConcrete>(); 
})

[tessierp]

I guess it makes sense if you need to write to the Audit table you will need a context with the provider.. I don't need to do this with the AuditBypass so I probably will go with that instead but I'll see.

Thanks for the details.

[tessierp]

This is very strange, by implementing IAuditBypass, the save functions are no longer being called. I thought it did before but I noticed I disabled the audits while doing a test. Is there anything else specific I need to do in the config when I implement IAuditBypass on the context?

[tessierp]

Alright so I got the issues resolved by adding a UsqDbContext and passing the right factory to get the context. Now there is one last bug I noticed. Whenever I try to insert a record that is not valid and returns a, lets say, foreign key violation, that record will still get audited in the database which is not the expected behavior, on top of that the record reports the it is valid which is not expected either.

Do you have any recommendations?

[thepirat000]

You should be able see the Error Message on the ErrorMessage property on the EF Audit Event.

If you don't want to audit failed transactions you have some options:

1. add a custom OnSaving action to discard the event in case of error:

using Audit.EntityFramework;

Audit.Core.Configuration.AddCustomAction(ActionType.OnEventSaving, scope =>
{
    var ev = scope.GetEntityFrameworkEvent();
    if (!string.IsNullOrEmpty(ev?.ErrorMessage))
    {
        scope.Discard();
    }
});

Or...

2. Make the AuditEntityAction return false when you want to discard the audit:

.AuditEntityAction<AuditLog>((ev, entry, entity) =>
{
    if (!string.IsNullOrEmpty(ev.GetEntityFrameworkEvent().ErrorMessage))
    {
        return false;
    }
    entity.AuditId = Guid.NewGuid();
    // ...
    return true;
})

Another thing I noticed is that it seems you are calling your AddAuditScope(userId) method for each user on each request?

Note that Configuration.AddCustomAction() will add the action to a static list, so each time a scope is created, it will call all the actions sequentially. Also you will have problems if multiple threads are setting the action at the same time.
You should do it the other way, the action should be responsible of getting the current user from contextual information (i.e. HttpContext)

[tessierp]

All try that tomorrow to see if the scope discard works. Or it may have to wait until next week.

As for calling AddAuditScope before each action, the reason that is done is because we haven't found a better way to get the user information from the JWT data or how to make that work when I add a custom action from the setup. I did try to get the information from the HTTPContext, getting the authorization header and "unwrapping" the JWT but each time the authorization header would be empty. So I am unsure why this happens but that is the main reason.

If you have any solution to propose, let me know.

Thanks for your help!

[tessierp]

Alright the discard option on errors work. Unfortunately, there is no way for me to solve the scope of who is logging. Logging doesn't happen from the Web API. Requests are sent to the system via a WEB API which is sent to RabbitMQ and picked up by a Request Processor system. Each requests are processed depending on a priority and only then do we know which user sent the request which is why I was calling an AddCustomAction to log the user performing the action. Each of these requests are processed in their own thread.

So, it is impossible for me to do it the way you propose since I can process many in parallel. In other words, it is impossible for me to do it as you propose using the HttpContext which is very generic and applies very well to a WebAPI but in our case, requests are not known in advance and cannot pre-insert a configuration that would extract a user ID in advance especially that many can be processed in parallel.

Is there any other way with your Framework that you would propose I should identify who is performing an action? Basically, I need to do this before each save and it shouldn't interfere with all other parallel executions, in other words, if operations are performed by others in parallel, each userId shouldn't be overriden by others for requests processed on other threads.. Now I'm I'm not so sure, with what you explained, if adding that through the configuration system will work. It seems to work now because I am a single user. Anyways, looking forward to see what you propose and if there is another way other than going through the configuration to do what I need.

[tessierp]

Let me know what you think but it seems to me and from what you said that given how specific my situation is that there is no way for me to identify the user given the parallel processing nature of the app, that I would need another approach. Looked at the documentation but it is not clear exactly how to proceed.

[thepirat000]

Can you share the code where you call your AddAuditScope(string userId) method? Is it in the same method as the DbContext.SaveChanges call?

[tessierp]

Share that code would be a bit complicated.. We have a DAL which is used to communicate with the Database layer. The database layer contains the context where the saving happens. In the DAL, that is where the custom action to keep track of the user is called and right after a call to the database is initiated. In that sense, everything is in the same "scope".

I can provide you the code where the a new entity is created :

        public async Task CreateEntityAsync(TDto dto, string userId)
        {
            _log?.LogTrace($"{nameof(CpiirDalDatabaseEntityWriterBase<TEntity, TDto>)}::{nameof(CreateEntityAsync)}");

            if (dto == default(TDto))
            {
                _log?.LogError($"Invalid argument {nameof(dto)}");
                throw new ArgumentNullException($"{nameof(dto)}", $"Invalid argument <{nameof(dto)}>");
            }

            try
            {
                TEntity entity = ConvertDtoToEntity(dto);

                if (await _cpiirDatabaseEntityWriter.IsEntityExistsAsync(entity))
                {
                    throw new CpiirDalException($"<{nameof(TDto)}> already exists : <{JsonSerializer.Serialize(dto)}>.");
                }

                SqlAuditNetHelper.LogUserPerformingTheAction(userId);
                await _cpiirDatabaseEntityWriter.AddEntityAsync(entity);
            }
            catch (DbUpdateException ex)
            {
                _log?.LogError(ex, $"A DbUpdateException occurred while adding <{nameof(TDto)}> : <{JsonSerializer.Serialize(dto)}>.");
                if (ex.InnerException != null)
                {
                    _log?.LogError(ex.InnerException, ex.InnerException.Message);
                }

                throw;
            }
            catch (Exception ex)
            {
                _log?.LogError(ex, $"An exception occurred while adding <{nameof(TDto)}> : <{JsonSerializer.Serialize(dto)}>.");
                if (ex.InnerException != null)
                {
                    _log?.LogError(ex.InnerException, ex.InnerException.Message);
                }

                throw;
            }
        }

The call to SqlAuditNetHelper.LogUserPerformingTheAction(userId); contains the following code :

            Audit.Core.Configuration.AddCustomAction(ActionType.OnEventSaving, scope =>
            {
                scope.Event.Environment.CustomFields["UserId"] = userId;
            });

And I changed the setup of audit.net slightly to prevent logging on errors following your previous input :

        public static void SetupAuditNetLog<TDbContext>(Assembly modelsAssembly, IDesignTimeDbContextFactory<TDbContext> contextFactory, bool saveAuditsOnErrors = false) where TDbContext : DbContext
        {
            Audit.Core.Configuration.Setup()
                .UseEntityFramework(_ => _
                    .UseDbContext(c => { return contextFactory.CreateDbContext(null); })
                    .AuditTypeMapper(t => typeof(AuditLog))
                    .AuditEntityAction<AuditLog>((ev, entry, entity) =>
                    {
                        var assemblyName = modelsAssembly.GetName();

                        entity.AuditId = Guid.NewGuid();
                        entity.Timestamp = DateTimeUtilities.GetUnixTimeSeconds(DateTime.UtcNow);
                        entity.TableName = entry.EntityType.Name;
                        entity.OperationData = entry.ToJson();
                        entity.Operation = entry.Action;
                        entity.OperationPerformedBy = ev.Environment.CustomFields["UserId"] as string;
                        entity.ModelAssemblyName = assemblyName.Name;
                        entity.ModelAssemblyVersion = assemblyName.Version.ToString();
                    })
                .IgnoreMatchedProperties(true));

            if (!saveAuditsOnErrors)
            {
                Audit.Core.Configuration.AddCustomAction(ActionType.OnEventSaving, scope =>
                {
                    var ev = scope.GetEntityFrameworkEvent();
                    if (!string.IsNullOrEmpty(ev?.ErrorMessage))
                    {
                        scope.Discard();
                    }
                });
            }
        }

This works but I am guessing, after what you said, it will probably fail if I have different users performing actions leading to reporting users who didn't really perform the operation. Unless I misunderstood what you meant.

The CreateEntityAsync each from their own threads, meaning they all have their own context and not all threads are calling the same CreateEntityAsync of course.

[thepirat000]

Yes, the multiple calls to AddCustomAction will not work properly on multiple threads and will be leaking memory.

The best solution really depends on your design. Does your _cpiirDatabaseEntityWriter makes the DbContext.SaveChanges() call? And how does it creates the DbContext, do you re-use the same DbContext for diffrent Requests?
Can you change the _cpiirDatabaseEntityWriter.AddEntityAsync method to accept the userId as a parameter?

(Will change this Issue to a Discussion)

[tessierp]

I was going to write to you about that. For some reason, none of the IAuditBypass functions are being called and I am not exactly sure why. I'll try without it for now.

[tessierp]

Also based on what you are saying, if ever we do want to Audit on failure, it wont work without IAuditBypass? To be very honest, Ideally I would prefer not to have to call any of the bypass methods since this is forcing me to override base class code and makes it a little less clean.

[tessierp]

Not use IAuditBypass and it seems I can get audit logged on errors or not depending on if I set or not the Discard option. So far so good, issues have been fixed following your recommendations.

Thanks!

[thepirat000]

Yes, the IAuditBypass is only needed in the case you make a change on a DbContext that fails and you are using the same DbContext instance for the audit saving. This is because the library will call SaveChanges on the audit DbContext, but EF detects the failed change that is on the same context, and tries to re-apply it.

So if you use a different instance of the DbContext for audit saving then implementing IAuditBypass is not needed.

[tessierp]

Again thank you very much for your help, it was appreciated!