search

dotnet / SqlClient

Microsoft.Data.SqlClient provides database connectivity to SQL Server for .NET applications.
MIT License
842 stars 281 forks source link

When server is unreachable, CancellationToken does not cancel the automatical retries #1619

Open janseris opened 2 years ago

janseris commented 2 years ago

Describe the bug

I am using a MAUI Blazor application. This occurs on Windows as well as on Android and I think it is not MAUI specific - it probably happens on any other platform (Console/WinForms, ...) The issue is that when DB server is unreachable (internet connection is OFF or the connection string is wrong), applying CancellationToken does nothing to stop/cancel connecting to the server. The CancellationToken is OK - I have tried debugging into the Data Access Layer EF Core function and the original CancellationToken is passed in as expected. The task itself is cancelled, but in the background, SqlClient is spamming for approximately 20 seconds until it gives up.

A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll

Code:

async Task RunAsyncDbCall()
    {
        int limitMilliseconds = 3000;
        cts = new CancellationTokenSource(limitMilliseconds /* ms */);
        Loading = true;
        var token = cts.Token;
        var DBCall = DBWarmUpService.TryWarmupDB;
        try
        {
            Trace.WriteLine($"-----[{DateTime.Now:HH:mm:ss.fff}] Trying WarmUp DB call with task cancellation timeout {limitMilliseconds} ms");

            await DBCall(token);
            Print($"---The task was completed [{DateTime.Now:HH:mm:ss.fff}]");
        }
        catch (OperationCanceledException)
        {
            Print($"---The task was cancelled [{DateTime.Now:HH:mm:ss.fff}]");
        }
        catch (Exception ex)
        {
            Trace.WriteLine(ExceptionHelper.GetExAndInnerExInfo(ex));
        }
        Loading = false; //in any case
    }

The code above calls this method in the end, deep in the layered architecture:

public async Task<int> DBWarmUpCall(CancellationToken token = default)
        {
            using (var db = DB)
            {
                var query =
                    from user in db.USER
                    select 1;
                var result = await query.FirstOrDefaultAsync(token);
                return result;
            }
        }

Output:

thread handling the ConnectivityChanged event: 1
Internet connection profiles: 
Network Access: Unknown
-----[01:55:55.162] Trying WarmUp DB call with task cancellation timeout 3000 ms
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\System.Linq.Queryable.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\Microsoft.EntityFrameworkCore.SqlServer.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\System.Collections.Immutable.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\Microsoft.EntityFrameworkCore.Relational.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\Microsoft.EntityFrameworkCore.Abstractions.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\System.ComponentModel.Primitives.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\Microsoft.Extensions.Caching.Abstractions.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\System.Diagnostics.DiagnosticSource.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\System.Transactions.Local.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'Anonymously Hosted DynamicMethods Assembly'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\Microsoft.Extensions.Caching.Memory.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\System.ComponentModel.Annotations.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\System.Net.NetworkInformation.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\System.Runtime.Extensions.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\System.Threading.Tasks.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\System.Threading.Timer.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\System.Resources.ResourceManager.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\System.Configuration.ConfigurationManager.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\System.Collections.Specialized.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\System.Net.WebClient.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\System.ComponentModel.EventBasedAsync.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\Microsoft.Identity.Client.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\System.Text.Encoding.CodePages.dll'. 
'Tempus.GUI.Mobile.MAUIBlazor.exe' (CoreCLR: clrhost): Loaded 'C:\Tempus.GUI.Mobile\Tempus.GUI.Mobile.Blazor\bin\Debug\net6.0-windows10.0.19041.0\win10-x64\AppX\Microsoft.Win32.Primitives.dll'. 
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'System.Threading.Tasks.TaskCanceledException' in System.Private.CoreLib.dll
A task was canceled.
Exception thrown: 'System.Threading.Tasks.TaskCanceledException' in System.Private.CoreLib.dll
A task was canceled.
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'System.Threading.Tasks.TaskCanceledException' in System.Private.CoreLib.dll
A task was canceled.
Exception thrown: 'System.Threading.Tasks.TaskCanceledException' in System.Private.CoreLib.dll
A task was canceled.
Exception thrown: 'System.Threading.Tasks.TaskCanceledException' in System.Private.CoreLib.dll
A task was canceled.
Exception thrown: 'System.Threading.Tasks.TaskCanceledException' in System.Private.CoreLib.dll
A task was canceled.
Exception thrown: 'System.Threading.Tasks.TaskCanceledException' in System.Private.CoreLib.dll
A task was canceled.
Exception thrown: 'System.Threading.Tasks.TaskCanceledException' in Microsoft.EntityFrameworkCore.Relational.dll
A task was canceled.
Exception thrown: 'System.Threading.Tasks.TaskCanceledException' in System.Private.CoreLib.dll
A task was canceled.
Exception thrown: 'System.Threading.Tasks.TaskCanceledException' in System.Private.CoreLib.dll
A task was canceled.
Exception thrown: 'System.Threading.Tasks.TaskCanceledException' in System.Private.CoreLib.dll
A task was canceled.
Exception thrown: 'System.Threading.Tasks.TaskCanceledException' in System.Private.CoreLib.dll
A task was canceled.
Exception thrown: 'System.Threading.Tasks.TaskCanceledException' in System.Private.CoreLib.dll
A task was canceled.
Exception thrown: 'System.Threading.Tasks.TaskCanceledException' in System.Private.CoreLib.dll
A task was canceled.
---The task was cancelled [01:55:59.130]
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
The thread 0xdcc has exited with code 0 (0x0).
The thread 0x4118 has exited with code 0 (0x0).
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
Exception thrown: 'Microsoft.Data.SqlClient.SqlException' in Microsoft.Data.SqlClient.dll
A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)```

To reproduce

Call FirstOrDefaultAsync on DbContext with CancellationToken.

Expected behavior

CancellationToken cancels the database connection attempts.

Further technical details

latest previews Additional context Add any other context about the problem here.

JRahnama commented 2 years ago

@janseris thanks for bringing this up. We currently are busy with our preview release tasks, We will resume on this after the release. Thanks for your patience.

janseris commented 2 years ago

@JRahnama Hi, has the time come now? Thanks I am still exploring how SqlCommands and SqlConnections are cancelled and what are the possibilities and it cancelling a SqlCommand requires a roundtrip to the database etc. Do you maybe have a link to any documentation explaining this? I cannot find a lot of details other than by trial and error method such as how this bug/unexpected behavior was found.

lcheunglci commented 2 years ago

I just checked with the team. This is a bug, and will need to do some investigation to see why the CancellationToken is not passed into the correct context where it can stop the execution. Once we have a fix, we'll get back to you soon.

Kaur-Parminder commented 1 year ago

@janseris Can you provide more details on scenario what are you doing when warmup DB? do you stop SQL Server service to make it unreachable in between?

Can you provide repro with console app and connection string that you are using?

janseris commented 1 year ago

@janseris Can you provide more details on scenario what are you doing when warmup DB? do you stop SQL Server service to make it unreachable in between?

do you stop SQL Server service to make it unreachable in between?

No, I don't touch SQL Server. I reproduce the "no connection situation" by simulating or turning off the internet connection on the client device (e.g. Android phone in this case). If I remember correctly, turning off the internet connection is sufficient to reproduce this bug.

Edit: I reviewed my original post and in this scenario, the "warmup db call" is just a normal DB call. Imagine that it is SELECT * FROM Users and that it is called GetAllUsers() (the actual code there is (SELECT 1 FROM Users).

Can you provide connection string that you are using?

Connection string is casual: server address, db name, SQL login, SQL password. Nothing else.

Can you provide repro with console app?

I do not have a repro console app. Shouldn't be hard to create. Some IServiceCollection.AddDbContextFactory etc.

In the call using (var db = DB), DB is just a shortcut to dbContextFactory.CreateDbContext()

janseris commented 1 year ago

Can you provide repro with console app and connection string that you are using?

I am sorry it's been almost a year and I do not have that test app anymore.

Kaur-Parminder commented 1 year ago

@janseris I tried this with MAUI App with sqlclient directly against cloud server by turning internet OFF on client side as you mentioned. I am not seeing this happening. My code is attached. I tried the step as you specified, a warmup call and following call with token cancel request and I am only seeing expected exceptions depending when internet goes off on second call.

Rollback Exception Type: Microsoft.Data.SqlClient.SqlException [DOTNET] Message: A transport-level error has occurred when receiving results from the server. (provider: TCP Provider, error: 35 - An internal exception was caught) Thread finished: Or Operation cancelled by user.

Retriesoncancellation-client.zip