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.

Sign up for GitHub

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

Jump to bottom

SqlDatabaseDefaultLocation: Integration tests fails itermittently when running on SQL Server 2022 #1837

Closed
johlju opened this issue Jan 22, 2023 · 2 comments · Fixed by #1839
Closed

SqlDatabaseDefaultLocation: Integration tests fails itermittently when running on SQL Server 2022 #1837

johlju opened this issue Jan 22, 2023 · 2 comments · Fixed by #1839
Labels
tests The issue or pull request is about tests only.

Comments

@johlju
Copy link
Member

johlju commented Jan 22, 2023

The integration tests for SqlDatabaseDefaultLocation fails itermittent with the exception

##[error]    [-] Should compile and apply the MOF without throwing 8.25s (8.24s|7ms)
##[error]     Expected no exception to be thrown, but an exception "PowerShell DSC resource DSC_SqlDatabaseDefaultLocation  failed to execute Set-TargetResource functionality with error message: System.InvalidOperationException: Changing the default path failed. ---> System.Exception: System.InvalidOperationException: Failed to connect to SQL instance 'fv-az171-119\DSCSQLTEST'. (SQLCOMMON0019) ---> System.Management.Automation.RuntimeException: ScriptHalted
##[error]        --- End of inner exception stack trace ---
##[error]        --- End of inner exception stack trace --- " was thrown from D:\a\1\s\tests\Integration\DSC_SqlDatabaseDefaultLocation.Integration.Tests.ps1:74 char:17
##[error]         + ...               Start-DscConfiguration @startDscConfigurationParameters
##[error]         +                   ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~.
##[error]     at } | Should -Not -Throw, D:\a\1\s\tests\Integration\DSC_SqlDatabaseDefaultLocation.Integration.Tests.ps1:75

It seems to always happen when running the configuration DSC_SqlDatabaseDefaultLocation_Data_Config, that is the first integration tests for the resource. Looking at the test run it seems to always fail on Start-DscConfiguration, but the next test that runs Get-DscConfiguration and then Test-DscConfiguration both passes. It seems that it cannot, for some reason (lack of resources on the build worker?), access the SQL Server instance at that moment. Restarting the failed tests run will normally make it pass.

Verbose logs:

2023-01-22T11:16:40.8374557Z �[95mRunning tests from 'D:\a\1\s\tests\Integration\DSC_SqlDatabaseDefaultLocation.Integration.Tests.ps1'�[0m
2023-01-22T11:16:40.9538364Z WARNING: There is no operation running currently. Stop will return without any action.
2023-01-22T11:16:41.1328005Z VERBOSE: Performing the operation "Start-DscConfiguration: SendMetaConfigurationApply" on target 
2023-01-22T11:16:41.1332488Z "MSFT_DSCLocalConfigurationManager".
2023-01-22T11:16:41.1959865Z VERBOSE: Perform operation 'Invoke CimMethod' with following parameters, ''methodName' = 
2023-01-22T11:16:41.1960970Z SendMetaConfigurationApply,'className' = MSFT_DSCLocalConfigurationManager,'namespaceName' = 
2023-01-22T11:16:41.1963007Z root/Microsoft/Windows/DesiredStateConfiguration'.
2023-01-22T11:16:41.1968864Z VERBOSE: An LCM method call arrived from computer fv-az171-119 with user sid 
2023-01-22T11:16:41.1970648Z S-1-5-21-4210079787-1595053341-967459737-500.
2023-01-22T11:16:41.1975550Z VERBOSE: [fv-az171-119]: LCM:  [ Start  Set      ]
2023-01-22T11:16:41.1980465Z VERBOSE: [fv-az171-119]: LCM:  [ Start  Resource ]  [MSFT_DSCMetaConfiguration]
2023-01-22T11:16:41.1985449Z VERBOSE: [fv-az171-119]: LCM:  [ Start  Set      ]  [MSFT_DSCMetaConfiguration]
2023-01-22T11:16:41.1991120Z VERBOSE: [fv-az171-119]: LCM:  [ End    Set      ]  [MSFT_DSCMetaConfiguration]  in 0.0150 seconds.
2023-01-22T11:16:41.1996010Z VERBOSE: [fv-az171-119]: LCM:  [ End    Resource ]  [MSFT_DSCMetaConfiguration]
2023-01-22T11:16:41.2000497Z VERBOSE: [fv-az171-119]: LCM:  [ End    Set      ]
2023-01-22T11:16:41.2005929Z VERBOSE: [fv-az171-119]: LCM:  [ End    Set      ]    in  0.0470 seconds.
2023-01-22T11:16:41.2010164Z VERBOSE: Operation 'Invoke CimMethod' complete.
2023-01-22T11:16:41.2033919Z VERBOSE: Set-DscLocalConfigurationManager finished in 0.074 seconds.
2023-01-22T11:16:42.1989117Z �[92mDescribing DSC_SqlDatabaseDefaultLocation_Integration�[0m
2023-01-22T11:16:42.2001919Z �[96m Context When using configuration DSC_SqlDatabaseDefaultLocation_Data_Config�[0m
2023-01-22T11:16:42.9826529Z VERBOSE: Perform operation 'Invoke CimMethod' with following parameters, ''methodName' = 
2023-01-22T11:16:42.9827544Z SendConfigurationApply,'className' = MSFT_DSCLocalConfigurationManager,'namespaceName' = 
2023-01-22T11:16:42.9830003Z root/Microsoft/Windows/DesiredStateConfiguration'.
2023-01-22T11:16:42.9941245Z VERBOSE: An LCM method call arrived from computer fv-az171-119 with user sid 
2023-01-22T11:16:42.9943036Z S-1-5-21-4210079787-1595053341-967459737-500.
2023-01-22T11:16:42.9972320Z VERBOSE: [fv-az171-119]: LCM:  [ Start  Set      ]
2023-01-22T11:16:43.3353398Z VERBOSE: [fv-az171-119]: LCM:  [ Start  Resource ]  [[File]SQLDataPath]
2023-01-22T11:16:43.3355048Z VERBOSE: [fv-az171-119]: LCM:  [ Start  Test     ]  [[File]SQLDataPath]
2023-01-22T11:16:43.4533889Z VERBOSE: [fv-az171-119]:                            [[File]SQLDataPath] The system cannot find the file specified.
2023-01-22T11:16:43.4548911Z VERBOSE: [fv-az171-119]:                            [[File]SQLDataPath] The related file/directory is: C:\SQLData.
2023-01-22T11:16:43.4579372Z VERBOSE: [fv-az171-119]: LCM:  [ End    Test     ]  [[File]SQLDataPath]  in 0.1250 seconds.
2023-01-22T11:16:43.4612063Z VERBOSE: [fv-az171-119]: LCM:  [ Start  Set      ]  [[File]SQLDataPath]
2023-01-22T11:16:43.4628122Z VERBOSE: [fv-az171-119]:                            [[File]SQLDataPath] The system cannot find the file specified.
2023-01-22T11:16:43.4659878Z VERBOSE: [fv-az171-119]:                            [[File]SQLDataPath] The related file/directory is: C:\SQLData.
2023-01-22T11:16:43.4881379Z VERBOSE: [fv-az171-119]: LCM:  [ End    Set      ]  [[File]SQLDataPath]  in 0.0000 seconds.
2023-01-22T11:16:43.5203413Z VERBOSE: [fv-az171-119]: LCM:  [ End    Resource ]  [[File]SQLDataPath]
2023-01-22T11:16:43.5306978Z VERBOSE: [fv-az171-119]: LCM:  [ Start  Resource ]  [[SqlDatabaseDefaultLocation]Integration_Test]
2023-01-22T11:16:43.5342279Z VERBOSE: [fv-az171-119]: LCM:  [ Start  Test     ]  [[SqlDatabaseDefaultLocation]Integration_Test]
2023-01-22T11:16:45.5614944Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Testing the default 
2023-01-22T11:16:45.5628453Z path for the 'Data' files.
2023-01-22T11:16:45.5635446Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Getting default path
2023-01-22T11:16:45.5641311Z  for 'Data' for instance 'DSCSQLTEST'.
2023-01-22T11:16:45.5647198Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Preferred module 
2023-01-22T11:16:45.5652794Z SqlServer found. (SQLCOMMON0023)
2023-01-22T11:16:45.5716156Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Importing PowerShell
2023-01-22T11:16:45.5723604Z  module 'SqlServer' with version '22.0.49' from path 'C:\Program 
2023-01-22T11:16:45.5735939Z Files\WindowsPowerShell\Modules\SqlServer\22.0.49\SqlServer.psm1'. (SQLCOMMON0025)
2023-01-22T11:16:45.5743940Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Connecting as 
2023-01-22T11:16:45.5752647Z current user 'fv-az171-119\SqlInstall' using integrated security. (SQLCOMMON0054)
2023-01-22T11:16:45.5755246Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Connected to SQL 
2023-01-22T11:16:45.5756170Z instance 'fv-az171-119\DSCSQLTEST'. (SQLCOMMON0018)
2023-01-22T11:16:45.5760128Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Current default path
2023-01-22T11:16:45.5765619Z  for 'Data' is 'C:\Db\160\Data\' and should be updated to 'C:\SQLData\'.
2023-01-22T11:16:45.5917252Z VERBOSE: [fv-az171-119]: LCM:  [ End    Test     ]  [[SqlDatabaseDefaultLocation]Integration_Test]  in 2.1110 seconds.
2023-01-22T11:16:45.5921822Z VERBOSE: [fv-az171-119]: LCM:  [ Start  Set      ]  [[SqlDatabaseDefaultLocation]Integration_Test]
2023-01-22T11:16:46.5248861Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Setting the default 
2023-01-22T11:16:46.5253105Z path for the 'Data' files.
2023-01-22T11:16:46.5258996Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Found PowerShell 
2023-01-22T11:16:46.5263703Z module SqlServer already imported in the session. (SQLCOMMON0026)
2023-01-22T11:16:46.5264268Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Connecting as 
2023-01-22T11:16:46.5269031Z current user 'fv-az171-119\SqlInstall' using integrated security. (SQLCOMMON0054)
2023-01-22T11:16:46.5276463Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Connected to SQL 
2023-01-22T11:16:46.5277170Z instance 'fv-az171-119\DSCSQLTEST'. (SQLCOMMON0018)
2023-01-22T11:16:46.5287308Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] The default path for
2023-01-22T11:16:46.5287912Z  'Data' has been changed from 'C:\Db\160\Data\' to 'C:\SQLData\'.
2023-01-22T11:16:46.5293070Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Restarting Sql 
2023-01-22T11:16:46.5299216Z Server: fv-az171-119\DSCSQLTEST.
2023-01-22T11:16:46.5300199Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Found PowerShell 
2023-01-22T11:16:46.5302755Z module SqlServer already imported in the session. (SQLCOMMON0026)
2023-01-22T11:16:46.5303549Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Connecting as 
2023-01-22T11:16:46.5304380Z current user 'fv-az171-119\SqlInstall' using integrated security. (SQLCOMMON0054)
2023-01-22T11:16:46.5310418Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Connected to SQL 
2023-01-22T11:16:46.5311003Z instance 'fv-az171-119\DSCSQLTEST'. (SQLCOMMON0018)
2023-01-22T11:16:46.5318700Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Getting information 
2023-01-22T11:16:46.5319290Z about service 'SQL Server'. (SQLCOMMON0037)
2023-01-22T11:16:46.5325647Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] 'SQL Server' service
2023-01-22T11:16:46.5326213Z  is restarting. (SQLCOMMON0038)
2023-01-22T11:16:50.2330821Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Starting service 
2023-01-22T11:16:50.2367613Z 'SQL Server Agent (DSCSQLTEST)'. (SQLCOMMON0042)
2023-01-22T11:16:50.2384699Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Waiting for instance
2023-01-22T11:16:50.2393630Z  fv-az171-119\DSCSQLTEST to report status online, with a timeout value of 120 seconds. (SQLCOMMON0043)
2023-01-22T11:16:50.2396200Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Found PowerShell 
2023-01-22T11:16:50.2397200Z module SqlServer already imported in the session. (SQLCOMMON0026)
2023-01-22T11:16:50.2401474Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Connecting as 
2023-01-22T11:16:50.2406949Z current user 'fv-az171-119\SqlInstall' using integrated security. (SQLCOMMON0054)
2023-01-22T11:16:50.3018593Z VERBOSE: [fv-az171-119]: LCM:  [ End    Set      ]  [[SqlDatabaseDefaultLocation]Integration_Test]  in 4.7070 seconds.
2023-01-22T11:16:51.0410487Z ##[error]    [-] Should compile and apply the MOF without throwing 8.25s (8.24s|7ms)�[0m
2023-01-22T11:16:51.1508084Z ##[error]     Expected no exception to be thrown, but an exception "PowerShell DSC resource DSC_SqlDatabaseDefaultLocation  failed to execute Set-TargetResource functionality with error message: System.InvalidOperationException: Changing the default path failed. ---> System.Exception: System.InvalidOperationException: Failed to connect to SQL instance 'fv-az171-119\DSCSQLTEST'. (SQLCOMMON0019) ---> System.Management.Automation.RuntimeException: ScriptHalted�[0m
2023-01-22T11:16:51.1509970Z ##[error]        --- End of inner exception stack trace ---�[0m
2023-01-22T11:16:51.1510508Z ##[error]        --- End of inner exception stack trace --- " was thrown from D:\a\1\s\tests\Integration\DSC_SqlDatabaseDefaultLocation.Integration.Tests.ps1:74 char:17�[0m
2023-01-22T11:16:51.1511337Z ##[error]         + ...               Start-DscConfiguration @startDscConfigurationParameters�[0m
2023-01-22T11:16:51.1511963Z ##[error]         +                   ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~.�[0m
2023-01-22T11:16:51.1512486Z ##[error]     at } | Should -Not -Throw, D:\a\1\s\tests\Integration\DSC_SqlDatabaseDefaultLocation.Integration.Tests.ps1:75�[0m
2023-01-22T11:16:51.1513006Z ##[error]     at Invoke-Assertion, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:8130�[0m
2023-01-22T11:16:51.1513509Z ##[error]     at Should<End>, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:8072�[0m
2023-01-22T11:16:51.1514000Z ##[error]     at <ScriptBlock>, D:\a\1\s\tests\Integration\DSC_SqlDatabaseDefaultLocation.Integration.Tests.ps1:56�[0m
2023-01-22T11:16:51.1514539Z ##[error]     at <ScriptBlock>, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:1998�[0m
2023-01-22T11:16:51.1514989Z ##[error]     at <ScriptBlock>, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:1959�[0m
2023-01-22T11:16:51.1515680Z ##[error]     at Invoke-ScriptBlock, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:2120�[0m
2023-01-22T11:16:51.1516164Z ##[error]     at Invoke-TestItem, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:1194�[0m
2023-01-22T11:16:51.1516640Z ##[error]     at Invoke-Block, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:830�[0m
2023-01-22T11:16:51.1517083Z ##[error]     at <ScriptBlock>, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:888�[0m
2023-01-22T11:16:51.1517590Z ##[error]     at <ScriptBlock>, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:1998�[0m
2023-01-22T11:16:51.1518033Z ##[error]     at <ScriptBlock>, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:1959�[0m
2023-01-22T11:16:51.1518524Z ##[error]     at Invoke-ScriptBlock, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:2123�[0m
2023-01-22T11:16:51.1519342Z ##[error]     at Invoke-Block, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:935�[0m
2023-01-22T11:16:51.1520037Z ##[error]     at <ScriptBlock>, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:888�[0m
2023-01-22T11:16:51.1520497Z ##[error]     at <ScriptBlock>, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:1998�[0m
2023-01-22T11:16:51.1521360Z ##[error]     at <ScriptBlock>, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:1959�[0m
2023-01-22T11:16:51.1521823Z ##[error]     at Invoke-ScriptBlock, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:2123�[0m
2023-01-22T11:16:51.1522326Z ##[error]     at Invoke-Block, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:935�[0m
2023-01-22T11:16:51.1522772Z ##[error]     at <ScriptBlock>, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:888�[0m
2023-01-22T11:16:51.1523266Z ##[error]     at <ScriptBlock>, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:1998�[0m
2023-01-22T11:16:51.1523716Z ##[error]     at <ScriptBlock>, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:1959�[0m
2023-01-22T11:16:51.1524244Z ##[error]     at Invoke-ScriptBlock, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:2123�[0m
2023-01-22T11:16:51.1524720Z ##[error]     at Invoke-Block, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:935�[0m
2023-01-22T11:16:51.1525227Z ##[error]     at <ScriptBlock>, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:1672�[0m
2023-01-22T11:16:51.1525672Z ##[error]     at <ScriptBlock>, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.ps1:3�[0m
2023-01-22T11:16:51.1526176Z ##[error]     at <ScriptBlock>, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:3164�[0m
2023-01-22T11:16:51.1526647Z ##[error]     at Invoke-InNewScriptScope, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:3171�[0m
2023-01-22T11:16:51.1527168Z ##[error]     at Run-Test, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:1675�[0m
2023-01-22T11:16:51.1527639Z ##[error]     at Invoke-Test, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:2475�[0m
2023-01-22T11:16:51.1528314Z ##[error]     at Invoke-Pester<End>, D:\a\1\s\output\RequiredModules\Pester\5.4.0\Pester.psm1:5272�[0m
2023-01-22T11:16:51.1528840Z ##[error]     at <ScriptBlock>, D:\a\1\s\output\RequiredModules\Sampler\0.116.1\tasks\Invoke-Pester.pester.build.ps1:906�[0m
2023-01-22T11:16:51.1529451Z ##[error]     at *Task, D:\a\1\s\output\RequiredModules\InvokeBuild\5.10.1\Invoke-Build.ps1:590�[0m
2023-01-22T11:16:51.1529948Z ##[error]     at *Task, D:\a\1\s\output\RequiredModules\InvokeBuild\5.10.1\Invoke-Build.ps1:562�[0m
2023-01-22T11:16:51.1530496Z ##[error]     at *Task, D:\a\1\s\output\RequiredModules\InvokeBuild\5.10.1\Invoke-Build.ps1:562�[0m
2023-01-22T11:16:51.1531002Z ##[error]     at <ScriptBlock><End>, D:\a\1\s\output\RequiredModules\InvokeBuild\5.10.1\Invoke-Build.ps1:748�[0m
2023-01-22T11:16:51.1531474Z ##[error]     at <ScriptBlock><Begin>, D:\a\1\s\build.ps1:507�[0m
2023-01-22T11:16:51.1531885Z ##[error]     at <ScriptBlock>, D:\a\_temp\8ef2bafb-ab92-40a8-b141-f5836907a719.ps1:37�[0m
2023-01-22T11:16:51.1532348Z ##[error]     at <ScriptBlock>, <No file>:1�[0m
2023-01-22T11:16:51.1532703Z VERBOSE: An LCM method call arrived from computer fv-az171-119 with user sid 
2023-01-22T11:16:51.1533093Z S-1-5-21-4210079787-1595053341-967459737-500.
2023-01-22T11:16:51.1533439Z WARNING: [fv-az171-119]:                            [] The GET operation will be carried against a pending 
2023-01-22T11:16:51.1533884Z configuration since the latest configuration has not converged yet.
2023-01-22T11:16:51.1534206Z VERBOSE: [fv-az171-119]: LCM:  [ Start  Get      ]      
2023-01-22T11:16:51.1534578Z VERBOSE: [fv-az171-119]: LCM:  [ Start  Get      ]  [[File]SQLDataPath]  
2023-01-22T11:16:51.1534949Z VERBOSE: [fv-az171-119]: LCM:  [ End    Get      ]  [[File]SQLDataPath]  in 0.0150 seconds.
2023-01-22T11:16:53.0603935Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Getting default path
2023-01-22T11:16:53.0611784Z  for 'Data' for instance 'DSCSQLTEST'.
2023-01-22T11:16:53.0615826Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Preferred module 
2023-01-22T11:16:53.0616212Z SqlServer found. (SQLCOMMON0023)
2023-01-22T11:16:53.0623379Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Importing PowerShell
2023-01-22T11:16:53.0626659Z  module 'SqlServer' with version '22.0.49' from path 'C:\Program 
2023-01-22T11:16:53.0627093Z Files\WindowsPowerShell\Modules\SqlServer\22.0.49\SqlServer.psm1'. (SQLCOMMON0025)
2023-01-22T11:16:53.0630607Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Connecting as 
2023-01-22T11:16:53.0632920Z current user 'fv-az171-119\SqlInstall' using integrated security. (SQLCOMMON0054)
2023-01-22T11:16:53.1657614Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Connected to SQL 
2023-01-22T11:16:53.1663401Z instance 'fv-az171-119\DSCSQLTEST'. (SQLCOMMON0018)
2023-01-22T11:16:53.2140931Z VERBOSE: [fv-az171-119]: LCM:  [ End    Get      ]  [[SqlDatabaseDefaultLocation]Integration_Test]  in 2.0790 seconds.
2023-01-22T11:16:53.2697242Z VERBOSE: [fv-az171-119]: LCM:  [ End    Get      ]    in  2.2820 seconds.
2023-01-22T11:16:53.2857366Z �[32m   [+] Should be able to call Get-DscConfiguration without throwing�[0m�[90m 2.32s (2.32s|3ms)�[0m
2023-01-22T11:16:53.3156543Z �[32m   [+] Should have set the resource and all the parameters should match�[0m�[90m 24ms (22ms|2ms)�[0m
2023-01-22T11:16:53.7467455Z VERBOSE: Perform operation 'Invoke CimMethod' with following parameters, ''methodName' = TestConfiguration,'className' 
2023-01-22T11:16:53.7503174Z = MSFT_DSCLocalConfigurationManager,'namespaceName' = root/Microsoft/Windows/DesiredStateConfiguration'.
2023-01-22T11:16:53.7511054Z VERBOSE: An LCM method call arrived from computer fv-az171-119 with user sid 
2023-01-22T11:16:53.7513005Z S-1-5-21-4210079787-1595053341-967459737-500.
2023-01-22T11:16:53.7517514Z VERBOSE: [fv-az171-119]: LCM:  [ Start  Test     ]
2023-01-22T11:16:53.7524654Z WARNING: [fv-az171-119]:                            [] The TEST operation will be carried against a pending 
2023-01-22T11:16:53.7526466Z configuration since the latest configuration has not converged yet.
2023-01-22T11:16:53.7531227Z VERBOSE: [fv-az171-119]: LCM:  [ Start  Resource ]  [[File]SQLDataPath]
2023-01-22T11:16:53.7536030Z VERBOSE: [fv-az171-119]: LCM:  [ Start  Test     ]  [[File]SQLDataPath]
2023-01-22T11:16:53.7541353Z VERBOSE: [fv-az171-119]:                            [[File]SQLDataPath] The destination object was found and no action 
2023-01-22T11:16:53.7542796Z is required.
2023-01-22T11:16:53.7548425Z VERBOSE: [fv-az171-119]: LCM:  [ End    Test     ]  [[File]SQLDataPath] True in 0.0160 seconds.
2023-01-22T11:16:53.7553250Z VERBOSE: [fv-az171-119]: LCM:  [ End    Resource ]  [[File]SQLDataPath]
2023-01-22T11:16:53.7558048Z VERBOSE: [fv-az171-119]: LCM:  [ Start  Resource ]  [[SqlDatabaseDefaultLocation]Integration_Test]
2023-01-22T11:16:53.7563042Z VERBOSE: [fv-az171-119]: LCM:  [ Start  Test     ]  [[SqlDatabaseDefaultLocation]Integration_Test]
2023-01-22T11:16:55.7501072Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Testing the default 
2023-01-22T11:16:55.7513050Z path for the 'Data' files.
2023-01-22T11:16:55.7520512Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Getting default path
2023-01-22T11:16:55.7524284Z  for 'Data' for instance 'DSCSQLTEST'.
2023-01-22T11:16:55.7530627Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Preferred module 
2023-01-22T11:16:55.7536564Z SqlServer found. (SQLCOMMON0023)
2023-01-22T11:16:55.7601703Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Importing PowerShell
2023-01-22T11:16:55.7613870Z  module 'SqlServer' with version '22.0.49' from path 'C:\Program 
2023-01-22T11:16:55.7620465Z Files\WindowsPowerShell\Modules\SqlServer\22.0.49\SqlServer.psm1'. (SQLCOMMON0025)
2023-01-22T11:16:55.7632225Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Connecting as 
2023-01-22T11:16:55.7635399Z current user 'fv-az171-119\SqlInstall' using integrated security. (SQLCOMMON0054)
2023-01-22T11:16:55.7636466Z VERBOSE: [fv-az171-119]:                            [[SqlDatabaseDefaultLocation]Integration_Test] Connected to SQL 
2023-01-22T11:16:55.7638188Z instance 'fv-az171-119\DSCSQLTEST'. (SQLCOMMON0018)
2023-01-22T11:16:55.7808237Z VERBOSE: [fv-az171-119]: LCM:  [ End    Test     ]  [[SqlDatabaseDefaultLocation]Integration_Test] True in 2.3140 
2023-01-22T11:16:55.7809172Z seconds.
2023-01-22T11:16:55.7809671Z VERBOSE: [fv-az171-119]: LCM:  [ End    Resource ]  [[SqlDatabaseDefaultLocation]Integration_Test]
2023-01-22T11:16:55.8213797Z VERBOSE: [fv-az171-119]: LCM:  [ End    Test     ]     Completed processing test operation. The operation returned 
2023-01-22T11:16:55.8222535Z True.
2023-01-22T11:16:55.8230798Z VERBOSE: [fv-az171-119]: LCM:  [ End    Test     ]    in  2.4850 seconds.
2023-01-22T11:16:55.8399345Z VERBOSE: Operation 'Invoke CimMethod' complete.
2023-01-22T11:16:55.8412089Z VERBOSE: Time taken for configuration job to complete is 2.521 seconds
2023-01-22T11:16:55.8534956Z �[32m   [+] Should return $true when Test-DscConfiguration is run�[0m�[90m 2.54s (2.54s|1ms)�[0m
@johlju johlju added tests The issue or pull request is about tests only. help wanted The issue is up for grabs for anyone in the community. labels Jan 22, 2023
@johlju
Copy link
Member Author

johlju commented Jan 22, 2023

If restarts the SQL Server and waits for ut to go online

Waiting for instance fv-az171-119\DSCSQLTEST to report status online, with a timeout value of 120 seconds.

the there is just one call to Connect-SQL.

Connecting as  current user 'fv-az171-119\SqlInstall' using integrated security. (SQLCOMMON0054)

Maybe it fails on the first connection attempt on this line, and that throws an unhandled exception:

SqlServerDsc/source/Modules/SqlServerDsc.Common/SqlServerDsc.Common.psm1

Line 1100 in bed3b12

$testConnectionServerObject = Connect-SQL -ServerName $ServerName -InstanceName $InstanceName -ErrorAction 'SilentlyContinue'

If Connect-SQL fails, back in the rsource's code this throws the error we are seeing

SqlServerDsc/source/DSCResources/DSC_SqlDatabaseDefaultLocation/DSC_SqlDatabaseDefaultLocation.psm1

Lines 209 to 210 in bed3b12

$errorMessage = $script:localizedData.ChangingPathFailed
New-InvalidOperationException -Message $errorMessage -ErrorRecord $_

In Connect-SQL if the status is not Online, it throws:

SqlServerDsc/source/Modules/SqlServerDsc.Common/SqlServerDsc.Common.psm1

Line 566 in bed3b12

throw

Which is caught by the try-catch-block:

SqlServerDsc/source/Modules/SqlServerDsc.Common/SqlServerDsc.Common.psm1

Lines 571 to 572 in bed3b12

$errorMessage = $script:localizedData.FailedToConnectToDatabaseEngineInstance -f $databaseEngineInstance
New-InvalidOperationException -Message $errorMessage -ErrorRecord $_

And that is the error we are seeing.

@johlju
Copy link
Member Author

johlju commented Jan 22, 2023 •
edited
Loading

In the function Restart-SqlService we are calling Connect-SQL with -ErrorAction 'SilentlyContinue', but that does not seem to work.

SqlServerDsc/source/Modules/SqlServerDsc.Common/SqlServerDsc.Common.psm1

Line 1100 in bed3b12

$testConnectionServerObject = Connect-SQL -ServerName $ServerName -InstanceName $InstanceName -ErrorAction 'SilentlyContinue'

I suggest we change the following lines to use Write-Error instead:

SqlServerDsc/source/Modules/SqlServerDsc.Common/SqlServerDsc.Common.psm1

Lines 571 to 572 in bed3b12

$errorMessage = $script:localizedData.FailedToConnectToDatabaseEngineInstance -f $databaseEngineInstance
New-InvalidOperationException -Message $errorMessage -ErrorRecord $_

With Write-Error (non-terminating error) we can control if the command should stop or silently continue using ErrorAction. See https://github.com/dsccommunity/SqlServerDsc/blob/main/CONTRIBUTING.md#non-terminating-error.

But we should make sure to add -ErrorAction 'Stop' to all other calls of Connect-Sql, throughout the module.

@johlju johlju mentioned this issue Jan 23, 2023
Merged
9 tasks
johlju added a commit that referenced this issue Jan 24, 2023
@johlju
SqlServerDsc: Connect-Sql now handles ErrorAction correctly (#1839)
979800d 
- SqlServerDsc.Common
  - `Connect-SQL`
    - Was updated to handle both `-ErrorAction 'Stop'` and `-ErrorAction 'SilentlyContinue'`
      when passed to the command ([issue #1837]).
@johlju johlju removed the help wanted The issue is up for grabs for anyone in the community. label Feb 5, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
tests The issue or pull request is about tests only.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

SqlServerDsc: Connect-Sql now handles ErrorAction correctly johlju/SqlServerDsc
1 participant
@johlju