Re: [Users] [ovirt-test-day-2] Possible bug while testing vm-init-persistent feature

From: "Shahar Havivi" <shaharh(a)redhat.com&gt; To: "Vojtech Szocs" <vszocs(a)redhat.com&gt; Cc: "users" <users(a)ovirt.org&gt;, "Einav Cohen" <ecohen(a)redhat.com&gt; Sent: Wednesday, February 12, 2014 1:17:08 PM Subject: Re: [ovirt-test-day-2] Possible bug while testing vm-init-persistent feature Thanks Vojtech, There is a bug (and a fix) here: https://bugzilla.redhat.com/1063883 Shahar. On 11.02.14 18:20, Vojtech Szocs wrote: > Hello, > > I think I found a possible bug while testing Shahar's vm-init-persistent > feature, not sure if related to vm-init-persistent or Engine vs. vdsm RPC > issue. > > Followed steps in [1,2] to install ovirt-engine on F19, then used it to > setup another F19 node as host via WebAdmin GUI. > > [1] http://www.ovirt.org/OVirt_3.4_TestDay#Installation_notes > [2] http://www.ovirt.org/OVirt_3.4.0_release_notes#SECOND_BETA_RELEASE > > On engine: > # rpm -qa ovirt-engine* > ovirt-engine-setup-base-3.4.0-0.7.beta2.fc19.noarch > ovirt-engine-webadmin-portal-3.4.0-0.7.beta2.fc19.noarch > ovirt-engine-websocket-proxy-3.4.0-0.7.beta2.fc19.noarch > ovirt-engine-dbscripts-3.4.0-0.7.beta2.fc19.noarch > ovirt-engine-setup-plugin-websocket-proxy-3.4.0-0.7.beta2.fc19.noarch > ovirt-engine-setup-plugin-ovirt-engine-3.4.0-0.7.beta2.fc19.noarch > ovirt-engine-tools-3.4.0-0.7.beta2.fc19.noarch > ovirt-engine-cli-3.4.0.3-1.fc19.noarch > ovirt-engine-setup-plugin-ovirt-engine-common-3.4.0-0.7.beta2.fc19.noarch > ovirt-engine-setup-3.4.0-0.7.beta2.fc19.noarch > ovirt-engine-backend-3.4.0-0.7.beta2.fc19.noarch > ovirt-engine-3.4.0-0.7.beta2.fc19.noarch > ovirt-engine-setup-plugin-allinone-3.4.0-0.7.beta2.fc19.noarch > ovirt-engine-sdk-python-3.4.0.3-1.fc19.noarch > ovirt-engine-restapi-3.4.0-0.7.beta2.fc19.noarch > ovirt-engine-lib-3.4.0-0.7.beta2.fc19.noarch > ovirt-engine-userportal-3.4.0-0.7.beta2.fc19.noarch > > On host: > # rpm -qa vdsm* > vdsm-python-zombiereaper-4.14.2-0.fc19.noarch > vdsm-xmlrpc-4.14.2-0.fc19.noarch > vdsm-4.14.2-0.fc19.x86_64 > vdsm-cli-4.14.2-0.fc19.noarch > vdsm-python-4.14.2-0.fc19.x86_64 > > Using default 3.4 DataCenter/Cluster, created WinXP VM via WebAdmin GUI > *without* Sysprep enabled. > > Trying to Run Once with WinXP ISO attached, I get: > > Error while executing action Run VM once: Network error during > communication with the Host. > > Relevant log part attached as XmlRpcExtensionException-part.log > > Command org.ovirt.engine.core.bll.RunVmOnceCommand throw Vdc Bll > exception. With error message VdcBLLException: > org.ovirt.engine.core.vdsbroker.vdsbroker.VDSNetworkException: > org.apache.xmlrpc.common.XmlRpcExtensionException: Null values aren't > supported, if isEnabledForExtensions() == false (Failed with error > VDS_NETWORK_ERROR and code 5022) > > Second try, created WinXP VM via WebAdmin GUI *with* Sysprep enabled. > On Initial Run tab, checked "Configure Time Zone" and providing VM OS > specific timezone override, whose value is different than in System > tab's (general) "Time Zone" field. > > Trying to Run Once with Sysprep enabled & WinXP ISO attached, I get: > > Cannot run VM. VM is running. > > Relevant log part attached as VmIsRunning-part.log > > Command CreateVmVDSCommand(HostName = f19-host-34beta2, HostId = > 02a21a1a-47d6-4d90-8059-a69f0724feff, > vmId=cd3722b0-3139-4d23-8ad4-f01875e85a63, vm=VM [winxp-foo]) execution > failed. Exception: RuntimeException: java.lang.NullPointerException > .. > CanDoAction of action RunVmOnce failed. > Reasons:VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,ACTION_TYPE_FAILED_VM_IS_RUNNING > > Checking if VM is really running on host (it's not): > # vdsClient -s 0 list table > (no results) > > Full engine.log + vdsm.log attached. I can provide WebAdmin GUI link > and more details if needed. It's possible that there's something wrong > with my engine/host, but I'm clueless as how to fix above issues.. > > Thanks, > Vojtech > 2014-02-12 00:07:02,041 INFO > [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] > (ajp--127.0.0.1-8702-5) [1891c562] START, IsVmDuringInitiatingVDSCommand( > vmId = cd3722b0-3139-4d23-8ad4-f01875e85a63), log id: 536a0258 > 2014-02-12 00:07:02,042 INFO > [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] > (ajp--127.0.0.1-8702-5) [1891c562] FINISH, IsVmDuringInitiatingVDSCommand, > return: false, log id: 536a0258 > 2014-02-12 00:07:02,052 INFO [org.ovirt.engine.core.bll.RunVmOnceCommand] > (ajp--127.0.0.1-8702-5) [1891c562] Running command: RunVmOnceCommand > internal: false. Entities affected : ID: > cd3722b0-3139-4d23-8ad4-f01875e85a63 Type: VM > 2014-02-12 00:07:02,068 INFO [org.ovirt.engine.core.bll.RunVmCommand] > (ajp--127.0.0.1-8702-5) [1891c562] Running VM with attached cd > en_windows_xp_professional_with_service_pack_3_x86_cd_vl_x14-73974.iso > 2014-02-12 00:07:02,071 INFO > [org.ovirt.engine.core.vdsbroker.vdsbroker.IsoPrefixVDSCommand] > (ajp--127.0.0.1-8702-5) [1891c562] START, IsoPrefixVDSCommand(HostName = > f19-host-34beta2, HostId = 02a21a1a-47d6-4d90-8059-a69f0724feff, > storagePoolId=00000002-0002-0002-0002-000000000002), log id: 160a4058 > 2014-02-12 00:07:02,080 INFO > [org.ovirt.engine.core.vdsbroker.vdsbroker.IsoPrefixVDSCommand] > (ajp--127.0.0.1-8702-5) [1891c562] FINISH, IsoPrefixVDSCommand, return: > /rhev/data-center/mnt/10.34.63.204:_home_iso_shared/0c78b4d6-ba00-4d3e-9f9f-65c7d5899d71/images/11111111-1111-1111-1111-111111111111, > log id: 160a4058 > 2014-02-12 00:07:02,090 INFO > [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] > (ajp--127.0.0.1-8702-5) [1891c562] START, CreateVmVDSCommand(HostName = > f19-host-34beta2, HostId = 02a21a1a-47d6-4d90-8059-a69f0724feff, > vmId=cd3722b0-3139-4d23-8ad4-f01875e85a63, vm=VM [winxp-foo]), log id: > 1106802f > 2014-02-12 00:07:02,100 ERROR > [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] > (ajp--127.0.0.1-8702-5) [1891c562] Error in excuting CreateVmVDSCommand: > java.lang.NullPointerException > at > org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand.initCreateVDSCommand(CreateVmVDSCommand.java:77) > [vdsbroker.jar:] > at > org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand.executeVdsIdCommand(CreateVmVDSCommand.java:41) > [vdsbroker.jar:] > at > org.ovirt.engine.core.vdsbroker.VdsIdVDSCommandBase.executeVDSCommand(VdsIdVDSCommandBase.java:42) > [vdsbroker.jar:] > at > org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:56) > [vdsbroker.jar:] > at > org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:28) > [dal.jar:] > at > org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:399) > [vdsbroker.jar:] > at > org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.RunVdsCommand(VDSBrokerFrontendImpl.java:33) > [bll.jar:] > at > org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.RunAsyncVdsCommand(VDSBrokerFrontendImpl.java:48) > [bll.jar:] > at org.ovirt.engine.core.bll.RunVmCommand.createVm(RunVmCommand.java:447) > [bll.jar:] > at org.ovirt.engine.core.bll.RunVmCommand.runVm(RunVmCommand.java:219) > [bll.jar:] > at > org.ovirt.engine.core.bll.RunVmCommand.executeVmCommand(RunVmCommand.java:288) > [bll.jar:] > at org.ovirt.engine.core.bll.VmCommand.executeCommand(VmCommand.java:89) > [bll.jar:] > at > org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1123) > [bll.jar:] > at > org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1208) > [bll.jar:] > at > org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1884) > [bll.jar:] > at > org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInSuppressed(TransactionSupport.java:174) > [utils.jar:] > at > org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:116) > [utils.jar:] > at org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1228) > [bll.jar:] > at > org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:351) > [bll.jar:] > at org.ovirt.engine.core.bll.Backend.runAction(Backend.java:413) > [bll.jar:] > at org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:392) > [bll.jar:] > at org.ovirt.engine.core.bll.Backend.runAction(Backend.java:350) > [bll.jar:] > at sun.reflect.GeneratedMethodAccessor96.invoke(Unknown Source) > [:1.7.0_51] > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > [rt.jar:1.7.0_51] > at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_51] > at > org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) > [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] > at > org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) > [jboss-invocation.jar:1.1.1.Final] > at > org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374) > [jboss-invocation.jar:1.1.1.Final] > at > org.ovirt.engine.core.bll.interceptors.ThreadLocalSessionCleanerInterceptor.injectWebContextToThreadLocal(ThreadLocalSessionCleanerInterceptor.java:13) > [bll.jar:] > at sun.reflect.GeneratedMethodAccessor17.invoke(Unknown Source) > [:1.7.0_51] > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > [rt.jar:1.7.0_51] > at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_51] > at > org.jboss.as.ee.component.ManagedReferenceLifecycleMethodInterceptorFactory$ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptorFactory.java:123) > [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] > at > org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) > [jboss-invocation.jar:1.1.1.Final] > at > org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) > [jboss-invocation.jar:1.1.1.Final] > at > org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:36) > [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] > at > org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) > [jboss-invocation.jar:1.1.1.Final] > at > org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) > [jboss-invocation.jar:1.1.1.Final] > at > org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) > [jboss-invocation.jar:1.1.1.Final] > at > org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) > [jboss-invocation.jar:1.1.1.Final] > at > org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) > [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] > at > org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) > [jboss-invocation.jar:1.1.1.Final] > at > org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:53) > [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] > at > org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) > [jboss-invocation.jar:1.1.1.Final] > at > org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:211) > [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] > at > org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:363) > [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] > at > org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:194) > [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] > at > org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) > [jboss-invocation.jar:1.1.1.Final] > at > org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) > [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] > at > org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) > [jboss-invocation.jar:1.1.1.Final] > at > org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) > [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] > at > org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) > [jboss-invocation.jar:1.1.1.Final] > at > org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) > [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] > at > org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) > [jboss-invocation.jar:1.1.1.Final] > at > org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) > [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] > at > org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) > [jboss-invocation.jar:1.1.1.Final] > at > org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) > [jboss-invocation.jar:1.1.1.Final] > at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165) > [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] > at > org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:173) > [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] > at > org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) > [jboss-invocation.jar:1.1.1.Final] > at > org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) > [jboss-invocation.jar:1.1.1.Final] > at > org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72) > [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] > at > org.ovirt.engine.core.common.interfaces.BackendLocal$$$view9.runAction(Unknown > Source) [common.jar:] > at > org.ovirt.engine.ui.frontend.server.gwt.GenericApiGWTServiceImpl.RunAction(GenericApiGWTServiceImpl.java:131) > at sun.reflect.GeneratedMethodAccessor95.invoke(Unknown Source) > [:1.7.0_51] > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > [rt.jar:1.7.0_51] > at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_51] > at com.google.gwt.rpc.server.RPC.invokeAndStreamResponse(RPC.java:196) > at com.google.gwt.rpc.server.RpcServlet.processCall(RpcServlet.java:172) > at com.google.gwt.rpc.server.RpcServlet.processPost(RpcServlet.java:233) > at > com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doPost(AbstractRemoteServiceServlet.java:62) > at javax.servlet.http.HttpServlet.service(HttpServlet.java:754) > [jboss-servlet-3.0-api.jar:1.0.1.Final] > at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) > [jboss-servlet-3.0-api.jar:1.0.1.Final] > at > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) > at > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) > at > org.ovirt.engine.ui.frontend.server.gwt.GwtCachingFilter.doFilter(GwtCachingFilter.java:132) > at > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280) > at > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) > at > org.ovirt.engine.core.branding.BrandingFilter.doFilter(BrandingFilter.java:72) > at > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280) > at > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) > at > org.ovirt.engine.core.utils.servlet.LocaleFilter.doFilter(LocaleFilter.java:64) > [utils.jar:] > at > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280) > at > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) > at > org.ovirt.engine.core.bll.AutomaticLoginFilter.doFilter(AutomaticLoginFilter.java:58) > [bll.jar:] > at > org.ovirt.engine.core.bll.AutomaticLoginFilter.doFilter(AutomaticLoginFilter.java:49) > [bll.jar:] > at > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280) > at > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) > at > org.ovirt.engine.core.authentication.AuthenticationFilter.doFilter(AuthenticationFilter.java:80) > [common.jar:] > at > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280) > at > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) > at > org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) > at > org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) > at > org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:489) > at > org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:153) > at > org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) > at > org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) > at org.jboss.web.rewrite.RewriteValve.invoke(RewriteValve.java:466) > at > org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) > at > org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) > at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:505) > at > org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:445) > at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:930) > at java.lang.Thread.run(Thread.java:744) [rt.jar:1.7.0_51] > > 2014-02-12 00:07:02,126 ERROR > [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] > (ajp--127.0.0.1-8702-5) [1891c562] Command CreateVmVDSCommand(HostName = > f19-host-34beta2, HostId = 02a21a1a-47d6-4d90-8059-a69f0724feff, > vmId=cd3722b0-3139-4d23-8ad4-f01875e85a63, vm=VM [winxp-foo]) execution > failed. Exception: RuntimeException: java.lang.NullPointerException > 2014-02-12 00:07:02,127 INFO > [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] > (ajp--127.0.0.1-8702-5) [1891c562] FINISH, CreateVmVDSCommand, log id: > 1106802f > 2014-02-12 00:07:02,128 WARN [org.ovirt.engine.core.bll.RunVmCommand] > (ajp--127.0.0.1-8702-5) [1891c562] Failed to run VM winxp-foo: > VdcBLLException: java.lang.RuntimeException: > java.lang.NullPointerException (Failed with error ENGINE and code 5001) > 2014-02-12 00:07:02,128 INFO [org.ovirt.engine.core.bll.RunVmCommand] > (ajp--127.0.0.1-8702-5) [1891c562] Trying to rerun VM winxp-foo > 2014-02-12 00:07:02,133 INFO > [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] > (ajp--127.0.0.1-8702-5) [1891c562] Correlation ID: 1891c562, Job ID: > cc077985-9602-4357-b7b3-4d6c6984b10f, Call Stack: null, Custom Event ID: > -1, Message: Failed to run VM winxp-foo on Host f19-host-34beta2. > 2014-02-12 00:07:02,142 INFO > [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] > (ajp--127.0.0.1-8702-5) [1891c562] START, IsVmDuringInitiatingVDSCommand( > vmId = cd3722b0-3139-4d23-8ad4-f01875e85a63), log id: 1abacf15 > 2014-02-12 00:07:02,143 INFO > [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] > (ajp--127.0.0.1-8702-5) [1891c562] FINISH, IsVmDuringInitiatingVDSCommand, > return: true, log id: 1abacf15 > 2014-02-12 00:07:02,143 WARN [org.ovirt.engine.core.bll.RunVmOnceCommand] > (ajp--127.0.0.1-8702-5) [1891c562] CanDoAction of action RunVmOnce failed. > Reasons:VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,ACTION_TYPE_FAILED_VM_IS_RUNNING > 2014-02-12 00:07:02,147 INFO > [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] > (ajp--127.0.0.1-8702-5) [1891c562] Correlation ID: 1891c562, Job ID: > cc077985-9602-4357-b7b3-4d6c6984b10f, Call Stack: null, Custom Event ID: > -1, Message: Failed to run VM winxp-foo (User: admin). > 2014-02-11 23:58:51,583 INFO > [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] > (ajp--127.0.0.1-8702-8) [d65a9c3] START, IsVmDuringInitiatingVDSCommand( > vmId = 8cbc01e2-5e4e-4eec-8d07-880e51167e5e), log id: 447c45c5 > 2014-02-11 23:58:51,590 INFO > [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] > (ajp--127.0.0.1-8702-8) [d65a9c3] FINISH, IsVmDuringInitiatingVDSCommand, > return: false, log id: 447c45c5 > 2014-02-11 23:58:51,607 INFO [org.ovirt.engine.core.bll.RunVmOnceCommand] > (ajp--127.0.0.1-8702-8) [d65a9c3] Running command: RunVmOnceCommand > internal: false. Entities affected : ID: > 8cbc01e2-5e4e-4eec-8d07-880e51167e5e Type: VM > 2014-02-11 23:58:51,621 INFO [org.ovirt.engine.core.bll.RunVmCommand] > (ajp--127.0.0.1-8702-8) [d65a9c3] Running VM with attached cd > en_windows_xp_professional_with_service_pack_3_x86_cd_vl_x14-73974.iso > 2014-02-11 23:58:51,628 INFO > [org.ovirt.engine.core.vdsbroker.vdsbroker.IsoPrefixVDSCommand] > (ajp--127.0.0.1-8702-8) [d65a9c3] START, IsoPrefixVDSCommand(HostName = > f19-host-34beta2, HostId = 02a21a1a-47d6-4d90-8059-a69f0724feff, > storagePoolId=00000002-0002-0002-0002-000000000002), log id: 23fb386d > 2014-02-11 23:58:51,637 INFO > [org.ovirt.engine.core.vdsbroker.vdsbroker.IsoPrefixVDSCommand] > (ajp--127.0.0.1-8702-8) [d65a9c3] FINISH, IsoPrefixVDSCommand, return: > /rhev/data-center/mnt/10.34.63.204:_home_iso_shared/0c78b4d6-ba00-4d3e-9f9f-65c7d5899d71/images/11111111-1111-1111-1111-111111111111, > log id: 23fb386d > 2014-02-11 23:58:51,647 INFO > [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] > (ajp--127.0.0.1-8702-8) [d65a9c3] START, CreateVmVDSCommand(HostName = > f19-host-34beta2, HostId = 02a21a1a-47d6-4d90-8059-a69f0724feff, > vmId=8cbc01e2-5e4e-4eec-8d07-880e51167e5e, vm=VM [winxp-foo]), log id: > 556e181c > 2014-02-11 23:58:51,658 INFO > [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] > (ajp--127.0.0.1-8702-8) [d65a9c3] START, CreateVDSCommand(HostName = > f19-host-34beta2, HostId = 02a21a1a-47d6-4d90-8059-a69f0724feff, > vmId=8cbc01e2-5e4e-4eec-8d07-880e51167e5e, vm=VM [winxp-foo]), log id: > 26da2a9f > 2014-02-11 23:58:51,673 ERROR > [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] > (ajp--127.0.0.1-8702-8) [d65a9c3] Command CreateVDSCommand(HostName = > f19-host-34beta2, HostId = 02a21a1a-47d6-4d90-8059-a69f0724feff, > vmId=8cbc01e2-5e4e-4eec-8d07-880e51167e5e, vm=VM [winxp-foo]) execution > failed. Exception: VDSNetworkException: > org.apache.xmlrpc.common.XmlRpcExtensionException: Null values aren't > supported, if isEnabledForExtensions() == false > 2014-02-11 23:58:51,685 INFO > [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] > (ajp--127.0.0.1-8702-8) [d65a9c3] FINISH, CreateVDSCommand, log id: > 26da2a9f > 2014-02-11 23:58:51,689 ERROR > [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] > (ajp--127.0.0.1-8702-8) [d65a9c3] VDS::create Failed creating vm winxp-foo > in vds = 02a21a1a-47d6-4d90-8059-a69f0724feff : f19-host-34beta2 error = > org.ovirt.engine.core.vdsbroker.vdsbroker.VDSNetworkException: > org.apache.xmlrpc.common.XmlRpcExtensionException: Null values aren't > supported, if isEnabledForExtensions() == false > 2014-02-11 23:58:51,697 INFO > [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] > (ajp--127.0.0.1-8702-8) [d65a9c3] FINISH, CreateVmVDSCommand, return: > Down, log id: 556e181c > 2014-02-11 23:58:51,701 ERROR [org.ovirt.engine.core.bll.RunVmOnceCommand] > (ajp--127.0.0.1-8702-8) [d65a9c3] Command > org.ovirt.engine.core.bll.RunVmOnceCommand throw Vdc Bll exception. With > error message VdcBLLException: > org.ovirt.engine.core.vdsbroker.vdsbroker.VDSNetworkException: > org.apache.xmlrpc.common.XmlRpcExtensionException: Null values aren't > supported, if isEnabledForExtensions() == false (Failed with error > VDS_NETWORK_ERROR and code 5022) > 2014-02-11 23:58:51,716 INFO > [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] > (ajp--127.0.0.1-8702-8) [d65a9c3] Correlation ID: d65a9c3, Job ID: > d83c76cd-9d55-459c-93a6-96087caa1951, Call Stack: null, Custom Event ID: > -1, Message: Failed to run VM winxp-foo (User: admin).