search

dsccommunity / DnsServerDsc

This module contains DSC resources for the management and configuration of Windows Server DNS Server.
MIT License
65 stars 54 forks source link

DnsServerDsc: Integration tests fails intermittently #239

Closed johlju closed 3 years ago

johlju commented 3 years ago

When running integration for some integration tests there are intermittent errors like below.

Cannot invoke the Test-DscConfiguration cmdlet. The Consistency Check or Pull cmdlet is in progress and must return 
before Test-DscConfiguration can be invoked. Use -Force option if that is available to cancel the current operation.
2021-03-27T09:36:33.6886862Z     Context When using configuration DnsRecordAaaa_ModifyRecord_Config
2021-03-27T09:36:34.0183504Z VERBOSE: Perform operation 'Invoke CimMethod' with following parameters, ''methodName' = 
2021-03-27T09:36:34.0185234Z SendConfigurationApply,'className' = MSFT_DSCLocalConfigurationManager,'namespaceName' = 
2021-03-27T09:36:34.0186938Z root/Microsoft/Windows/DesiredStateConfiguration'.
2021-03-27T09:36:34.0289970Z VERBOSE: An LCM method call arrived from computer fv-az17-538 with user sid 
2021-03-27T09:36:34.0291569Z S-1-5-21-2095185083-239186595-2028721889-500.
2021-03-27T09:36:34.0329137Z VERBOSE: [fv-az17-538]: LCM:  [ Start  Set      ]
2021-03-27T09:36:34.1428735Z VERBOSE: [fv-az17-538]: LCM:  [ Start  Resource ]  [[xDnsServerPrimaryZone]Zone Aaaa.test]
2021-03-27T09:36:34.1436065Z VERBOSE: [fv-az17-538]: LCM:  [ Start  Test     ]  [[xDnsServerPrimaryZone]Zone Aaaa.test]
2021-03-27T09:36:34.1441294Z VERBOSE: [fv-az17-538]:                            [[xDnsServerPrimaryZone]Zone Aaaa.test] Checking DNS server zone 
2021-03-27T09:36:34.1444347Z with name 'Aaaa.test' is 'Present'...
2021-03-27T09:36:34.1646053Z VERBOSE: [fv-az17-538]: LCM:  [ End    Test     ]  [[xDnsServerPrimaryZone]Zone Aaaa.test]  in 0.0170 seconds.
2021-03-27T09:36:34.1672704Z VERBOSE: [fv-az17-538]: LCM:  [ Skip   Set      ]  [[xDnsServerPrimaryZone]Zone Aaaa.test]
2021-03-27T09:36:34.1673526Z VERBOSE: [fv-az17-538]: LCM:  [ End    Resource ]  [[xDnsServerPrimaryZone]Zone Aaaa.test]
2021-03-27T09:36:34.1797479Z VERBOSE: [fv-az17-538]: LCM:  [ Start  Resource ]  [[DnsRecordAaaa]Integration_Test]
2021-03-27T09:36:34.1802918Z VERBOSE: [fv-az17-538]: LCM:  [ Start  Test     ]  [[DnsRecordAaaa]Integration_Test]
2021-03-27T09:36:34.2087611Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] Calling GetResourceRecord() from 
2021-03-27T09:36:34.2093301Z the DnsRecordAaaa class to get the object's current state.
2021-03-27T09:36:34.2096955Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] Getting specified DNS Aaaa record 
2021-03-27T09:36:34.2097839Z in zone 'Aaaa.test' from 'localhost'.
2021-03-27T09:36:34.2352115Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] A matching DNS resource record was
2021-03-27T09:36:34.2353129Z  found.
2021-03-27T09:36:34.2514837Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] MATCH: Value (type 
2021-03-27T09:36:34.2528101Z 'System.String') for property 'IPv6Address' does match. Current state is '2001:db8:85a3::8a2e:370:7334' and desired 
2021-03-27T09:36:34.2528858Z state is '2001:db8:85a3::8a2e:370:7334'. (DRC0020)
2021-03-27T09:36:34.2530614Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] MATCH: Value (type 
2021-03-27T09:36:34.2543730Z 'System.String') for property 'ZoneName' does match. Current state is 'Aaaa.test' and desired state is 'Aaaa.test'. 
2021-03-27T09:36:34.2544424Z (DRC0020)
2021-03-27T09:36:34.2545102Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] MATCH: Value (type 
2021-03-27T09:36:34.2545928Z 'System.String') for property 'DnsServer' does match. Current state is 'localhost' and desired state is 'localhost'. 
2021-03-27T09:36:34.2546543Z (DRC0020)
2021-03-27T09:36:34.2547233Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] MATCH: Value (type 
2021-03-27T09:36:34.2548040Z 'System.String') for property 'Name' does match. Current state is 'www' and desired state is 'www'. (DRC0020)
2021-03-27T09:36:34.2548933Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] NOTMATCH: Value (type 
2021-03-27T09:36:34.2550106Z 'System.String') for property 'TimeToLive' does not match. Current state is '01:00:00' and desired state is '05:00:00'.
2021-03-27T09:36:34.2553187Z  (DRC0021)
2021-03-27T09:36:34.2553941Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] DNS record is NOT in the desired 
2021-03-27T09:36:34.2554561Z state.
2021-03-27T09:36:34.2555270Z VERBOSE: [fv-az17-538]: LCM:  [ End    Test     ]  [[DnsRecordAaaa]Integration_Test]  in 0.1030 seconds.
2021-03-27T09:36:34.2555963Z VERBOSE: [fv-az17-538]: LCM:  [ Start  Set      ]  [[DnsRecordAaaa]Integration_Test]
2021-03-27T09:36:34.3021472Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] Getting specified DNS Aaaa record 
2021-03-27T09:36:34.3022363Z in zone 'Aaaa.test' from 'localhost'.
2021-03-27T09:36:34.3272582Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] Calling GetResourceRecord() from 
2021-03-27T09:36:34.3284105Z the DnsRecordAaaa class to get the object's current state.
2021-03-27T09:36:34.3301088Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] Getting specified DNS Aaaa record 
2021-03-27T09:36:34.3313084Z in zone 'Aaaa.test' from 'localhost'.
2021-03-27T09:36:34.3463565Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] A matching DNS resource record was
2021-03-27T09:36:34.3464704Z  found.
2021-03-27T09:36:34.3573479Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] MATCH: Value (type 
2021-03-27T09:36:34.3578626Z 'System.String') for property 'IPv6Address' does match. Current state is '2001:db8:85a3::8a2e:370:7334' and desired 
2021-03-27T09:36:34.3580585Z state is '2001:db8:85a3::8a2e:370:7334'. (DRC0020)
2021-03-27T09:36:34.3587312Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] MATCH: Value (type 'Ensure') for 
2021-03-27T09:36:34.3588117Z property 'Ensure' does match. Current state is 'Present' and desired state is 'Present'. (DRC0020)
2021-03-27T09:36:34.3652723Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] MATCH: Value (type 
2021-03-27T09:36:34.3658116Z 'System.String') for property 'ZoneName' does match. Current state is 'Aaaa.test' and desired state is 'Aaaa.test'. 
2021-03-27T09:36:34.3667588Z (DRC0020)
2021-03-27T09:36:34.3668399Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] MATCH: Value (type 
2021-03-27T09:36:34.3669154Z 'System.String') for property 'DnsServer' does match. Current state is 'localhost' and desired state is 'localhost'. 
2021-03-27T09:36:34.3669736Z (DRC0020)
2021-03-27T09:36:34.3670322Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] MATCH: Value (type 
2021-03-27T09:36:34.3671067Z 'System.String') for property 'Name' does match. Current state is 'www' and desired state is 'www'. (DRC0020)
2021-03-27T09:36:34.3671805Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] NOTMATCH: Value (type 
2021-03-27T09:36:34.3672636Z 'System.String') for property 'TimeToLive' does not match. Current state is '01:00:00' and desired state is '05:00:00'.
2021-03-27T09:36:34.3673260Z  (DRC0021)
2021-03-27T09:36:34.3673823Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] Modifying existing record.
2021-03-27T09:36:34.3745254Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] Modifying www of DNS resource 
2021-03-27T09:36:34.3747648Z record AAAA of zone Aaaa.test on localhost server.
2021-03-27T09:36:34.4062770Z VERBOSE: [fv-az17-538]: LCM:  [ End    Set      ]  [[DnsRecordAaaa]Integration_Test]  in 0.1260 seconds.
2021-03-27T09:36:34.4068005Z VERBOSE: [fv-az17-538]: LCM:  [ End    Resource ]  [[DnsRecordAaaa]Integration_Test]
2021-03-27T09:36:34.4073795Z VERBOSE: [fv-az17-538]: LCM:  [ End    Set      ]
2021-03-27T09:36:34.4081822Z VERBOSE: [fv-az17-538]: LCM:  [ End    Set      ]    in  0.3460 seconds.
2021-03-27T09:36:34.4086705Z VERBOSE: Operation 'Invoke CimMethod' complete.
2021-03-27T09:36:34.4096324Z VERBOSE: Time taken for configuration job to complete is 0.433 seconds
2021-03-27T09:36:34.4438477Z       [+] Should compile and apply the MOF without throwing 698ms
2021-03-27T09:36:34.4532152Z VERBOSE: An LCM method call arrived from computer fv-az17-538 with user sid 
2021-03-27T09:36:34.4556457Z S-1-5-21-2095185083-239186595-2028721889-500.
2021-03-27T09:36:34.5382841Z VERBOSE: [fv-az17-538]: LCM:  [ Start  Get      ]      
2021-03-27T09:36:34.5388054Z VERBOSE: [fv-az17-538]:                            [[xDnsServerPrimaryZone]Zone Aaaa.test] Checking DNS server zone 
2021-03-27T09:36:34.5389657Z with name 'Aaaa.test' is 'Present'...
2021-03-27T09:36:34.5870048Z VERBOSE: [fv-az17-538]: LCM:  [ End    Get      ]  [[xDnsServerPrimaryZone]Zone Aaaa.test]  in 0.0140 seconds.
2021-03-27T09:36:34.6138554Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] Calling GetResourceRecord() from 
2021-03-27T09:36:34.6139647Z the DnsRecordAaaa class to get the object's current state.
2021-03-27T09:36:34.6140331Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] Getting specified DNS Aaaa record 
2021-03-27T09:36:34.6140916Z in zone 'Aaaa.test' from 'localhost'.
2021-03-27T09:36:34.6380809Z VERBOSE: [fv-az17-538]:                            [[DnsRecordAaaa]Integration_Test] A matching DNS resource record was
2021-03-27T09:36:34.6383882Z  found.
2021-03-27T09:36:34.6465059Z VERBOSE: [fv-az17-538]: LCM:  [ End    Get      ]  [[DnsRecordAaaa]Integration_Test]  in 0.0990 seconds.
2021-03-27T09:36:34.6508765Z VERBOSE: [fv-az17-538]: LCM:  [ End    Get      ]    in  0.1950 seconds.
2021-03-27T09:36:34.7071037Z       [+] Should be able to call Get-DscConfiguration without throwing 261ms
2021-03-27T09:36:34.7561946Z       [+] Should have set the resource and all the parameters should match 19ms
2021-03-27T09:36:34.7594495Z VERBOSE: Perform operation 'Invoke CimMethod' with following parameters, ''methodName' = TestConfiguration,'className' 
2021-03-27T09:36:34.7597434Z = MSFT_DSCLocalConfigurationManager,'namespaceName' = root/Microsoft/Windows/DesiredStateConfiguration'.
2021-03-27T09:36:34.7662820Z VERBOSE: An LCM method call arrived from computer fv-az17-538 with user sid 
2021-03-27T09:36:34.7686858Z S-1-5-21-2095185083-239186595-2028721889-500.
2021-03-27T09:36:34.8103605Z Cannot invoke the Test-DscConfiguration cmdlet. The Consistency Check or Pull cmdlet is in progress and must return 
2021-03-27T09:36:34.8156890Z before Test-DscConfiguration can be invoked. Use -Force option if that is available to cancel the current operation.
2021-03-27T09:36:34.8157636Z VERBOSE: Operation 'Invoke CimMethod' complete.
2021-03-27T09:36:34.8160726Z     + CategoryInfo          : NotSpecified: (root/Microsoft/...gurationManager:String) [], CimException
2021-03-27T09:36:34.8161289Z VERBOSE: Time taken for configuration job to complete is 0.057 seconds
2021-03-27T09:36:34.8170122Z     + FullyQualifiedErrorId : MI RESULT 1
2021-03-27T09:36:34.8171122Z     + PSComputerName        : localhost
2021-03-27T09:36:34.8174466Z  
2021-03-27T09:36:34.9343768Z       [-] Should return $true when Test-DscConfiguration is run 152ms
2021-03-27T09:36:34.9971563Z         Expected 'True', but got $null.
2021-03-27T09:36:34.9981351Z         144:                 Test-DscConfiguration -Verbose | Should -Be 'True'
2021-03-27T09:36:34.9988009Z         at <ScriptBlock>, D:\a\1\s\tests\Integration\Classes\DnsRecordAaaa.integration.tests.ps1: line 144
johlju commented 3 years ago

It can be resolved by after each Context-block run Wait-ForIdleLcm -Clear.

Example:

https://github.com/dsccommunity/DnsServerDsc/blob/2b802d7ced2c6b3cbf6300305fc66bfc8c686969/tests/Integration/Classes/DnsServerCache.Integration.Tests.ps1#L74

Sudman1 commented 3 years ago

I saw this too. I have a build testing now.