Lots of ArgumentException in 2.0.7: "Metadata for field 'FieldName' of record '2' did not match the original record's metadata"

[cmeeren]

After updating to 2.0.7, I receive a lot of these:

System.AggregateException: One or more errors occurred. (One or more errors occurred. (One or more errors occurred. (One or more errors occurred. (Metadata for field 'CreatedAt' of record '2' did not match the original record's metadata.))))  ---> System.AggregateException: One or more errors occurred. (One or more errors occurred. (One or more errors occurred. (Metadata for field 'CreatedAt' of record '2' did not match the original record's metadata.)))  ---> System.AggregateException: One or more errors occurred. (One or more errors occurred. (Metadata for field 'CreatedAt' of record '2' did not match the original record's metadata.))  ---> System.AggregateException: One or more errors occurred. (Metadata for field 'CreatedAt' of record '2' did not match the original record's metadata.)  ---> System.ArgumentException: Metadata for field 'CreatedAt' of record '2' did not match the original record's metadata.
   at void Microsoft.SqlServer.Server.ValueUtilsSmi.SetIEnumerableOfSqlDataRecord_Unchecked(SmiEventSink_Default sink, SmiTypedGetterSetter setters, int ordinal, SmiMetaData metaData, IEnumerable<SqlDataRecord> value, ParameterPeekAheadValue peekAhead)
   at void Microsoft.SqlServer.Server.ValueUtilsSmi.SetCompatibleValueV200(SmiEventSink_Default sink, SmiTypedGetterSetter setters, int ordinal, SmiMetaData metaData, object value, ExtendedClrTypeCode typeCode, int offset, int length, ParameterPeekAheadValue peekAhead)
   at void System.Data.SqlClient.TdsParser.WriteSmiParameter(SqlParameter param, int paramIndex, bool sendDefault, TdsParserStateObject stateObj)
   at Task System.Data.SqlClient.TdsParser.TdsExecuteRPC(_SqlRPC[] rpcArray, int timeout, bool inSchema, SqlNotificationRequest notificationRequest, TdsParserStateObject stateObj, bool isCommandProc, bool sync, TaskCompletionSource<object> completion, int startRpc, int startParam)
   at SqlDataReader System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, bool returnStream, bool async, int timeout, out Task task, bool asyncWrite, SqlDataReader ds)
   at Task System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource<object> completion, bool sendToPipe, int timeout, bool asyncWrite, string methodName)
   at IAsyncResult System.Data.SqlClient.SqlCommand.BeginExecuteNonQuery(AsyncCallback callback, object stateObject)
   at Task<TResult> System.Threading.Tasks.TaskFactory<TResult>.FromAsyncImpl(Func<AsyncCallback, object, IAsyncResult> beginMethod, Func<IAsyncResult, TResult> endFunction, Action<IAsyncResult> endAction, object state, TaskCreationOptions creationOptions)
   at Task<int> System.Data.SqlClient.SqlCommand.ExecuteNonQueryAsync(CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at async Task<TResult> Polly.NoOp.NoOpEngine.ImplementationAsync<TResult>(Func<Context, CancellationToken, Task<TResult>> action, Context context, CancellationToken cancellationToken, bool continueOnCapturedContext)
   at async Task<TResult> Polly.AsyncPolicy<TResult>.ExecuteAsync(Func<Context, CancellationToken, Task<TResult>> action, Context context, CancellationToken cancellationToken, bool continueOnCapturedContext)
   at void Polly.Wrap.AsyncPolicyWrapEngine+<>c__DisplayClass2_0<TResult>+<<ImplementationAsync>b__0>d.MoveNext()
   at async Task<TResult> Polly.Retry.AsyncRetryEngine.ImplementationAsync<TResult>(Func<Context, CancellationToken, Task<TResult>> action, Context context, CancellationToken cancellationToken, ExceptionPredicates shouldRetryExceptionPredicates, ResultPredicates<TResult> shouldRetryResultPredicates, Func<DelegateResult<TResult>, TimeSpan, int, Context, Task> onRetryAsync, int permittedRetryCount, IEnumerable<TimeSpan> sleepDurationsEnumerable, Func<int, DelegateResult<TResult>, Context, TimeSpan> sleepDurationProvider, bool continueOnCapturedContext)
   at async Task<TResult> Polly.AsyncPolicy.ExecuteAsync<TResult>(Func<Context, CancellationToken, Task<TResult>> action, Context context, CancellationToken cancellationToken, bool continueOnCapturedContext)
   at async Task<TResult> Polly.Wrap.AsyncPolicyWrapEngine.ImplementationAsync<TResult>(Func<Context, CancellationToken, Task<TResult>> func, Context context, CancellationToken cancellationToken, bool continueOnCapturedContext, IAsyncPolicy outerPolicy, IAsyncPolicy<TResult> innerPolicy)
   at async Task<TResult> Polly.AsyncPolicy<TResult>.ExecuteAsync(Func<Context, CancellationToken, Task<TResult>> action, Context context, CancellationToken cancellationToken, bool continueOnCapturedContext)
   --- End of inner exception stack trace ---
   at FSharpAsync<c> CompositionHelpers.catchHandler@1<b, a, c>(a opName, b input, Exception _arg2) in C:/agent/_work/10/s/src/Core/CompositionHelpers.fs:line 115
   at FSharpOption<FSharpAsync<c>> [email protected](Exception edi) in C:/agent/_work/10/s/src/Core/CompositionHelpers.fs:line 108
   at AsyncReturn Microsoft.FSharp.Control.AsyncPrimitives.CallFilterThenInvoke<T>(AsyncActivation<T> ctxt, FSharpFunc<Exception, FSharpOption<FSharpAsync<T>>> catchFilter, ExceptionDispatchInfo edi) in F:/workspace/_work/1/s/src/fsharp/FSharp.Core/async.fs:line 436
   at AsyncReturn Microsoft.FSharp.Control.Trampoline.Execute(FSharpFunc<Unit, AsyncReturn> firstAction) in F:/workspace/_work/1/s/src/fsharp/FSharp.Core/async.fs:line 109
   --- End of inner exception stack trace ---
   at Step<a> [email protected](Unit unitVar0)
   at ICriticalNotifyCompletion FSharp.Control.Tasks.TaskBuilder+StepStateMachine<a>.nextAwaitable()
   at Step<b> FSharp.Control.Tasks.TaskBuilder+bindTaskConfigureFalse@131.Invoke(Unit unitVar0)
   at ICriticalNotifyCompletion FSharp.Control.Tasks.TaskBuilder+StepStateMachine<a>.nextAwaitable()
   at Step<b> FSharp.Control.Tasks.TaskBuilder+bindTaskConfigureFalse@131.Invoke(Unit unitVar0)
   at ICriticalNotifyCompletion FSharp.Control.Tasks.TaskBuilder+StepStateMachine<a>.nextAwaitable()
   at Step<b> FSharp.Control.Tasks.TaskBuilder+bindTaskConfigureFalse@131.Invoke(Unit unitVar0)
   at ICriticalNotifyCompletion FSharp.Control.Tasks.TaskBuilder+StepStateMachine<a>.nextAwaitable()
   at Step<b> FSharp.Control.Tasks.TaskBuilder+bindTaskConfigureFalse@131.Invoke(Unit unitVar0)
   at ICriticalNotifyCompletion FSharp.Control.Tasks.TaskBuilder+StepStateMachine<a>.nextAwaitable()
   --- End of inner exception stack trace ---
   at Step<b> FSharp.Control.Tasks.TaskBuilder+bindTaskConfigureFalse@131.Invoke(Unit unitVar0)
   at ICriticalNotifyCompletion FSharp.Control.Tasks.TaskBuilder+StepStateMachine<a>.nextAwaitable()
   at Step<b> FSharp.Control.Tasks.TaskBuilder+bindTaskConfigureFalse@131.Invoke(Unit unitVar0)
   at ICriticalNotifyCompletion FSharp.Control.Tasks.TaskBuilder+StepStateMachine<a>.nextAwaitable()
   at Step<b> FSharp.Control.Tasks.TaskBuilder+bindTaskConfigureFalse@131.Invoke(Unit unitVar0)
   at ICriticalNotifyCompletion FSharp.Control.Tasks.TaskBuilder+StepStateMachine<a>.nextAwaitable()
   at Step<b> FSharp.Control.Tasks.TaskBuilder+bindTaskConfigureFalse@131.Invoke(Unit unitVar0)
   at ICriticalNotifyCompletion FSharp.Control.Tasks.TaskBuilder+StepStateMachine<a>.nextAwaitable()
   at Step<Unit> [email protected](Unit unitVar0)
   at Step<a> FSharp.Control.Tasks.TaskBuilder.tryWith<a>(FSharpFunc<Unit, Step<a>> step, FSharpFunc<Exception, Step<a>> catch)

Reverting to 2.0.6 fixes the problem.

The stack trace doesn't tell me anything useful, but perhaps you know something, given that it happens in 2.0.7 but not in 2.0.6.

[smoothdeveloper]

@cmeeren thanks for the report, can you share what the type provider instanciation looks like?

The change in 2.0.7 is about table types, there was a tweak around constructing SqlMetaData objects, if you are using TVP, sharing the datatypes used in those would be helpful.

The unit tests of the library may not cover the specific type which fails, so I can add those to make sure there is no regression.

[cmeeren]

Here's the TP instantiation:

type Db =
  SqlProgrammabilityProvider<"
    Data Source=.;
    Initial Catalog=MyDbName;
    Integrated Security=True">

At runtime I use this connection string:

Server=tcp:MYSERVER.database.windows.net,1433;Initial Catalog=MYDB;Persist Security Info=False;User ID=MYUSER;Password=MYPASSWORD;MultipleActiveResultSets=False;Encrypt=True;TrustServerCertificate=False;Connection Timeout=30;

I invoke an sproc that uses TVP:

use cmd = new Db.dbo.User_Save(connStr)
do!
  cmd.AsyncExecute(
    userId = dto.UserId,
    ...
    sessions = (
      dto.Sessions
      |> Array.map (fun s ->
          Db.dbo.``User-Defined Table Types``.SaveSession(
            SessionId = s.SessionId,
            ...)
      )
    )
  )
  |> Async.Ignore<int>

The table type is defined like this:

CREATE TYPE [dbo].[SaveSession] AS TABLE
(
  [SessionId] NVARCHAR(100) NOT NULL,
  [IpAddress] NVARCHAR(45) NOT NULL,
  [Source] TINYINT NULL,
  [CreatedAt] DATETIMEOFFSET NOT NULL,
  [LastActive] DATETIMEOFFSET NOT NULL,
  [AbsoluteExpirationAfterSeconds] INT NOT NULL,
  [InactiveExpirationAfterSeconds] INT NOT NULL,
  [UserAgent] NVARCHAR(MAX) NULL
)

⚠ Note that I do not experience the problem if I connect to my local DB (the first connection string).

[smoothdeveloper]

We may deal with inconsistency among different versions of SQL Server, could you run the following query in both your local and production environment and bring back any difference you see between the two?

select 
	c.name
	, c.system_type_id
	, c.user_type_id
	, c.is_nullable
	, c.max_length
	, c.is_identity
	, c.is_computed
	, c.[precision]
	, c.scale
from 
	sys.table_types as tt
	inner join sys.columns as c on tt.type_table_object_id = c.object_id
order by 
	tt.user_type_id
	, c.column_id

[cmeeren]

No results in either case.

[smoothdeveloper]

mmmh, is it running on the application database or on the master database?

AFAIU, it should return the definition of TVP.

[cmeeren]

I ran it on the app databases.

[smoothdeveloper]

it looks different here:

[cmeeren]

My bad, I ran against the wrong DB.

They're idential and look like this:

[smoothdeveloper]

Ok, thanks, your best luck for now until I can reproduce it, would be to step through the provider itself through SqlClient.sln.

I've tried to add a test with TVP containing datetimeoffset and it passes, your best luck would be to try to run similar test against your production database.

You may try to debug the test from my branch: #394 running on same server where you face the issue.

What version of SQL Server which causes the issue?

[cmeeren]

What version of SQL Server which causes the issue?

Azure SQL.

[smoothdeveloper]

@cmeeren I don't have access to any such version, if you can't debug it, if you could privately share an usable connection to me, I'll try to debug it over the coming days.

[cmeeren]

I'll see what I can do. I came across a fix here for a similar issue in an unrelated repo. Could that help?

[cmeeren]

During development of my own SQL wrapper generator (mentioned in #383 (comment) and soon to be released), I believe I have found the issue.

I have not found it documented anywhere (SqlMetaData in general seems to be very poorly documented), but for the SQL types datetime2, datetimeoffset, and time, the precision parameter in the SqlMetaData constructor must be hardcoded to be 0uy.

In other words, this is wrong (The 23uy, 28uy, and 10uy comes from the DB query that fetches the table type schema):

SqlMetaData("datetime2", SqlDbType.DateTime2, 23uy, 3uy)  // Column defined as datetime2(3)
SqlMetaData("datetimeoffset", SqlDbType.DateTimeOffset, 28uy, 1uy)  // Column defined as datetimeoffset(1)
SqlMetaData("time", SqlDbType.Time, 10uy, 1uy)  // Column defined as time(1)

Whereas this works:

SqlMetaData("datetime2", SqlDbType.DateTime2, 0uy, 3uy)
SqlMetaData("datetimeoffset", SqlDbType.DateTimeOffset, 0uy, 1uy)
SqlMetaData("time", SqlDbType.Time, 0uy, 1uy)

I ran my (I daresay robust) suite of precision-loss-tests after making this change, and all tests still pass.

Note:

• In my case (in my generator), the problem seems to only occur if I pass multiple TVP rows. For some reason, if passing only one, it works anyway. I haven't tested this in SqlClient.
• I do not know of any side effects of using 0uy. Again, I have not seen this documented anywhere.
• A confusing aspect of size/precision/scale is that SqlParameter uses precision/scale only for decimal and uses size for other parametrized SQL types, whereas SqlMetaData requires the precision/scale constructor instead of the size constructor also for time, datetime2, and datetimeoffset (these use Size in SqlParameter). This is confusing since these three types only have a single parameter in SQL, and it is not documented anywhere what the other parameter should be set to in SqlMetaData. (As mentioned above, 0uy seems to work.)

[smoothdeveloper]

@cmeeren thanks a lot for the extensive reporting, I've put together a PR: #401 with adjustment if you could try it in your environment.

We don't have it running under unit tests because we don't have SQL Azure in the CI, I'm still unable to confirm.

[smoothdeveloper]

@cmeeren, I've published a 2.1.0-beta0 release with the fix from #401, if you have a chance to confirm it fixes the behaviour you were noticing, that would be great.

Thanks.

[cmeeren]

Thanks. Unfortunately I am on holiday now, and when I'm back in January I will need to focus on migrating our services to Facil. (Updating all the APIs is a lot of churn, so I can't prioritize updating SqlClient first and then waiting for a likely fixed intermittent issue to manifest itself.) Thanks for fixing it, though. As mentioned previously, it looks correct.