xExchMailboxDatabase returns error message during first run.

Question

xExchMailboxDatabase returns error message during first run.

heinejeppesen opened this issue 2 years ago · 9 comments

Problem description

I'm trying to deploy Exchange 2019 CU12 on Server 2022 for dev environments.
Deployment is through Azure DevOps/BICEP/Azure Automation on Azure VMs.

The error comes every time the pipeline runs, deploying from scratch.
When looking at the DSC State in Azure Automation, the state becomes compliant at the second run, so almost immediately after pipeline has completed.

I can't force the error again, by testing manually, so I can't trigger the error once the initial deployment has succeeded.
Log info is what I get returned from AZ CLI/BICEP through the pipeline.

Everything works, but for some reason the DSC fails the initial runs but succeeds at second run.

Verbose logs

The PowerShell DSC resource C:\\\\\\\\Program Files\\\\\\\\WindowsPowerShell\\\\\\\\Modules\\\\\\\\xExchange\\\\\\\\1.34.0\\\\\\\\DscResources\\\\\\\\MSFT_xExchMailboxDatabase returned results in a format that is not valid. The results from running Test-TargetResource must be the boolean value True or False.

DSC configuration

# Configure database
        xExchMailboxDatabase ExchDB {
            Name                     = "DB01"
            Credential               = $domainAdminCredentialNetBios
            EdbFilePath              = "F:\Exchange\DB01\DB01.edb"
            LogFolderPath            = "F:\Exchange\DB01"
            Server                   = 'Exch001'
            CircularLoggingEnabled   = $true
            DatabaseCopyCount        = 1
            IssueWarningQuota        = 'unlimited'
            ProhibitSendQuota        = 'unlimited'
            ProhibitSendReceiveQuota = 'unlimited'
            AllowServiceRestart      = $true
            DependsOn                = '[PendingReboot]AfterExchangeInstall'
        }

Operating system the target node is running

Server 2022

Exchange Server edition and version the target node is running

Exchange Standard - clean new ISO from Microsoft.

PowerShell version and build the target node is running

5.1 (Server 2022 built-in)

xExchange version

2019 CU12

Module 1.34.0

Answer 1 · 2022-11-14T17:08:46.000Z

Will running Test-DscConfiguration on a non-configured node return the error? It sounds like a command is called in the Test-TargetResource function that return a value so the there are more than one value is returned (or an invalid value is returmed).

Answer 2 · 2022-11-14T21:47:34.000Z

Thanks!

I didn't think of trying that, so I just build a new Server 2022 manually and installed Exchange 2019 CU.
Now I get this, right after installing Exchange (it's with the 1.33.0 module, but same error)

PS C:\Deploy> C:\Deploy\Test.ps1
The PowerShell DSC resource C:\Program Files\WindowsPowerShell\Modules\xExchange\1.33.0\DscResources\MSFT_xExchMailboxDatabase returned results in a format that is not valid. The results from running Test-Tar
getResource must be the boolean value True or False.
+ CategoryInfo : InvalidResult: (root/Microsoft/...gurationManager:String) [], CimException
+ FullyQualifiedErrorId : TestTargetResourceInvalidResultFormat
+ PSComputerName : localhost

I ran the test immediately (Maybe 15-20 seconds after install DSC finished).
Now, if I test again - after just writing this message, the error is gone and DSC reports expected status.

So it seems there needs to be a waiting period of maybe 60-120 seconds, after Exchange installation finishes, before the xMailboxDatabase check runs.

Maybe the Get-MailboxDatabase cmdlet fails when the error occurs (because Exchange is still getting settled in) and this isn't handled (enough) in the DSC module?

Answer 3 · 2022-11-15T13:44:23.000Z

Here's the verbose logging from the failure:

VERBOSE: Perform VERBOSE: An VERBOSE: [EXCH001]: LCM: VERBOSE: [EXCH001]: LCM: VERBOSE: [EXCH001]: LCM: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: VERBOSE: [EXCH001]: LCM: VERBOSE: [EXCH001]: LCM: The PowerShell + CategoryInfo + FullyQualifiedErrorId + PSComputerName : localhost operation 'Invoke CimMethod' with following parameters, ''methodName' = TestConfiguration,'className' = MSFT_DSCLocalConfigurationManager,'namespaceName' = root/Microsoft/Windows/DesiredStateConfiguration'.
LCM method call arrived from computer EXCH001 with user sid S-1-5-21-4141454203-2807943697-4034847775-62845.
[ Start Compare ]
[ Start Resource ] [[xExchMailboxDatabase]ExchDB]
[ Start Test ] [[xExchMailboxDatabase]ExchDB]
[[xExchMailboxDatabase]ExchDB] Entering function 'Test-TargetResource'. Notable parameters: Name = 'DB01'
[[xExchMailboxDatabase]ExchDB] Checking if setup is partially complete
[[xExchMailboxDatabase]ExchDB] Checking values at key 'HKLM:\SOFTWARE\Microsoft\ExchangeServer\v15\CafeRole'
[[xExchMailboxDatabase]ExchDB] Checking values at key 'HKLM:\SOFTWARE\Microsoft\ExchangeServer\v15\ClientAccessRole'
[[xExchMailboxDatabase]ExchDB] Checking values at key 'HKLM:\SOFTWARE\Microsoft\ExchangeServer\v15\FrontendTransportRole'
[[xExchMailboxDatabase]ExchDB] Checking values at key 'HKLM:\SOFTWARE\Microsoft\ExchangeServer\v15\HubTransportRole'
[[xExchMailboxDatabase]ExchDB] Checking values at key 'HKLM:\SOFTWARE\Microsoft\ExchangeServer\v15\MailboxRole'
[[xExchMailboxDatabase]ExchDB] Exchange is present and setup is detected as being fully complete.
[[xExchMailboxDatabase]ExchDB] Creating new Remote PowerShell session to Exchange
[[xExchMailboxDatabase]ExchDB] Perform operation 'Enumerate CimInstances' with following parameters, ''namespaceName' = root\cimv2,'className' = Win32_ComputerSystem'.
[[xExchMailboxDatabase]ExchDB] Operation 'Enumerate CimInstances' complete.
[[xExchMailboxDatabase]ExchDB] Connecting to exch001.betaplace.dk.
[[xExchMailboxDatabase]ExchDB] Loading module from path 'C:\Windows\TEMP\DSCExchangeModule\DSCExchangeModule.psd1'.
[[xExchMailboxDatabase]ExchDB] Loading 'FormatsToProcess' from path 'C:\Windows\TEMP\DSCExchangeModule\DSCExchangeModule.format.ps1xml'.
[[xExchMailboxDatabase]ExchDB] Loading module from path 'C:\Windows\TEMP\DSCExchangeModule\DSCExchangeModule.psm1'.
[[xExchMailboxDatabase]ExchDB] Importing function 'Get-MailboxDatabase'.
[[xExchMailboxDatabase]ExchDB] Importing function 'Get-Recipient'.
[[xExchMailboxDatabase]ExchDB] Importing function 'Set-ADServerSettings'.
[[xExchMailboxDatabase]ExchDB] Invalid setting 'CircularLoggingEnabled'. Expected value: 'True'. Actual value: 'False'
[[xExchMailboxDatabase]ExchDB] Invalid setting 'IssueWarningQuota'. Expected value: 'unlimited'. Actual value: '1.899 GB (2,039,480,320 bytes)'
[[xExchMailboxDatabase]ExchDB] Invalid setting 'ProhibitSendQuota'. Expected value: 'unlimited'. Actual value: '2 GB (2,147,483,648 bytes)'
[[xExchMailboxDatabase]ExchDB] Invalid setting 'ProhibitSendReceiveQuota'. Expected value: 'unlimited'. Actual value: '2.3 GB (2,469,396,480 bytes)'
[ End Test ] [[xExchMailboxDatabase]ExchDB] False in 19.9700 seconds.
[ FAILEDCompare ] Completed processing compare operation. The operation returned False.
DSC resource C:\Program Files\WindowsPowerShell\Modules\xExchange\1.33.0\DscResources\MSFT_xExchMailboxDatabase returned results in a format that is not valid. The results from running Test-TargetResource must be the boolean value True or False.
: InvalidResult: (root/Microsoft/...gurationManager:String) [], CimException
: TestTargetResourceInvalidResultFormat

VERBOSE: Operation 'Invoke CimMethod' complete.
VERBOSE: Time taken for configuration job to complete is 20.097 seconds

Answer 4 · 2022-11-15T13:46:18.000Z

This is a successful test maybe 30-60 seconds later again, where the issue is now gone.

VERBOSE: Perform operation 'Invoke CimMethod' with following parameters, ''methodName' = TestConfiguration,'className' = MSFT_DSCLocalConfigurationManager,'namespaceName' = root/Microsoft/Windows/DesiredStateConfiguration'.
VERBOSE: An LCM method call arrived from computer EXCH001 with user sid S-1-5-21-4141454203-2807943697-4034847775-62845.
VERBOSE: [EXCH001]: LCM: [ Start Compare ]
VERBOSE: [EXCH001]: LCM: [ Start Resource ] [[xExchMailboxDatabase]ExchDB]
VERBOSE: [EXCH001]: LCM: [ Start Test ] [[xExchMailboxDatabase]ExchDB]
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Entering function 'Test-TargetResource'. Notable parameters: Name = 'DB01'
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Importing the xExchange Remote PowerShell Module.
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Checking if setup is partially complete
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Checking values at key 'HKLM:\SOFTWARE\Microsoft\ExchangeServer\v15\CafeRole'
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Checking values at key 'HKLM:\SOFTWARE\Microsoft\ExchangeServer\v15\ClientAccessRole'
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Checking values at key 'HKLM:\SOFTWARE\Microsoft\ExchangeServer\v15\FrontendTransportRole'
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Checking values at key 'HKLM:\SOFTWARE\Microsoft\ExchangeServer\v15\HubTransportRole'
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Checking values at key 'HKLM:\SOFTWARE\Microsoft\ExchangeServer\v15\MailboxRole'
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Exchange is present and setup is detected as being fully complete.
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Creating new Remote PowerShell session to Exchange
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Perform operation 'Enumerate CimInstances' with following parameters, ''namespaceName' = root\cimv2,'className' = Win32_ComputerSystem'.
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Operation 'Enumerate CimInstances' complete.
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Connecting to exch001.betaplace.dk.
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Loading module from path 'C:\Windows\TEMP\DSCExchangeModule\DSCExchangeModule.psm1'.
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Importing function 'Get-MailboxDatabase'.
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Importing function 'Get-Recipient'.
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Importing function 'Set-ADServerSettings'.
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Invalid setting 'CircularLoggingEnabled'. Expected value: 'True'. Actual value: 'False'
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Invalid setting 'IssueWarningQuota'. Expected value: 'unlimited'. Actual value: '1.899 GB (2,039,480,320 bytes)'
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Invalid setting 'ProhibitSendQuota'. Expected value: 'unlimited'. Actual value: '2 GB (2,147,483,648 bytes)'
VERBOSE: [EXCH001]: [[xExchMailboxDatabase]ExchDB] Invalid setting 'ProhibitSendReceiveQuota'. Expected value: 'unlimited'. Actual value: '2.3 GB (2,469,396,480 bytes)'
VERBOSE: [EXCH001]: LCM: [ End Test ] [[xExchMailboxDatabase]ExchDB] False in 4.5940 seconds.
VERBOSE: [EXCH001]: LCM: [ End Resource ] [[xExchMailboxDatabase]ExchDB]
VERBOSE: [EXCH001]: LCM: [ End Compare ] Completed processing compare operation. The operation returned False.
VERBOSE: [EXCH001]: LCM: [ End Compare ] in 4.8460 seconds.
VERBOSE: Operation 'Invoke CimMethod' complete.

Answer 5 · 2022-11-15T16:20:45.000Z

I also get this error regularly. It's probably only happens on first DSC execution.
I took a closer look at this today. The problem is probably line 117 in Modules/xExchangeHelper/xExchangeHelper.psm1

Can you please test following:
In C:\Program Files\WindowsPowerShell\Modules\xExchange\1.33.0\Modules\xExchangeHelper\xExchangeHelper.psm1 change Line 117 from Import-RemoteExchangeModule -Session $session -Verbose:$VerbosePreference to Import-RemoteExchangeModule -Session $session -Verbose:$VerbosePreference | Out-Null

Delete Folder c:\windows\temp\DSCExchangeModule

Apply your DSC configuration.

Answer 6 · 2022-11-15T18:09:29.000Z

Great find! The fix worked with my first test ;-)
I will try to run a few more later tonight.

Answer 7 · 2022-11-15T18:56:11.000Z

Cool :-)
If your tests are fine, I will make a Pull Request for this bug.

Answer 8 · 2022-11-18T13:06:22.000Z

Multiple tests show success so far, so it looks like it's working. ;-)

Five successful runs and two failed control runs, without the change.

Answer 9 · 2022-11-18T17:28:55.000Z

Perfect. I will create a pull request next week.