vVol Troubleshooting – What to do with a Empty VP URL

I have been wanting to put together a kind of a series of vVol (I still have a hard time typing vVol instead of VVol) troubleshooting, tips or some things I’ve been seeing. I’ve gotten a couple of those already, but I should be getting more out and maybe actually help out someone.

One of the more common issues I have seen when getting started with vVols is when an ESXi host is unable to authenticate with the VASA Providers. Even though the vCenter Server has registered the Storage Providers successfully. There can be a few reasons for this happening, so I wanted to dig into some of those reasons, how to troubleshoot them and hopefully fix them.

The Setup and Issue

Let’s dive into what we are wanting to look at. In this example I am just getting vVols setup with the vCenter. In this vCenter I have just registered the storage providers and everything there is healthy. The protocol endpoint is connected to all of the hosts in the ESXi Cluster and I just created the vVol Datastore. Now here is when I see the issue, I get a report that the vVol Datastore “inaccessible” for 1 or 2 of the hosts in the ESXi Cluster. Well, that’s strange, it’s fine on all of the other hosts in the cluster, why is it broken with this host?

The first place I generally will be looking at is the vvold log on the ESXi host that the vVol Datastore reports as inaccessible.

The Empty VP URL Issue

2019-08-12T22:59:18.124Z info vvold[2298793] [Originator@6876 sub=Default] VendorProviderMgr::AddOrRef VP (sn1-m20-c12-25-ct0) Uid () URL (https://10.21.88.113:8084/version.xml)
 2019-08-12T22:59:18.124Z info vvold[2298793] [Originator@6876 sub=Default] DlgSoapCtxPool: Created new DlgSoapCtxPool ([14DlgSoapCtxPool:0x000000c29694e690]) for VP (sn1-m20-c12-25-ct0) session (000000c29694e520)
 2019-08-12T22:59:18.124Z info vvold[2298793] [Originator@6876 sub=Default] VendorProviderMgr:UpdateFirewallRules: Firewall operation add on rule id:VVOLD_8084 success

 2019-08-12T22:59:18.124Z info vvold[2298793] [Originator@6876 sub=Default] VasaSession::GetEndPoint: with url https://10.21.88.113:8084/version.xml
 2019-08-12T22:59:18.128Z warning vvold[2298793] [Originator@6876 sub=Default] VasaSession::GetEndPoint: failed to get endpoint, err=SSL Exception: Verification parameters:
 --> PeerThumbprint: 0B:2F:E1:52:F3:85:EB:CD:BE:B4:FF:E3:B2:64:1B:FB:F5:BA:55:F4
 --> ExpectedThumbprint:
 --> ExpectedPeerName: 10.21.88.113
 --> The remote host certificate has these problems:
 -->
 --> * unable to get local issuer certificate, using default
 2019-08-12T22:59:18.128Z info vvold[2298793] [Originator@6876 sub=Default] VasaSession::Initialize url is empty
 2019-08-12T22:59:18.128Z warning vvold[2298793] [Originator@6876 sub=Default] VasaSession::DoSetContext: Empty VP URL for VP (sn1-m20-c12-25-ct0)!
 2019-08-12T22:59:18.128Z info vvold[2298793] [Originator@6876 sub=Default] Initialize: Failed to establish connection https://10.21.88.113:8084/version.xml
 2019-08-12T22:59:18.128Z error vvold[2298793] [Originator@6876 sub=Default] Initialize: Unable to init session to VP sn1-m20-c12-25-ct0 state: 0

I see that when the host is attempting to authenticate with the VP (VASA Provider) it is unable to locate the VP’s issuer certificate, and because that issuer certificate is missing the VP URL for Initialization is missing the host is unable to authenticate with the VASA Provider.

A look at a Good Authentication

One of my favorite troubleshooting workflows is to compare the problem with a healthy/normal working example. So, next I want to take a look at the vvold log for the host that everything is working for just fine. I’ll see that the request to GetEndPoint is made and succeeds right away.

2019-08-12T22:59:18.086Z info vvold[2571765] [Originator@6876 sub=Default] VendorProviderMgr::AddOrRef VP (sn1-m20-c12-25-ct0) Uid () URL (https://10.21.88.113:8084/version.xml)
 2019-08-12T22:59:18.086Z info vvold[2571765] [Originator@6876 sub=Default] DlgSoapCtxPool: Created new DlgSoapCtxPool ([14DlgSoapCtxPool:0x0000002177da0d40]) for VP (sn1-m20-c12-25-ct0) session (0000002177da0bd0)
 2019-08-12T22:59:18.087Z info vvold[2571765] [Originator@6876 sub=Default] VendorProviderMgr:UpdateFirewallRules: Firewall operation add on rule id:VVOLD_8084 success
 2019-08-12T22:59:18.087Z info vvold[2571765] [Originator@6876 sub=Default] VasaSession::GetEndPoint: with url https://10.21.88.113:8084/version.xml
 2019-08-12T22:59:18.098Z info vvold[2571765] [Originator@6876 sub=Default] VasaSession::Parse xml: id=4, loc=/vasa, myVer=4, ver=0
 2019-08-12T22:59:18.098Z info vvold[2571765] [Originator@6876 sub=Default] VasaSession::ParseVersionXml: Effective VP endpoint is https://10.21.88.113:8084/vasa (version 4)
 2019-08-12T22:59:18.098Z info vvold[2571765] [Originator@6876 sub=Default] VasaSession::DoSetContext: Setting GUID: 'D2CCA827-514D-E611-0000-78654321006B'  VC UID: '1143a5e7-f7de-4311-b0d8-781e84d1c908' (lastEventId was -1)
 2019-08-12T22:59:18.323Z warning vvold[2571765] [Originator@6876 sub=Default] VasaSession::SetState: VP sn1-m20-c12-25-ct0 [OutOfSync -> Connected], state change locked!
 2019-08-12T22:59:18.323Z info vvold[2571765] [Originator@6876 sub=Default] VasaSession::DoSetContext: master soap's original keep_alive = 1
 2019-08-12T22:59:18.324Z info vvold[2571765] [Originator@6876 sub=Default] VasaSession::DoSetContext: VP sn1-m20-c12-25-ct0 url https://10.21.88.113:8084/vasa: success eventTimer 5000000  maxBatchsize 1 maxConcurrentRequestsPerSession 5 _sessionId [440680165843882267] _genId 1

Notice the difference between the two when the VP URL is looked up with the GetEndPoint.

2019-08-12T22:59:18.087Z info vvold[2571765] [Originator@6876 sub=Default] VasaSession::GetEndPoint: with url https://10.21.88.113:8084/version.xml
 2019-08-12T22:59:18.098Z info vvold[2571765] [Originator@6876 sub=Default] VasaSession::Parse xml: id=4, loc=/vasa, myVer=4, ver=0
 2019-08-12T22:59:18.098Z info vvold[2571765] [Originator@6876 sub=Default] VasaSession::ParseVersionXml: Effective VP endpoint is https://10.21.88.113:8084/vasa (version 4)

=====
vs
=====


 2019-08-12T22:59:18.124Z info vvold[2298793] [Originator@6876 sub=Default] VasaSession::GetEndPoint: with url https://10.21.88.113:8084/version.xml
 2019-08-12T22:59:18.128Z warning vvold[2298793] [Originator@6876 sub=Default] VasaSession::GetEndPoint: failed to get endpoint, err=SSL Exception: Verification parameters:
 --> PeerThumbprint: 0B:2F:E1:52:F3:85:EB:CD:BE:B4:FF:E3:B2:64:1B:FB:F5:BA:55:F4
 --> ExpectedThumbprint:
 --> ExpectedPeerName: 10.21.88.113
 --> The remote host certificate has these problems:
 -->
 --> * unable to get local issuer certificate, using default

The immediate failure is the SSL Exception. More often than not, there is one of two outcomes at play here. The first being that vvold has the local trusted root certs cached from before the storage provider was registered. I’ve seen this more often with earlier builds of 6.5, but with 6.5 U3 it should be an issue any more. The second would be that the vCenter hasn’t pushed the Trusted Certs to the ESXi host.

What can I do to fix this?

With stale or cached certificate information in vvold we want to go ahead and clear that out. I will usually start off just issue the following to the affected ESXi Host:

/etc/init.d/vvold ssl_reset
/etc/init.d/vvold restart

With both of those getting ran this will make sure that there isn’t any cached cert locations or details in vvold. Here is an example of running through this:

2019-08-12T23:14:34.663Z info vvold[2298782] [Originator@6876 sub=Default] VasaSession::GetEndPoint: with url https://10.21.88.113:8084/version.xml
 2019-08-12T23:14:34.666Z warning vvold[2298782] [Originator@6876 sub=Default] VasaSession::GetEndPoint: failed to get endpoint, err=SSL Exception: Verification parameters:
 --> PeerThumbprint: 0B:2F:E1:52:F3:85:EB:CD:BE:B4:FF:E3:B2:64:1B:FB:F5:BA:55:F4
 --> ExpectedThumbprint:
 --> ExpectedPeerName: 10.21.88.113
 --> The remote host certificate has these problems:
 -->
 --> * unable to get local issuer certificate, using default
 2019-08-12T23:14:34.667Z info vvold[2298782] [Originator@6876 sub=Default] VasaSession::Initialize url is empty
 2019-08-12T23:14:34.667Z warning vvold[2298782] [Originator@6876 sub=Default] VasaSession::DoSetContext: Empty VP URL for VP (sn1-m20-c12-25-ct0)!
 2019-08-12T23:14:34.667Z info vvold[2298782] [Originator@6876 sub=Default] Initialize: Failed to establish connection https://10.21.88.113:8084/version.xml
 2019-08-12T23:14:34.667Z error vvold[2298782] [Originator@6876 sub=Default] Initialize: Unable to init session to VP sn1-m20-c12-25-ct0 state: 0

==========
/etc/init.d/vvold ssl_reset is ran
==========

 2019-08-12T23:14:34.817Z [/etc/init.d/vvold[2299926]: /etc/init.d/vvold ssl_reset, PID 2299926]
 2019-08-12T23:14:34.821Z info vvold[2298809] [Originator@6876 sub=Default] Reading from pipe returned 1
 2019-08-12T23:14:34.821Z warning vvold[2298809] [Originator@6876 sub=Default] VVold caught signal 1
 2019-08-12T23:14:34.821Z warning vvold[2298793] [Originator@6876 sub=Default] ReloadSslCert: Resetting all VASA sessions on receiving SIGHUP
 2019-08-12T23:14:34.821Z info vvold[2298793] [Originator@6876 sub=Default] VendorProviderMgr::ResetVPSessions: Resetting only SSL sessions
 2019-08-12T23:14:34.821Z warning vvold[2298793] [Originator@6876 sub=Default] VVolServiceInstance::SetSSLContext: Skipping CRL check as env variable VVOLD_DO_CRL_CHECK is not set!
 2019-08-12T23:14:34.822Z info vvold[2298793] [Originator@6876 sub=Default] VendorProviderMgr::ResetVPSessions: Skipping non-SSL session to VP (sn1-405-c12-21-ct0)
 2019-08-12T23:14:34.822Z info vvold[2298793] [Originator@6876 sub=Default] VendorProviderMgr::ResetVPSessions: Skipping non-SSL session to VP (sn1-m20-c12-25-ct0)
 2019-08-12T23:14:34.822Z [/etc/init.d/vvold[2299926]: vvold signalled for SSL reset]
 2019-08-12T23:14:34.975Z info vvold[2298809] [Originator@6876 sub=Default] VasaSession::GetEndPoint: with url https://10.21.88.117:8084/version.xml
 2019-08-12T23:14:34.988Z info vvold[2298809] [Originator@6876 sub=Default] VasaSession::Parse xml: id=4, loc=/vasa, myVer=4, ver=0
 2019-08-12T23:14:34.988Z info vvold[2298809] [Originator@6876 sub=Default] VasaSession::ParseVersionXml: Effective VP endpoint is https://10.21.88.117:8084/vasa (version 4)
 2019-08-12T23:14:34.988Z info vvold[2298809] [Originator@6876 sub=Default] VasaSession::DoSetContext: Setting GUID: 'D2CCA827-514D-E611-0000-78654321009B'  VC UID: '1143a5e7-f7de-4311-b0d8-781e84d1c908' (lastEventId was -1)
 2019-08-12T23:14:34.988Z info vvold[2298809] [Originator@6876 sub=Default] GetVasaHostInitiators: Adding FC HBA  wwpn: 20:00:00:25:b5:22:00:0d wwnn: 20:00:00:25:b5:44:00:47
 2019-08-12T23:14:34.988Z info vvold[2298809] [Originator@6876 sub=Default] GetVasaHostInitiators: Adding FC HBA  wwpn: 20:00:00:25:b5:22:00:3d wwnn: 20:00:00:25:b5:44:00:47
 2019-08-12T23:14:34.988Z info vvold[2298809] [Originator@6876 sub=Default] GetVasaHostInitiators: Adding FC HBA  wwpn: 20:00:00:25:b5:66:00:0d wwnn: 20:00:00:25:b5:44:00:47
 2019-08-12T23:14:34.988Z info vvold[2298809] [Originator@6876 sub=Default] GetVasaHostInitiators: Adding FC HBA  wwpn: 20:00:00:25:b5:66:00:3d wwnn: 20:00:00:25:b5:44:00:47
 2019-08-12T23:14:34.988Z info vvold[2298809] [Originator@6876 sub=Default] GetVasaHostInitiators: Adding iSCSI HBA [iqn:iqn.1998-01.com.vmware:esxi-1]
 2019-08-12T23:14:34.988Z info vvold[2298809] [Originator@6876 sub=Default] VasaSession::InitSoap: Master soap client created successfully
 2019-08-12T23:14:34.988Z info vvold[2298809] [Originator@6876 sub=Default] VasaSession::InitSoap: _masterSoap=000000c2e0724010, iomode=33558544
 2019-08-12T23:14:34.988Z info vvold[2298809] [Originator@6876 sub=Default] VasaSession::InitSoap VVold using 15 secs for soap connect timeout
 2019-08-12T23:14:34.988Z info vvold[2298809] [Originator@6876 sub=Default] VasaSession::InitSoap VVold using 75 secs for soap receive timeout
 2019-08-12T23:14:35.240Z warning vvold[2298809] [Originator@6876 sub=Default] vvol_ssl_auth_init: Will skip CRL check as env variable VVOLD_DO_CRL_CHECK is not set!
 2019-08-12T23:14:35.240Z warning vvold[2298809] [Originator@6876 sub=Default] VasaSession:DoSetContext: Setting VASAVERSION cookie to "3.0"
 2019-08-12T23:14:35.240Z info vvold[2298809] [Originator@6876 sub=Default] VasaSession::KillAllConnections VP (sn1-405-c12-21-ct0), purged 0 connections, 0 currently active, new genId (1) (broadcast wakeup to all threads waiting for free connection)
 2019-08-12T23:14:35.334Z warning vvold[2298809] [Originator@6876 sub=Default] VasaSession::SetState: VP sn1-405-c12-21-ct0 [OutOfSync -> Connected], state change locked!
 2019-08-12T23:14:35.335Z info vvold[2298809] [Originator@6876 sub=Default] VasaSession::DoSetContext: master soap's original keep_alive = 1
 2019-08-12T23:14:35.335Z info vvold[2298809] [Originator@6876 sub=Default] VasaSession::DoSetContext: VP sn1-405-c12-21-ct0 url https://10.21.88.117:8084/vasa: success eventTimer 5000000  maxBatchsize 1 maxConcurrentRequestsPerSession 5 _sessionId [-1520153752992228692] _genId 1
 2019-08-12T23:14:35.335Z info vvold[2298809] [Originator@6876 sub=Default] VasaSession::CheckForceParams: Environment variable VVOLD_FORCE_MAX_CONNECTIONS_PER_SESSION not set, using 5 conns/session!
 2019-08-12T23:14:35.335Z info vvold[2298809] [Originator@6876 sub=Default]
 --> VasaOp::SetPEContextInt [#1]: ===> Issuing 'setPEContext' to VP sn1-405-c12-21-ct0 (#outstanding 0/5) [session state: Connected]
 2019-08-12T23:14:35.335Z info vvold[2298809] [Originator@6876 sub=Default] VasaSession::GetFreeConn: VP (sn1-405-c12-21-ct0), added new connection ([14VasaConnection:0x000000c2969a0c10]) to the pool (size now 1/5), _genId 1!
 2019-08-12T23:14:35.335Z info vvold[2298784] [Originator@6876 sub=Default]
 --> VasaOp::EventPollerCB [#2]: ===> Issuing 'getEvents' to VP sn1-405-c12-21-ct0 (#outstanding 1/5) [session state: Connected]
 2019-08-12T23:14:35.336Z info vvold[2298784] [Originator@6876 sub=Default] VasaSession::GetFreeConn: VP (sn1-405-c12-21-ct0), added new connection ([14VasaConnection:0x000000c296966eb0]) to the pool (size now 2/5), _genId 1!
 2019-08-12T23:14:35.348Z error vvold[2298784] [Originator@6876 sub=Default]
 --> VasaOp::ThrowFromSessionError [#2]: ===> FINAL SUCCESS getEvents VP (sn1-405-c12-21-ct0) Container (sn1-405-c12-21-ct0) timeElapsed=12 msecs (#outstanding 1)

Right after the ssl_reset completes, we see that the GetEndPoint is able to complete without a failure and the VP is successfully initialized. If I recall correctly you only need to run the ssl_reset, but I tend to just run both in tandem to be safe.

Restarting vvold didn’t fix it, what next?

What about if that didn’t actually fix anything and the problem still persists and the same error is in vvold? This could be due to the Trusted CA Certs not actually getting pushed from vCenter to the ESXi hosts. I’ve seen this most often when importing a new Trusted CA Cert to vCenter after ESXi hosts are already in vCenter. Essentially the trusted certs aren’t successfully getting pushed to the ESXi hosts in the vCenter automatically after getting added.

There are a couple of ways that you can manually push the Trusted Root certs to the ESXi hosts. One way would be to right click on the host in the GUI, navigate to certificates and then choose the option to Refresh CA Certificates. This will in turn push all certificates in the TRUSTED_ROOTS storage to the ESXi host. Another way would be to leverage PowerCLI and do this. Here is a workflow that I have been using in these cases with PowerShell and PowerCLI:

## Connect to the vCenter Server ##
Connect-VIServer -server prod-vcsa

## Get the ESXi hosts and set it to a variable ##
$hosts = get-vmhost

## Start the Service Instance ##
$si = Get-View ServiceInstance

## Start the certificate Manager view ##
$certMgr = Get-View -Id $si.Content.CertificateManager

## Using the Cert Manager, refresh the ESXi hosts Certs ##
## This pushes all certificates in the TRUSTED_ROOTS store in the vCenter Server VECS store to the host. ##
$certMgr.CertMgrRefreshCACertificatesAndCRLs($Hosts.ExtensionData.MoRef)

## Now in vCenter the vvol datastore should be accessible for each of those hosts.  No need to do the ssl_reset and restart on VVold ## 

Then an example of actually running through it.

PS C:> Connect-VIServer -Server dev-vcsa
 Name                           Port  User                          
 ----                           ----  ----                          
 dev-vcsa                       443   ALEX\Carver                   
 PS C:> Get-Cluster -Name "Dev Cluster"
 Name                           HAEnabled  HAFailover DrsEnabled DrsAutomationLevel  
                                           Level                                     
 ----                           ---------  ---------- ---------- ------------------  
 Dev Cluster                    True       1          True       FullyAutomated      
 PS C:> $ESXi_Cluster = Get-Cluster -Name "Dev Cluster"
 PS C:> $ESXi_Cluster | Get-VMHost
 Name                 ConnectionState PowerState NumCpu CpuUsageMhz CpuTotalMhz   MemoryUsageGB   MemoryTotalGB Version
 ----                 --------------- ---------- ------ ----------- -----------   -------------   ------------- -------
 esxi-7.alex.pures… Connected       PoweredOn      16         151       38304          14.586         255.897   6.7.0
 esxi-6.alex.pures… Connected       PoweredOn      20         141       43880          16.166         255.892   6.7.0
 esxi-4.alex.pures… Connected       PoweredOn      20          94       43880           8.945         255.892   6.7.0
 PS C:> $hosts = $ESXi_Cluster | Get-VMHost
 PS C:> $hosts
 Name                 ConnectionState PowerState NumCpu CpuUsageMhz CpuTotalMhz   MemoryUsageGB   MemoryTotalGB Version
 ----                 --------------- ---------- ------ ----------- -----------   -------------   ------------- -------
 esxi-7.alex.pures… Connected       PoweredOn      16         151       38304          14.586         255.897   6.7.0
 esxi-6.alex.pures… Connected       PoweredOn      20         141       43880          16.166         255.892   6.7.0
 esxi-4.alex.pures… Connected       PoweredOn      20          94       43880           8.945         255.892   6.7.0
 PS C:> $si = Get-View ServiceInstance
 PS C:> $certMgr = Get-View -Id $si.Content.CertificateManager
 PS C:> $certMgr.CertMgrRefreshCACertificatesAndCRLs($Hosts.ExtensionData.MoRef)
 PS C:> 

Then check the vvold log on the host that had the issue and you should see that everything is good again. I would recommend that you check to make sure that the Root Cert Refresh completed correctly in the Tasks. One issue that can happen is that vCenter is failing to push the Trusted Certs to the ESXi host.

This can happen because of stale entries in the PSC/SSO or some other combination that the communication between the ESXi host and vCenter is hitting an error. In the end, if vCenter is unable to push the Trusted Certs to the ESXi host, then the host will be unable to authenticate with the VASA Provider. VMware has updated their KB that covers how to check if there is an issue with the VECS or Expired/outdated certificates: https://kb.vmware.com/s/article/2146011

There is the possibility that this symptom is indicative of another issue, but more often than not the VP URL being empty is because of one of the two issues above.