Bug 958488
| Summary: | [LOG] engine: several Exceptions during engine restart on Live Storage Migration | ||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | Red Hat Enterprise Virtualization Manager | Reporter: | Dafna Ron <dron> | ||||||||
| Component: | ovirt-engine | Assignee: | Daniel Erez <derez> | ||||||||
| Status: | CLOSED DUPLICATE | QA Contact: | Ori Gofen <ogofen> | ||||||||
| Severity: | high | Docs Contact: | |||||||||
| Priority: | unspecified | ||||||||||
| Version: | 3.2.0 | CC: | acanan, acathrow, amureini, bazulay, derez, iheim, jkt, lpeer, ogofen, Rhev-m-bugs, scohen, yeylon | ||||||||
| Target Milestone: | --- | Flags: | scohen:
Triaged+
|
||||||||
| Target Release: | 3.5.0 | ||||||||||
| Hardware: | x86_64 | ||||||||||
| OS: | Linux | ||||||||||
| Whiteboard: | storage | ||||||||||
| Fixed In Version: | Doc Type: | Bug Fix | |||||||||
| Doc Text: | Story Points: | --- | |||||||||
| Clone Of: | |||||||||||
| : | 959739 (view as bug list) | Environment: | |||||||||
| Last Closed: | 2014-05-13 11:04:46 UTC | Type: | Bug | ||||||||
| Regression: | --- | Mount Type: | --- | ||||||||
| Documentation: | --- | CRM: | |||||||||
| Verified Versions: | Category: | --- | |||||||||
| oVirt Team: | Storage | RHEL 7.3 requirements from Atomic Host: | |||||||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||||||
| Embargoed: | |||||||||||
| Bug Depends On: | |||||||||||
| Bug Blocks: | 959739 | ||||||||||
| Attachments: |
|
||||||||||
still relevant? (In reply to Itamar Heim from comment #10) > still relevant? This is a logging issue as far as we know. We prefer cleaning up the log to make the real issues stand out and make it more usable which is why this bug is still open. Created attachment 894700 [details]
engine logs
After executing several time live storage migration and engine restart commands,
move disk failed with exception:
2014-05-12 15:06:33,484 ERROR [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-78) BaseAsyncTask::LogEndTaskFailure: Task 45a27e5c-3db5-4d39-826c-b8cc0eb44f4e
8011 -- Result: cleanSuccess
8012 -- Message: VDSGenericException: VDSErrorException: Failed in vdscommand to HSMGetAllTasksStatusesVDS, error = Volume already exists,
8013 -- Exception: VDSGenericException: VDSErrorException: Failed in vdscommand to HSMGetAllTasksStatusesVDS, error = Volume already exists
log is attached.
vdsm version:
vdsm-cli-4.14.7-1.el6ev.noarch
engine version:
rhevm-3.4.0-0.18.el6ev.noarch
Hi Ori, It seems like another issue not related to the log problems described in the bug (looks like a duplicate of bug 1070863). For further investigation, can you please attach the relevant vdsm logs as well. Created attachment 894764 [details]
vdsm+engine logs
notice that the failure appears at 15:06 and there's a lot going through sense then that not necessary associated with current bug
Looking at the logs [1], seems that the live migration has failed at the VmReplicateDiskFinish step of LSM, which means we don't perform cleanup (see more information at bug 1070863 comment #5). Hence, the error mentioned in comment #15 is acceptable by the current design (which might be revisited when addressing bug 1070863). Hence, the described issue should probably be marked as an exact duplicate. Just for getting the full picture, I couldn't find in the vdsm logs the underlined reason of diskReplicateFinish failure. @Ori - can you please attach the HSM logs as well? [1] 2014-05-12 15:00:43,611 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (org.ovirt.thread.pool-4-thread-22) [3535aafd] Command VmReplicateDiskFinishVDSCommand(HostName = camel-vdsb, HostId = 7d729d71-58ed-4e0b-b76e-9aac4a6c85c5, vmId=9245371c-f666-400a-8887-c55bd39e6741) execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to VmReplicateDiskFinishVDS, error = Drive replication error, code = 55 Hey Daniel, I believe I executed the operation with only one host (SPM). As I recall,creating this bug involve the same steps described in BZ #1070863 *** This bug has been marked as a duplicate of bug 1070863 *** remark: all the other mentioned exceptions are verified (except VDSErrorException) |
Created attachment 742269 [details] log Description of problem: if we restart ovirt-engine right at the begining of live storage migration we are getting several exceptions: 1. CreateAllSnapshotsFromVmCommand throw exception: - for connection manager is shutdown 2. java.lang.NullPointerException on transaction rolled back 3. java.lang.RuntimeException Unable to suspend transaction 4. java.lang.IllegalArgumentException for lookup resource type: LOCK_MANAGER 5. Failed to run compensation on startup for Command org.ovirt.engine.core.bll.RemoveSnapshotCommand Version-Release number of selected component (if applicable): sf14 How reproducible: 100% Steps to Reproduce: 1. start a live storage migration 2. before createVolume is sent to the spm -> restart the ovirt-engine 3. Actual results: we are getting several exceptions and the tasks are not cleared from asyn_tasks and comepensation Expected results: 1. we should have no exceptions 2. tasks should be cleared. Additional info: full log 1. 2013-05-01 14:52:24,238 ERROR [org.ovirt.engine.core.bll.CreateAllSnapshotsFromVmCommand] (pool-4-thread-49) [402ad15a] Command org.ovirt.engine.core.bll.CreateAllSnapshotsFromVmCommand throw exception: org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is java.sql.SQLException: javax.resource.ResourceException: IJ000451: The connection manager is shutdown: java:/ENGINEDataSource at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:80) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:573) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:637) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:666) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:706) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE] at org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall.executeCallInternal(PostgresDbEngineDialect.java:155) [engine-dal.jar:] at org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall.doExecute(PostgresDbEngineDialect.java:121) [engine-dal.jar:] at org.springframework.jdbc.core.simple.SimpleJdbcCall.execute(SimpleJdbcCall.java:181) [spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE] at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeImpl(SimpleJdbcCallsHandler.java:124) [engine-dal.jar:] at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeReadAndReturnMap(SimpleJdbcCallsHandler.java:75) [engine-dal.jar:] at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeReadList(SimpleJdbcCallsHandler.java:66) [engine-dal.jar:] 2. 2013-05-01 14:52:24,267 ERROR [org.ovirt.engine.core.bll.CreateAllSnapshotsFromVmCommand] (pool-4-thread-49) [402ad15a] Transaction rolled-back for command: org.ovirt.engine.core.bll.CreateAllSnapshotsFromVmCommand. 2013-05-01 14:52:24,267 INFO [org.ovirt.engine.core.utils.transaction.TransactionSupport] (pool-4-thread-49) [402ad15a] transaction rolled back 2013-05-01 14:52:24,278 ERROR [org.ovirt.engine.core.bll.job.ExecutionHandler] (pool-4-thread-49) [402ad15a] java.lang.NullPointerException 2013-05-01 14:52:24,280 ERROR [org.ovirt.engine.core.bll.job.ExecutionHandler] (pool-4-thread-49) [402ad15a] Failed to end Job 4ec69407-2c89-420d-81f3-de9d8dffb2ec, CreateAllSnapshotsFromVm: java.lang.IllegalArgumentException: JBAS011857: NamingStore is null at org.jboss.as.naming.NamingContext.<init>(NamingContext.java:152) at org.jboss.as.naming.NamingContext.<init>(NamingContext.java:125) at org.jboss.as.naming.InitialContext.<init>(InitialContext.java:86) at org.jboss.as.naming.InitialContextFactory.getInitialContext(InitialContextFactory.java:44) at javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:684) [rt.jar:1.7.0_19] at javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:307) [rt.jar:1.7.0_19] at javax.naming.InitialContext.getURLOrDefaultInitCtx(InitialContext.java:335) [rt.jar:1.7.0_19] at javax.naming.InitialContext.lookup(InitialContext.java:411) [rt.jar:1.7.0_19] at org.ovirt.engine.core.utils.ejb.EJBUtilsStrategy.findResource(EJBUtilsStrategy.java:65) [engine-utils.jar:] at org.ovirt.engine.core.utils.ejb.EjbUtils.findResource(EjbUtils.java:36) [engine-utils.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.findTransactionManager(TransactionSupport.java:20) [engine-utils.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:189) [engine-utils.jar:] at org.ovirt.engine.core.bll.job.JobRepositoryImpl.updateCompletedJobAndSteps(JobRepositoryImpl.java:215) [engine-bll.jar:] at org.ovirt.engine.core.bll.job.ExecutionHandler.endJob(ExecutionHandler.java:428) [engine-bll.jar:] at org.ovirt.engine.core.bll.job.ExecutionHandler.endJob(ExecutionHandler.java:402) [engine-bll.jar:] at org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1167) [engine-bll.jar:] at org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:315) [engine-bll.jar:] at org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:361) [engine-bll.jar:] at org.ovirt.engine.core.bll.Backend.runInternalAction(Backend.java:566) [engine-bll.jar:] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_19] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_19] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_19] at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_19] 3. 2013-05-01 14:52:24,296 ERROR [org.ovirt.engine.core.bll.lsm.LiveMigrateVmDisksCommand] (pool-4-thread-49) [402ad15a] Command org.ovirt.engine.core.bll.lsm.LiveMigrateVmDisksCommand throw exception: javax.ejb.EJBException: java.lang.RuntimeException: Unable to suspend transaction at org.jboss.as.ejb3.tx.CMTTxInterceptor.handleExceptionInNoTx(CMTTxInterceptor.java:191) [jboss-as-ejb3.jar:7.2.0.Final-redhat-3] at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:237) [jboss-as-ejb3.jar:7.2.0.Final-redhat-3] at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:374) [jboss-as-ejb3.jar:7.2.0.Final-redhat-3] at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:218) [jboss-as-ejb3.jar:7.2.0.Final-redhat-3] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2] at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3.jar:7.2.0.Final-redhat-3] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2] at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [jboss-as-ejb3.jar:7.2.0.Final-redhat-3] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2] at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3.jar:7.2.0.Final-redhat-3] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2] at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee.jar:7.2.0.Final-redhat-3] 4. 2013-05-01 14:52:24,328 ERROR [org.ovirt.engine.core.utils.ejb.EJBUtilsStrategy] (pool-4-thread-49) [402ad15a] Failed to lookup resource type: LOCK_MANAGER. JNDI name: java:global/engine/engine-bll/LockManager: java.lang.IllegalArgumentException: JBAS011857: NamingStore is null at org.jboss.as.naming.NamingContext.<init>(NamingContext.java:152) at org.jboss.as.naming.NamingContext.<init>(NamingContext.java:125) at org.jboss.as.naming.InitialContext.<init>(InitialContext.java:86) at org.jboss.as.naming.InitialContextFactory.getInitialContext(InitialContextFactory.java:44) at javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:684) [rt.jar:1.7.0_19] at javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:307) [rt.jar:1.7.0_19] at javax.naming.InitialContext.getURLOrDefaultInitCtx(InitialContext.java:335) [rt.jar:1.7.0_19] at javax.naming.InitialContext.lookup(InitialContext.java:411) [rt.jar:1.7.0_19] at org.ovirt.engine.core.utils.ejb.EJBUtilsStrategy.findBean(EJBUtilsStrategy.java:104) [engine-utils.jar:] at org.ovirt.engine.core.utils.ejb.EjbUtils.findBean(EjbUtils.java:23) [engine-utils.jar:] at org.ovirt.engine.core.utils.lock.LockManagerFactory.getLockManager(LockManagerFactory.java:10) [engine-utils.jar:] at org.ovirt.engine.core.bll.CommandBase.getLockManager(CommandBase.java:1499) [engine-bll.jar:] at org.ovirt.engine.core.bll.CommandBase.freeLock(CommandBase.java:1492) [engine-bll.jar:] at org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1152) [engine-bll.jar:] at org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:315) [engine-bll.jar:] at org.ovirt.engine.core.bll.MultipleActionsRunner.executeValidatedCommand(MultipleActionsRunner.java:183) [engine-bll.jar:] at org.ovirt.engine.core.bll.MultipleActionsRunner.RunCommands(MultipleActionsRunner.java:164) [engine-bll.jar:] at org.ovirt.engine.core.bll.MultipleActionsRunner$1.run(MultipleActionsRunner.java:101) [engine-bll.jar:] at org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil$InternalWrapperRunnable.run(ThreadPoolUtil.java:71) [engine-utils.jar:] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [rt.jar:1.7.0_19] at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) [rt.jar:1.7.0_19] 5. 2013-05-01 14:52:33,013 ERROR [org.ovirt.engine.core.bll.Backend] (ServerService Thread Pool -- 36) Failed to run compensation on startup for Command org.ovirt.engine.core.bll.RemoveSnapshotCommand , Command Id : 07f7d1fa-b718-4f4a-ba6c-65940c70304b 2013-05-01 14:52:33,361 ERROR [org.ovirt.engine.core.engineencryptutils.EncryptionUtils] (ServerService Thread Pool -- 36) Failed to decrypt Data must start with zero 2013-05-01 14:52:33,361 ERROR [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ServerService Thread Pool -- 36) Failed to decrypt value for property TruststorePass will be used encrypted value 2013-05-01 14:52:33,632 INFO [org.ovirt.engine.core.bll.Backend] (ServerService Thread Pool -- 36) VDSBrokerFrontend: 5/1/13 2:52 PM 2013-05-01 14:52:33,637 INFO [org.ovirt.engine.core.bll.Backend] (ServerService Thread Pool -- 36) CpuFlagsManager: 5/1/13 2:52 PM 2013-05-01 14:52:33,639 INFO [org.ovirt.engine.core.bll.AuditLogCleanupManager] (ServerService Thread Pool -- 36) Setting audit clean up manager to run at: 35 35 3 * * ? 2013-05-01 14:52:33,670 INFO [org.ovirt.engine.core.bll.Backend] (ServerService Thread Pool -- 36) AuditLogCleanupManager: 5/1/13 2:52 PM 2013-05-01 14:52:33,675 INFO [org.ovirt.engine.core.bll.TagsDirector] (ServerService Thread Pool -- 36) TagsDirector initialization 2013-05-01 14:52:33,702 INFO [org.ovirt.engine.core.bll.TagsDirector] (ServerService Thread Pool -- 36) Tag root added to tree 2013-05-01 14:52:33,716 INFO [org.ovirt.engine.core.bll.Backend] (ServerService Thread Pool -- 36) TagsDirector: 5/1/13 2:52 PM 2013-05-01 14:52:33,725 INFO [org.ovirt.engine.core.bll.Backend] (ServerService Thread Pool -- 36) IsoDomainListSyncronizer: 5/1/13 2:52 PM 2013-05-01 14:52:33,755 INFO [org.ovirt.engine.core.bll.Backend] (ServerService Thread Pool -- 36) InitHandlers: 5/1/13 2:52 PM 2013-05-01 14:52:33,768 WARN [org.ovirt.engine.core.utils.ErrorTranslatorImpl] (ServerService Thread Pool -- 36) Code MAC_ADDRESS_IS_IN_USE appears more than once in string table.