Storage Providers fail to display in Web Client with error message: "The storage service is not initialized. Try again later."

Products

• VMware vCenter Server
• VMware vSphere ESXi

Issue/Introduction

Symptoms:

• When checking Storage Providers in the Web Client you see empty list and an error similar to: The storage service is not initialized. Try again later.
• In /var/log/vmware/vmware-sps/sps.log on vCenter Server you see errors similar to:

20xx-yy-zzT06:06:50.942Z [pool-20-thread-1] DEBUG opId=sps-PSVDCleanup-257037-916 com.vmware.vim.sms.policy.PolicyManagerImpl - Waiting for 1000 millisecs till all the providers are loaded...
20xx-yy-zzT06:06:51.942Z [pool-20-thread-1] DEBUG opId=sps-PSVDCleanup-257037-916 com.vmware.vim.sms.policy.PolicyManagerImpl - Waiting for 1000 millisecs till all the providers are loaded...
20xx-yy-zzT06:06:52.942Z [pool-20-thread-1] DEBUG opId=sps-PSVDCleanup-257037-916 com.vmware.vim.sms.policy.PolicyManagerImpl - Waiting for 1000 millisecs till all the providers are loaded...
20xx-yy-zzT06:06:53.942Z [pool-20-thread-1] DEBUG opId=sps-PSVDCleanup-257037-916 com.vmware.vim.sms.policy.PolicyManagerImpl - Waiting for 1000 millisecs till all the providers are loaded...
20xx-yy-zzT06:06:54.943Z [pool-20-thread-1] DEBUG opId=sps-PSVDCleanup-257037-916 com.vmware.vim.sms.policy.PolicyManagerImpl - Waiting for 1000 millisecs till all the providers are loaded...
20xx-yy-zzT06:06:55.684Z [pool-24-thread-10] DEBUG opId=lro-2-42443ae5-bcc com.vmware.vim.storage.common.security.CommonActivationValidator - Found saml token in auth data for user: vpxd-********-****-****-****-***********
20xx-yy-zzT06:06:55.684Z [pool-24-thread-10] DEBUG opId=lro-2-42443ae5-bcc com.vmware.vim.storage.common.security.CommonActivationValidator - Validating session using saml token...
20xx-yy-zzT06:06:55.684Z [pool-22-thread-4] DEBUG opId=lro-2-42443ae5-bcc com.vmware.vim.storage.common.util.SimpleTimeCounter - TIMER STARTED: queryProvider
20xx-yy-zzT06:06:55.684Z [pool-22-thread-4] DEBUG opId=lro-2-42443ae5-bcc com.vmware.vim.sms.StorageManagerImpl - ProviderLoader initialization is ongoing.
20xx-yy-zzT06:06:55.684Z [pool-22-thread-4] ERROR opId=lro-2-42443ae5-bcc com.vmware.vim.sms.StorageManagerImpl - [queryProvider] Failed with exception.
(sms.fault.ServiceNotInitialized) {

• In /var/log/iofiltervpd.log on ESXi host you see entries similar to:

20xx-yy-zzT00:13:10Z iofiltervpd[69019]: IOFVPSSL_VerifySSLCertificate:150:Client certificate can't be verified
20xx-yy-zzT00:13:20Z iofiltervpd[69019]: IOFVPSSL_VerifySSLCertificate:150:Client certificate can't be verified
20xx-yy-zzT00:13:30Z iofiltervpd[69019]: IOFVPSSL_VerifySSLCertificate:150:Client certificate can't be verified

• When checking status of SPS service, it is still in Yellow state even after several hours after SPS service restart:

root@vc01 [ /tmp ]# wget localhost:22000/sms/HealthStatus ; cat HealthStatus ; rm HealthStatus
--20xx-yy-zz 12:46:26-- http://localhost:22000/sms/HealthStatus
Resolving localhost... 127.0.0.1
Connecting to localhost|127.0.0.1|:22000... connected.
HTTP request sent, awaiting response... 200
Length: unspecified [application/xml]
Saving to: ‘HealthStatus’

HealthStatus [ <=> ] 450 --.-KB/s in 0s

20xx-yy-zz 12:46:26 (49.1 MB/s) - ‘HealthStatus’ saved [450]

<?xml version="1.0" encoding="UTF-8" standalone="yes"?><healthStatus schemaVersion="1.0" xmlns="http://www.vmware.com/cis/cm/common/jaxb/healthstatus"><status>YELLOW</status><message messageKey="com.vmware.vim.sms.InitializationInProgress" defaultMessage="{0} initializing..."><param xsi:type="xs:string" xmlns:xs="http://www.xxxxx.org/2001/XMLSchema" xmlns:xsi="http://www.xxxxx.org/2001/XMLSchema-instance">VASA providers</param></message></healthStatus>

 

• When running netstat command you see stuck connection to specific IOFilter in CLOSE_WAIT state for several hours:

root@vc01 [ /var/log/vmware/vmware-sps ]# netstat -pan output | grep -i sps

tcp       0 0 127.0.0.1:22000           0.0.0.0:*         LISTEN        30309/vmware-sps.la
tcp       0 0 127.0.0.1:22100           0.0.0.0:*         LISTEN        30309/vmware-sps.la
tcp       0 0 127.0.0.1:8190            0.0.0.0:*         LISTEN        30309/vmware-sps.la
tcp       0 0 127.0.0.1:8191            0.0.0.0:*         LISTEN        30309/vmware-sps.la
tcp       0 0 127.0.0.1:8190            127.0.0.1:47768   ESTABLISHED   30309/vmware-sps.la
tcp       0 0 127.0.0.1:56588           127.0.0.1:10080   ESTABLISHED   30309/vmware-sps.la
tcp       0 0 127.0.0.1:51832           127.0.0.1:443     ESTABLISHED   30309/vmware-sps.la
tcp    1867 64240 192.xx.yyy.zzz:57181    192.xx.yy.zz:9080  CLOSE_WAIT    30309/vmware-sps.la <<<<<<<<<<<< Example of stuck Provider (CLOSE_WAIT connection for several hours)
tcp       0 0 127.0.0.1:52184           127.0.0.1:443     ESTABLISHED   30309/vmware-sps.la
tcp       0 0 127.0.0.1:52266           127.0.0.1:443     ESTABLISHED   30309/vmware-sps.la
tcp       0 0 127.0.0.1:56776           127.0.0.1:10080   ESTABLISHED   30309/vmware-sps.la
tcp       0 293 192.xxx.yy.zzz:37614      192.xx.yy.zzz:9080   ESTABLISHED   30309/vmware-sps.la
unix  3 [ ] STREAM CONNECTED 26144279 30309/vmware-sps.la
unix  3 [ ] STREAM CONNECTED 26141247 30309/vmware-sps.la
unix  2 [ ] STREAM CONNECTED 26147124 30309/vmware-sps.la
unix  2 [ ] STREAM CONNECTED 26147419 30309/vmware-sps.la
unix  3 [ ] STREAM CONNECTED 26148013 30309/vmware-sps.la

Environment

VMware vSphere ESXi 6.7
VMware vCenter Server 6.x
VMware vSphere ESXi 6.5

Resolution

This issue is resolved in VMware vSphere 6.5 U3 and 6.7 U3.