How to Create SOAP Trace Logs to Troubleshoot PowerCLI Errors

Ugh! That’s my first reaction to seeing a failure from PowerCLI when I’m running through a workflow with PowerShell, however, I recently learned the process of creating a SOAP trace log to better troubleshoot failures in PowerShell when using PowerCLI.

Based off of prior experience, nine times out of ten the error messaging is not helpful and then even checking the logs in vCenter doesn’t give much information on why the failure triggered. With the recent release of PowerCLI 12 I have had the unfortunate pleasure of finding new issues with some queries against vVols related objects. In the process of troubleshooting these with VMware I learned a few new things when trying to troubleshoot and root cause the failure. Let me share what I’ve learned!

Setting up SOAP Trace Logs

One of the new methods of troubleshooting and tracing down the failures was the ability to create a log that had all of the SOAP calls made during this call. There were were two aspects that I learned, creating a SMS SOAP trace and creating a SPBM SOAP trace. What is the difference? There are different calls that are made with PowerCLI had different workflows related to them. One of the cmdlets, Get-VasaStorageArray, is making the calls through SMS to query the storage arrays by provider. The other was with the cmdlet, Get-SpbmStoragePolicy, which makes a query through pbm (policy based management).

Creating a SMS Soap Trace Log

First let me show the workflow that I followed when getting the SOAP Trace for the SMS process.

New-Item -ItemType directory -Path C:\soap-log\

$env:PowerCLISmsSoapLoggingFilePath = 'C:\soap-log\smsSoapLog.txt'

connect-viserver -server vcsa.alex.purestorage.com

Get-VasaStorageArray

First I created the directory that I wanted to store the Log that I was creating. Then I set a new environment variable for the SMS SOAP logging path. After that I connected to the vCenter Server and ran the command that I was troubleshooting. Here was the error/failure that PowerShell gave me:

Get-VasaStorageArray
Get-VasaStorageArray : 2/24/2021 2:26:41 PM Get-VasaStorageArray Object reference not set to an instance of an object.
At line:1 char:1
+ Get-VasaStorageArray
+ ~~~~~~~~~~~~~~~~~~~~
+ CategoryInfo : NotSpecified: (:) [Get-VasaStorageArray], VimException
+ FullyQualifiedErrorId : Core_BaseCmdlet_UnknownError,VMware.VimAutomation.Storage.Commands.Cmdlets.Sms.GetVasaStorageArray 

Not the most helpful of errors as I do not see what Provider it failed on. However, since I know that the call I’m making is going to be issuing a QueryArray to the Storage Providers registered, I can search for those sections in the log. Here was the interesting part, I only see 3 QueryArrays being issued in the trace and the last one does have nothing returned for it.

grep -c "<QueryArray " smsSoapLog.txt
3

When looking at these I can see that there was a queryProvider request/response then a queryArray request/response. The first two were fine, but the third and final one, we have a problem.

-----SoapRequest at 2/24/2021 2:26:41 PM
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">
  <s:Header>
    <Action s:mustUnderstand="1" xmlns="http://schemas.microsoft.com/ws/2005/05/addressing/none">urn:sms/6.5</Action>
    <vcSessionCookie>"18b51e00c545b61479dc6877a70ec47276dd134f"</vcSessionCookie>
  </s:Header>
  <s:Body xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema">
    <QueryArray xmlns="urn:sms">
      <_this type="SmsStorageManager">storageManager</_this>
      <providerId>921efe0b-c6ad-4d98-a293-e02f670c5731</providerId>
    </QueryArray>
  </s:Body>
</s:Envelope>

-----SoapResponse at 2/24/2021 2:26:41 PM
<soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:soapenc="http://schemas.xmlsoap.org/soap/encoding/" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
  <s:Header xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" />
  <soapenv:Body>
    <QueryArrayResponse xmlns="urn:sms" xmlns:sms="urn:sms" />
  </soapenv:Body>
</soapenv:Envelope>

Notice that, it’s a Null or Empty response. This was the final queryArray that we saw as well, after that it’s done. However, that doesn’t mean that this was the failure. Since we do see another queryProvider happen right after this and we don’t see an attempt to queryArray after that. This is where something else that I learned may help to further debut it. I went through the following workflow:

$e = $Error[0]

$e.Exception

2/24/2021 2:26:41 PM Get-VasaStorageArray Object reference not set to an instance of an object.

$e.Exception.StackTrace


$e.Exception.InnerException.StackTrace
at VMware.VimAutomation.Storage.Impl.V1.Sms.VasaProviderImpl.GetDateTimeFromString(String dateTimeString)
at VMware.VimAutomation.Storage.Impl.V1.Sms.VasaProviderImpl..ctor(String connectionId, String moRefId, VasaProviderInfo extensionData)
at VMware.VimAutomation.Storage.Impl.V1.Service.SmsStorageServiceImpl.GetVasaProviderInfo(String providerId, Boolean refresh)
at VMware.VimAutomation.Storage.Impl.V1.Sms.VasaProviderImpl.Initialize()
at VMware.VimAutomation.Storage.Impl.V1.Service.SmsStorageServiceImpl.GetVasaStorageArray(IEnumerable`1 provider, Boolean refresh)
at VMware.VimAutomation.Storage.Impl.V1.Service.SmsStorageServiceImpl.GetVasaStorageArray(String[] name, VasaProvider[] provider, VvolStorageContainer[] storageContainer, Boolean refresh)
at VMware.VimAutomation.Storage.Commands.Cmdlets.Sms.GetVasaStorageArray.GetVasaStorageArrayWorker.DoWork(List`1 moList)
at VMware.VimAutomation.Storage.Commands.Util.StorageCmdletWorker.DoWork(List`1 moList)
at VMware.VimAutomation.Sdk.Util10Ps.BaseCmdlet.CmdletWorker.StartWork(Object obj)

Did that help me very much? Well, kind of, since I can see that the stacktrace on the inner exception looks to be triggered when trying to get specific strings/refrences for a provider. Obviously at this point I need help since I’m a PowerShell and PowerCLI noob. I’m currently working with VMware to dig into this more, but it’s an ongoing process. I was just really excited to lear some more debugging workflows to help out.

This wasn’t the only new aspect that I learned though. I also learned how to grab a SPBM SOAP trace.

Creating a SPBM SOAP Trace Log

Now onto the SPBM failure that I was getting. Here was what I ran (this was something specific to PowerCLI 12.2 as this same workflow worked fine on 12.1).

Get-SpbmStoragePolicy

Name Description Rule Sets Common Rules
---- ----------- --------- ------------
Management Storag... Management Storage policy used for... {(VSAN.hostFailuresToTolera... {}
VVol No Requireme... Allow the datastore to determine t...
VM Encryption Policy Sample storage policy for VMware's... {} {}
Management Storag... Management Storage policy used for... {(VSAN.hostFailuresToTolera... {}
Management Storag... Management Storage policy used for... {(VSAN.hostFailuresToTolera... {}
Management Storag... Management Storage policy used for... {(VSAN.hostFailuresToTolera... {}
SIOC vVols {(com.purestorage.storage.p... {}
Host-local PMem D... Storage policy used as default for... {} {PMem.PMemType (missing)=Lo...
vSAN Default Stor... Storage policy used as default for... {(VSAN.hostFailuresToTolera... {}
Management Storag... Management Storage policy used for... {(VSAN.hostFailuresToTolera... {}
Stretched-Storage... {(AC-Stretched-Storage-Tag)} {}
Management Storag... Management Storage policy used for... {(VSAN.hostFailuresToTolera... {}
Get-SpbmStoragePolicy : 2/11/2021 2:08:53 PM Get-SpbmStoragePolicy Rule set has other line of service rules without any persistence line of service rule.
At line:1 char:1
+ Get-SpbmStoragePolicy
+ ~~~~~~~~~~~~~~~~~~~~~
+ CategoryInfo : InvalidArgument: (:) [Get-SpbmStoragePolicy], VimException
+ FullyQualifiedErrorId : Spbm_Impl_ProfileServiceImpl_RuleSetNoPersistenceNamespace,VMware.VimAutomation.Storage.Commands.Cmdlets.Spbm.GetStorageProfile

Get-SpbmStoragePolicy : 2/11/2021 2:08:53 PM Get-SpbmStoragePolicy Rule set has other line of service rules without any persistence line of service rule.
At line:1 char:1
+ Get-SpbmStoragePolicy
+ ~~~~~~~~~~~~~~~~~~~~~
+ CategoryInfo : InvalidArgument: (:) [Get-SpbmStoragePolicy], VimException
+ FullyQualifiedErrorId : Spbm_Impl_ProfileServiceImpl_RuleSetNoPersistenceNamespace,VMware.VimAutomation.Storage.Commands.Cmdlets.Spbm.GetStorageProfile

Get-SpbmStoragePolicy : 2/11/2021 2:08:53 PM Get-SpbmStoragePolicy Rule set has other line of service rules without any persistence line of service rule.
At line:1 char:1
+ Get-SpbmStoragePolicy
+ ~~~~~~~~~~~~~~~~~~~~~
+ CategoryInfo : InvalidArgument: (:) [Get-SpbmStoragePolicy], VimException
+ FullyQualifiedErrorId : Spbm_Impl_ProfileServiceImpl_RuleSetNoPersistenceNamespace,VMware.VimAutomation.Storage.Commands.Cmdlets.Spbm.GetStorageProfile

Get-SpbmStoragePolicy : 2/11/2021 2:08:53 PM Get-SpbmStoragePolicy Rule set has other line of service rules without any persistence line of service rule.
At line:1 char:1
+ Get-SpbmStoragePolicy
+ ~~~~~~~~~~~~~~~~~~~~~
+ CategoryInfo : InvalidArgument: (:) [Get-SpbmStoragePolicy], VimException
+ FullyQualifiedErrorId : Spbm_Impl_ProfileServiceImpl_RuleSetNoPersistenceNamespace,VMware.VimAutomation.Storage.Commands.Cmdlets.Spbm.GetStorageProfile 

Now, this is a pretty big issue, as none of the non default policies that I had created would be getting displayed here. In order to get the logging setup I went through the following:

New-Item -ItemType directory -Path C:\soap-log\

$env:PowerCLISpbmSoapLoggingFilePath = 'C:\soap-log\spbmSoapLog.txt'

connect-viserver -server vcsa.alex.purestorage.com

Get-SpbmStoragePolicy

I also went ahead and and set the error to $e and ran through the stack trace to see if that helped.

$e
Get-SpbmStoragePolicy : 2/11/2021 2:08:53 PM    Get-SpbmStoragePolicy           Rule set has other line of service rules without any persistence line of service rule. 
At line:1 char:1
+ Get-SpbmStoragePolicy
+ ~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : InvalidArgument: (:) [Get-SpbmStoragePolicy], VimException
    + FullyQualifiedErrorId : Spbm_Impl_ProfileServiceImpl_RuleSetNoPersistenceNamespace,VMware.VimAutomation.Storage.Commands.Cmdlets.Spbm.GetStorageProfile
 
$e.Exception
2/11/2021 2:08:53 PM    Get-SpbmStoragePolicy           Rule set has other line of service rules without any persistence line of service rule.

$e.Exception.StackTrace
   at VMware.VimAutomation.Storage.Impl.V1.Utils.PbmProxyObjectHelper.ValidateSpbmRuleSetWithLineOfService(SpbmRule[] rules, SpbmStoragePolicyCategoryType policyCategory)
   at VMware.VimAutomation.Storage.Impl.V1.Utils.PbmProxyObjectHelper.GetSpbmRuleSetFromProxy(StorageClient client, PbmCapabilitySubProfile proxySubProfile, SpbmStoragePolicyCategoryType policycategory, List`1 commonRulesCapabilityId, Dictionary`2 capabilityDictionary, Dictionary`2 tagDictionary, Dictionary`2 policyComponentMap)
   at VMware.VimAutomation.Storage.Impl.V1.Utils.PbmProxyObjectHelper.GetStoragePolicyFromProxy(StorageClient client, PbmCapabilityProfile proxyProfile, Dictionary`2 capabilityDictionary, Dictionary`2 tagDictionary, Dictionary`2 policyComponentMap)
   at VMware.VimAutomation.Storage.Impl.V1.Service.SpbmProfileServiceImpl.<GetStoragePolicyById>d__11.MoveNext()

$e.Exception.InnerException

$e.Exception.InnerException.StackTrace

To be fair, this one is something that I’m finding a bit more complicated to trace down. Looking through the SOAP trace log I didn’t find too much either. This is one that I also ran through this on 12.1 (when it worked) and tried to match the SOAP workflow for the failure point and drew a blank. I’m currently working with VMware to track down what changed in the pbm workflows.

So these are a couple of new things that I recently had fun learning and who knows, maybe they’ll help out someone in the future.