SqlAgDatabase: Timeout elapsed during backup on secondary

[dlenkov]

Problem description

Trying to add 675GB database to SQL AG.
The backup operation times out on secondary node.
The issue is similar to the one described in #1358, but the current one is related to backup, not restore.

Verbose logs

"msg": "Failed to invoke DSC Set method: PowerShell DSC resource DSC_SqlAGDatabase  failed to execute Set-TargetResource functionality with error message: The operation on the database 'dbtsta1000' failed with the following errors: System.ComponentModel.Win32Exception (0x80004005): The wait operation timed out\r\n   at System.Management.Automation.MshCommandRuntime.ThrowTerminatingError(ErrorRecord errorRecord). ",

"verbose_set": [
    "Perform operation 'Invoke CimMethod' with following parameters, ''methodName' = ResourceSet,'className' = MSFT_DSCLocalConfigurationManager,'namespaceName' = root/Microsoft/Windows/DesiredStateConfiguration'.",
    "An LCM method call arrived from computer SERVER-NODE-02 with user sid S-1-5-21-7777777777-8888888888-999999999-00000.",
    "[server-node-02]: LCM:  [ Start  Set      ]  [[SqlAGDatabase]DirectResourceAccess]",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] Found PowerShell module SQLPS already imported in the session. (SQLCOMMON0026)",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] Found PowerShell module SQLPS already imported in the session. (SQLCOMMON0026)",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] Connecting as current user 'DOMAIN\\service-user' using integrated security. (SQLCOMMON0054)",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] Connected to SQL instance 'server-node-01\\DB01'. (SQLCOMMON0018)",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] Adding the following databases to the 'dbtsta1000' availability group: dbtsta1000.",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] Found PowerShell module SQLPS already imported in the session. (SQLCOMMON0026)",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] Connecting as current user 'DOMAIN\\service-user' using integrated security. (SQLCOMMON0054)",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] Connected to SQL instance 'server-node-02\\DB01'. (SQLCOMMON0018)",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] Found PowerShell module SQLPS already imported in the session. (SQLCOMMON0026)",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] Connecting as current user 'DOMAIN\\service-user' using integrated security. (SQLCOMMON0054)",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] Connected to SQL instance 'server-node-02\\DB01'. (SQLCOMMON0018)",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] Returning the results of the query `EXEC master.dbo.xp_fileexist 'D:\\Data'`. (SQLCOMMON0057)",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] Found PowerShell module SQLPS already imported in the session. (SQLCOMMON0026)",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] Connecting as current user 'DOMAIN\\service-user' using integrated security. (SQLCOMMON0054)",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] Connected to SQL instance 'server-node-02\\DB01'. (SQLCOMMON0018)",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] Returning the results of the query `EXEC master.dbo.xp_fileexist 'E:\\Log'`. (SQLCOMMON0057)",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] BACKUP DATABASE [dbtsta1000] TO  DISK = N'\\\\server-node-02\\backup\\dbtsta1000_Full_20220418113646.bak' WITH NOFORMAT, NOINIT, NOSKIP, REWIND, NOUNLOAD,  STATS = 10",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] 10 percent processed.",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] 20 percent processed.",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] 30 percent processed.",
    "[server-node-02]:                            [[SqlAGDatabase]DirectResourceAccess] The backup or restore was aborted.",
    "[server-node-02]: LCM:  [ End    Set      ]  [[SqlAGDatabase]DirectResourceAccess]  in 601.0670 seconds.",
    "Operation 'Invoke CimMethod' complete.",
    "Time taken for configuration job to complete is 601.225 seconds"
]

DSC configuration

"AvailabilityGroupName": "dbtsta1000",
"BackupPath": "\\server-node-02\backup",
"DatabaseName": "dbtsta1000"
"DependsOn": null,
"Ensure": "Present",
"Force": null,
"InstanceName": "DB01",
"MatchDatabaseOwner": null,
"ProcessOnlyOnActiveNode": null,
"PsDscRunAsCredential_password": "password",
"PsDscRunAsCredential_username": "[email protected]",
"ReplaceExisting": null,
"ServerName": "server-node-01",
"module_version": "15.2.0",
"resource_name": "SqlAGDatabase"

Suggested solution

Add StatementTimeout parameter with value of 0 (no timeout) to the invocation of Connect-SQL in the Set-TargetResource function in SqlAGDatabase resource (DSC_SqlAGDatabase.psm1).

SQL Server edition and version

Microsoft SQL Server 2019 (RTM-CU12) (KB5004524) - 15.0.4153.1 (X64)   Jul 19 2021 15:37:34   Copyright (C) 2019 Microsoft Corporation  Developer Edition (64-bit) on Windows Server 2019 Standard 10.0 <X64> (Build 17763: ) (Hypervisor)

SQL Server PowerShell modules

Name  Version Path
----  ------- ----
SQLPS 15.0    C:\Program Files (x86)\Microsoft SQL Server\150\Tools\PowerShell\Modules\SQLPS\SQLPS.psd1

Operating system

OsName               : Microsoft Windows Server 2019 Standard
OsOperatingSystemSKU : StandardServerEdition
OsArchitecture       : 64-bit
WindowsVersion       : 1809
WindowsBuildLabEx    : 17763.1.amd64fre.rs5_release.180914-1434
OsLanguage           : en-US
OsMuiLanguages       : {en-US}

PowerShell version

Name                           Value
----                           -----
PSVersion                      5.1.17763.2268
PSEdition                      Desktop
PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0...}
BuildVersion                   10.0.17763.2268
CLRVersion                     4.0.30319.42000
WSManStackVersion              3.0
PSRemotingProtocolVersion      2.3
SerializationVersion           1.1.0.1

SqlServerDsc version

Name         Version Path
----         ------- ----
SqlServerDsc 15.2.0  C:\Program Files\WindowsPowerShell\Modules\SqlServerDsc\15.2.0\SqlServerDsc.psd1

[johlju]

I think we should add a new parameter StatementTimeout to SqlAgDatabase so users can specify the timeout themself rather than hardcode it to 0. Hardcoding it could lead to that it never timeout when it for some reason failed. 🤔

[dlenkov]

Makes sense, done and updated the PR.