Bug 823285 - Gluster - Backend: Create volume sometimes fails with NPE [@ auditloghandling.AuditLogDirector.updateTimeoutLogableObject() ]
Gluster - Backend: Create volume sometimes fails with NPE [@ auditloghandling...
Status: CLOSED CURRENTRELEASE
Product: oVirt
Classification: Community
Component: ovirt-engine-core (Show other bugs)
unspecified
Unspecified Unspecified
unspecified Severity high
: ---
: ---
Assigned To: Shireesh
Haim
gluster
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2012-05-20 11:21 EDT by Daniel Paikov
Modified: 2014-12-29 12:31 EST (History)
10 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2012-12-17 02:49:38 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Daniel Paikov 2012-05-20 11:21:01 EDT
Create volume sometimes fails with exception. No commands reach the Gluster host.

2012-05-20 18:14:02,576 WARN  [org.ovirt.engine.core.dal.job.ExecutionMessageDirector] (ajp--0.0.0.0-8009-4) [7aca5fe6] The message key CreateGlusterVolume is missing from bundles/ExecutionMessages
2012-05-20 18:14:02,644 INFO  [org.ovirt.engine.core.bll.gluster.CreateGlusterVolumeCommand] (ajp--0.0.0.0-8009-4) [7aca5fe6] Running command: CreateGlusterVolumeCommand internal: false. Entities affected :  ID: 99408929-82cf-4dc7-a532-9d998063fa95 Type: VdsGroups
2012-05-20 18:14:02,649 INFO  [org.ovirt.engine.core.vdsbroker.gluster.CreateGlusterVolumeVDSCommand] (ajp--0.0.0.0-8009-4) [7aca5fe6] START, CreateGlusterVolumeVDSCommand(vdsId = c0513964-a27a-11e1-a47d-001a4a1697b0), log id: 767ffe45
2012-05-20 18:14:02,751 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (ajp--0.0.0.0-8009-4) [7aca5fe6] Failed in CreateGlusterVolumeVDS method
2012-05-20 18:14:02,751 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (ajp--0.0.0.0-8009-4) [7aca5fe6] Error code unexpected and error message VDSGenericException: VDSErrorException: Failed to CreateGlusterVolumeVDS, error = Unexpected exception
2012-05-20 18:14:02,751 ERROR [org.ovirt.engine.core.vdsbroker.VDSCommandBase] (ajp--0.0.0.0-8009-4) [7aca5fe6] Command CreateGlusterVolumeVDS execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to CreateGlusterVolumeVDS, error = Unexpected exception
2012-05-20 18:14:02,752 INFO  [org.ovirt.engine.core.vdsbroker.gluster.CreateGlusterVolumeVDSCommand] (ajp--0.0.0.0-8009-4) [7aca5fe6] FINISH, CreateGlusterVolumeVDSCommand, log id: 767ffe45
2012-05-20 18:14:02,752 ERROR [org.ovirt.engine.core.bll.gluster.CreateGlusterVolumeCommand] (ajp--0.0.0.0-8009-4) [7aca5fe6] Command org.ovirt.engine.core.bll.gluster.CreateGlusterVolumeCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to CreateGlusterVolumeVDS, error = Unexpected exception
2012-05-20 18:14:02,754 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogableBase] (ajp--0.0.0.0-8009-4) [7aca5fe6] Error during log command: org.ovirt.engine.core.bll.gluster.CreateGlusterVolumeCommand. Exception java.lang.NullPointerException: java.lang.NullPointerException
        at org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector.updateTimeoutLogableObject(AuditLogDirector.java:740) [engine-dal.jar:]
        at org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector.log(AuditLogDirector.java:687) [engine-dal.jar:]
        at org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector.log(AuditLogDirector.java:683) [engine-dal.jar:]
        at org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector.log(AuditLogDirector.java:679) [engine-dal.jar:]
        at org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogableBase.log(AuditLogableBase.java:439) [engine-dal.jar:]
        at org.ovirt.engine.core.bll.CommandBase.LogCommand(CommandBase.java:907) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.Execute(CommandBase.java:870) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.ExecuteAction(CommandBase.java:268) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:336) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.Backend.RunAction(Backend.java:294) [engine-bll.jar:]
        at sun.reflect.GeneratedMethodAccessor145.invoke(Unknown Source) [:1.6.0_24]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [:1.6.0_24]
        at java.lang.reflect.Method.invoke(Method.java:616) [:1.6.0_24]
        at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) [jboss-as-ee-7.1.0.Beta1b.jar:]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:]
        at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374) [jboss-invocation-1.1.1.Final.jar:]
        at org.ovirt.engine.core.utils.ThreadLocalSessionCleanerInterceptor.injectWebContextToThreadLocal(ThreadLocalSessionCleanerInterceptor.java:11) [engine-utils.jar:]
        at sun.reflect.GeneratedMethodAccessor16.invoke(Unknown Source) [:1.6.0_24]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [:1.6.0_24]
        at java.lang.reflect.Method.invoke(Method.java:616) [:1.6.0_24]
        at org.jboss.as.ee.component.ManagedReferenceLifecycleMethodInterceptorFactory$ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptorFactory.java:123) [jboss-as-ee-7.1.0.Beta1b.jar:]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:]
        at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation-1.1.1.Final.jar:]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:]
        at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee-7.1.0.Beta1b.jar:]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:]
        at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) [jboss-invocation-1.1.1.Final.jar:]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:]
        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:]
        at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) [jboss-as-ee-7.1.0.Beta1b.jar:]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:]
        at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:53) [jboss-as-ejb3-7.1.0.Beta1b.jar:]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:221) [jboss-as-ejb3-7.1.0.Beta1b.jar:]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:367) [jboss-as-ejb3-7.1.0.Beta1b.jar:]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:205) [jboss-as-ejb3-7.1.0.Beta1b.jar:]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:]
        at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3-7.1.0.Beta1b.jar:]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:]
        at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:44) [jboss-as-ee-7.1.0.Beta1b.jar:]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:]
        at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:55) [jboss-as-ejb3-7.1.0.Beta1b.jar:]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:]
        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:]
        at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165) [jboss-as-ee-7.1.0.Beta1b.jar:]
        at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:173) [jboss-as-ee-7.1.0.Beta1b.jar:]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:]
        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:]
        at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72) [jboss-as-ee-7.1.0.Beta1b.jar:]
        at org.ovirt.engine.core.common.interfaces.BackendLocal$$$view10.RunAction(Unknown Source) [engine-common.jar:]
        at org.ovirt.engine.ui.frontend.server.gwt.GenericApiGWTServiceImpl.RunAction(GenericApiGWTServiceImpl.java:120)
        at sun.reflect.GeneratedMethodAccessor144.invoke(Unknown Source) [:1.6.0_24]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [:1.6.0_24]
        at java.lang.reflect.Method.invoke(Method.java:616) [:1.6.0_24]
        at com.google.gwt.rpc.server.RPC.invokeAndStreamResponse(RPC.java:196)
        at com.google.gwt.rpc.server.RpcServlet.processCall(RpcServlet.java:161)
        at com.google.gwt.rpc.server.RpcServlet.processPost(RpcServlet.java:222)
        at com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doPost(AbstractRemoteServiceServlet.java:62)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:754) [jboss-servlet-api_3.0_spec-1.0.0.Final.jar:]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.0.Final.jar:]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329)
        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.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:151)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155)
        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:362)
        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:679) [:1.6.0_24]
Comment 1 Shireesh 2012-05-21 05:43:24 EDT
Could you please share the details entered in the "create volume" screen when this happened? Are you able to simulate this consistently? Have you observed any particular pattern / scenario when this happens?

On which machine did you check the VDSM logs? Please note that the gluster commands are executed on a random server of the cluster which is in UP status. So when you have more than one servers (hosts) in the cluster, you have to refer the engine log to find out where the command was executed. e.g.

[org.ovirt.engine.core.vdsbroker.gluster.CreateGlusterVolumeVDSCommand] (ajp--0.0.0.0-8009-4) [7aca5fe6] START, CreateGlusterVolumeVDSCommand(vdsId = c0513964-a27a-11e1-a47d-001a4a1697b0), log id: 767ffe45

In this case, the VDS command was executed (or at least attempted) on the server with id (c0513964-a27a-11e1-a47d-001a4a1697b0)

Apologies if you were already aware of these things :)
Comment 2 Daniel Paikov 2012-05-21 06:12:16 EDT
(In reply to comment #1)
> Could you please share the details entered in the "create volume" screen
> when this happened? Are you able to simulate this consistently? Have you
> observed any particular pattern / scenario when this happens?
> 
> On which machine did you check the VDSM logs? Please note that the gluster
> commands are executed on a random server of the cluster which is in UP
> status. So when you have more than one servers (hosts) in the cluster, you
> have to refer the engine log to find out where the command was executed. e.g.
> 
> [org.ovirt.engine.core.vdsbroker.gluster.CreateGlusterVolumeVDSCommand]
> (ajp--0.0.0.0-8009-4) [7aca5fe6] START, CreateGlusterVolumeVDSCommand(vdsId
> = c0513964-a27a-11e1-a47d-001a4a1697b0), log id: 767ffe45
> 
> In this case, the VDS command was executed (or at least attempted) on the
> server with id (c0513964-a27a-11e1-a47d-001a4a1697b0)
> 
> Apologies if you were already aware of these things :)

As far as I can see, this happens because the brick I'm trying to configure is already in use by a different volume. Basically we should be verifying that the host:/directory string is unique and hasn't been used before.
Comment 3 Shireesh 2012-05-21 06:58:45 EDT
 
> As far as I can see, this happens because the brick I'm trying to configure
> is already in use by a different volume. Basically we should be verifying
> that the host:/directory string is unique and hasn't been used before.

Thanks, this helps. However, if the issue is happening for this reason, it must have reached the gluster host and returned with an error from there, in contrast to the statement "No commands reach the Gluster host."

I think I've found the bug anyway, and will fix it.
Comment 4 Shireesh 2012-05-22 03:03:54 EDT
While this issue requires a fix in backend, and I'm working on it, it looks like there is an issue in gluster-vdsm side as well. I can see following in the vdsm log (/var/log/vdsm/vdsm.log), which means that the gluster-vdsm code is unable to gracefully return an error returned by the gluster CLI. Adding Bala in CC to look into this.

---------------------------------------------------------

GlusterVolumeCreateFailedException: Volume create failed
---
Error:
Brick: 192.168.2.22:/tmp/spa1-1 already in use
---

---
Return Code:
255
Thread-59955::ERROR::2012-05-22 12:26:37,762::BindingXMLRPC::897::vds::(wrapper) unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/BindingXMLRPC.py", line 882, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/gluster/gluster_api.py", line 78, in volumeCreate
    stripeCount, transport):
  File "/usr/share/vdsm/supervdsm.py", line 67, in __call__
    return callMethod()
  File "/usr/share/vdsm/supervdsm.py", line 65, in <lambda>
    **kwargs)
  File "<string>", line 2, in glusterVolumeCreate
  File "/usr/lib64/python2.7/multiprocessing/managers.py", line 759, in _callmethod
    kind, result = conn.recv()
TypeError: ('__init__() takes exactly 4 arguments (1 given)', <class 'gluster.gluster_exception.GlusterVolumeCreateFailedException'>, ())
Comment 5 Shireesh 2012-05-22 03:52:58 EDT
Have fixed the bug on backend side in the patch

http://gerrit.ovirt.org/4651

This will make sure that there is no NPE in the backend. However the error message seen on UI will not clearly indicate the reason, because of the issue on gluster-vdsm side.
Comment 6 Daniel Paikov 2012-06-10 09:05:40 EDT
Checked on 9xJun.

Note You need to log in before you can comment on or make changes to this bug.