SQL Trace/Profiler - Ambiguous date format being displayed (.NET Core/EF)

user_10916580 0
Viewed 728

We have a SQL Server 2008R2 instance installed with a language of English (United States). SSMS > Instance > Properties > General.

We have a Login set up with default language "British English". SSMS > Security > Logins > User > Properties.

The front end .NET Core application generates an insert statement (EF) via a form/Web API, which creates an "sp_executesql" system stored procedure using the Login set up above.

Using the SQL Server Profiler, I can see that the generated insert SQL contains string dates in the format 'yyyy-mm-dd'. For example "2019-01-15 10:59:19.410".

Prior to executing the statement there is an exec sp_reset_connection followed by the following SET statements (I believe this has something to do with connection pool sharing to ensure correct settings for each login).

-- network protocol: LPC
set quoted_identifier on
set arithabort off
set numeric_roundabort off
set ansi_warnings on
set ansi_padding on
set ansi_nulls on
set concat_null_yields_null on
set cursor_close_on_commit off
set implicit_transactions off
set language British
set dateformat dmy
set datefirst 1
set transaction isolation level read committed

What is confusing me is that the statement runs successfully even though there are dates in the yyyy-mm-dd format whilst the environment is set up as British English (DMY). For example - "2019-01-15 10:59:19.410".

I have learnt that "2019-01-15 10:59:19.410" will be interpreted as 1st day of the 15th month 2019 if DMY is current setting.

For example this will fail as SQL will try to interpret date string as yyyy-dd-mm

SET LANGUAGE [British English];

SELECT
    CAST('2019-01-13' AS DATETIME);

Msg 242, Level 16, State 3, Line 3 The conversion of a varchar data type to a datetime data type resulted in an out-of-range value.

Setting language to English (us_english) changes string interpretation to MDY and the above statement works.

I am aware that I can use non ambiguous date strings but the issue I am having is related to the date strings being generated by the EF front end.

I can't work out why the statement is running successfully. Obviously there are implicit casts from date strings to DATETIME types.

If I copy the statement from SQL profiler and paste into SSMS and try to run against the same database/same user then it fails as I would expect.

Msg 8114, Level 16, State 1, Line 14 Error converting data type varchar to datetime.

So...

I understand what is going on when converting from string dates to DATETIME type and get consistent results running queries in SSMS but I can't understand why a query that fails in SSMS is running from the front end.

I apologise if this isn't very well explained.

entity-framework-core asp.net-core sql-server
2 Answers

What actually happens is that Entity Framework generates parameterized statements which are then passed to the server using the (binary) TDS protocol, which is how applications talk to SQL Server. DATETIME values passed as RPC parameters are not passed as strings -- they are passed as byte sequences that represent an exact value (for example, 2019-01-15T10:59:19.410 is represented as D6 A9 00 00 AF 16 B5 00 when sent over as a DATETIME (two little-endian integers). (Disclaimer: I haven't actually checked with a packet sniffer, so I may have gotten the bytes wrong).

When these parameterized statements are presented by SQL Profiler as if they were text batches, it reformats the values into strings because T-SQL has no native literal format for DATETIME values. Unfortunately it does so with a format that's not guaranteed to roundtrip under all possible language settings, which should be considered a bug in Profiler. All it's missing is a T, but that's an important omission.

Something similar happens with the mysterious exec sp_reset_connection calls you can see littering the traces of all applications that use connection pooling -- no application actually generates these calls, and if you try to execute this statement in Management Studio you'll see that there is no sp_reset_connection procedure. On the protocol level, there is just a "reset this connection" bit in the packet header that is translated to a fictitious call with fictitious SET statements representing the current options when this is presented as a statement or event trace.

In short: your applications are working fine, but if you want to replay exactly what happens when they're making calls, copy-pasting the Profiler output won't do.

user_41379160

I have just stumbled across this blog that explains it very clearly - https://weblogs.sqlteam.com/dang/2007/10/11/sql-trace-parameter-values-are-not-always-as-they-seem/

Images in the above link are no longer available (originally posted in 2007).

The text however is very informative, which I have pasted below before it disappears completely.

I hope that this helps somebody.

Dan Guzman Blog

SQL Trace Parameter values are not always as they seem Thu Oct 11, 2007 by Dan Guzman

I stumbled across surprising SQL Trace/Profiler behaviour I think is worth mentioning. Parameter values reported in trace RPC starting/completed events are not the values that SQL Server uses to execute the query. Here’s an example I recently discovered that shows this behavior. I ran the following C# code to execute parameterized query "SELECT @DateTime" with the parameter value set to October 11, 2007. The console message verified that SQL Server returned the expected date.

I pasted the script from the trace and ran it from a SQL Server Management Studio query window. Here’s the trace of the SSMS script execution:

Even though the SQL looks the same, the SSMS query returned a different date (“November 10, 2007”) than the application ("October 11, 2007")! What’s up with that? Why would the same script return different values when run from application code vs. Management Studio (or Query Analyzer), even with identical session settings?

The reason for the behavior difference is the trace event class. The application trace showed an RPC:Completed event but the SSMS session trace showed SQL:BatchCompleted. Both had the same “exec sp_executesql…” statement in the TextData. Even though the trace reported the same TextData for both events, SQL Server processed the RPC differently than the SQL batch and the trace didn’t show the complete story for the RPC event.

The issue is that the datetime input parameter value for the RPC event was not really included in the SQL statement like the trace RPC:Completed event showed. The actual datetime parameter value that SQL Server used during RPC execution was passed in native (i.e. binary) format via the low-level TDS protocol. The trace TextData was only a reverse-engineered string representation of that value rather than the actual value SQL Server used.

In contrast, the batch sent by SSMS wasn’t parameterized so SQL Server needed to parse the datetime string value in the batch text. The datetime string "2007-10-11 00:00:00:000" (generated by the trace, not passed by the app) is ambiguous and interpreted differently depending on the DATEFORMAT setting. Due to the "DATEFORMAT DMY" setting in the script, the date string value was (mis)interpreted as November 10, 2007 instead of October 11, 2007. The DATEFORMAT setting had no affect on the RPC (parameterized value) because the setting affects only string parsing and not the native datetime value provided by the application.

I discovered this issue when I was helping a user who was working with a French language SQL Server (that's why I specified DATEFORMAT DMY) troubleshoot a datetime parameter problem. The trace data led me down the wrong path because it didn't immediately click with me that 1) DATEFORMAT doesn't affect RPC datetime parameters and 2) trace RPC TextData isn't used for query execution anyway. I filed Connect feedback on this to suggest that SQL Trace/Profiler be changed to serialize RPC datetime values in a DATEFORMAT neutral format like "2007-10-11T00:00:00:000" or "20071011 00:00:00:000". This will provide the same behavior when the trace TextData SQL is executed as a batch and be a bit more intuitive when analyzing trace data.

Copyright © 2018 - Dan Guzman

user_109165800
Related