Storage Management Service Error

[mblake4u]

Hi,

I'm getting a error with the Storage Management Service when I try to access Storage Views in vCenter (version 4.1.0).

I thought VMware vCenter Server 4.0 Update 1 was supposed to resolve the error, but not in my case.

When accessing the Storage View for a host I get: The storage service is not initialized. Please try again later.

When clicking on update I get: An internal error was encountered while initializing the storage service.

The strange thing is if I remove one host from vCenter then it works - I can update and see the Storage Views, but when I add it back then I'm unable to access it again and I get: An Unknown error has occurred.

Are there some logs I should be checking to tell me what's wrong with this host?

Cheers

[f10]

Hi,

Check the sms.log located at C:\ProgramData\VMware\VMware VirtualCenter\Logs to start troubleshooting this issue.

Since the issue is reported only when storage view tab is accessed from vCenter I would suggest rescanning the datastore for the entire cluster as the first step, so right click on cluster and click rescan for datastore.

Regards,
Arun

If you found this or other information useful, please consider awarding points for "Correct" or "Helpful". Regards, Arun VCP3/4, HPCP, HP UX CSA http://kb.vmware.com/

[mblake4u]

Hi Arun,

Thanks for replying - I've had a look at the logs (after a reboot of the server) and there are some ERROR events which are repeated quite frequently. I think I can see some other errors that are generated when you click on Storage Views, or Update.

I've attached the log for completeness but here are entries which might be relevant:

2011-08-29 11:29:43,405 [http-127.0.0.1-8080-1] ERROR com.vmware.vim.sms.ServiceImpl  - Operation QueryList failed
com.vmware.vim.sms.fault.ServiceNotInitialized
at com.vmware.vim.sms.ServiceImpl.QueryList(Unknown Source)
at com.vmware.vim.sms.api.SmServiceMessageReceiverInOut.invokeBusinessLogic(Unknown Source)
at org.apache.axis2.receivers.AbstractInOutMessageReceiver.invokeBusinessLogic(AbstractInOutMessageReceiver.java:40)
at org.apache.axis2.receivers.AbstractMessageReceiver.receive(AbstractMessageReceiver.java:96)
at org.apache.axis2.engine.AxisEngine.receive(AxisEngine.java:145)
at org.apache.axis2.transport.http.HTTPTransportUtils.processHTTPPostRequest(HTTPTransportUtils.java:275)
at org.apache.axis2.transport.http.AxisServlet.doPost(AxisServlet.java:120)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.vmware.vim.sms.HTTPStatusCodeFilter.doFilter(Unknown Source)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.vmware.vim.sms.HTTPStatusCodeFilter.doFilter(Unknown Source)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:849)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:454)
at java.lang.Thread.run(Thread.java:619)

2011-08-29 11:31:15,541 [pool-37-thread-3] ERROR com.vmware.vim.sms.provider.VcProviderImpl  - PopulateVmFilesTask Failed : com.ibatis.common.jdbc.exception.NestedSQLException:  
--- The error occurred in com/vmware/vim/sms/data/xml/CacheDbQuerySqlMap.xml. 
--- The error occurred while applying a parameter map. 
--- Check the insert_vmFile-InlineParameterMap. 
--- Check the statement (update failed). 
--- Cause: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: ENTITYID_VMFILE_INDEX_9  ON PUBLIC.VMFILE(ENTITYID) [23001-64]
2011-08-29 11:31:15,541 [Thread-9] ERROR com.vmware.vim.sms.provider.VcProviderImpl  - Failed populating service cache
java.util.concurrent.ExecutionException: java.lang.RuntimeException: com.ibatis.common.jdbc.exception.NestedSQLException:  
--- The error occurred in com/vmware/vim/sms/data/xml/CacheDbQuerySqlMap.xml. 
--- The error occurred while applying a parameter map. 
--- Check the insert_vmFile-InlineParameterMap. 
--- Check the statement (update failed). 
--- Cause: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: ENTITYID_VMFILE_INDEX_9  ON PUBLIC.VMFILE(ENTITYID) [23001-64]
at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:222)
at java.util.concurrent.FutureTask.get(FutureTask.java:83)
at com.vmware.vim.sms.provider.VcProviderImpl.waitForTasks(Unknown Source)
at com.vmware.vim.sms.provider.VcProviderImpl.sync(Unknown Source)
at com.vmware.vim.sms.ServiceImpl.syncServiceCache(Unknown Source)
at com.vmware.vim.sms.ServiceImpl.init(Unknown Source)
at com.vmware.vim.sms.ServiceImpl.access$100(Unknown Source)
at com.vmware.vim.sms.ServiceImpl$ServiceInitializer.run(Unknown Source)
Caused by: java.lang.RuntimeException: com.ibatis.common.jdbc.exception.NestedSQLException:  
--- The error occurred in com/vmware/vim/sms/data/xml/CacheDbQuerySqlMap.xml. 
--- The error occurred while applying a parameter map. 
--- Check the insert_vmFile-InlineParameterMap. 
--- Check the statement (update failed). 
--- Cause: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: ENTITYID_VMFILE_INDEX_9  ON PUBLIC.VMFILE(ENTITYID) [23001-64]
at com.vmware.vim.sms.provider.VcProviderImpl$PopulateVmFilesTask.run(Unknown Source)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:619)
Caused by: com.ibatis.common.jdbc.exception.NestedSQLException:  
--- The error occurred in com/vmware/vim/sms/data/xml/CacheDbQuerySqlMap.xml. 
--- The error occurred while applying a parameter map. 
--- Check the insert_vmFile-InlineParameterMap. 
--- Check the statement (update failed). 
--- Cause: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: ENTITYID_VMFILE_INDEX_9  ON PUBLIC.VMFILE(ENTITYID) [23001-64]
at com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.executeUpdate(GeneralStatement.java:91)
at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.insert(SqlMapExecutorDelegate.java:447)
at com.ibatis.sqlmap.engine.impl.SqlMapSessionImpl.insert(SqlMapSessionImpl.java:82)
at com.ibatis.sqlmap.engine.impl.SqlMapClientImpl.insert(SqlMapClientImpl.java:59)
at com.vmware.vim.sms.provider.VcProviderImpl.populateVmFiles(Unknown Source)
at com.vmware.vim.sms.provider.VcProviderImpl.access$000(Unknown Source)
... 7 more
Caused by: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: ENTITYID_VMFILE_INDEX_9  ON PUBLIC.VMFILE(ENTITYID) [23001-64]
at org.h2.message.Message.getSQLException(Message.java:89)
at org.h2.message.Message.getSQLException(Message.java:93)
at org.h2.message.Message.getSQLException(Message.java:71)
at org.h2.index.BaseIndex.getDuplicateKeyException(BaseIndex.java:68)
at org.h2.index.TreeIndex.add(TreeIndex.java:55)
at org.h2.table.TableData.addRow(TableData.java:89)
at org.h2.command.dml.Insert.update(Insert.java:113)
at org.h2.command.CommandContainer.update(CommandContainer.java:68)
at org.h2.command.Command.executeUpdate(Command.java:125)
at org.h2.jdbc.JdbcPreparedStatement.execute(JdbcPreparedStatement.java:161)
at com.ibatis.sqlmap.engine.execution.SqlExecutor.executeUpdate(SqlExecutor.java:81)
at com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.sqlExecuteUpdate(GeneralStatement.java:200)
at com.ibatis.sqlmap.engine.mapping.statement.GeneralStatement.executeUpdate(GeneralStatement.java:78)
... 12 more

2011-08-29 11:31:15,543 [Thread-9] ERROR com.vmware.vim.sms.ServiceImpl  - Unknown exception encountered during service initialization
com.vmware.vim.sms.fault.ProviderSyncFault
at com.vmware.vim.sms.provider.VcProviderImpl.sync(Unknown Source)
at com.vmware.vim.sms.ServiceImpl.syncServiceCache(Unknown Source)
at com.vmware.vim.sms.ServiceImpl.init(Unknown Source)
at com.vmware.vim.sms.ServiceImpl.access$100(Unknown Source)
at com.vmware.vim.sms.ServiceImpl$ServiceInitializer.run(Unknown Source)
2011-08-29 11:31:15,543 [Thread-9] INFO  com.vmware.vim.sms.ServiceImpl$ServiceInitializer  - Retry #10 in 30 seconds

I see those errors relating to primary keys and the other ones also seem to relate to the database, but I don't really know how I should go about resolving them. I've got a pretty standard configuration and haven't done anything to the database myself.

I don't suppose you have any ideas on how to go about resolving these errors?

Regards,

Michael

[f10]

Thanks for sharing the logs Michael.

Can you describe the storage (iSCSI, FC, NFS) that is configured in your vSphere environment and are you experiencing any issues related to storage?

Regards,
Arun

If you found this or other information useful, please consider awarding points for "Correct" or "Helpful". Regards, Arun VCP3/4, HPCP, HP UX CSA http://kb.vmware.com/

[mblake4u]

Hi Arun,

No, we aren't experiencing any storage related issues except for this one.

We use DAS (RAID5) and NFS shares (NetApp and Iomega). All the shares are accessible and we aren't having any problems with them.

The Storage Adapters are:

PowerEdge R710 SATA IDE Controller

vmhba0 / Block SCSI

vmhba36 / Block SCSI

Broadcom iSCSI Adapter

vmhba32 / iSCSI

vmhba33 / iSCSI

vmhba34 / iSCSI

vmhba35 / iSCSI

Dell PERC 6/i Integrated

vmhba1 / SCSI

iSCSI Software Adapter

iSCSI Software Adapter / iSCSI

This particular cluster I'm having problems with has 3 hosts - it seems to be one of the hosts that is causing problems. If I remove this host then I can access Storage Views but if I add it back to the cluster I can't. If I remove the other 2 hosts and leave this one in the cluster I can access Storage Views so it seems like there's some kind of incompatibility between this host and the other 2.

All three hosts have the same version of ESX (4.1.0, 260247), have the same licence (Essentials Plus) and are the same model (Dell R710).

They've all got the same NFS shares and storage adapters.

Perhaps I should be checking the logs on this host (even though it works when it's the only one in the cluster)? What would you suggest?

Many thanks,

Michael

[f10]

NFS, thats what I was suspecting. I would suggest you to check the mount points on the faulty host and compare it with the others, you might find some indescripency :smileyhappy:. If the mount points are the same when compared to all other ESX/ESXi hosts then file a SR with VMware support.

I hope this informatoin helps.

Regards,
Arun

If you found this or other information useful, please consider awarding points for "Correct" or "Helpful". Regards, Arun VCP3/4, HPCP, HP UX CSA http://kb.vmware.com/

[mblake4u]

Hi Arun,

Thanks for your help and pointing me in the right direction. I opened a SR with VMware and this was their response:

Thanks. The reason I ask is that we're seeing the following in sms.log:

Caused by: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: ENTITYID_VMFILE_INDEX_9 ON PUBLIC.VMFILE(ENTITYID) [23001-64]
 at org.h2.message.Message.getSQLException(Message.java:89)
 at org.h2.message.Message.getSQLException(Message.java:93)

2011-08-31 08:55:49,786 [Timer-2] ERROR com.vmware.vim.sms.provider.VcProviderImpl - Failed populating service cache

The error occurred in com/vmware/vim/sms/data/xml/CacheDbQuerySqlMap.xml.
--- The error occurred while applying a parameter map.
--- Check the insert_vmFile-InlineParameterMap.
--- Check the statement (update failed).


That sequence of error closely matches an issue we've seen before.

Specfically this may occur when an ESX or ESXi host has more than one NFS mount point in the same tree. It could occur if you have duplicate NFS mount points attached to the ESX host.

 For example, two NFS mounts may point to the same target using a different hostname or IP address:

/nfs-server-ip-address/sharename/folder
/nfs-server-hostname/sharename/folder

Or two NFS mounts may point to different depths of the same tree. For example:

/nfs-server-ip-address/sharename/
/nfs-server-ip-address/sharename/folder




You need to check for the above and if there are duplicates  NFS mount entrys they  need to be removed from the ESX/ESXi hosts. To do that:

1. Connect to the vCenter Server using the vSphere Client.

1. Select each ESX host in the inventory.

3. Click Home.

4. Click Datastores.

5. Identify any duplicate NFS exports mounted by a single ESX/ESXi host as a Datastore.

6. Select the duplicate NFS Datastore, and click the Summary tab.

7. Ensure the number of Virtual Machines and Templates is 0 (zero) before proceeding. If there are  virtual machines using the duplicate NFS Datastore, power them off or Storage vMotion them to an alternate datastore.

8. Right-click each duplicate NFS Datastore, and click Unmount.

9. Restart the vCenter services for the change to take effect.

10.Reconnect to the vCenter Server using the vSphere Client.

11. Click Home.

12. Click vCenter Service Status.

13. Review the Storage Management Service and ensure there is no alert.

My particular problem was:

/nfs-server-ip-address/sharename/
/nfs-server-ip-address/sharename/folder

After changing the 2 conflicting shares to

/nfs-server-ip-address/sharename/folder2
/nfs-server-ip-address/sharename/folder

it started to work!

In fact I didn't need to restart anything. Just changing the conflicting share to something that worked allowed me to access Storage Views again.

Thanks for your help.

Regards, Michael

[f10]

Thanks for the update Michael, I am glad the the issue is fixed :smileyhappy: