Triggers not firing intermittently

[anthony-keller]

Version
3.2.1
Running in net7.0 aspnet application

Scenario

Some code omitted for brevity.

    public class SubmitFleetBookingForReviewHandler
        : IRequestHandler<SubmitFleetBookingForReviewInput, SubmitFleetBookingForReviewOutput>
    {
        private readonly ILogger<SubmitFleetBookingForReviewHandler> _logger;
        private readonly IRequestAuthVariables _requestAuthVars;
        private readonly ISupplierAuthorizer _supplierAuthorizer;
        private readonly IClock _clock;
        private readonly AutoGuruDbContext _db;
        private readonly IBookingStatusTransitionValidator _bookingStatusTransitioner;
        private readonly IRequestHandler<AcceptFleetSignOnAgreementRequest, Unit> _acceptFleetSignOnAgreementHandler;
        private readonly IRequestHandler<AssessBookingBusinessRulesRequest, BookingBusinessRuleBookingAssessment> _assessBookingBusinessRulesHandler;

        public SubmitFleetBookingForReviewHandler(
            AutoGuruDbContext db,
        )
        {
            _db = db;
        }

        public async Task<SubmitFleetBookingForReviewOutput> Handle(
            SubmitFleetBookingForReviewInput request,
            CancellationToken cancellationToken)
        {
            <code here that changes the booking>

            try
            {
                _logger.LogDebug("Before 1st save. Booking Id = {bookingId} Booking Status Id = {bookingStatusId} DbContextId = {dbContextId} Lease = {lease}",
                    bookingId, booking.BookingStatusID, _db.ContextId.InstanceId, _db.ContextId.Lease);
                _logger.LogDebug("Changes before 1st save. {changes}", _db.ChangeTracker.DebugView.LongView);

                await _db.SaveChangesAsync(CancellationToken.None);

                _logger.LogDebug("After 1st save. Booking Id = {bookingId} Booking Status Id = {bookingStatusId} DbContextId = {dbContextId} Lease = {lease}",
                    bookingId, booking.BookingStatusID, _db.ContextId.InstanceId, _db.ContextId.Lease);
                _logger.LogDebug("Changes after 1st save. {changes}", _db.ChangeTracker.DebugView.LongView);

                _logger.LogInformation("Fleet booking ({bookingId}) submitted for review,", bookingId);
            }
            catch (DbUpdateConcurrencyException)
            {
                return new SubmitFleetBookingForReviewOutput(bookingId, new ConcurrentUpdateError());
            }

            <code here that changes the booking again>

            _logger.LogDebug("Before 2nd save. Booking Id = {bookingId} Booking Status Id = {bookingStatusId} DbContextId = {dbContextId} Lease = {lease}",
                bookingId, booking.BookingStatusID, _db.ContextId.InstanceId, _db.ContextId.Lease);
            _logger.LogDebug("Changes before 2nd save. {changes}", _db.ChangeTracker.DebugView.LongView);

            await _db.SaveChangesAsync(CancellationToken.None);

            _logger.LogDebug("After 2nd save. Booking Id = {bookingId} Booking Status Id = {bookingStatusId} DbContextId = {dbContextId} Lease = {lease}",
                bookingId, booking.BookingStatusID, _db.ContextId.InstanceId, _db.ContextId.Lease);
            _logger.LogDebug("Changes after 2nd save. {changes}", _db.ChangeTracker.DebugView.LongView);
        }
    }

We have a number of triggers attached to the Booking, some IBeforeSaveTrigger and some IAfterSaveTrigger.

Intermittently the triggers on Booking don't fire during the 2nd SaveChangesAsync() in the code above.

Logs

FailedLogs.txt

SuccessLogs.txt

Differences
When successful, 33 triggers are discovered. When it fails, the first 22 triggers match, but 11 are missing.

Invoking trigger: "AutoGuru.DataAccess.Triggers.Booking_BeforeSave_SetSupplierPaidAt" as "EntityFrameworkCore.Triggered.IBeforeSaveTrigger`1[AutoGuru.Entities.Booking]"
Invoking trigger: "AutoGuru.DataAccess.Triggers.Booking_BeforeSave_SetAutoGuruPaidAt" as "EntityFrameworkCore.Triggered.IBeforeSaveTrigger`1[AutoGuru.Entities.Booking]"
Invoking trigger: "AutoGuru.DataAccess.Triggers.Booking_BeforeSave_SetRatesAndDiscountsForFleetBookings" as "EntityFrameworkCore.Triggered.IBeforeSaveTrigger`1[AutoGuru.Entities.Booking]"
Invoking trigger: "AutoGuru.DataAccess.Triggers.Booking_BeforeSave_SetPayerAndPaymentTerms" as "EntityFrameworkCore.Triggered.IBeforeSaveTrigger`1[AutoGuru.Entities.Booking]"
Booking_BeforeSave_SetMerchantServiceFeeForFleetBooking. Booking Id = 6005225 % = 0.0350 $ = 14.37
Booking Id = 6005225 Fleet Company Id = 1 Supplier Id = 830 Booking Status Id = 33 DbContextId = fba0254d-8bb0-4555-adff-a648aa665397 Lease 26
Invoking trigger: "AutoGuru.DataAccess.Triggers.Booking_BeforeSave_SetMerchantServiceFeeForFleetBooking" as "EntityFrameworkCore.Triggered.IBeforeSaveTrigger`1[AutoGuru.Entities.Booking]"
Invoking trigger: "AutoGuru.DataAccess.Triggers.Booking_BeforeSave_SetLastReviewedPropertiesOfBookingTicketItems" as "EntityFrameworkCore.Triggered.IBeforeSaveTrigger`1[AutoGuru.Entities.Booking]"
Invoking trigger: "AutoGuru.DataAccess.Triggers.Booking_BeforeSave_SetDataFee" as "EntityFrameworkCore.Triggered.IBeforeSaveTrigger`1[AutoGuru.Entities.Booking]"
Invoking trigger: "AutoGuru.DataAccess.Triggers.Booking_BeforeSave_ResetClaimOnAction" as "EntityFrameworkCore.Triggered.IBeforeSaveTrigger`1[AutoGuru.Entities.Booking]"
Invoking trigger: "AutoGuru.Shared.Bookings.Booking_ConsumeSupplierTimeSlot" as "EntityFrameworkCore.Triggered.IBeforeSaveTrigger`1[AutoGuru.Entities.Booking]"
Invoking trigger: "AutoGuru.DataAccess.Triggers.CreationTimestampingTrigger" as "EntityFrameworkCore.Triggered.IBeforeSaveTrigger`1[AutoGuru.Entities.Abstractions.ICreationTimestamped]"
Invoking trigger: "AutoGuru.DataAccess.Triggers.UpdateTimestampingTrigger" as "EntityFrameworkCore.Triggered.IBeforeSaveTrigger`1[AutoGuru.Entities.Abstractions.IUpdateTimestamped]"

The logs show the DbContextId of the DbContext injected into the code above and the DbContextId used in the trigger discovery process (TriggerContextTracker). The same context is used (as expected) but the changes don't seem to be detected.

We're using the default cascade behavior and limit.

In terms of testing, it is sometimes very intermittent in that I could use JMeter to submit 1000 bookings and all are successful. In other tests, multiple could fail within the first 100 requests.

I will be doing further investigations and will update as I make discoveries.

[koenbeuk]

Thanks for reporting this in such detail! I wonder if this is related to #156 as in both cases the issue seems to be intermittent. I'm a bit swamped right now but I can allocate some time this weekend to take a closer look.

[anthony-keller]

It could be I guess. Since we're still using transient for the triggers it could be slightly different.

I'll be working on this issue today - hopefully I can narrow it down a bit more or find a solution.

I'm running it in .net 7 and EF Core 7 so it's all of the latest bits. I've got your source in our project to enable some additional logging.

We originally thought that the changes were being detected on a different instance of the DbContext but that doesn't seem to be the case.

Hopefully I'll get you some more info.

[anthony-keller]

I'm about to test with a single trigger (the trigger that sets the merchant service fee in the logs).

Then I plan to add more logging into the trigger discovery and execution code. I'm keen to log the tracked changes as close as possible to where they're used to determine the triggers to execute.

[anthony-keller]

I have added further logging.

• 223-306: The first save of the booking. Changes the status from 3 to 12. All triggers fired.
• 300: The Booking with change type Modified is added to the discovered changes.
• Notice that the changes are being detected on the same DbContextId
• 217: The discovered changes is not null
• 206-216: Adding discovered changes. It seems that the Booking with change type Modified is skipped because it was already in the list of discovered changes.
• This means that all triggers on Booking are not executed.

FailedVerboseLog.txt

In contrast, when it runs successfully

• 72: Discovered changes is null
• 63: Booking with change type Modified is added to discovered changes
• All triggers fire successfully

SuccessVerboseLog.txt

This issue is intermittent so it feels like some sort of race condition.

I think the issue is that _discoveredChanges in TriggerContextTracker is being retained between calls to SaveChangesAsync. Is it reasonable to clear the discovered changes at the end of trigger execution?

My current thought is that the issue is in TriggerSessionSaveChangesInterceptor and is something to do with the parallel save changes count. If the second SaveChangesAsync enlists the trigger session before the first SaveChangesAsync delists the session and disposes the session, then discovered changes will be retained between saves.

[koenbeuk]

Is it reasonable to clear the discovered changes at the end of trigger execution?

Yes, TriggerContextTracker is managed by a TriggerSession who's lifetime is tied to the SaveChanges() method.

If the second SaveChangesAsync enlists the trigger session before the first SaveChangesAsync delists the session and disposes the session, then discovered changes will be retained between saves.

That should never happen. _parallelSaveChangesCount is a bit of a misleading name as it's counting the recursive number of calls to SaveChanges(), e.g.

//userCode
db.SaveChanges();
// trigger1
db.SaveChanges();
// trigger2
db.SaveChanges();

Will effectively cause:

interceptor.SavingChanges(...); // userCode, Enlists a new trigger session
interceptor.SavingChanges(...); // trigger1, Reuses trigger session
interceptor.SavedChanges(...); // trigger1, Does not dispose trigger session
interceptor.SavingChanges(...); // trigger2, Reuses trigger session
interceptor.SavedChanges(...); // trigger2, Does not dispose trigger session
interceptor.SavedChanges(...) // userCode: Disposes trigger session

Are you by any chance using DbContextPooling?

[anthony-keller]

We are using pooling

[anthony-keller]

I can probably run some tests today without pooling and see what happens.

[koenbeuk]

I'm wondering if there is a bug in code where the trigger session is not delisted correctly, this could cause the behavior that you're seeing and frankly, the interceptor is somewhat fragile.

Can you make the interceptor a resettable service? (while using Pooling):

class TriggerSessionSaveChangesInterceptor : ISaveChangesInterceptor, IResettableSevice {
    ...

    public void ResetState() {
        if (_triggerSession is not null) {
            throw new ThisIsBadAndShouldNeverHappenException();
        }
    }
}

And update the registration in TriggerOptionExtensions.cs:

// from: 
services.TryAddScoped<IInterceptor, TriggerSessionSaveChangesInterceptor>();

// to:
services.AddScoped<TriggerSessionSaveChangesInterceptor>();
services.AddScoped<IInterceptor>(sp => sp.GetRequiredService<TriggerSessionSaveChangesInterceptor>());
services.AddScoped<IResettableSevice>(sp => sp.GetRequiredService<TriggerSessionSaveChangesInterceptor>());

Looking forward to hearing your results

[anthony-keller]

Tested around 4k bookings and was unable to reproduce after implementing IResettableService. The exception was not thrown.

[anthony-keller]

Added

        public void ResetState()
        {
            if (_triggerSession is not null)
            {
                throw new InvalidOperationException("Trigger session should be null here. This should never happen.");
            }
        }

        public Task ResetStateAsync(CancellationToken cancellationToken = new CancellationToken())
        {
            if (_triggerSession is not null)
            {
                throw new InvalidOperationException("Trigger session should be null here. This should never happen.");
            }

            return Task.CompletedTask;
        }

I was able to get the exception to throw 3 times

System.InvalidOperationException: Trigger session should be null here. This should never happen.    at EntityFrameworkCore.Triggered.Internal.TriggerSessionSaveChangesInterceptor.ResetState() in /src/EntityFrameworkCore.Triggered/src/EntityFrameworkCore.Triggered/Internal/TriggerSessionSaveChangesInterceptor.cs:line 195    at Microsoft.EntityFrameworkCore.DbContext.Microsoft.EntityFrameworkCore.Infrastructure.IResettableService.ResetState()    at Microsoft.EntityFrameworkCore.Internal.DbContextPool`1.Return(IDbContextPoolable context)    at 

This is thrown from a background service processing events from a queue.

[anthony-keller]

I have not been able to reproduce the issue after adding the code above. I've tried many thousands of requests.

I reverted to the version before I added the code above and was able to reproduce twice.

[koenbeuk]

Ok I think we isolated the issue:

The SaveChangesFailed and SaveChangesFailedAsync interceptor methods are not called when a trigger raises an exception explicitly, e.g.

public class ThrowExceptionTrigger : IBeforeSaveTrigger<Entity>
{
    public void BeforeSave(ITriggerContext<Entity> context)
        => throw new InvalidOperationException("Throwing up...");
}

Will ignore SaveChangesFailed and SavedChanges and therefore not dispose of the TriggerSession. A pooled DbContext would then hang on to the trigger session which is both a memory leak and can cause the behavior that you're describing.

We would certainly want to make TriggerSessionSaveChangesInterceptor a ResettableService to ensure that TriggerSession will always get deposed of. In addition, We'll need to figure out if we can make AfterSaveFailed triggers work properly again or otherwise document accordingly.

I'll spend some time on it this weekend.

[anthony-keller]

Thanks. Let me know if I can help with anything.