DacFx icon indicating copy to clipboard operation
DacFx copied to clipboard
verified publisher icon microsoft

SqlPackage Import fails with timeout when enabling triggers

Open craigminihan opened this issue 4 years ago • 5 comments

  • SqlPackage or DacFx Version: 16.0.5400.1
  • .NET Framework (Windows-only) or .NET Core: 4.7.02053
  • Environment (local platform and source/target platforms): Windows Server 2019 Standard, SQL Server 2017, Azure SQL Database

Steps to Reproduce:

  1. Export database with SqlPackage to bacpac file
  2. Import database with SqlPackage into Azure SQL Database Elastic Pool (Gen5 8 vCores)
  3. Import runs and completes processing tables and enables indexes
  4. Timeout when enabling triggers as follows:
Microsoft.Data.Tools.Diagnostics.Tracer Verbose: 0 : 2022-04-21T21:01:42 : Executing Step 1492, Not Tracked, Type 'EnableDmlTriggersStep', Section 'None', Operation '0', Ignorable Errors 'None', Script is as follows: 

ENABLE TRIGGER [dbo].[trig_Search_Specification]
    ON [dbo].[tbl_Company_Specification];

Microsoft.Data.Tools.Diagnostics.Tracer Error: 19 : 2022-04-21T21:02:12 : Retry requested: Retry count = 1. Delay = 00:00:00.2500000, SQL Error Code = -2146232060, SQL Error Number = -2, Can retry error = True, Will retry = True Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.ComponentModel.Win32Exception (0x80004005): The wait operation timed out
   at Microsoft.Data.SqlClient.SqlCommand.<>c.<RunExecuteReaderTds>b__243_0()
   at Microsoft.Data.SqlClient.AsyncHelper.WaitForCompletion(Task task, Int32 timeout, Action onTimeout, Boolean rethrowExceptions)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at Microsoft.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
   at Microsoft.Data.Tools.Schema.Common.SqlClient.ReliableSqlConnection.QuerySessionSettings(IDbCommand originalCommand)
   at Microsoft.Data.Tools.Schema.Common.SqlClient.ReliableSqlConnection.CacheOrReplaySessionSettings(IDbCommand originalCommand, Tuple`2[] sessionSettings)
   at Microsoft.Data.Tools.Schema.Common.SqlClient.ReliableSqlConnection.<>c__DisplayClass2.<ExecuteReader>b__1()
   at Microsoft.Data.Tools.Schema.Common.SqlClient.RetryPolicy.ExecuteAction[R](Func`2 func, Nullable`1 token)
ClientConnectionId:00000000-0000-0000-0000-000000000000
Error Number:-2,State:0,Class:11
Microsoft.Data.Tools.Diagnostics.Tracer Warning: 0 : 2022-04-21T21:02:12 : Retry occurred: session: 77dffe89-d0f0-4047-8f47-27c9e1095d13; attempt - 1; delay - 00:00:00.2500000; exception - "Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.ComponentModel.Win32Exception (0x80004005): The wait operation timed out
   at Microsoft.Data.SqlClient.SqlCommand.<>c.<RunExecuteReaderTds>b__243_0()
   at Microsoft.Data.SqlClient.AsyncHelper.WaitForCompletion(Task task, Int32 timeout, Action onTimeout, Boolean rethrowExceptions)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at Microsoft.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
   at Microsoft.Data.Tools.Schema.Common.SqlClient.ReliableSqlConnection.QuerySessionSettings(IDbCommand originalCommand)
   at Microsoft.Data.Tools.Schema.Common.SqlClient.ReliableSqlConnection.CacheOrReplaySessionSettings(IDbCommand originalCommand, Tuple`2[] sessionSettings)
   at Microsoft.Data.Tools.Schema.Common.SqlClient.ReliableSqlConnection.<>c__DisplayClass2.<ExecuteReader>b__1()
   at Microsoft.Data.Tools.Schema.Common.SqlClient.RetryPolicy.ExecuteAction[R](Func`2 func, Nullable`1 token)
ClientConnectionId:00000000-0000-0000-0000-000000000000
Error Number:-2,State:0,Class:11"
Microsoft.Data.Tools.Diagnostics.Tracer Error: 19 : 2022-04-21T21:02:12 : Retry requested: Retry count = 1. Delay = 00:00:00.2500000, SQL Error Code = -2146232060, SQL Error Number = -2, Can retry error = True, Will retry = True Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.ComponentModel.Win32Exception (0x80004005): The wait operation timed out
   at Microsoft.Data.SqlClient.SqlCommand.<>c.<RunExecuteReaderTds>b__243_0()
   at Microsoft.Data.SqlClient.AsyncHelper.WaitForCompletion(Task task, Int32 timeout, Action onTimeout, Boolean rethrowExceptions)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at Microsoft.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
   at Microsoft.Data.Tools.Schema.Common.SqlClient.ReliableSqlConnection.QuerySessionSettings(IDbCommand originalCommand)
   at Microsoft.Data.Tools.Schema.Common.SqlClient.ReliableSqlConnection.CacheOrReplaySessionSettings(IDbCommand originalCommand, Tuple`2[] sessionSettings)
   at Microsoft.Data.Tools.Schema.Common.SqlClient.ReliableSqlConnection.<>c__DisplayClass5.<ExecuteScalar>b__4()
   at Microsoft.Data.Tools.Schema.Common.SqlClient.RetryPolicy.ExecuteAction[R](Func`2 func, Nullable`1 token)
ClientConnectionId:00000000-0000-0000-0000-000000000000
Error Number:-2,State:0,Class:11
Microsoft.Data.Tools.Diagnostics.Tracer Warning: 0 : 2022-04-21T21:02:12 : Retry occurred: session: 77dffe89-d0f0-4047-8f47-27c9e1095d13; attempt - 1; delay - 00:00:00.2500000; exception - "Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.ComponentModel.Win32Exception (0x80004005): The wait operation timed out
   at Microsoft.Data.SqlClient.SqlCommand.<>c.<RunExecuteReaderTds>b__243_0()
   at Microsoft.Data.SqlClient.AsyncHelper.WaitForCompletion(Task task, Int32 timeout, Action onTimeout, Boolean rethrowExceptions)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at Microsoft.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
   at Microsoft.Data.Tools.Schema.Common.SqlClient.ReliableSqlConnection.QuerySessionSettings(IDbCommand originalCommand)
   at Microsoft.Data.Tools.Schema.Common.SqlClient.ReliableSqlConnection.CacheOrReplaySessionSettings(IDbCommand originalCommand, Tuple`2[] sessionSettings)
   at Microsoft.Data.Tools.Schema.Common.SqlClient.ReliableSqlConnection.<>c__DisplayClass5.<ExecuteScalar>b__4()
   at Microsoft.Data.Tools.Schema.Common.SqlClient.RetryPolicy.ExecuteAction[R](Func`2 func, Nullable`1 token)
ClientConnectionId:00000000-0000-0000-0000-000000000000
Error Number:-2,State:0,Class:11"

etc.

Post failure the trigger can be enabled in SSMS with no issue via the context menu or executing the ENABLE TRIGGER directly.

Intervening during the retry sequence and enabling the trigger does not affect the outcome, the retry loop continues with eventual failure of the import.

Did this occur in prior versions? If not - which version(s) did it work in? Unknown

(DacFx/SqlPackage/SSMS/Azure Data Studio)

craigminihan avatar Apr 21 '22 20:04 craigminihan

DacFx does not support importing into elastic pools, as mentioned in the limitations for bacpacs. The workaround for importing into an elastic pool is to create a single database for DacFx operations, then move the database into an elastic pool. Can you try doing this and see if the enabling triggers is still timing out?

There are also a couple parameters that might help with the timeout error: /p:CommandTimeout and /p: LongRunningCommandTimeout. More info on these options can be found here.

kisantia avatar Apr 26 '22 20:04 kisantia

@kisantia thanks for the pointers, I'll run it into a dedicated Gen5 now.

Timeout-wise I'm already using:

  • /TargetTimeout:60
  • /p:CommandTimeout=3600
  • /p:LongRunningCommandTimeout=0

Let me know if you recommend other timeout values.

craigminihan avatar Apr 26 '22 22:04 craigminihan

@kisantia I ran on a Gen5 Business Critical 8 vCore, however it failed on the triggers in exactly the same way as before.

I created a new backup with a /TableData:smalltable param to restrict the amount of data in the bacpac. I ran the import against this new file and it completed correctly. The full file is 16GB in size, the small version is 0.5MB.

craigminihan avatar Apr 27 '22 17:04 craigminihan

@craigminihan can you try increasing the TargetTimeout and /p:CommandTimeout?

kisantia avatar May 03 '22 19:05 kisantia

@kisantia I updated the timeouts to /TargetTimeout:600 and /p:CommandTimeout=7200 but the end result was the same.

Reviewing the logs I can see the following timestamps:

  • Microsoft.Data.Tools.Diagnostics.Tracer Error: 19 : 2022-05-04T00:43:59 : Retry requested: Retry count = 1
  • Microsoft.Data.Tools.Diagnostics.Tracer Error: 19 : 2022-05-04T00:44:29 : Ignore Error requested: Retry count = 1
  • Microsoft.Data.Tools.Diagnostics.Tracer Error: 19 : 2022-05-04T00:45:00 : Ignore Error requested: Retry count = 2
  • Microsoft.Data.Tools.Diagnostics.Tracer Error: 19 : 2022-05-04T00:45:30 : Ignore Error requested: Retry count = 3
  • ...
  • Microsoft.Data.Tools.Diagnostics.Tracer Error: 19 : 2022-05-04T01:02:04 : Retry requested: Retry count = 24
  • Microsoft.Data.Tools.Diagnostics.Tracer Error: 0 : 2022-05-04T01:02:04 : Unable to retrieve Azure session-id

The retry sequence suggests a 30s timeout is being used. During this time CPU and IO counts on the database are both zero suggesting there is nothing actually happening.

The trigger which appears to cause the timeout is not enabled by the import. Later when enabled in SSMS it completes instantly.

craigminihan avatar May 04 '22 13:05 craigminihan