Devart ChangeConflictException but values still written to database

I have an intermittent Devart.Data.Linq.ChangeConflictException: Row not found or changed raising it's ugly head. The funny thing is, the change is still written to the database!

The stack trace says:

Devart.Data.Linq.ChangeConflictException: Row not found or changed. at Devart.Data.Linq.Engine.b4.a(IObjectEntry[] A_0, ConflictMode A_1, a A_2) at Devart.Data.Linq.Engine.b4.a(ConflictMode A_0) at Devart.Data.Linq.DataContext.SubmitChanges(ConflictMode failureMode) at Devart.Data.Linq.DataContext.SubmitChanges() at Billing.Eway.EwayInternal.SuccessCustomerRenewal(String username, Bill bill, EwayTransaction transaction) in c:\Users\Ian\Source\Repos\billing-class-library\Billing\Billing\Eway\EwayInternal.cs:line 552 at Billing.Eway.Eway.BillAllUsers() in c:\Users\Ian\Source\Repos\billing-class-library\Billing\Billing\Eway\Eway.cs:line 138

And my code for Billing.Eway.EwayInternal.SuccessCustomerRenewal:

    internal static void SuccessCustomerRenewal(string username, Bill bill, EwayTransaction transaction)
{
    // Give them their points!
    ApplyBillToCustomerAccount(username, bill, true);
    BillingEmail.SendRenewalSuccessEmail(username, bill, transaction);

    using (MsSqlDataClassesDataContext msSqlDb = new MsSqlDataClassesDataContext())
    {
        // TODO: Remove this logging
        msSqlDb.Log = new StreamWriter(@"logs\db\" + Common.GetCurrentTimeStamp() + "-MsSQL.txt", true) { AutoFlush = true };

        EwayCustomer ewayCustomer = msSqlDb.EwayCustomers.First(c => c.Username == username);
        ewayCustomer.NextBillingDate = Common.GetPlanExpiry(bill.BillPlan);

        using (MySqlDataContext mySqlDb = new MySqlDataContext())
        {
            // TODO: Remove this logging
            mySqlDb.Log = new StreamWriter(@"logs\db\" + Common.GetCurrentTimeStamp() + "-MySQL.txt", true) { AutoFlush = true };
            BillingMySqlContext.Customer grasCustomer = mySqlDb.Customers.First(c => c.Username == username);

            // Extend their membership date out so that the plan doesn't expire because of a failed credit card charge.
            grasCustomer.MembershipDate =
                ewayCustomer.NextBillingDate.AddDays(1);
            mySqlDb.SubmitChanges();  // <-- This is line 552
        }

        msSqlDb.SubmitChanges();
    }
}

I know that the issue occurs on the mySqlDb.SubmitChanges() line, since that DB context is the one using Devart (Linq solution for MySQL databases): the other context uses pure MS Linq.

Not only is the change written to the MySql DB (inner using block), but it is also written to the MsSql DB (outer using block). But that's where the magical success ends.

If I could I would write a Minimal, Complete and Verifiable example, but strangely I'm unable to generate a Devart ChangeConflictException.

So, why does the change get saved to the database after a Devart.Data.Linq.ChangeConflictException? When I previously encountered System.Data.Linq.ChangeConflictException changes weren't saved.

Edit 1:

I've also now included the .PDB file and gotten line number confirmation of the exact source of the exception.

Edit 2:

I now understand why I can't generate a ChangeConflictException, so how is it happening here?
These are the attributes for MembershipDate:_

[Column(Name = @"Membership_Date", Storage = "_MembershipDate", CanBeNull = false, DbType = "DATETIME NOT NULL", UpdateCheck = UpdateCheck.Never)]

I know I can explicitly force my changes through to override any potential conflict, but that seems undesirable (I don't know what I would be overriding!). Similarly I could wrap the submit in a try block, and retry (re-reading each time) until success, but that seems clunky. How should I deal with this intermittent issue?

Edit 3:

It's not caused by multiple calls. This function is called in one place, by a single-instance app. It creates log entries every time it is run, and they are only getting created once. I have since moved the email call to the top of the method: the email only gets sent once, the exception occurs, and database changes are still made.

I believe it has something to do with the using blocks. Whilst stepping through the debugger on an unrelated issue, I entered the using block, but stopped execution before the SubmitChanges() call. And the changes were still written to the database. My understanding was that using blocks were to ensure resources were cleaned up (connections closed, etc), but it seems that the entire block is being executed. A new avenue to research...
But it still doesn't answer how a ChangeConflictException is even possible given Devart explicitly ignores them.

Edit 4:

So I wasn't going crazy, the database change did get submitted even after I ended execution in the middle of the using block, but it only works for websites.

Edit 5:

As per @Evk's suggestion I've included some DB logging (and updated the stacktrace and code snippet above). The incidence rate of this exception seems to have dropped, as it has only just happened since I implemented the logging. Here are the additional details:

Outer (MS SQL) logfile:

SELECT TOP (1) [t0].[id], [t0].[Username], [t0].[TokenId], [t0].[PlanId], [t0].[SignupDate], [t0].[NextBillingDate], [t0].[PaymentType], [t0].[RetryCount], [t0].[AccountStatus], [t0].[CancelDate] FROM [dbo].[EwayCustomer] AS [t0] WHERE [t0].[Username] = @p0 -- @p0: Input NVarChar (Size = 4000; Prec = 0; Scale = 0) [dyonis] -- Context: SqlProvider(Sql2008) Model: AttributedMetaModel Build: 4.0.30319.18408a

(It just shows the SELECT call (.First()), none of the updates show).

Inner (MySQL) logfile:

SELECT t1.Customer_ID, t1.Username, t1.Account_Group, t1.Account_Password, t1.First_Name, t1.Last_Name, t1.Account_Type, t1.Points, t1.PromoPoints, t1.Phone, t1.Cell, t1.Email, t1.Address1, t1.Address2, t1.City, t1.State, t1.Country, t1.Postcode, t1.Membership_Group, t1.Suspend_On_Zero_Points, t1.Yahoo_ID, t1.MSN_ID, t1.Skype_ID, t1.Repurchase_Thresh, t1.Active, t1.Delete_Account, t1.Last_Activity, t1.Membership_Expires_After_x_Days, t1.Membership_Date, t1.auth_name, t1.created_by, t1.created_on, t1.AccountGroup_Points_Used, t1.AccountGroup_Points_Threashold, t1.LegacyPoints, t1.Can_Make_Reservation, t1.Gallery_Access, t1.Blog_Access, t1.Private_FTP, t1.Photometrica, t1.Promo_Code, t1.Promo_Expire_DTime, t1.Gift_FirstName, t1.Gift_LastName, t1.Gift_Email, t1.Gift_Phone, t1.Gift_Active, t1.NoMarketingEmail, t1.Can_Schedule, t1.Refered_By, t1.Q1_Hear_About_Us, t1.Q2_Exp_Level, t1.Q3_Intrests, t1.GIS_DTime_UTC, t1.Membership_Expire_Notice_Sent, t1.Promo_Expire_Notice_Sent, t1.isEncrypted, t1.PlanId FROM grasbill.customers t1 WHERE t1.Username = :p0 LIMIT 1 -- p0: Input VarChar (Size = 6; DbType = AnsiString) [dyonis] -- Context: Devart.Data.MySql.Linq.Provider.MySqlDataProvider Mapping: AttributeMappingSource Build: 4.4.519.0

UPDATE grasbill.customers SET Membership_Date = :p1 WHERE Customer_ID = :key1 -- p1: Input DateTime (Size = 0; DbType = DateTime) [8/3/2016 4:42:53 AM] -- key1: Input Int (Size = 0; DbType = Int32) [7731] -- Context: Devart.Data.MySql.Linq.Provider.MySqlDataProvider Mapping: AttributeMappingSource Build: 4.4.519.0

(Shows the SELECT and UPDATE calls)

So the log files don't really give any clue as to what's happening, but again the MS SQL database has been updated! The NextBillingDate field has been set correctly, as per this line:

ewayCustomer.NextBillingDate = Common.GetPlanExpiry(bill.BillPlan);

If it hadn't been updated, the user would have been billed again on the next timer tick (5 mins later), and I can see from logging that didn't happen.

One other interesting thing to note is the log file timestamps. As you can see from the code above I grab the current (UTC) time for the log filename. Here is the information shown by Windows File Explorer:

The MS SQL logfile was created at 04:42 (UTC) and last modified at 14:42 (UTC+10, Windows local-time), but the MySQL logfile was last modified at 15:23 (UTC+10), 41 minutes after it was created. Now I assume the logfile StreamWriter is closed as soon as it leaves scope. Is this delay an expected side effect of the exception? Did it take 41 minutes for the garbage collector to realise I no longer needed a reference to the StreamWriter? Or is something else going on?

Solution

Well 6 months later I finally got to the bottom of this problem. Not sure if it will ever help anyone else, but I'll detail it anyway.

There were 2 problems in play here, and 1 of them was idiocy (as they usually are), but one was legitimately something I did not know or expect.

Problem 1

The reason the changes were magically made to the database even though there was an exception was because the very first line of code in that function ApplyBillToCustomerAccount(username, bill, true); updates the database! <facepalm>

Problem 2

The (Devart) ChangeConflictException isn't only thrown if the data has changed, but also if you're not making any changes. MS SQL stores DateTimes with great precision, but MySQL (or the one I'm running at least) only stores down to seconds. And here's where the intermittency came in. If my database calls were quick enough, or just near the second boundary, they both got rounded to the same time. Devart saw no changes to be written, and threw a ChangeConflictException.

I recently made some optimisations to the database which resulted in far greater responsiveness, and massively increased incidence of this exception. That was one of the clues.

Also I tried changing the Found Rows parameter to true as instructed in the linked Devart post but found it did not help in my case. Or perhaps I did it wrong. Either way now that I've found the source of the issue I can eliminate the duplicate database updates.