Skip to main content
Pure Technical Services

Troubleshooting: vVols Mental Model

Currently viewing public documentation. Please login to access the full scope of documentation.

KP_Ext_Announcement.png

Troubleshooting Overview

The purpose of this KB is to give a general vVols troubleshooting workflow and mental model.  As each case can be unique, it's important to get the right information early and to start time lining all of the events.

Related vVol KBs and White Papers


Troubleshooting Flowchart/Workflow

Here is a simple mental model of initially troubleshooting a vVols issue.  It's good to remember that the questions you ask initially are going to provide some of the greatest help in troubleshooting and solving the issue earlier rather than later.  If the issue is a Sev1, then it's even more important to ask the right questions and start getting the customer something to gather for you.

This is not meant to be an exhaustive mental model or flow chart.  This will help you get started and start framing the issue and asking the right questions early and often.

Notes:
Binding and unbinding is automatic. There is never a need for a VMware or FlashArray administrator to manually bind a vVol to an ESXi host.

FlashArrays only bind vVols to ESXi hosts that make requests; they do not bind them to host groups.

If multiple PEs are presented to an ESXi host, the host selects one at random to satisfy each bind request. Array administrators cannot control which PE is used for a bind.

This blog post contains a detailed description of ESXi host to PE to vVol binding.

The end user should never need to manually connect a vVol to a FlashArray Host or Hostgroup.  Read more about why you shouldn't manually connect the vVol here.


Command Output Examples

Here we can go over what some of the best commands to troubleshoot vVols issues from the esxcli are and what we would expect to see from them.

  • vmware -vl
    • [root@UCS-Blade-8:~] vmware -vl
      VMware ESXi 6.7.0 build-8169922
      VMware ESXi 6.7.0 GA

Why is this one useful?  It's a quick way for us to find out what version of ESXi they are using.

  • esxcfg-info -w |head
    • [root@UCS-Blade-8:~] esxcfg-info -w |head
      +Hardware Info :
         |----BIOS UUID...................................................0x3e 0x98 0x4e 0x8a 0x57 0x3e 0xe1 0x11 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x1
         |----BIOS Vendor.................................................Cisco Systems, Inc.
         |----BIOS Version................................................B200M4.3.1.3i.0.032120171710
         |----BIOS ReleaseDate............................................2017-03-21T00:00:00
         |----BIOS Asset Tag..............................................
         |----Product Name................................................UCSB-B200-M4
         |----Vendor Name.................................................Cisco Systems Inc
         |----Serial Number...............................................
         |----Enclosure Serial Number.....................................

Why is this one useful?  It's a quick way for us to find out what hardware their host is running.  In the example above we have a UCS Blade, specifically an M4 blade.

  • esxcli storage core adapter list
    • [root@UCS-Blade-8:~] esxcli storage core adapter list
      HBA Name  Driver  Link State  UID                                   Capabilities         Description
      --------  ------  ----------  ------------------------------------  -------------------  ---------------------------------------------------
      vmhba0    fnic    link-up     fc.20000025b5100007:20000025b510aa07  Second Level Lun ID  (0000:0c:00.0) Cisco Systems Inc Cisco VIC FCoE HBA
      vmhba1    fnic    link-up     fc.20000025b5100007:20000025b510bb07  Second Level Lun ID  (0000:0d:00.0) Cisco Systems Inc Cisco VIC FCoE HBA

Why is this one useful?  Here we can find out if their are FC or iSCSI and if they are FC we can find out if they have support for second level lun IDs (required for vvols).

  • esxcfg-scsidevs -c |grep "1MB"
    • [root@UCS-Blade-8:~] esxcfg-scsidevs -c |grep "1MB"
      naa.624a93707dac5a64a4ae4de00004822f  Direct-Access    /vmfs/devices/disks/naa.624a93707dac5a64a4ae4de00004822f  1MB       NMP     PURE Fibre Channel Disk (naa.624a93707dac5a64a4ae4de00004822f)
      

Why is this one useful?  It's a quick way for us to find out what the device id is for the protocol endpoint presented to the host.  Remember your ID, we'll use it again.

  • esxcfg-mpath -L -d naa.624a93707dac5a64a4ae4de00004822f
    • [root@UCS-Blade-8:~] esxcfg-mpath -L -d naa.624a93707dac5a64a4ae4de00004822f
      vmhba1:C0:T10:L150 state:active naa.624a93707dac5a64a4ae4de00004822f vmhba1 0 10 150 NMP active san fc.20000025b5100007:20000025b510bb07 fc.524a93786fea4b11:524a93786fea4b11
      vmhba0:C0:T10:L150 state:active naa.624a93707dac5a64a4ae4de00004822f vmhba0 0 10 150 NMP active san fc.20000025b5100007:20000025b510aa07 fc.524a93786fea4b10:524a93786fea4b10
      vmhba1:C0:T11:L150 state:active naa.624a93707dac5a64a4ae4de00004822f vmhba1 0 11 150 NMP active san fc.20000025b5100007:20000025b510bb07 fc.524a93786fea4b01:524a93786fea4b01
      vmhba0:C0:T11:L150 state:active naa.624a93707dac5a64a4ae4de00004822f vmhba0 0 11 150 NMP active san fc.20000025b5100007:20000025b510aa07 fc.524a93786fea4b00:524a93786fea4b00

Why is this one useful?  Here we can find out what the state of the paths are to the protocol endpoint and if they are active/up.

  • esxcli storage vvol protocolendpoint list
    • [root@UCS-Blade-8:~] esxcli storage vvol protocolendpoint list
         naa.624a93707dac5a64a4ae4de00004822f
         Host Id: naa.624a93707dac5a64a4ae4de00004822f
         Array Id: com.purestorage:7dac5a64-a4ae-4de0-8e14-1fbbd2accb91
         Type: SCSI
         Accessible: true
         Configured: true
         Lun Id: naa.624a93707dac5a64a4ae4de00004822f
         Remote Host:
         Remote Share:
         NFS4x Transport IPs:
         Server Scope:
         Server Major:
         Auth:
         User:
         Storage Containers: 75a7cd5b-916d-35f0-b9f5-a720a71aaee9
      

Why is this one useful?  Alright, now we have some good vvol specific ones.  This one will list out the protocol endpoint, it's status and the Array ID and Container ID.

  • esxcli storage vvol vasaprovider list
    • [root@UCS-Blade-8:~] esxcli storage vvol vasaprovider list
      SLC-m50r2-ct0
         VP Name: SLC-m50r2-ct0
         URL: https://10.204.112.170:8084
         Status: online
         Arrays:
               Array Id: com.purestorage:7dac5a64-a4ae-4de0-8e14-1fbbd2accb91
               Is Active: true
               Priority: 200

Why is this one useful?  Here we get to see what vasa provider is connected to the host and what it's state is.  This is important because vCenter forwards this information to the host along with the certificate.  We never input the vasa provider (storage provider in vCenter) to the host directly, this is give to the vCenter that then forwards it the hosts.  If we have an error here, then we either have a problem with the Date (check the date to make sure it's current), a connectivity issue, or a certificate issue.

  • nc -z <VP IP address> 8084
    • [root@UCS-Blade-8:~] nc -z 10.204.112.170 8084
      Connection to 10.204.112.170 8084 port [tcp/*] succeeded!

Why is this one useful?  Ah, this let's us test if the host is able to connect to the vasa provider over port 8084 over it's management address.  Either the port is open and able to connect or it's not.  If this isn't connecting, then we have a problem.

  • esxcli storage vvol vasacontext get
    • [root@UCS-Blade-8:~] esxcli storage vvol vasacontext get
      6e47f6d1-7386-48dc-b119-75abe6f369af

Why is this one useful?  This will show us the VASA context (VC UUID) associated with the host.  This is important if we have to look through the vCenter sps log or correlate what we see in the vvold log with the VC UUID.

  • esxcli storage vvol storagecontainer list
    • [root@UCS-Blade-8:~] esxcli storage vvol storagecontainer list
      SLC-m50r2-vVol-Container
         StorageContainer Name: SLC-m50r2-vVol-Container
         UUID: vvol:75a7cd5b916d35f0-b9f5a720a71aaee9
         Array: com.purestorage:7dac5a64-a4ae-4de0-8e14-1fbbd2accb91
         Size(MB): 8589934592
         Free(MB): 8589864503
         Accessible: true
         Default Policy:

Why is this one useful?  This is going to get us all vvol storage containers that the host can see.  We would expect there to be a size listed and for the accessibility to show as true.


Logs and Log Lines of Interest

Here we are going to go over what logs are important and then try to give some quick pointers on what we are looking for in the logs.

Know your Logs

  • Array Logs

    • /var/log/purity/vasa.log
      • Here we log any requests that are coming from any of the hosts and vCenter regarding vasa.  It's not the cleanest or easiest log to read or follow, but it's important for us to correlate requests that come in from the host to what's happening on the array with those requests.

    • 
/var/log/purity/middleware.log
      • It won't be often that you'll need to directly look through the middleware log, but there may be times you need to see what's happening to the request that vasa is forwarding to middleware and the rest server.

  • Host Logs

    • /var/log/vvold.log
      • Alright, this is likely the most important log on the host for us to be looking through if we have a vvol issue.  We will more than likely be able to isolate the issue from this log alone, but not always.  Here we will be able to see any request, operation or success/failure regarding vvol operations.  We'll be able to see the bind/unbind requests and any other queries to the vasa provider and protocol endpoint.  

    • /var/log/vmkernel.log 

      • This goes without saying that we always want to gather the vmkernel log and will often being reviewing the operations and activity happening here.

  • vCenter Server Logs

    • /var/log/vmware/vmware-sps/sps.log
      • What is the SPS Log?  SPS is the VMware vSphere Profile-Driven Storage Service that runs on vCenter.  This allows vCenter to utilize the vSphere Storage API's for Storage Awareness (VASA).  Why is this an important log?  In this log we are able to see if there are issues or errors with the vCenter communicating between the hosts and array.  If there are certificate issues between the host and vCenter they will often show up here as well.  Along with this, we can see if there are requests taking a long time to complete.  Overall this is a crucial log to gather.

 


Examples of What to Look for and Action Plans

Here we can go over some of the common issues we would see and what to look for in the logs and the command outputs.

First we'll take a look at some of the lines in each log we want to look at and explain what we are looking through.  Then we'll see if we are in certain situations what we need to do to get out of them.

  • vvold.log

Before really digging into the logs we should have at least ran the commands above and gotten their output (if we only have support logs they are under the commands directory).  So we should know what our PE name is, what the vCenter VASA context ID is and what the Storage Container's name and state are.  Okay, so in normal conditions, this is what I would expect to see in the vvold.log.

-- Good Example 1
  • 2018-08-15T23:18:40.020Z info vvold[2216001] [Originator@6876 sub=Default] Came to SI::GetVvolContainer: container 0f6cc3d3-bfdb-37eb-9318-5299b53e59da
    2018-08-15T23:18:40.020Z info vvold[2216001] [Originator@6876 sub=Default] StorageArray::GetArrayInfo arrayId com.purestorage:2f2c2c8a-afcf-4019-b489-60ea4f9d0a3f
    2018-08-15T23:18:40.020Z info vvold[2216001] [Originator@6876 sub=Default] HostManager::GetPEsForStorageArray arrayId: com.purestorage:2f2c2c8a-afcf-4019-b489-60ea4f9d0a3f, peVec.size: 2, peType: SCSI
    2018-08-15T23:18:40.020Z info vvold[2216001] [Originator@6876 sub=Default] ProtocolEndpoint::GetPEInfo PE info (
    --> SCSI PE, ID (host: naa.624a93702f2c2c8aafcf401900de781f, vasa: naa.624a93702f2c2c8aafcf401900de781f) (accessible, configured))
    2018-08-15T23:18:40.020Z info vvold[2216001] [Originator@6876 sub=Default] ProtocolEndpoint::GetPEInfo PE info (
    --> SCSI PE, ID (host: naa.624a93702f2c2c8aafcf401900e2a9cc, vasa: naa.624a93702f2c2c8aafcf401900e2a9cc) (accessible, configured))
    2018-08-15T23:18:40.020Z info vvold[2216001] [Originator@6876 sub=Default] SI:GetVvolContainer successful for SLC-450-2-vVol-Container, id=0f6cc3d3-bfdb-37eb-9318-5299b53e59da, maxvVol=0 MB
    2018-08-15T23:18:53.308Z info vvold[2216045] [Originator@6876 sub=Default]
    --> VasaOp::EventPollerCB [#10099]: ===> Issuing 'getEvents' to VP SLC-450-2-ct0 (#outstanding 0/5) [session state: Connected]
    2018-08-15T23:18:53.320Z error vvold[2216045] [Originator@6876 sub=Default]
    --> VasaOp::ThrowFromSessionError [#10099]: ===> FINAL SUCCESS getEvents VP (SLC-450-2-ct0) Container (SLC-450-2-ct0) timeElapsed=11 msecs (#outstanding 0)

Okay, so what are we seeing here?  Basically we see the first request to get the vvol container and it succeeds and we see the container ID printed.  Then we see the Array Info queried and we get the Array ID printed.  From that point we see the Protocol Endpoint is queried.  Then we see that the SCSI PE is accessible and configured (in this case there were two PE's connected to the host, other times you'll only see one).  Then we see confirmation that the Get vVol Container was successful for that vVol Container (datastore).  Then we see an event issued.  This could be binds, unbinds, deletes, etc.  In this case it was a getEvents, it's issued and then we see it's completed.  The nice there here is that we can also correlated that with what we see in the vasa log.  I'll cover that below a little.

Okay, that's if things are good, what about if things are bad? 

-- Bad Example 1
  • --> VasaOp::EventPollerCB [#64810]: ===> Issuing 'getEvents' to VP SLC-OOTO-ct0 (#outstanding 0/5) [session state: Connected]
    2018-08-15T12:53:04.003Z error vvold[2099148] [Originator@6876 sub=Default]
    --> VasaOp::ThrowFromSessionError [#64810]: ===> FINAL FAILURE getEvents, error (STORAGE_FAULT / Couldn't verify the client SSL certificate / ) VP (SLC-OOTO-ct0) Container (SLC-OOTO-ct0) timeElapsed=2 msecs (#outstanding 0)
    2018-08-15T12:53:04.004Z error vvold[2099129] [Originator@6876 sub=Default] VasaSession::EventPollerCB VP SLC-OOTO-ct0: getEvents failed (STORAGE_FAULT, Couldn't verify the client SSL certificate / ) [session state: Connected]
    

Now, we have a Failure.  That line FINAL FAILURE can be useful to look for.  Here it's saying that the host couldn't verify the client SSL Cert.  The reason behind this can be a couple reasons, but most often it's because the customer either registered another vCenter for the storage provider and it wiped out the cert for the vCenter the host is one or the customer is setting up this vCenter on an array that already had vVols configured for a different vCenter.  More often than not though it's because they accidently registered a different vCenter when they shouldn't have.  Let's get another bad example that's a little harder to troubleshoot.

-- Bad Example 2
  • 2018-08-15T13:19:41.718Z info vvold[53FDB70] [Originator@6876 sub=Default] SI:AddVvolContainer@2151 03b67838-0f88-3b63-bd54-d8e56ba04288 with arrayId com.purestorage:ff3188e8-906d-4f3b-9235-0b901e7f6b63 present false
    2018-08-15T13:19:41.718Z info vvold[53FDB70] [Originator@6876 sub=Default] StorageContainerMgr::Add 03b67838-0f88-3b63-bd54-d8e56ba04288 slc-m20r2-vvol-container
    2018-08-15T13:19:42.018Z info vvold[53BCB70] [Originator@6876 sub=Default] Came to SI::UpdateVvolContainer: Container  with 1 Arrays and 1 VPs
    2018-08-15T13:19:42.019Z info vvold[53BCB70] [Originator@6876 sub=Default] VendorProviderMgr::AddOrRef VP (SLC-m20r2-ct0) URL (https://10.204.120.210:8084/version.xml)
    2018-08-15T13:19:42.019Z info vvold[53BCB70] [Originator@6876 sub=Default] DlgSoapCtxPool: Created new DlgSoapCtxPool ([14DlgSoapCtxPool:0x02437f70]) for VP (SLC-m20r2-ct0) session (024632f8)
    2018-08-15T13:19:42.034Z info vvold[53BCB70] [Originator@6876 sub=Libs] Firewall: allowed access to port 8084
    2018-08-15T13:19:42.035Z info vvold[53BCB70] [Originator@6876 sub=Default] VendorProviderMgr:UpdateFirewallRules: Firewall operation add on rule id:VVOLD_8084 success
    2018-08-15T13:19:42.035Z info vvold[53BCB70] [Originator@6876 sub=Default] VasaSession::GetEndPoint: with url https://10.204.120.210:8084/version.xml
    2018-08-15T13:19:42.048Z warning vvold[53BCB70] [Originator@6876 sub=Default] VasaSession::GetEndPoint: failed to get endpoint, err=SSL Exception: Verification parameters:
    --> PeerThumbprint: 2A:6E:2B:77:71:8F:1E:9A:06:5B:70:0B:7C:CE:28:BB:57:C8:14:5B
    --> ExpectedThumbprint:
    --> ExpectedPeerName: 10.204.120.210
    --> The remote host certificate has these problems:
    -->
    --> * unable to get local issuer certificate, using default
    2018-08-15T13:19:42.049Z info vvold[53BCB70] [Originator@6876 sub=Default] VasaSession::Initialize url is empty
    2018-08-15T13:19:42.050Z warning vvold[53BCB70] [Originator@6876 sub=Default] VasaSession::DoSetContext: Empty VP URL for VP (SLC-m20r2-ct0)!
    2018-08-15T13:19:42.050Z info vvold[53BCB70] [Originator@6876 sub=Default] Initialize: Failed to establish connection https://10.204.120.210:8084/version.xml
    2018-08-15T13:19:42.051Z error vvold[53BCB70] [Originator@6876 sub=Default] Initialize: Unable to init session to VP SLC-m20r2-ct0 state: 0
    2018-08-15T13:19:42.053Z info vvold[53BCB70] [Originator@6876 sub=Default] Calling UnbindAllVirtualVolumesFromHost::Initialize: for 3E984E8A-573E-E111-0000-000000000008
    2018-08-15T13:19:42.055Z info vvold[53BCB70] [Originator@6876 sub=Default]
    --> VasaOp::UnbindAllVirtualVolumesFromHost [#0]: ===> Issuing 'unbindAllVirtualVolumesFromHost' to VP SLC-m20r2-ct0 (#outstanding 0/4) [session state: Uninitialized]
    2018-08-15T13:19:42.055Z error vvold[53BCB70] [Originator@6876 sub=Default]
    --> VasaOp::ThrowFromSessionError [#0]: ===> FINAL FAILURE unbindAllVirtualVolumesFromHost, error (INVALID_SESSION / Bad session state (Uninitialized)) VP (SLC-m20r2-ct0) Container (SLC-m20r2-ct0) timeElapsed=0 msecs (#outstanding 0)
    2018-08-15T13:19:42.056Z error vvold[53BCB70] [Originator@6876 sub=Default] AddOrRef:VP (SLC-m20r2-ct0) url (https://10.204.120.210:8084/version.xml) Initialization failed Bad session state (Uninitialized)
    2018-08-15T13:19:42.132Z info vvold[53BCB70] [Originator@6876 sub=Libs] Firewall: denied access to port 8084
    2018-08-15T13:19:42.132Z info vvold[53BCB70] [Originator@6876 sub=Default] VendorProviderMgr:UpdateFirewallRules: Firewall operation remove on rule id:VVOLD_8084 success
    2018-08-15T13:19:42.132Z info vvold[53BCB70] [Originator@6876 sub=Default] VasaSession::DestroyNolock for url https://10.204.120.210:8084/version.xml
    2018-08-15T13:19:42.132Z info vvold[53BCB70] [Originator@6876 sub=Default] VasaSession::KillAllConnections VP (SLC-m20r2-ct0), purged 0 connections, 0 currently active, new genId (1) (broadcast wakeup to all threads waiting for free connection)
    2018-08-15T13:19:42.133Z error vvold[53BCB70] [Originator@6876 sub=Default] VvolServiceInstance::UpdateVendorProviderInt: Got exception for VP (SLC-m20r2-ct0): Bad session state (Uninitialized)
    2018-08-15T13:19:42.133Z error vvold[53BCB70] [Originator@6876 sub=Default] VvolServiceInstance::GetBestVpRefForArrayId: No Best VP available for array (com.purestorage:ff3188e8-906d-4f3b-9235-0b901e7f6b63)
    2018-08-15T13:19:42.133Z warning vvold[53BCB70] [Originator@6876 sub=Default] SI:UpdateVendorProviderInt: No best vp for arrayId com.purestorage:ff3188e8-906d-4f3b-9235-0b901e7f6b63

So, what's going on here?  This is on the initial creation of the storage container and we are seeing 0MB in size, but the vCenter was able to register the storage provider and the customer was able to create the vvol datastore.  However after that one or more hosts are showing up with 0MB size and you are unable to access the vVol container.  Here are the important lines, "unable to get local issuer cert" combined with "Initialize url is empty"  Then we see that there is an Invalid session.  This is because vCenter is failing to forward the vasa cert information to the host.  Sometimes simply rebooting the host will clear this, but other times you have to refresh the cert on the host and then reboot.  View this document to refresh the cert.  This is covered in the troubleshooting storage provider and vvol setup KB in more detail on the recovery.

  • vmkernel.log

I'll try to get some examples in here (or if anyone has any good ones), but really what you are going to want to do is search for your naa. device for the protocol endpoint and then the vvol container id.  So, if you use the output of the example commands above, you'd want to use naa.624a93707dac5a64a4ae4de00004822f and 75a7cd5b-916d-35f0-b9f5-a720a71aaee9 .  Like I said, I'll try get some better examples in here or if anyone has and good once, let me know.

  • sps.log

The sps log is a great place to go if the storage provider completed successfully, but the hosts are unable to mount to the vvol datastore and you suspect the cert isn't getting pushed to the host.  The log is also a great place to look if vCenter is unable to register the arrays storage providers.

Here is a look at when a storage provider is registered successfully.

  • 2018-08-15T13:18:59.747Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.storage.common.util.SimpleTimeCounter - TIMER STOPPED: VasaClientImpl : registerCACertificatesAndCRLs for provider: https://10.204.120.210:8084/version.xml, TIME TAKEN: 917 ms.
    2018-08-15T13:18:59.747Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.ProviderCache - [setProviderTrustedCertPropagationStatus] Setting TrustedCertPropagationStatus, as the bootstrapping call is made to the VP https://10.204.120.210:8084/version.xml.
    2018-08-15T13:18:59.753Z [pool-22-thread-8] DEBUG opId=8db779f5-04bf-4c45-a348-9d8c2278cd3e com.vmware.vim.sms.task.TaskImpl - Received API call : queryInfo for task - ManagedObjectReference: type = SmsTask, value = SmsTask-286, serverGuid = b7c32861-7d43-4a3d-bb33-d8c2164acf09
    2018-08-15T13:18:59.810Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderUtils - Provider name: SLC-m20r2-ct0
    2018-08-15T13:18:59.811Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderUtils - Provider description: null
    2018-08-15T13:18:59.811Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderUtils - Provider namespace: com.purestorage
    2018-08-15T13:18:59.811Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderUtils - Provider URL: https://10.204.120.210:8084/version.xml
    2018-08-15T13:18:59.811Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderUtils - Provider version: 1.0
    2018-08-15T13:18:59.811Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderUtils - Provider VASA version: 3.0
    2018-08-15T13:18:59.811Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderUtils - Provider unique identifier: 06cf1c73-8108-4fc0-b6c7-e89ffea2aa8e
    2018-08-15T13:18:59.811Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderUtils - Provider identifier: dd04fa3a-4fb6-3238-ae66-3b9b138a6ec3
    2018-08-15T13:18:59.811Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderImpl - [isLegacyProvider] the provider is NOT a legacy provider
    2018-08-15T13:18:59.811Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.version.VersionStrategyHelper - [checkIfAlreadyRegistered] Using providerKey: com.purestorage:dd04fa3a-4fb6-3238-ae66-3b9b138a6ec3
    2018-08-15T13:18:59.811Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.version.Version3Strategy - [provisionCASignedCertificate] provider url: https://10.204.120.210:8084/version.xml
    2018-08-15T13:18:59.859Z [pool-24-thread-5] DEBUG opId=a5bc864e-742c-45a6-8e98-f57ddb4bdb1a com.vmware.vim.storage.common.security.CommonActivationValidator - Validating session using session cookie...
    2018-08-15T13:18:59.903Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderUtils - [createConnection] Using CustomHostnameVerifier...
    2018-08-15T13:18:59.906Z [pool-22-thread-9] DEBUG opId=a5bc864e-742c-45a6-8e98-f57ddb4bdb1a com.vmware.vim.sms.task.TaskImpl - Received API call : queryInfo for task - ManagedObjectReference: type = SmsTask, value = SmsTask-286, serverGuid = b7c32861-7d43-4a3d-bb33-d8c2164acf09
    2018-08-15T13:18:59.949Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.version.Version3Strategy - [provisionCASignedCertificate] Provider's certificate is trusted and retainVasaProviderCertificate is false. Skipping VMCA provisioning, but certificate life cycle can still be managed.
    2018-08-15T13:18:59.949Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderInfoPersistenceManager - [saveProviderInfo] Saving the provider information of provider: 06cf1c73-8108-4fc0-b6c7-e89ffea2aa8e
    2018-08-15T13:18:59.949Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderInfoPersistenceManager - [saveKvProviderInfo] Saving the provider information to KV store...
    2018-08-15T13:18:59.950Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.storage.common.kv.LocalKvReaderWriter - Batch getting objects [06cf1c73-8108-4fc0-b6c7-e89ffea2aa8e] from KV store
    2018-08-15T13:18:59.955Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.storage.common.kv.BasicKvProvider - Inserting object with id 06cf1c73-8108-4fc0-b6c7-e89ffea2aa8e in provider [Name:providerInfoKvProvider Optimistic locking:false].
    2018-08-15T13:18:59.965Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.storage.common.kv.BasicKvProvider - Successfully inserted object with id 06cf1c73-8108-4fc0-b6c7-e89ffea2aa8e in provider [Name:providerInfoKvProvider Optimistic locking:false].
    2018-08-15T13:18:59.965Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderInfoPersistenceManager - [saveXdbProviderInfo] RISE is enabled, skipping the operation!!!
    2018-08-15T13:18:59.966Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.version.Version3Strategy - [setContext] setContext attempt #1
    2018-08-15T13:18:59.990Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderImpl - [setContext] WWN : 2305843171165208577:2305843171165252097: IQN:null
    2018-08-15T13:18:59.990Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderImpl - [setContext] WWN : 2305843171165208577:2305843171165256449: IQN:null
    2018-08-15T13:18:59.990Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderImpl - [setContext] WWN : :: IQN:iqn.1998-01.com.vmware:ucs-blade-2
    2018-08-15T13:18:59.990Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderImpl - [setContext] WWN : 2305843171165208576:2305843171165252096: IQN:null
    2018-08-15T13:18:59.990Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderImpl - [setContext] WWN : 2305843171165208576:2305843171165256448: IQN:null
    2018-08-15T13:18:59.990Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderImpl - [setContext] WWN : :: IQN:iqn.1998-01.com.vmware:ucs-blade-1
    2018-08-15T13:18:59.990Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderImpl - [setContext]Chapname :
    2018-08-15T13:18:59.990Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.storage.common.util.SimpleTimeCounter - TIMER STARTED: VasaClientImpl : setContext for provider: https://10.204.120.210:8084/version.xml
    2018-08-15T13:19:00.005Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.storage.common.util.SimpleTimeCounter - TIMER STOPPED: VasaClientImpl : setContext for provider: https://10.204.120.210:8084/version.xml, TIME TAKEN: 15 ms.
    2018-08-15T13:19:00.005Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.version.Version3Strategy - [setContext] setContext attempt #1 is successful!
    2018-08-15T13:19:00.005Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.storage.common.util.SimpleTimeCounter - TIMER STARTED: VasaClientImpl : queryArrays for provider: https://10.204.120.210:8084/version.xml
    2018-08-15T13:19:00.011Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.storage.common.util.SimpleTimeCounter - TIMER STOPPED: VasaClientImpl : queryArrays for provider: https://10.204.120.210:8084/version.xml, TIME TAKEN: 6 ms.
    2018-08-15T13:19:00.011Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProfile - [Init] Initializing profiles supported by the provider...
    2018-08-15T13:19:00.011Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProfile - [Init] Number of arrays reported by the provider - 1
    2018-08-15T13:19:00.011Z [pool-14-thread-2] ERROR opId= com.vmware.vim.sms.provider.vasa.VasaProfile - Invalid Profile ProfileBasedManagementProfile returned for storage array: com.purestorage:ff3188e8-906d-4f3b-9235-0b901e7f6b63
    2018-08-15T13:19:00.011Z [pool-14-thread-2] ERROR opId= com.vmware.vim.sms.provider.vasa.VasaProfile - Invalid Profile ReplicationProfile returned for storage array: com.purestorage:ff3188e8-906d-4f3b-9235-0b901e7f6b63
    2018-08-15T13:19:00.011Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProfile - Array specific priorities -
    2018-08-15T13:19:00.011Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProfile - array - com.purestorage:ff3188e8-906d-4f3b-9235-0b901e7f6b63 priority - 200
    2018-08-15T13:19:00.011Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProfile - Profiles supported by array -
    2018-08-15T13:19:00.011Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProfile - ArrayId - com.purestorage:ff3188e8-906d-4f3b-9235-0b901e7f6b63 : VirtualVolumeProfile
    2018-08-15T13:19:00.011Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProfile - Profiles supported by provider -ProfileBasedManagementProfile
    2018-08-15T13:19:00.011Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProfile - Profiles supported by provider -ReplicationProfile
    2018-08-15T13:19:00.011Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderImpl - Set manageable arrays [com.purestorage:ff3188e8-906d-4f3b-9235-0b901e7f6b63] for provider: 06cf1c73-8108-4fc0-b6c7-e89ffea2aa8e
    2018-08-15T13:19:00.011Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.version.VersionStrategyHelper - [populateRelatedStorageArray] arrayId - com.purestorage:ff3188e8-906d-4f3b-9235-0b901e7f6b63
    2018-08-15T13:19:00.012Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderInfoPersistenceManager - [updateProviderInfo] Updating the provider information of provider: 06cf1c73-8108-4fc0-b6c7-e89ffea2aa8e
    2018-08-15T13:19:00.012Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderInfoPersistenceManager - [updateKvProviderInfo] Updating the provider information stored in KV store...
    2018-08-15T13:19:00.012Z [pool-24-thread-6] DEBUG opId=24110324-0338-48b5-9a23-3921039266fa com.vmware.vim.storage.common.security.CommonActivationValidator - Validating session using session cookie...
    2018-08-15T13:19:00.012Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.storage.common.kv.LocalKvReaderWriter - Batch getting objects [06cf1c73-8108-4fc0-b6c7-e89ffea2aa8e] from KV store
    2018-08-15T13:19:00.032Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderInfoPersistenceManager - [updateXdbProviderInfo] RISE is enabled, skipping the operation!!!
    2018-08-15T13:19:00.032Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderImpl - [initializeProviderComponents] Initializing related components of the provider
    2018-08-15T13:19:00.033Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.catalog.MessageCatalogHandler - [initializeCatalog] Submitting request to initialize catalogs for provider 06cf1c73-8108-4fc0-b6c7-e89ffea2aa8e
    2018-08-15T13:19:00.033Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderImpl - [initEventAndAlarmManagers] Initializing event and alarm managers...
    2018-08-15T13:19:00.033Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.event.VpxdEventPoster - Start event sender...
    2018-08-15T13:19:00.035Z [pool-14-thread-2] DEBUG opId= com.vmware.vim.sms.provider.vasa.VasaProviderImpl - [setStatus] For provider https://10.204.120.210:8084/version.xml, status changed from disconnected -> connected
    

We can see that the process and then that the provider status updated from disconnected to connected.  There are going to be a lot more lines regarding the registration than just these ones.  This is just a short snipped of some of these lines in the sps log.

Then let's say someone accidently registered the arrays storage provider with another vCenter.  Well, you'll see a fair amount of errors in the sps log with certificate errors.

  • 2018-08-17T00:48:37.679Z [pool-9-thread-3] ERROR opId=sps-Main-210327-691 com.vmware.vim.sms.util.CustomHostNameVerifier - [verify] Hostname verification failed for host: 10.204.120.140
    javax.net.ssl.SSLPeerUnverifiedException: peer not authenticated
        at sun.security.ssl.SSLSessionImpl.getPeerCertificates(SSLSessionImpl.java:431)
        at com.vmware.vim.sms.util.CustomHostNameVerifier.retrieveSubjectAlternateNames(CustomHostNameVerifier.java:121)
        at com.vmware.vim.sms.util.CustomHostNameVerifier.verify(CustomHostNameVerifier.java:65)
        at com.vmware.vim.sms.util.CustomSslSocketFactory.verifyHostName(CustomSslSocketFactory.java:520)
        at com.vmware.vim.sms.util.CustomSslSocketFactory.createSocket(CustomSslSocketFactory.java:445)
        at org.apache.commons.httpclient.HttpConnection.open(Unknown Source)
        at org.apache.commons.httpclient.MultiThreadedHttpConnectionManager$HttpConnectionAdapter.open(Unknown Source)
        at org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(Unknown Source)
        at org.apache.commons.httpclient.HttpMethodDirector.executeMethod(Unknown Source)
        at org.apache.commons.httpclient.HttpClient.executeMethod(Unknown Source)
        at org.apache.commons.httpclient.HttpClient.executeMethod(Unknown Source)
        at org.apache.axis2.transport.http.AbstractHTTPSender.executeMethod(AbstractHTTPSender.java:542)
        at org.apache.axis2.transport.http.HTTPSender.sendViaPost(HTTPSender.java:199)
        at org.apache.axis2.transport.http.HTTPSender.send(HTTPSender.java:76)
        at org.apache.axis2.transport.http.CommonsHTTPTransportSender.writeMessageWithCommons(CommonsHTTPTransportSender.java:400)
        at org.apache.axis2.transport.http.CommonsHTTPTransportSender.invoke(CommonsHTTPTransportSender.java:225)
        at org.apache.axis2.engine.AxisEngine.send(AxisEngine.java:435)
        at org.apache.axis2.description.OutInAxisOperationClient.send(OutInAxisOperation.java:402)
        at org.apache.axis2.description.OutInAxisOperationClient.executeImpl(OutInAxisOperation.java:229)
        at org.apache.axis2.client.OperationClient.execute(OperationClient.java:165)
        at com.vmware.vim.vasa.VasaServiceStub.getAlarms(VasaServiceStub.java:16976)
        at com.vmware.vim.sms.client.stub.VasaServiceStubImpl.getAlarms(VasaServiceStubImpl.java:39)
        at com.vmware.vim.sms.client.VasaClientImpl.getAlarms(VasaClientImpl.java:354)
        at sun.reflect.GeneratedMethodAccessor445.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.vmware.vim.sms.client.VasaClientMethodInvoker.invokeMethod(VasaClientMethodInvoker.java:48)
        at com.vmware.vim.sms.client.VasaClientMethodInvoker.invoke(VasaClientMethodInvoker.java:35)
        at com.vmware.vim.sms.client.VasaClientHandler.invoke(VasaClientHandler.java:27)
        at com.sun.proxy.$Proxy109.getAlarms(Unknown Source)
        at com.vmware.vim.sms.provider.vasa.alarm.AlarmDispatcher.pollAlarms(AlarmDispatcher.java:88)
        at com.vmware.vim.sms.provider.vasa.alarm.AlarmManagerImpl$AlarmPollerTask.run(AlarmManagerImpl.java:116)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
    2018-08-17T00:48:37.680Z [pool-9-thread-3] ERROR opId=sps-Main-210327-691 com.vmware.vim.sms.provider.vasa.alarm.AlarmDispatcher - Error: org.apache.axis2.AxisFault: Host name could not be verified! occured as provider: https://10.204.120.140:8084/version.xml is offline
    2018-08-17T00:48:41.331Z [pool-9-thread-1] ERROR opId=sps-Main-210327-691 com.vmware.vim.sms.util.CustomSslSocketFactory - CompositeTrustManager could not validate certificate:
    [
    [
      Version: V3
      Subject: CN=10.204.120.145, OU=Pure Storage, O=Pure Storage, C=US
      Signature Algorithm: SHA256withRSA, OID = 1.2.840.113549.1.1.11
    
      Key:  Sun RSA public key, 2048 bits
      modulus: 18122153372164252573033424097843690887418975566040415877823123655719253307095990209989539572313677055190498129716162489371839183743661651125150686114701198394331093374987494456189170163716448903667019602645041646476995156371864105445121778999395999052696852929604861456444573502245023045796331024989214121728276733382022772680257053498445263698232661922686355454743568264037465895352294781210422432501890655317643838051848383867059233249731786535284046647456560243193009786425949980999777069112605981351106385385127999305863274722052202593217949497672452915867373908324295260538315933112559919840693775930275218178411
      public exponent: 65537
      Validity: [From: Tue Aug 14 12:15:03 UTC 2018,
                   To: Thu Aug 15 12:15:03 UTC 2019]
      Issuer: OU=VMware Engineering, O=ucs-d-vcsa-vpsc-1.slc.purestorage.com, ST=California, C=US, DC=slc.purestorage.com, DC=UCS-vCSA-SSO, CN=CA
      SerialNumber: [    e93be3f8 59d837b1]
      
      --
      
      2018-08-17T00:48:41.332Z [pool-9-thread-1] ERROR opId=sps-Main-210327-691 com.vmware.vim.sms.util.CustomHostNameVerifier - [verify] Hostname verification failed for host: 10.204.120.145
    javax.net.ssl.SSLPeerUnverifiedException: peer not authenticated
        at sun.security.ssl.SSLSessionImpl.getPeerCertificates(SSLSessionImpl.java:431)
        at com.vmware.vim.sms.util.CustomHostNameVerifier.retrieveSubjectAlternateNames(CustomHostNameVerifier.java:121)
        at com.vmware.vim.sms.util.CustomHostNameVerifier.verify(CustomHostNameVerifier.java:65)
        at com.vmware.vim.sms.util.CustomSslSocketFactory.verifyHostName(CustomSslSocketFactory.java:520)
        at com.vmware.vim.sms.util.CustomSslSocketFactory.createSocket(CustomSslSocketFactory.java:445)
        at org.apache.commons.httpclient.HttpConnection.open(Unknown Source)
        at org.apache.commons.httpclient.MultiThreadedHttpConnectionManager$HttpConnectionAdapter.open(Unknown Source)
        at org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(Unknown Source)
        at org.apache.commons.httpclient.HttpMethodDirector.executeMethod(Unknown Source)
        at org.apache.commons.httpclient.HttpClient.executeMethod(Unknown Source)
        at org.apache.commons.httpclient.HttpClient.executeMethod(Unknown Source)
        at org.apache.axis2.transport.http.AbstractHTTPSender.executeMethod(AbstractHTTPSender.java:542)
        at org.apache.axis2.transport.http.HTTPSender.sendViaPost(HTTPSender.java:199)
        at org.apache.axis2.transport.http.HTTPSender.send(HTTPSender.java:76)
        at org.apache.axis2.transport.http.CommonsHTTPTransportSender.writeMessageWithCommons(CommonsHTTPTransportSender.java:400)
        at org.apache.axis2.transport.http.CommonsHTTPTransportSender.invoke(CommonsHTTPTransportSender.java:225)
        at org.apache.axis2.engine.AxisEngine.send(AxisEngine.java:435)
        at org.apache.axis2.description.OutInAxisOperationClient.send(OutInAxisOperation.java:402)
        at org.apache.axis2.description.OutInAxisOperationClient.executeImpl(OutInAxisOperation.java:229)
        at org.apache.axis2.client.OperationClient.execute(OperationClient.java:165)
        at com.vmware.vim.vasa.VasaServiceStub.getAlarms(VasaServiceStub.java:16976)
        at com.vmware.vim.sms.client.stub.VasaServiceStubImpl.getAlarms(VasaServiceStubImpl.java:39)
        at com.vmware.vim.sms.client.VasaClientImpl.getAlarms(VasaClientImpl.java:354)
        at sun.reflect.GeneratedMethodAccessor445.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.vmware.vim.sms.client.VasaClientMethodInvoker.invokeMethod(VasaClientMethodInvoker.java:48)
        at com.vmware.vim.sms.client.VasaClientMethodInvoker.invoke(VasaClientMethodInvoker.java:35)
        at com.vmware.vim.sms.client.VasaClientHandler.invoke(VasaClientHandler.java:27)
        at com.sun.proxy.$Proxy109.getAlarms(Unknown Source)
        at com.vmware.vim.sms.provider.vasa.alarm.AlarmDispatcher.pollAlarms(AlarmDispatcher.java:88)
        at com.vmware.vim.sms.provider.vasa.alarm.AlarmManagerImpl$AlarmPollerTask.run(AlarmManagerImpl.java:116)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
    2018-08-17T00:48:41.334Z [pool-9-thread-1] ERROR opId=sps-Main-210327-691 com.vmware.vim.sms.provider.vasa.alarm.AlarmDispatcher - Error: org.apache.axis2.AxisFault: Host name could not be verified! occured as provider: https://10.204.120.145:8084/version.xml is offline
    2018-08-17T00:48:42.588Z [pool-11-thread-3] INFO  opId= com.vmware.vim.sms.StorageManagerImpl - Starting Timer: unregisterProviderInt. Provider id: 6c1f7427-63cc-4736-bd1b-81bef325671f
    2018-08-17T00:48:42.593Z [Thread-272] WARN  opId= com.vmware.vim.sms.provider.vasa.event.VpxdEventPoster - InterruptedException due to unregistration of the provider
    2018-08-17T00:48:42.594Z [Thread-273] WARN  opId= com.vmware.vim.sms.provider.vasa.event.EventDispatcher.SyncTask - InterruptedException due to unregistration of the provider
    2018-08-17T00:48:42.764Z [pool-11-thread-3] INFO  opId= com.vmware.vim.sms.StorageManagerImpl - Timer stopped: unregisterProviderInt, Time taken: 176 ms.
    2018-08-17T00:48:42.765Z [Thread-322] INFO  opId= com.vmware.sps.vp.VendorProviderUnregisterThread - Starting cleanup for provider 6c1f7427-63cc-4736-bd1b-81bef325671f
    2018-08-17T00:48:42.765Z [Thread-322] INFO  opId= com.vmware.sps.vp.VasaProviderPolicyDataCleaner - Cleaning the CapabilityMetadata from pbm for provider 6c1f7427-63cc-4736-bd1b-81bef325671f and schema
    2018-08-17T00:48:42.765Z [Thread-322] INFO  opId= com.vmware.pbm.capability.impl.KvSchemaService - Unregistering capability metadata for providerInfo (pbm.capability.provider.CapabilityProviderInfo) {
       dynamicType = null,
       dynamicProperty = null,
       providerUuid = 6c1f7427-63cc-4736-bd1b-81bef325671f,
       schemaId =
    }
    2018-08-17T00:48:42.772Z [Thread-322] INFO  opId= com.vmware.pbm.capability.impl.KvSchemaService - Successfully unregistered capability metadata for providerInfo (pbm.capability.provider.CapabilityProviderInfo) {
       dynamicType = null,
       dynamicProperty = null,
       providerUuid = 6c1f7427-63cc-4736-bd1b-81bef325671f,
       schemaId =
    }
    2018-08-17T00:48:42.772Z [Thread-322] INFO  opId= com.vmware.sps.vp.VasaProviderPolicyDataCleaner - Successfully cleaned up the CapabilityMetadata for provider 6c1f7427-63cc-4736-bd1b-81bef325671f and schema
    2018-08-17T00:48:42.772Z [Thread-322] INFO  opId= com.vmware.sps.vp.VasaProviderPolicyDataCleaner - Cleaning CBP, storage associations and IOF info for vpId 6c1f7427-63cc-4736-bd1b-81bef325671f and vpType
    2018-08-17T00:48:42.777Z [Thread-322] INFO  opId= com.vmware.sps.vp.VasaProviderPolicyDataCleaner - No CBP and storage associations for provider 6c1f7427-63cc-4736-bd1b-81bef325671f and vpType
    2018-08-17T00:48:42.781Z [Thread-322] INFO  opId= com.vmware.sps.vp.VendorProviderUnregisterThread - Successfully cleanedUp policy data for provider 6c1f7427-63cc-4736-bd1b-81bef325671f
    2018-08-17T00:48:45.139Z [pool-17-thread-1] INFO  opId=q-252798:SmsPropertyProvider:710391-188194-h5c:70038103 com.vmware.vim.sms.StorageManagerImpl - Starting Timer: queryArray. Provider id: null
    2018-08-17T00:48:45.143Z [pool-17-thread-1] INFO  opId=q-252798:SmsPropertyProvider:710391-188194-h5c:70038103 com.vmware.vim.sms.StorageManagerImpl - Timer stopped: queryArray, Time taken: 4 ms.
    2018-08-17T00:48:45.146Z [pool-17-thread-2] INFO  opId=q-252798:SmsPropertyProvider:710391-188195-h5c:70038103 com.vmware.vim.sms.StorageManagerImpl - Starting Timer: queryProvider.
    2018-08-17T00:48:45.146Z [pool-17-thread-2] INFO  opId=q-252798:SmsPropertyProvider:710391-188195-h5c:70038103 com.vmware.vim.sms.StorageManagerImpl - Timer stopped: queryProvider, Time taken: 0 ms.
    2018-08-17T00:48:45.776Z [pool-7-thread-2] INFO  opId=sps-DTCPoller-210366-88 com.vmware.pbm.qs.listener.DatastoreTagChangePoller - Starting Timer: DatastoreTagChangePoller.
    2018-08-17T00:48:45.783Z [pool-7-thread-2] INFO  opId=sps-DTCPoller-210366-88 com.vmware.pbm.qs.listener.DatastoreTagChangePoller - Timer stopped: DatastoreTagChangePoller, Time taken: 6 ms. Processed 0 TagAssociationInfo(s)
    2018-08-17T00:48:47.681Z [pool-9-thread-4] ERROR opId=sps-Main-210327-691 com.vmware.vim.sms.util.CustomSslSocketFactory - CompositeTrustManager could not validate certificate:
    

Keep in mind that you can find other issue here, but it's good to keep in mind the type of lines that we will see and what you want to be looking for in them.

  • vasa.log

On the array, we often need to look through the VASA log to confirm that the requests are coming in and they are being returned successfully.  

-- Good Example 1
  • --------------------------------------
    2018-08-15 19:37:22,317:INFO:[qtp1165897474-82271] Inbound Message
    ----------------------------
    ID: 1872706
    Address: https://10.1.4.122:8084/vasa
    Encoding: UTF-8
    Http-Method: POST
    Content-Type: application/soap+xml; charset=utf-8; action="urn:createVirtualVolume"
    Headers: {connection=[keep-alive], Content-Length=[3522], content-type=[application/soap+xml; charset=utf-8; action="urn:createVirtualVolume"], Cookie=[$Version=1;VASAVERSION=3.0;$Path="/" $Version=0;VASASESSIONID=2963676189260860191;$Path="/vasa";$Domain="10.1.4.122"], Host=[10.1.4.122:8084], SOAPAction=["urn:createVirtualVolume"], User-Agent=[gSOAP/2.8]}
    Payload: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://www.w3.org/2003/05/soap-envelope" xmlns:SOAP-ENC="http://www.w3.org/2003/05/soap-encoding" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:vasaxsd="http://vasa.vim.vmware.com/xsd" xmlns:fault="http://fault.vasa.vim.vmware.com/xsd" xmlns:capability="http://capability.policy.data.vasa.vim.vmware.com/xsd" xmlns:profile="http://profile.policy.data.vasa.vim.vmware.com/xsd" xmlns:provider="http://provider.capability.policy.data.vasa.vim.vmware.com/xsd" xmlns:lineofservice="http://lineofservice.data.vasa.vim.vmware.com/xsd" xmlns:replicationFault="http://fault.replication.vasa.vim.vmware.com/xsd" xmlns:ns1="http://statistics.data.vasa.vim.vmware.com/xsd" xmlns:replication="http://replication.data.vasa.vim.vmware.com/xsd" xmlns:placement="http://placement.policy.data.vasa.vim.vmware.com/xsd" xmlns:ns2="http://types.capability.policy.data.vasa.vim.vmware.com/xsd" xmlns:vvol="http://vvol.data.vasa.vim.vmware.com/xsd" xmlns:data="http://data.vasa.vim.vmware.com/xsd" xmlns:compliance="http://compliance.policy.data.vasa.vim.vmware.com/xsd" xmlns:policy="http://policy.data.vasa.vim.vmware.com/xsd" xmlns:b11="http://com.vmware.vim.vasa/2.0/vasaServiceSoap11Binding" xmlns:xsdvasa="http://com.vmware.vim.vasa/2.0/xsd" xmlns:b12="http://com.vmware.vim.vasa/2.0/vasaServiceSoap12Binding">
      <SOAP-ENV:Body>
        <xsdvasa:createVirtualVolume>
          <xsdvasa:containerId>ce9d6a5a-067c-31d7-92e2-d3341ddadd46</xsdvasa:containerId>
          <xsdvasa:vvolType>Config</xsdvasa:vvolType>
          <xsdvasa:storageProfile xsi:type="profile:StorageProfile">
            <profile:constraints xsi:type="profile:CapabilityConstraints"/>
            <profile:createdBy>Temporary user handle</profile:createdBy>
            <profile:creationTime>2017-06-01T16:48:31Z</profile:creationTime>
            <profile:description>Allow the datastore to determine the best placement strategy for storage objects</profile:description>
            <profile:generationId>0</profile:generationId>
            <profile:lastUpdatedBy>Temporary user handle</profile:lastUpdatedBy>
            <profile:lastUpdatedTime>2017-06-01T16:48:31Z</profile:lastUpdatedTime>
            <profile:name>vVol No Requirements Policy</profile:name>
            <profile:profileId>f4e5bade-15a2-4805-bf8e-52318c4ce443</profile:profileId>
          </xsdvasa:storageProfile>
          <xsdvasa:sizeInMB>4096</xsdvasa:sizeInMB>
          <xsdvasa:metadata xsi:type="data:NameValuePair">
            <data:parameterName>VMW_CreateTime</data:parameterName>
            <data:parameterValue>2018-08-15T18:37:22.316433Z</data:parameterValue>
          </xsdvasa:metadata>
          <xsdvasa:metadata xsi:type="data:NameValuePair">
            <data:parameterName>VMW_ContainerId</data:parameterName>
            <data:parameterValue>ce9d6a5a-067c-31d7-92e2-d3341ddadd46</data:parameterValue>
          </xsdvasa:metadata>
          <xsdvasa:metadata xsi:type="data:NameValuePair">
            <data:parameterName>VMW_vVolName</data:parameterName>
            <data:parameterValue>New Virtual Machine delletme</data:parameterValue>
          </xsdvasa:metadata>
          <xsdvasa:metadata xsi:type="data:NameValuePair">
            <data:parameterName>VMW_vVolType</data:parameterName>
            <data:parameterValue>Config</data:parameterValue>
          </xsdvasa:metadata>
          <xsdvasa:metadata xsi:type="data:NameValuePair">
            <data:parameterName>VMW_VvolProfile</data:parameterName>
            <data:parameterValue>f4e5bade-15a2-4805-bf8e-52318c4ce443:0</data:parameterValue>
          </xsdvasa:metadata>
          <xsdvasa:containerCookie>containerCookie/ce9d6a5a-067c-31d7-92e2-d3341ddadd46/v-hv3.prod.projectwaking.com</xsdvasa:containerCookie>
        </xsdvasa:createVirtualVolume>
      </SOAP-ENV:Body>
    </SOAP-ENV:Envelope>
    
    
    --------------------------------------
    2018-08-15 19:37:22,318:INFO:[qtp1165897474-82271] Valid session ID 2963676189260860191 used (before timeout)
    2018-08-15 19:37:22,393:INFO:[qtp1165897474-82271] Finished loading profiles- contents to internal map: {f4e5bade-15a2-4805-bf8e-52318c4ce443=com.vmware.vim.vasa.data.policy.profile.xsd.StorageProfile@69b8312e, 7508ed62-e4a9-4cf1-9ef9-fb1f07b72bc0=com.vmware.vim.vasa.data.policy.profile.xsd.StorageProfile@c8a88ab4, a0847ad3-e5fe-470a-9eb5-d60976a730ae=com.vmware.vim.vasa.data.policy.profile.xsd.StorageProfile@8485d9d8}
    2018-08-15 19:37:22,933:INFO:[qtp1165897474-82271] Outbound Message
    ---------------------------
    ID: 1872706
    Response-Code: 200
    Encoding: UTF-8
    Content-Type: application/soap+xml
    Headers: {}
    Payload: <soap:Envelope xmlns:soap="http://www.w3.org/2003/05/soap-envelope">
      <soap:Body>
        <createVirtualVolumeResponse xmlns="http://com.vmware.vim.vasa/2.0/xsd" xmlns:ns2="http://fault.vasa.vim.vmware.com/xsd" xmlns:ns3="http://data.vasa.vim.vmware.com/xsd" xmlns:ns4="http://fault.replication.vasa.vim.vmware.com/xsd" xmlns:ns5="http://policy.data.vasa.vim.vmware.com/xsd" xmlns:ns6="http://statistics.data.vasa.vim.vmware.com/xsd" xmlns:ns7="http://compliance.policy.data.vasa.vim.vmware.com/xsd" xmlns:ns8="http://capability.policy.data.vasa.vim.vmware.com/xsd" xmlns:ns9="http://lineofservice.data.vasa.vim.vmware.com/xsd" xmlns:ns10="http://vvol.data.vasa.vim.vmware.com/xsd" xmlns:ns11="http://replication.data.vasa.vim.vmware.com/xsd" xmlns:ns12="http://placement.policy.data.vasa.vim.vmware.com/xsd" xmlns:ns13="http://profile.policy.data.vasa.vim.vmware.com/xsd" xmlns:ns14="http://provider.capability.policy.data.vasa.vim.vmware.com/xsd" xmlns:ns15="http://types.capability.policy.data.vasa.vim.vmware.com/xsd" xmlns:ns16="http://vasa.vim.vmware.com/xsd">
          <return>
            <ns10:cancelable>false</ns10:cancelable>
            <ns10:cancelled>false</ns10:cancelled>
            <ns10:name>createVirtualVolume</ns10:name>
            <ns10:progress>0</ns10:progress>
            <ns10:progressUpdateAvailable>false</ns10:progressUpdateAvailable>
            <ns10:result xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xs="http://www.w3.org/2001/XMLSchema" xsi:type="xs:string">rfc4122.e5d63cc0-4de8-4d76-9d4d-9f247b38fe69</ns10:result>
            <ns10:startTime>2018-08-15T19:37:22.932+01:00</ns10:startTime>
            <ns10:taskId>a5fe8d28-9443-45db-8fa5-2a8586a1a544</ns10:taskId>
            <ns10:taskState>Success</ns10:taskState>
          </return>
        </createVirtualVolumeResponse>
      </soap:Body>
    </soap:Envelope>
    
    
    --------------------------------------
    

In the above example, we can see the array receiving a request to create a vVol for a VM named "delletme" and the array responding to the host in about a half second with the same ID (1872706) response-code 200 (successful).

-- Bad Example 1
  • 2018-08-15 17:20:49,194:ERROR:[qtp1165897474-82109] Could not find a PE ID for session -1074469574783975767. Host: V-HV06 - HostManagerInfo:
    hostPeList:
    
    
    hostGuidToPort:
       00000000-0000-0000-0000-0CC47A6C1AF2 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:vsan1-233a06f2}
       00000000-0000-0000-0000-0CC47A6C1E48 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv2-1488952d}
       00000000-0000-0000-0000-0CC47A6C1E4C ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv1-6af1254e}
       00000000-0000-0000-0000-0CC47A6C1E3C ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv4-4151318f}
       00000000-0000-0000-0000-0CC47A6C1E40 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv5-2b49b75a}
       00000000-0000-0000-0000-0CC47A6B765C ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:v-hv3-36171443}
    
    
    sessionIdToPort:
       733921287974569127 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:bk-hv02-776218b8}
       733921287974569127 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:vsan1-233a06f2}
       733921287974569127 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:bk-hv03-42a46689}
       733921287974569127 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv4-4151318f}
       733921287974569127 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv1-56814c82}
       733921287974569127 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv1-6af1254e}
       733921287974569127 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv2-1488952d}
       733921287974569127 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:v-hv3-36171443}
       733921287974569127 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv4-5e704fcd}
       733921287974569127 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv5-2b49b75a}
       -1074469574783975767 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:vsan1-233a06f2}
       -767339667774479850 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv5-2b49b75a}
       1829091039740396691 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:bk-hv02-776218b8}
       1829091039740396691 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:vsan1-233a06f2}
       1829091039740396691 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:bk-hv03-42a46689}
       1829091039740396691 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv4-4151318f}
       1829091039740396691 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv1-56814c82}
       1829091039740396691 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv1-6af1254e}
       1829091039740396691 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv2-1488952d}
       1829091039740396691 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:v-hv3-36171443}
       1829091039740396691 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv4-5e704fcd}
       1829091039740396691 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv5-2b49b75a}
       7466636292555851427 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:bk-hv02-776218b8}
       7466636292555851427 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:vsan1-233a06f2}
       7466636292555851427 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:bk-hv03-42a46689}
       7466636292555851427 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv4-4151318f}
       7466636292555851427 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv1-56814c82}
       7466636292555851427 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv1-6af1254e}
       7466636292555851427 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv2-1488952d}
       7466636292555851427 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:v-hv3-36171443}
       7466636292555851427 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv4-5e704fcd}
       7466636292555851427 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv5-2b49b75a}
       -4546817863127842564 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv2-1488952d}
       7135227803667720493 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv4-4151318f}
       834160397652537132 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:v-hv3-36171443}
       7920006239820753291 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv1-6af1254e}
       -191642555971191023 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:bk-hv02-776218b8}
       -191642555971191023 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:vsan1-233a06f2}
       -191642555971191023 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:bk-hv03-42a46689}
       -191642555971191023 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv4-4151318f}
       -191642555971191023 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv1-56814c82}
       -191642555971191023 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv1-6af1254e}
       -191642555971191023 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv2-1488952d}
       -191642555971191023 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:v-hv3-36171443}
       -191642555971191023 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv4-5e704fcd}
       -191642555971191023 ::: Port{portType=IQN, wwnOrIqn=iqn.1998-01.com.vmware:hv5-2b49b75a}
    2018-08-15 17:20:49,525:INFO:[qtp1165897474-82109] Must exist at least one conglomerate volume connected to the host to bind.  HostPeId([])
    2018-08-15 17:20:49,526:INFO:[qtp1165897474-82109] Application {http://vasa.purestorage.com/}vasa#{http://com.vmware.vim.vasa/2.0/}bindVirtualVolume has thrown exception, unwinding now: vasa.vim.vmware.com._2_0.StorageFault: Must exist at least one conglomerate volume connected to the host to bind.
    2018-08-15 17:20:49,526:INFO:[qtp1165897474-82109] class org.apache.cxf.binding.soap.interceptor.Soap12FaultOutInterceptor$Soap12FaultOutInterceptorInternalapplication/soap+xml
    

Here, we could not find a PE ID for a VM creation triggered from vCenter; additionally, we can see VASA complaining about not having a volume connected to the host to bind. This particular issue is caused by a  known issue (PURE-125789) where there are too many protection group items and it takes too long to give VMware the information back about the files and directories that live in the vVol.

  • middleware.log

There aren't going to be very many times that you will need to look at the middleware log.  That said if you do, you'll want to look for the RestServer log lines specific to vvols.  You will see a POST, GET or DELETE request issued in middleware, which is forwarded these requests from the vasa provider on the controller.

Here are some normal looking lines.

/var/log/purity/middleware.log-2018061320.gz:2018-06-13 19:59:23.448 [grizzly-http-server-1] INFO com.purestorage.middleware.rest.RestServer GET /latest/volumes/connections?names=vvol-W2K16-Template-65630452-vg/Config-22a980d2&filter=host%3D%27UCS-BLADE-7-FC%27 HTTP/1.1 200, 26 bytes, 2 ms
/var/log/purity/middleware.log-2018061320.gz:2018-06-13 19:59:23.673 [request-write-thread-3] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/@vvol-W2K16-Template-65630452-vg%2FConfig-22a980d2/connections HTTP/1.1 200, 230 bytes, 224 ms
/var/log/purity/middleware.log-2018061320.gz:2018-06-13 20:00:48.423 [grizzly-http-server-0] INFO com.purestorage.middleware.rest.RestServer GET /latest/volumes/connections?names=vvol-W2K16-Template-65630452-vg/Config-22a980d2&filter=host%3D%27UCS-BLADE-7-FC%27 HTTP/1.1 200, 230 bytes, 9 ms
/var/log/purity/middleware.log-2018061320.gz:2018-06-13 20:00:48.590 [request-write-thread-2] INFO com.purestorage.middleware.rest.RestServer DELETE /latest/hosts/@UCS-BLADE-7-FC/connections/volumes/@vvol-W2K16-Template-65630452-vg%2FConfig-22a980d2 HTTP/1.1 200, 132 bytes, 165 ms
/var/log/purity/middleware.log-2018061320.gz:2018-06-13 20:00:50.445 [grizzly-http-server-2] INFO com.purestorage.middleware.rest.RestServer GET /latest/volumes/connections?names=vvol-RHEL-Template-fc7d0f0a-vg/Config-74649a7e&filter=host%3D%27UCS-BLADE-8-FC%27 HTTP/1.1 200, 229 bytes, 10 ms
/var/log/purity/middleware.log-2018061320.gz:2018-06-13 20:00:50.613 [request-write-thread-0] INFO com.purestorage.middleware.rest.RestServer DELETE /latest/hosts/@UCS-BLADE-8-FC/connections/volumes/@vvol-RHEL-Template-fc7d0f0a-vg%2FConfig-74649a7e HTTP/1.1 200, 131 bytes, 164 ms
/var/log/purity/middleware.log-2018061407.gz:2018-06-14 06:43:12.556 [grizzly-http-server-1] INFO com.purestorage.middleware.rest.RestServer GET /latest/volumes/connections?names=vvol--vSphere-HA-0ffc7dd1-vg/Config-b42f1357&filter=host%3D%27UCS-BLADE-8-FC%27 HTTP/1.1 200, 26 bytes, 2 ms
/var/log/purity/middleware.log-2018061407.gz:2018-06-14 06:43:12.771 [request-write-thread-1] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/@vvol--vSphere-HA-0ffc7dd1-vg%2FConfig-b42f1357/connections HTTP/1.1 200, 227 bytes, 214 ms
/var/log/purity/middleware.log-2018061407.gz:2018-06-14 06:43:12.851 [grizzly-http-server-4] INFO com.purestorage.middleware.rest.RestServer GET /latest/volumes/connections?names=vvol-W2K16-Template-65630452-vg/Config-22a980d2&filter=host%3D%27UCS-BLADE-8-FC%27 HTTP/1.1 200, 26 bytes, 2 ms
/var/log/purity/middleware.log-2018061407.gz:2018-06-14 06:43:13.071 [request-write-thread-2] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/@vvol-W2K16-Template-65630452-vg%2FConfig-22a980d2/connections HTTP/1.1 200, 230 bytes, 219 ms
/var/log/purity/middleware.log-2018061407.gz:2018-06-14 06:43:13.202 [grizzly-http-server-5] INFO com.purestorage.middleware.rest.RestServer GET /latest/volumes/connections?names=vvol-RHEL-Template-fc7d0f0a-vg/Config-74649a7e&filter=host%3D%27UCS-BLADE-8-FC%27 HTTP/1.1 200, 26 bytes, 2 ms 

 You can see that the requests are happening fairly quickly, all under a second.  Now, here are some not so good times.

2018-06-25 10:00:08.110 [request-write-thread-2] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/@vvol-ucs-d-v-VM-RHEL7-005-vg%2FConfig-540798ea/connections HTTP/1.1 200, 233 bytes, 1289 ms
2018-06-25 10:00:09.178 [request-write-thread-3] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/@vvol-ucs-d-v-VM-win10-009-vg%2FConfig-0a1cf2cd/connections HTTP/1.1 200, 233 bytes, 1656 ms
2018-06-25 10:00:09.893 [request-write-thread-1] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/@vvol-ucs-d-v-VM-RHEL7-015-vg%2FConfig-c8e9a4e1/connections HTTP/1.1 200, 234 bytes, 2933 ms
2018-06-25 10:00:10.200 [request-write-thread-3] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/@vvol-m20-vd-vm-04-vg%2FConfig-cf7dcb62/connections HTTP/1.1 200, 225 bytes, 2606 ms
2018-06-25 10:00:10.712 [request-write-thread-0] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/@vvol-ucs-d-v-VM-RHEL7-022-vg%2FConfig-7de1cdda/connections HTTP/1.1 200, 234 bytes, 3529 ms
2018-06-25 10:00:11.706 [request-write-thread-0] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/@vvol-ucs-d-v-VM-win10-009-vg%2FSwap-98ff0ed2/tags HTTP/1.1 200, 1021 bytes, 148 ms
2018-06-25 10:00:12.044 [request-write-thread-2] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/@vvol-ucs-d-v-VM-RHEL7-011-vg%2FConfig-c0db5933/connections HTTP/1.1 200, 234 bytes, 4519 ms
2018-06-25 10:00:12.104 [request-write-thread-2] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/destroyed/@vvol-ucs-d-v-VM-win10-009-vg%2FSwap-98ff0ed2 HTTP/1.1 200, 79 bytes, 385 ms
2018-06-25 10:00:12.962 [request-write-thread-0] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/@vvol-ucs-d-v-VM-RHEL7-005-vg%2FSwap-87958a4d/tags HTTP/1.1 200, 1021 bytes, 13 ms
2018-06-25 10:00:12.988 [request-write-thread-0] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/destroyed/@vvol-ucs-d-v-VM-RHEL7-005-vg%2FSwap-87958a4d HTTP/1.1 200, 79 bytes, 25 ms
2018-06-25 10:00:13.732 [request-write-thread-1] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/@vvol-ucs-d-v-VM-win10-025-vg%2FConfig-f716935b/connections HTTP/1.1 200, 234 bytes, 5536 ms
2018-06-25 10:00:14.962 [request-write-thread-1] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/@vvol-ucs-d-v-VM-RHEL7-015-vg%2FSwap-f0993e6d/tags HTTP/1.1 200, 1021 bytes, 79 ms
2018-06-25 10:00:14.996 [request-write-thread-2] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/destroyed/@vvol-ucs-d-v-VM-RHEL7-015-vg%2FSwap-f0993e6d HTTP/1.1 200, 79 bytes, 33 ms
2018-06-25 10:00:15.296 [request-write-thread-1] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/@vvol-ucs-d-v-VM-win10-009-vg%2FSwap-98ff0ed2/tags HTTP/1.1 200, 150 bytes, 41 ms
2018-06-25 10:00:15.342 [request-write-thread-2] INFO com.purestorage.middleware.rest.RestServer DELETE /latest/volumes/tags?names=vvol-ucs-d-v-VM-win10-009-vg/Swap-98ff0ed2&keys=VMW_CreateTime HTTP/1.1 200, 140 bytes, 45 ms
2018-06-25 10:00:16.120 [request-write-thread-2] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/@vvol-ucs-d-v-VM-RHEL7-022-vg%2FSwap-3defe31c/tags HTTP/1.1 200, 1021 bytes, 115 ms
2018-06-25 10:00:16.134 [request-write-thread-0] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/@vvol-ucs-d-v-VM-RHEL7-005-vg%2FSwap-87958a4d/tags HTTP/1.1 200, 150 bytes, 12 ms
2018-06-25 10:00:16.173 [request-write-thread-2] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/destroyed/@vvol-ucs-d-v-VM-RHEL7-022-vg%2FSwap-3defe31c HTTP/1.1 200, 79 bytes, 51 ms
2018-06-25 10:00:16.223 [request-write-thread-0] INFO com.purestorage.middleware.rest.RestServer DELETE /latest/volumes/tags?names=vvol-ucs-d-v-VM-RHEL7-005-vg/Swap-87958a4d&keys=VMW_CreateTime HTTP/1.1 200, 140 bytes, 87 ms
2018-06-25 10:00:16.534 [request-write-thread-3] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/@vvol-ucs-d-v-VM-W2K16-022-vg%2FConfig-c8211875/connections HTTP/1.1 200, 234 bytes, 7207 ms
2018-06-25 10:00:17.432 [request-write-thread-3] INFO com.purestorage.middleware.rest.RestServer POST /latest/volumes/@vvol-ucs-d-v-VM-RHEL7-011-vg%2FSwap-472ad915/tags HTTP/1.1 200, 1021 bytes, 23 ms

You can see that the times to complete these requests are much higher now.  If we start stringing together a lot more of these long requests we can eventually get to the point that operations timeout.

Known Bugs

PURE-135909 - Storage provider is inaccessible on all hosts using vVols, due to VASA not allowing intermediate CA certificates for client authentication. 

PURE-146541 - Hosts with Virtual FC adapters are unable to access vVols.