The above log entry is a result of the engine closing connection dueOn Tue, Jan 24, 2017 at 9:38 AM, Fred Rolland <frolland@redhat.com> wrote:
> Hi,
>
> I see some issues in the communication between host0 and the the engine.
> Vdsm returned the answer to call getSpmStatus and then got an SSL error. [1]
>
> After that, the engine tried to send to the same host0 connectStorageServer
> requests that failed.
> The process of attaching the storage domain failed because the host was not
> connected to the NFS server.
> I think the engine should not have tried to attach the storage domain if
> connectStorageServer request failed.
> Can you open a bug on this ?
>
> Regardless, the SSL error and communication issue should be investigated
> further by infra team.
>
> Regards,
>
> Fred
>
> [1]
> jsonrpc.Executor/5::DEBUG::2017-01-19
> 12:13:48,711::__init__::555::jsonrpc.JsonRpcServer::(_ handle_request) Return
> 'StoragePool.getSpmStatus' in bridge with {'spmId': 1, 'spmStatus': 'SPM',
> 'spmLver': 2L}
> jsonrpc.Executor/5::INFO::2017-01-19
> 12:13:48,711::__init__::513::jsonrpc.JsonRpcServer::(_ serveRequest) RPC call
> StoragePool.getSpmStatus succeeded in 0.00 seconds
> JsonRpc (StompReactor)::ERROR::2017-01-19
> 12:13:49,449::betterAsyncore::113::vds.dispatcher::(recv) SSL error during
> reading data: unexpected eof
to higher level
timeout occurring
>
> [2]
> 2017-01-19 12:13:49,455 ERROR
> [org.ovirt.engine.core.vdsbroker.vdsbroker. Above log entry tells us that a command timeout. In order toConnectStorageServerVDSCommand ]
> (org.ovirt.thread.pool-6-thread-5) [4a2c0e44] Command
> 'ConnectStorageServerVDSCommand (HostName = lago-basic-suite-4-0-host0,
> StorageServerConnectionManagementVDSParameters:{runAsync=' true',
> hostId='4c4d9ad9-32a1-406a-93da-1710e069c690',
> storagePoolId='00000000-0000-0000-0000-000000000000', storageType='NFS',
> connectionList='[StorageServerConnections:{id=' da9131c8-1cd9-46bb-b7ea- f83228e04d3f',
> connection='192.168.201.4:/exports/nfs/iso', iqn='null', vfsType='null',
> mountOptions='null', nfsVersion='V3', nfsRetrans='null', nfsTimeo='null',
> iface='null', netIfaceName='null'}]'})' execution failed:
> VDSGenericException: VDSNetworkException: Message timeout which can be
> caused by communication issues
>
understand what happened
I would check this command why it did not get a response. Usually it
is send 300 secs
prior above message.
It is desired approach when we see higher timeout to close the
connection and attempt to
reconnect.
>
>
> On Mon, Jan 23, 2017 at 4:35 PM, Shlomo Ben David <sbendavi@redhat.com>
> wrote:
>>
>> Hi,
>>
>> Job [1] failed with the following errors (logs [2]):
>>
>> {"jsonrpc": "2.0", "id": "669e1306-3206-4a64-a33f-d18176531ff8", "error":
>> {"message": "Storage domain does not exist:
>> (u'ab6c9588-d957-4be3-9862-d2596db463d9',)", "code": 358}}�
>> 2017-01-19 12:13:51,619 DEBUG
>> [org.ovirt.vdsm.jsonrpc.client.internal. ResponseWorker] (ResponseWorker)
>> [3a116b94] Message received: {"jsonrpc": "2.0", "id":
>> "669e1306-3206-4a64-a33f-d18176531ff8", "error": {"message": "Storage domain
>> does not exist: (u'ab6c9588-d957-4be3-9862-d2596db463d9',)", "code": 358}}
>> 2017-01-19 12:13:51,620 ERROR
>> [org.ovirt.engine.core.vdsbroker.irsbroker. AttachStorageDomainVDSCommand]
>> (default task-27) [6a6480a4] Failed in 'AttachStorageDomainVDS' method
>> 2017-01-19 12:13:51,624 ERROR
>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling. AuditLogDirector]
>> (default task-27) [6a6480a4] Correlation ID: null, Call Stack: null, Custom
>> Event ID: -1, Message: VDSM command failed: Storage domain does not exist:
>> (u'ab6c9588-d957-4be3-9862-d2596db463d9',)
>> 2017-01-19 12:13:51,624 ERROR
>> [org.ovirt.engine.core.vdsbroker.irsbroker. AttachStorageDomainVDSCommand]
>> (default task-27) [6a6480a4] Command 'AttachStorageDomainVDSCommand(
>> AttachStorageDomainVDSCommandParameters:{runAsync='true',
>> storagePoolId='fc33da6d-5da7-4005-a693-f170437c176c',
>> ignoreFailoverLimit='false',
>> storageDomainId='ab6c9588-d957-4be3-9862-d2596db463d9'}) ' execution failed:
>> IRSGenericException: IRSErrorException: Failed to AttachStorageDomainVDS,
>> error = Storage domain does not exist:
>> (u'ab6c9588-d957-4be3-9862-d2596db463d9',), code = 358
>> 2017-01-19 12:13:51,632 DEBUG
>> [org.ovirt.engine.core.utils.timer.FixedDelayJobListener]
>> (DefaultQuartzScheduler10) [] Rescheduling
>> DEFAULT.org.ovirt.engine.core.vdsbroker.irsbroker. IrsProxyData. hostsStorageConnectionsAndPool MetadataRefresh#- 9223372036854775793
>> as there is no unfired trigger.
>> 2017-01-19 12:13:51,624 DEBUG
>> [org.ovirt.engine.core.vdsbroker.irsbroker. AttachStorageDomainVDSCommand]
>> (default task-27) [6a6480a4] Exception:
>> org.ovirt.engine.core.vdsbroker.irsbroker. IrsOperationFailedNoFailoverEx ception:
>> IRSGenericException: IRSErrorException: Failed to AttachStorageDomainVDS,
>> error = Storage domain does not exist:
>> (u'ab6c9588-d957-4be3-9862-d2596db463d9',), code = 358
>> at
>> org.ovirt.engine.core.vdsbroker.irsbroker. AttachStorageDomainVDSCommand. createDefaultConcreteException ( AttachStorageDomainVDSCommand. java:25)
>> [vdsbroker.jar:]
>> at
>> org.ovirt.engine.core.vdsbroker.vdsbroker. BrokerCommandBase. createException( BrokerCommandBase.java:222)
>> [vdsbroker.jar:]
>> at
>> org.ovirt.engine.core.vdsbroker.vdsbroker. BrokerCommandBase. proceedProxyReturnValue( BrokerCommandBase.java:192)
>> [vdsbroker.jar:]
>> at
>> org.ovirt.engine.core.vdsbroker.irsbroker. AttachStorageDomainVDSCommand. executeIrsBrokerCommand( AttachStorageDomainVDSCommand. java:18)
>> [vdsbroker.jar:]
>> at
>> org.ovirt.engine.core.vdsbroker.irsbroker. IrsBrokerCommand.lambda$ executeVDSCommand$0( IrsBrokerCommand.java:161)
>> [vdsbroker.jar:]
>> at
>> org.ovirt.engine.core.vdsbroker.irsbroker. IrsProxyData. runInControlledConcurrency( IrsProxyData.java:248)
>> [vdsbroker.jar:]
>> at
>> org.ovirt.engine.core.vdsbroker.irsbroker. IrsBrokerCommand. executeVDSCommand( IrsBrokerCommand.java:158)
>> [vdsbroker.jar:]
>> at
>> org.ovirt.engine.core.vdsbroker.VDSCommandBase. executeCommand(VDSCommandBase. java:73)
>> [vdsbroker.jar:]
>> at
>> org.ovirt.engine.core.dal.VdcCommandBase.execute( VdcCommandBase.java:33)
>> [dal.jar:]
>> at
>> org.ovirt.engine.core.vdsbroker.ResourceManager. runVdsCommand(ResourceManager. java:451)
>> [vdsbroker.jar:]
>> at
>> org.ovirt.engine.core.bll.VDSBrokerFrontendImpl. runVdsCommand( VDSBrokerFrontendImpl.java:33)
>> [bll.jar:]
>> at
>> org.ovirt.engine.core.bll.CommandBase.runVdsCommand( CommandBase.java:2171)
>> [bll.jar:]
>> at
>> org.ovirt.engine.core.bll.storage. StorageHandlingCommandBase. runVdsCommand( StorageHandlingCommandBase. java:657)
>> [bll.jar:]
>> at
>> org.ovirt.engine.core.bll.storage.domain. AttachStorageDomainToPoolComma nd.executeCommand( AttachStorageDomainToPoolComma nd.java:152)
>> [bll.jar:]
>> at
>> org.ovirt.engine.core.bll.CommandBase. executeWithoutTransaction( CommandBase.java:1305)
>> [bll.jar:]
>> at
>> org.ovirt.engine.core.bll.CommandBase. executeActionInTransactionScop e(CommandBase.java:1447)
>> [bll.jar:]
>> at
>> org.ovirt.engine.core.bll.CommandBase.runInTransaction( CommandBase.java:2075)
>> [bll.jar:]
>> at
>> org.ovirt.engine.core.utils.transaction. TransactionSupport. executeInSuppressed( TransactionSupport.java:166)
>> [utils.jar:]
>> at
>> org.ovirt.engine.core.utils.transaction. TransactionSupport. executeInScope( TransactionSupport.java:105)
>> [utils.jar:]
>> at org.ovirt.engine.core.bll.CommandBase.execute( CommandBase.java:1490)
>> [bll.jar:]
>> at
>> org.ovirt.engine.core.bll.CommandBase.executeAction( CommandBase.java:398)
>> [bll.jar:]
>> at org.ovirt.engine.core.bll.Backend.runAction(Backend. java:493)
>> [bll.jar:]
>> at org.ovirt.engine.core.bll.Backend.runActionImpl(Backend. java:475)
>> [bll.jar:]
>> at org.ovirt.engine.core.bll.Backend.runAction(Backend. java:428)
>> [bll.jar:]
>> at sun.reflect.GeneratedMethodAccessor217. invoke(Unknown Source)
>> [:1.8.0_111]
>> at
>> sun.reflect.DelegatingMethodAccessorImpl. invoke( DelegatingMethodAccessorImpl. java:43)
>> [rt.jar:1.8.0_111]
>> at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_111]
>> at
>> org.jboss.as.ee.component.ManagedReferenceMethodIntercep tor.processInvocation( ManagedReferenceMethodIntercep tor.java:52)
>> at
>> org.jboss.invocation.InterceptorContext.proceed( InterceptorContext.java:340)
>> at
>> org.jboss.invocation.InterceptorContext$Invocation. proceed(InterceptorContext. java:437)
>> at
>> org.jboss.as.weld.ejb.Jsr299BindingsInterceptor. delegateInterception( Jsr299BindingsInterceptor. java:70)
>> [wildfly-weld-10.1.0.Final.jar:10.1.0.Final]
>> at
>> org.jboss.as.weld.ejb.Jsr299BindingsInterceptor. doMethodInterception( Jsr299BindingsInterceptor. java:80)
>> [wildfly-weld-10.1.0.Final.jar:10.1.0.Final]
>> at
>> org.jboss.as.weld.ejb.Jsr299BindingsInterceptor. processInvocation( Jsr299BindingsInterceptor. java:93)
>> [wildfly-weld-10.1.0.Final.jar:10.1.0.Final]
>> at
>> org.jboss.as.ee.component.interceptors. UserInterceptorFactory$1. processInvocation( UserInterceptorFactory.java: 63)
>> at
>> org.jboss.invocation.InterceptorContext.proceed( InterceptorContext.java:340)
>> at
>> org.jboss.invocation.InterceptorContext$Invocation. proceed(InterceptorContext. java:437)
>> at
>> org.ovirt.engine.core.bll.interceptors. CorrelationIdTrackerIntercepto r.aroundInvoke( CorrelationIdTrackerIntercepto r.java:13)
>> [bll.jar:]
>> at sun.reflect.GeneratedMethodAccessor63. invoke(Unknown Source)
>> [:1.8.0_111]
>> at
>> sun.reflect.DelegatingMethodAccessorImpl. invoke( DelegatingMethodAccessorImpl. java:43)
>> [rt.jar:1.8.0_111]
>> at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_111]
>> at
>> org.jboss.as.ee.component.ManagedReferenceLifecycleMetho dInterceptor. processInvocation( ManagedReferenceLifecycleMetho dInterceptor.java:89)
>> at
>> org.jboss.invocation.InterceptorContext.proceed( InterceptorContext.java:340)
>> at
>> org.jboss.as.ejb3.component.invocationmetrics. ExecutionTimeInterceptor. processInvocation( ExecutionTimeInterceptor.java: 43)
>> [wildfly-ejb3-10.1.0.Final.jar:10.1.0.Final]
>> at
>> org.jboss.invocation.InterceptorContext.proceed( InterceptorContext.java:340)
>> at
>> org.jboss.invocation.InterceptorContext$Invocation. proceed(InterceptorContext. java:437)
>> at
>> org.jboss.weld.ejb.AbstractEJBRequestScopeActivat ionInterceptor.aroundInvoke( AbstractEJBRequestScopeActivat ionInterceptor.java:73)
>> [weld-core-impl-2.3.5.Final.jar:2.3.5.Final]
>> at
>> org.jboss.as.weld.ejb.EjbRequestScopeActivationInter ceptor.processInvocation( EjbRequestScopeActivationInter ceptor.java:83)
>> [wildfly-weld-10.1.0.Final.jar:10.1.0.Final]
>> at
>> org.jboss.invocation.InterceptorContext.proceed( InterceptorContext.java:340)
>> at
>> org.jboss.as.ee.concurrent.ConcurrentContextInterceptor. processInvocation( ConcurrentContextInterceptor. java:45)
>> [wildfly-ee-10.1.0.Final.jar:10.1.0.Final]
>> at
>> org.jboss.invocation.InterceptorContext.proceed( InterceptorContext.java:340)
>> at
>> org.jboss.invocation.InitialInterceptor. processInvocation( InitialInterceptor.java:21)
>> at
>> org.jboss.invocation.InterceptorContext.proceed( InterceptorContext.java:340)
>> at
>> org.jboss.invocation.ChainedInterceptor. processInvocation( ChainedInterceptor.java:61)
>> at
>> org.jboss.as.ee.component.interceptors. ComponentDispatcherInterceptor .processInvocation( ComponentDispatcherInterceptor .java:52)
>> at
>> org.jboss.invocation.InterceptorContext.proceed( InterceptorContext.java:340)
>> at
>> org.jboss.as.ejb3.component.singleton. SingletonComponentInstanceAsso ciationInterceptor. processInvocation( SingletonComponentInstanceAsso ciationInterceptor.java:53)
>> [wildfly-ejb3-10.1.0.Final.jar:10.1.0.Final]
>> at
>> org.jboss.invocation.InterceptorContext.proceed( InterceptorContext.java:340)
>> at
>> org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx( CMTTxInterceptor.java:263)
>> [wildfly-ejb3-10.1.0.Final.jar:10.1.0.Final]
>> at
>> org.jboss.as.ejb3.tx.CMTTxInterceptor.supports( CMTTxInterceptor.java:374)
>> [wildfly-ejb3-10.1.0.Final.jar:10.1.0.Final]
>> at
>> org.jboss.as.ejb3.tx.CMTTxInterceptor. processInvocation( CMTTxInterceptor.java:243)
>> [wildfly-ejb3-10.1.0.Final.jar:10.1.0.Final]
>> at
>> org.jboss.invocation.InterceptorContext.proceed( InterceptorContext.java:340)
>> at
>> org.jboss.as.ejb3.component.interceptors. CurrentInvocationContextInterc eptor.processInvocation( CurrentInvocationContextInterc eptor.java:41)
>> [wildfly-ejb3-10.1.0.Final.jar:10.1.0.Final]
>> at
>> org.jboss.invocation.InterceptorContext.proceed( InterceptorContext.java:340)
>> at
>> org.jboss.as.ejb3.component.invocationmetrics. WaitTimeInterceptor. processInvocation( WaitTimeInterceptor.java:47)