Can EF sometimes retry after successful write?

Question

I have UNIQUE constraint on a database table which is occasionally throwing an exception when writing a new record. The constraint covers three fields - one of which is a DATETIMEOFFSET(7). The value for that field is being set to the current time when hitting a webapi endpoint.

I can't think of any reason there would be an exact duplicate time being inserted by multiple webapi requests - it seems highly unlikely given the accuracy of the time field.

Unfortunately, I can't reproduce the exception, we're just occasionally seeing it in our logs.

The only thing I can think of is if within the same request, Entity Framework is somehow retrying the database write after thinking it's failed, when it hasn't - causing the exception. We're using SqlAzureExecutionStrategy which after decompiling its ShouldRetryOn method, it looks like it retries on the following error codes ...

40613: Database not currently available 41301: A transaction dependency failure occurred, and the current transaction can no longer commit. 41302: The current transaction attempted to update a record that has been updated since this transaction started. The transaction was aborted. 41305: The current transaction failed to commit due to a repeatable read validation failure. 41325: The current transaction failed to commit due to a serializable validation failure. 10928: Resource ID : %d. The %ls limit for the database is %d and has been reached. See 'http://go.microsoft.com/fwlink/?LinkId=267637' for assistance. 10929: Resource ID : %d. The %ls minimum guarantee is %d, maximum limit is %d and the current usage for the database is %d. However, the server is currently too busy to support %ls greater than %d for this database. See 'http://go.microsoft.com/fwlink/?LinkId=26 40197: The service has encountered an error processing your request. Please try again. Error code %d. 40501: The service is currently busy. Retry the request after 10 seconds. Incident ID: %ls. Code: %d 233: The column '%.*ls' in table '%.*ls' cannot be null. 10053: Could not convert the data value due to reasons other than sign mismatch or overflow. 10054: The data value for one or more columns overflowed the type used by the provider. 10060: Connection error 20: ? 64: A connection was successfully established with the server, but then an error occurred during the pre-login handshake

I would have thought that it would only retry if it fails to write though. Is it possible that it does write the record, but Entity Framework might get confused and try again anyway?

UPDATE

Below is the exception ...

System.Data.Entity.Infrastructure.RetryLimitExceededException: Maximum number of retries (5) exceeded while executing database operations with 'MyExecutionStrategy'.
See inner exception for the most recent failure. ---> System.Data.Entity.Core.UpdateException: An error occurred while updating the entries.
See the inner exception for details. ---> System.Data.SqlClient.SqlException: Violation of UNIQUE KEY constraint 'UQ_SessionLog'. Cannot insert duplicate key in object 'dbo.SessionLog'. The duplicate key value is (f6aeb1b8-c747-4f0b-9053-bf95a5630662, 2016-07-12 11:42:32.7077612  01:00, 0).
The statement has been terminated.
  at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
  at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
  at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
  at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean%26 dataReady)
  at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
  at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task%26 task, Boolean asyncWrite, SqlDataReader ds)
  at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task%26 task, Boolean asyncWrite)
  at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean asyncWrite)
  at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
  at StackExchange.Profiling.Data.ProfiledDbCommand.ExecuteNonQuery() in d:\Files\GitHub\miniprofiler\dotnet\StackExchange.Profiling\Data\ProfiledDbCommand.cs:line 264
  at System.Data.Common.DbCommand.ExecuteNonQueryAsync(CancellationToken cancellationToken)

You set that DATETIMEOFFSET from code or via database (default database value)? — Evk, Dec 13 '16 at 10:07
Is it an SQL exception or is there an SQL exception in the chain of inner exceptions? Your loggng should specifically look into the `Errors` and `ErrorCode` properties. Especially the error code tells you if you run into a `UNIQUE` constraint violation. — Sefe, Dec 13 '16 at 10:09
@Evk It's being set in code (webapi action that triggers the DbContext SaveChanges) — Dan, Dec 13 '16 at 10:18
If you use something like DateTimeOffset.Now, it's precision is quite low (https://msdn.microsoft.com/en-us/library/system.datetimeoffset.now(v=vs.110).aspx : "... the clock's resolution is approximately 10-15 milliseconds". It's very likely that you can get multiple requests in 10-15 milliseconds interval. — Evk, Dec 13 '16 at 10:21
@Evk Not that likely in our use case I'm afraid. Especially with the endpoint in question. Especially as we've seen it more than once. — Dan, Dec 13 '16 at 10:24

score 4 · Answer 1 · edited May 23 '17 at 11:53

4

The precision of DateTime is not as much as the number of millisecond digits would lead you to believe. Its highly likely that you will get duplicates in a multithreaded environment

Trying to find an authoritative answer on exactly how precise it is : https://msdn.microsoft.com/EN-US/library/system.datetime.utcnow.aspx

"The resolution of this property depends on the system timer."

You are not the first to experience this problem

C# DateTime.Now precision

DateTime precision vs accuracy?

https://manski.net/2014/07/high-resolution-clock-in-csharp/

etc etc

edited May 23 '17 at 11:53

Community

1
1

answered Dec 13 '16 at 10:11

Ewan

1,261
1
14
25

Given the use case of this end point, I'd be very surprised if this was the issue. But saying that - I'd also be very surprised if EF was retrying after a successful write - as that would obviously cause all sorts of issues for people. Very strange. – Dan Dec 13 '16 at 10:46
well without seeing the code we can just guess. but try changing to a guid and see if it stops happening – Ewan Dec 13 '16 at 10:52
or... take the unique constraint off and see if you get duplicates – Ewan Dec 13 '16 at 10:53
Thought so - I was just wondering if there was a possibly that EF was retrying - so thought it worth posted to see if anyone knew of any weird cases where this might happen. Thank you for your help - if I work out what it is, I'll update here with the info. – Dan Dec 13 '16 at 11:04

Can EF sometimes retry after successful write?

UPDATE

1 Answers1