Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

SqlDataReader.GetStream(0).CopyToAsync hangs when CommandTimeout == 0 #1971

Closed
pacoteinnov opened this issue Mar 28, 2023 · 11 comments
Closed

Comments

@pacoteinnov
Copy link

Describe the bug

SqlDataReader.GetStream(0).CopyToAsync hangs when CommandTimeout == 0 and transferring more than 7937 bytes.

To reproduce

static async Task Test(string connectionString, Guid fileId)
{
    await using SqlConnection connection = new();
    connection.ConnectionString = connectionString;
    await connection.OpenAsync();

    await using SqlCommand command = new("SELECT [filedata] FROM FileTable where id = @fileId", connection);
    command.Parameters.AddWithValue("fileId", fileId);

    await using SqlDataReader reader = await command.ExecuteReaderAsync(System.Data.CommandBehavior.SequentialAccess);

    command.CommandTimeout = 0;

    if (await reader.ReadAsync() && !(await reader.IsDBNullAsync(0)))
    {
        MemoryStream outputStream = new();
        await reader.GetStream(0).CopyToAsync(outputStream);
    }
}

The table with a FILESTREAM column but I guess it happens with a VARBINARY.

It does not hang if I change the CommandTimeout to int.MaxValue.

I can create a complete project if needed.

Expected behavior

No hangs when transferring data from a stream.

Further technical details

Microsoft.Data.SqlClient version: 5.1.0
.NET target: .NET 7
SQL Server version: SQL Server 2019
Operating system: Windows 10

@lcheunglci
Copy link
Contributor

Hi @pacoteinnov, thanks for bringing this issue to our attention. When setting the CommandTimeout=0, it will wait indefinitely. However, it seems odd that it doesn't hang if you specified int.MaxValue or at least wait for a very long time before it times out. If you can provide a complete project that would be very help for us to investigate. Thanks!

@lcheunglci lcheunglci added the 🆕 Triage Needed For new issues, not triaged yet. label Mar 28, 2023
@lcheunglci
Copy link
Contributor

lcheunglci commented Mar 28, 2023

If you could also provide the stack trace or provide eventsource trace when it's hung, it would also be very helpful for us. Thanks!

@lcheunglci lcheunglci added ℹ️ Needs more Info Issues that have insufficient information to pursue investigations and removed 🆕 Triage Needed For new issues, not triaged yet. labels Mar 28, 2023
@pacoteinnov
Copy link
Author

All async logical stacks:
>	[Async] System.Private.CoreLib.dll!Task (int) [Promise]	C#
 	[Async] System.Private.CoreLib.dll!System.IO.Stream.CopyToAsync.__Core|27_0(System.IO.Stream, System.IO.Stream, int, System.Threading.CancellationToken) Line 108	C#
 	[Async] ReproIssue1971.dll!ReproIssue1971.Program.Repro(string, string, string, string) Line 58	C#
 	[Async] ReproIssue1971.dll!ReproIssue1971.Program.Main(string[]) Line 9	C#
 	ReproIssue1971.dll!ReproIssue1971.Program.<Main>(string[])	Unknown

>	[Async] Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.SqlSequentialStream.ReadAsync.AnonymousMethod__0(System.Threading.Tasks.Task<int>)	Unknown

@pacoteinnov
Copy link
Author

All threads stacks:

Not Flagged		32900	1	Main Thread	Main Thread	System.Private.CoreLib.dll!System.Threading.ManualResetEventSlim.Wait
 	 	 	 	 	 	System.Private.CoreLib.dll!System.Threading.ManualResetEventSlim.Wait(int, System.Threading.CancellationToken) Line 575
 	 	 	 	 	 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.SpinThenBlockingWait(int, System.Threading.CancellationToken) Line 3021
 	 	 	 	 	 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.InternalWaitCore(int, System.Threading.CancellationToken) Line 2956
 	 	 	 	 	 	System.Private.CoreLib.dll!System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(System.Threading.Tasks.Task) Line 145
 	 	 	 	 	 	[Waiting on Async Operation, double-click or press enter to view Async Call Stacks]
 	 	 	 	 	 	ReproIssue1971.dll!ReproIssue1971.Program.<Main>(string[])

Not Flagged		38296	4	Worker Thread	.NET Timer	System.Private.CoreLib.dll!System.Threading.WaitHandle.WaitOneNoCheck
 	 	 	 	 	 	System.Private.CoreLib.dll!System.Threading.WaitHandle.WaitOneNoCheck(int) Line 139
 	 	 	 	 	 	System.Private.CoreLib.dll!System.Threading.TimerQueue.TimerThread() Line 94

Not Flagged		35060	6	Worker Thread	.NET ThreadPool Worker	System.Private.CoreLib.dll!Interop.Kernel32.GetQueuedCompletionStatus
 	 	 	 	 	 	[Managed to Native Transition]
 	 	 	 	 	 	System.Private.CoreLib.dll!Interop.Kernel32.GetQueuedCompletionStatus(nint, out uint, out nuint, out nint, int) Line 4871
 	 	 	 	 	 	System.Private.CoreLib.dll!System.Threading.LowLevelLifoSemaphore.WaitForSignal(int) Line 204
 	 	 	 	 	 	System.Private.CoreLib.dll!System.Threading.LowLevelLifoSemaphore.Wait(int, bool) Line 124
 	 	 	 	 	 	System.Private.CoreLib.dll!System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() Line 71

Not Flagged		4200	7	Worker Thread	.NET ThreadPool Gate	System.Private.CoreLib.dll!System.Threading.WaitHandle.WaitOneNoCheck
 	 	 	 	 	 	System.Private.CoreLib.dll!System.Threading.WaitHandle.WaitOneNoCheck(int) Line 139
 	 	 	 	 	 	System.Private.CoreLib.dll!System.Threading.PortableThreadPool.GateThread.GateThreadStart() Line 49

Not Flagged		52324	8	Worker Thread	.NET ThreadPool Worker	System.Private.CoreLib.dll!Interop.Kernel32.GetQueuedCompletionStatus
 	 	 	 	 	 	[Managed to Native Transition]
 	 	 	 	 	 	System.Private.CoreLib.dll!Interop.Kernel32.GetQueuedCompletionStatus(nint, out uint, out nuint, out nint, int) Line 4871
 	 	 	 	 	 	System.Private.CoreLib.dll!System.Threading.LowLevelLifoSemaphore.WaitForSignal(int) Line 204
 	 	 	 	 	 	System.Private.CoreLib.dll!System.Threading.LowLevelLifoSemaphore.Wait(int, bool) Line 124
 	 	 	 	 	 	System.Private.CoreLib.dll!System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() Line 71

Not Flagged	>	7076	10	Worker Thread	.NET ThreadPool Worker	System.Private.CoreLib.dll!Interop.Kernel32.GetQueuedCompletionStatus
 	 	 	 	 	 	[Managed to Native Transition]
 	 	 	 	 	 	System.Private.CoreLib.dll!Interop.Kernel32.GetQueuedCompletionStatus(nint, out uint, out nuint, out nint, int) Line 4871
 	 	 	 	 	 	System.Private.CoreLib.dll!System.Threading.LowLevelLifoSemaphore.WaitForSignal(int) Line 204
 	 	 	 	 	 	System.Private.CoreLib.dll!System.Threading.LowLevelLifoSemaphore.Wait(int, bool) Line 124
 	 	 	 	 	 	System.Private.CoreLib.dll!System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() Line 71

@pacoteinnov
Copy link
Author

Event source:

<prov.DbConnectionHelper.ConnectionString_Set|API> 1, 'Data Source=localhost;Initial Catalog="redacted";User ID=redacted;Encrypt=False'
<sc.SqlConfigurableRetryLogicManager.ConnectionProvider|INFO> Requested the ConnectionProvider value.
<sc.AppConfigManager.FetchConfigurationSection|INFO>: Unable to load custom `SqlConfigurableRetryLogicConnection`. Default value of `T` type returns.
<sc.AppConfigManager.FetchConfigurationSection|INFO>: Unable to load custom `SqlConfigurableRetryLogicCommand`. Default value of `T` type returns.
SqlConnection.OpenAsyncRetry | Info | Object Id 1
<sc|SqlAuthenticationProviderManager|Ctor|Info>Neither SqlClientAuthenticationProviders nor SqlAuthenticationProviders configuration section found.
TdsParserStateObjectFactory.CreateTdsParserStateObject | Info | AppContext switch 'Switch.Microsoft.Data.SqlClient.UseManagedNetworkingOnWindows' not enabled, native networking implementation will be used.
TdsParser.Connect | SEC | Connection Object Id 4, Authentication Mode: SqlPassword
<sc.TdsParser.Connect|SEC> Sending prelogin handshake
<sc.TdsParser.SendPreLoginHandshake|INFO> ClientConnectionID 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, ActivityID cdc53ee5-7df0-4a05-9a4f-8f0caa4704da:1
<sc.TdsParser.Connect|SEC> Consuming prelogin handshake
<sc.TdsParser.Connect|SEC> Prelogin handshake successful
<sc.TdsParser.TryRun|SEC> Received login acknowledgement token
<sc.AppConfigManager.FetchConfigurationSection|INFO>: Unable to load custom `AppContextSwitchOverrides`. Default value of `T` type returns.
<sc.SqlAppContextSwitchManager.ApplyContextSwitches|INFO> Entry point.
<sc.SqlAppContextSwitchManager.ApplyContextSwitches|INFO> Exit point.
<sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|SetState|Info>State changed from NotStarted to HasLoggedIn.
<prov.DbConnectionFactory.CreatePooledConnection|RES|CPOOL> 1, Pooled database connection created.
SqlConnection.Retry | Info | Object Id 1
SqlCommand.Set_CommandText | API | Object Id 1, String Value = 'null', Client Connection Id null
SqlCommand.Set_Connection | API | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308
SqlCommand.Set_CommandText | API | Object Id 1, String Value = 'IF OBJECT_ID('TableWithBinaryData', 'U') IS NOT NULL DROP TABLE TableWithBinaryData', Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308
<sc.SqlConfigurableRetryLogicManager.CommandProvider|INFO> Requested the CommandProvider value.
SqlCommand.InternalExecuteNonQuery | INFO | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, AsyncCommandInProgress=False
SqlCommand.InternalExecuteNonQuery | INFO | Object Id 1, RPC execute method name BeginExecuteNonQuery, isAsync True, inRetry False
SqlCommand.RunExecuteNonQueryTds | Info | Object Id 1, Activity Id 81d8ae6a-73a5-4d7e-aa0c-15af6aa3dab2:1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, Command executed as SQLBATCH, Command Text 'IF OBJECT_ID('TableWithBinaryData', 'U') IS NOT NULL DROP TABLE TableWithBinaryData'
SqlCommand.SetActiveConnectionAndResult | API | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, MARS=False
TdsParserStateObject.ReadAsyncCallback | Info | State Object Id 1, received error 0 on idle connection
SqlCommand.InternalEndExecuteNonQuery | INFO | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, MARS=False, AsyncCommandInProgress=True
SqlCommand.VerifyEndExecuteState | API | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, MARS=False, AsyncCommandInProgress=True
TdsParserStateObject.DecrementOpenResultCount | INFO | State Object Id 1, Processing Attention.
CachedAsyncState.ResetAsyncState | API | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, AsyncCommandInProgress=True
CachedAsyncState.ResetAsyncState | API | ObjectId null, Client Connection Id null, AsyncCommandInProgress=null
SqlCommand.Set_CommandText | API | Object Id 2, String Value = 'null', Client Connection Id null
SqlCommand.Set_Connection | API | ObjectId 2, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308
SqlCommand.Set_CommandText | API | Object Id 2, String Value = 'CREATE TABLE TableWithBinaryData (id int, bindata VARBINARY(MAX))', Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308
<sc.SqlConfigurableRetryLogicManager.CommandProvider|INFO> Requested the CommandProvider value.
SqlCommand.InternalExecuteNonQuery | INFO | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, AsyncCommandInProgress=False
SqlCommand.InternalExecuteNonQuery | INFO | Object Id 2, RPC execute method name BeginExecuteNonQuery, isAsync True, inRetry False
SqlCommand.RunExecuteNonQueryTds | Info | Object Id 2, Activity Id b3efb635-3f63-4b33-b2e0-7ea9aef999a2:1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, Command executed as SQLBATCH, Command Text 'CREATE TABLE TableWithBinaryData (id int, bindata VARBINARY(MAX))'
SqlCommand.SetActiveConnectionAndResult | API | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, MARS=False
TdsParserStateObject.ReadAsyncCallback | Info | State Object Id 1, received error 0 on idle connection
SqlCommand.InternalEndExecuteNonQuery | INFO | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, MARS=False, AsyncCommandInProgress=True
SqlCommand.VerifyEndExecuteState | API | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, MARS=False, AsyncCommandInProgress=True
TdsParserStateObject.DecrementOpenResultCount | INFO | State Object Id 1, Processing Attention.
CachedAsyncState.ResetAsyncState | API | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, AsyncCommandInProgress=True
CachedAsyncState.ResetAsyncState | API | ObjectId null, Client Connection Id null, AsyncCommandInProgress=null
SqlCommand.Set_CommandText | API | Object Id 3, String Value = 'null', Client Connection Id null
SqlCommand.Set_Connection | API | ObjectId 3, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308
SqlCommand.Set_CommandText | API | Object Id 3, String Value = 'INSERT INTO TableWithBinaryData (id, bindata) VALUES (1, @bindata)', Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308
<sc.SqlConfigurableRetryLogicManager.CommandProvider|INFO> Requested the CommandProvider value.
SqlCommand.InternalExecuteNonQuery | INFO | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, AsyncCommandInProgress=False
SqlCommand.InternalExecuteNonQuery | INFO | Object Id 3, RPC execute method name BeginExecuteNonQuery, isAsync True, inRetry False
SqlCommand.SetActiveConnectionAndResult | API | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, MARS=False
TdsParserStateObject.ReadAsyncCallback | Info | State Object Id 1, received error 0 on idle connection
SqlCommand.InternalEndExecuteNonQuery | INFO | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, MARS=False, AsyncCommandInProgress=True
SqlCommand.VerifyEndExecuteState | API | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, MARS=False, AsyncCommandInProgress=True
TdsParserStateObject.DecrementOpenResultCount | INFO | State Object Id 1, Processing Attention.
CachedAsyncState.ResetAsyncState | API | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, AsyncCommandInProgress=True
CachedAsyncState.ResetAsyncState | API | ObjectId null, Client Connection Id null, AsyncCommandInProgress=null
SqlCommand.Set_CommandText | API | Object Id 4, String Value = 'null', Client Connection Id null
SqlCommand.Set_Connection | API | ObjectId 4, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308
SqlCommand.Set_CommandText | API | Object Id 4, String Value = 'SELECT bindata FROM TableWithBinaryData WHERE id = @id', Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308
<sc.SqlConfigurableRetryLogicManager.CommandProvider|INFO> Requested the CommandProvider value.
SqlCommand.InternalExecuteReaderAsync | API> 4, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, Command Text = 'SELECT bindata FROM TableWithBinaryData WHERE id = @id'
SqlCommand.RunExecuteReaderTds | Info | Object Id 4, Activity Id b3efb635-3f63-4b33-b2e0-7ea9aef999a2:1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, Command executed as RPC, RPC Name 'sp_executesql'
SqlCommand.SetActiveConnectionAndResult | API | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, MARS=False
TdsParserStateObject.ReadAsyncCallback | Info | State Object Id 1, received error 0 on idle connection
SqlCommand.EndExecuteReaderInternal | API | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, MARS=False, AsyncCommandInProgress=True
SqlCommand.InternalEndExecuteReader | INFO | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, MARS=False, AsyncCommandInProgress=True
SqlCommand.VerifyEndExecuteState | API | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, MARS=False, AsyncCommandInProgress=True
CachedAsyncState.ResetAsyncState | API | ObjectId 1, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308, AsyncCommandInProgress=True
SqlCommand.Set_CommandTimeout | API | ObjectId 4, Command Timeout value 0, Client Connection Id 1b0d7aa3-2390-4d78-9ba9-283c8ef53308
TdsParserStateObject.ReadAsyncCallback | Info | State Object Id 1, received error 0 on idle connection

@pacoteinnov
Copy link
Author

The project: https://github.com/pacoteinnov/ReproIssue1917

@pacoteinnov
Copy link
Author

I have these two exceptions (that are not present without the CommandTimeout=0):


System.NullReferenceException
  HResult=0x80004003
  Message=Object reference not set to an instance of an object.
  Source=Microsoft.Data.SqlClient
  StackTrace:
   at Microsoft.Data.SqlClient.SqlDataReader.SqlDataReaderAsyncCallContext`2.DisposeCore()
System.NullReferenceException
  HResult=0x80004003
  Message=Object reference not set to an instance of an object.
  Source=Microsoft.Data.SqlClient
  StackTrace:
   at Microsoft.Data.SqlClient.SqlDataReader.SqlDataReaderAsyncCallContext`2.DisposeCore()
   at Microsoft.Data.SqlClient.AAsyncBaseCallContext`2.ClearCore()
   at Microsoft.Data.SqlClient.AAsyncBaseCallContext`2.Dispose()
   at Microsoft.Data.SqlClient.SqlDataReader.CompleteAsyncCall[T](Task`1 task, SqlDataReaderBaseAsyncCallContext`1 context)
   at Microsoft.Data.SqlClient.SqlDataReader.SqlDataReaderBaseAsyncCallContext`1.CompleteAsyncCallCallback(Task`1 task, Object state)
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs:line 268
--- End of stack trace from previous location ---

  This exception was originally thrown at this call stack:
    Microsoft.Data.SqlClient.SqlDataReader.SqlDataReaderAsyncCallContext<T, TDisposable>.DisposeCore()
    Microsoft.Data.SqlClient.AAsyncBaseCallContext<TOwner, TTask>.ClearCore()
    Microsoft.Data.SqlClient.AAsyncBaseCallContext<TOwner, TTask>.Dispose()
    Microsoft.Data.SqlClient.SqlDataReader.CompleteAsyncCall<T>(System.Threading.Tasks.Task<T>, Microsoft.Data.SqlClient.SqlDataReader.SqlDataReaderBaseAsyncCallContext<T>)
    Microsoft.Data.SqlClient.SqlDataReader.SqlDataReaderBaseAsyncCallContext<T>.CompleteAsyncCallCallback(System.Threading.Tasks.Task<T>, object)
    System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(System.Threading.Thread, System.Threading.ExecutionContext, System.Threading.ContextCallback, object) in ExecutionContext.cs

@ErikEJ
Copy link
Contributor

ErikEJ commented Mar 28, 2023

See #1903 - fixed in 5.1.1

@lcheunglci
Copy link
Contributor

Thanks @ErikEJ for spotting that. The v5.1.1 release should be out later today.

@lcheunglci lcheunglci removed the ℹ️ Needs more Info Issues that have insufficient information to pursue investigations label Mar 28, 2023
@lcheunglci
Copy link
Contributor

Please try out the new v5.1.1 release and let us know or close the issue if this resolves your issue. Thanks!

@pacoteinnov
Copy link
Author

Please try out the new v5.1.1 release and let us know or close the issue if this resolves your issue. Thanks!

I confirm that the 5.1.1 release fixes the problems. Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants