Bug 1396835 - Ovirt-engine: sporadic Nullpointer exceptions in server.log (APIv3 related?)
Summary: Ovirt-engine: sporadic Nullpointer exceptions in server.log (APIv3 related?)
Keywords:
Status: CLOSED DUPLICATE of bug 1396833
Alias: None
Product: ovirt-engine
Classification: oVirt
Component: RestAPI
Version: 4.0.5.5
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: ---
: ---
Assignee: Juan Hernández
QA Contact: Pavel Stehlik
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-11-20 18:13 UTC by Markus Stockhausen
Modified: 2016-11-22 20:43 UTC (History)
6 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2016-11-22 20:43:01 UTC
oVirt Team: Infra
Embargoed:


Attachments (Terms of Use)

Description Markus Stockhausen 2016-11-20 18:13:39 UTC
Description of problem:

server.log shows errors.


Version-Release number of selected component (if applicable):

4.0.5.4

How reproducible:

unknown

Steps to Reproduce:

unknown

Actual results:

2016-11-20 18:57:54,053 ERROR [io.undertow.request] (default task-35) UT005023: Exception handling request to /ovirt-engine/api/v3: java.lang.RuntimeException: org.jboss.resteasy.spi.UnhandledException: java.lang.NullPointerException
        at io.undertow.servlet.spec.RequestDispatcherImpl.forwardImpl(RequestDispatcherImpl.java:245) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.spec.RequestDispatcherImpl.forwardImplSetup(RequestDispatcherImpl.java:147) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.spec.RequestDispatcherImpl.forward(RequestDispatcherImpl.java:111) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at org.ovirt.engine.api.restapi.invocation.VersionFilter.doFilter(VersionFilter.java:139) [restapi-jaxrs.jar:]
        at org.ovirt.engine.api.restapi.invocation.VersionFilter.doFilter(VersionFilter.java:68) [restapi-jaxrs.jar:]
        at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at org.ovirt.engine.api.restapi.invocation.CurrentFilter.doFilter(CurrentFilter.java:84) [restapi-jaxrs.jar:]
        at org.ovirt.engine.api.restapi.invocation.CurrentFilter.doFilter(CurrentFilter.java:63) [restapi-jaxrs.jar:]
        at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at org.ovirt.engine.core.aaa.filters.RestApiSessionMgmtFilter.doFilter(RestApiSessionMgmtFilter.java:78) [aaa.jar:]
        at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at org.ovirt.engine.core.aaa.filters.EnforceAuthFilter.doFilter(EnforceAuthFilter.java:39) [aaa.jar:]
        at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at org.ovirt.engine.core.aaa.filters.SsoRestApiNegotiationFilter.doFilter(SsoRestApiNegotiationFilter.java:91) [aaa.jar:]
        at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at org.ovirt.engine.core.aaa.filters.SsoRestApiAuthFilter.doFilter(SsoRestApiAuthFilter.java:47) [aaa.jar:]
        at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at org.ovirt.engine.core.aaa.filters.SessionValidationFilter.doFilter(SessionValidationFilter.java:59) [aaa.jar:]
        at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at org.ovirt.engine.core.aaa.filters.RestApiSessionValidationFilter.doFilter(RestApiSessionValidationFilter.java:35) [aaa.jar:]
        at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at org.ovirt.engine.api.restapi.security.CSRFProtectionFilter.doFilter(CSRFProtectionFilter.java:111) [restapi-jaxrs.jar:]
        at org.ovirt.engine.api.restapi.security.CSRFProtectionFilter.doFilter(CSRFProtectionFilter.java:102) [restapi-jaxrs.jar:]
        at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at org.ovirt.engine.api.restapi.security.CORSSupportFilter.doFilter(CORSSupportFilter.java:183) [restapi-jaxrs.jar:]
        at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.security.handlers.AuthenticationConstraintHandler.handleRequest(AuthenticationConstraintHandler.java:53) [undertow-core-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46) [undertow-core-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.security.ServletSecurityConstraintHandler.handleRequest(ServletSecurityConstraintHandler.java:59) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60) [undertow-core-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50) [undertow-core-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43) [undertow-core-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.4.0.Final.jar:1.4.0.Final]
        at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:292) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202) [undertow-core-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:805) [undertow-core-1.4.0.Final.jar:1.4.0.Final]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_111]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_111]
        at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_111]
Caused by: org.jboss.resteasy.spi.UnhandledException: java.lang.NullPointerException
        at org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:77) [resteasy-jaxrs-3.0.19.Final.jar:3.0.19.Final]
        at org.jboss.resteasy.core.ExceptionHandler.handleException(ExceptionHandler.java:220) [resteasy-jaxrs-3.0.19.Final.jar:3.0.19.Final]
        at org.jboss.resteasy.core.SynchronousDispatcher.writeException(SynchronousDispatcher.java:175) [resteasy-jaxrs-3.0.19.Final.jar:3.0.19.Final]
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:418) [resteasy-jaxrs-3.0.19.Final.jar:3.0.19.Final]
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:209) [resteasy-jaxrs-3.0.19.Final.jar:3.0.19.Final]
        at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:221) [resteasy-jaxrs-3.0.19.Final.jar:3.0.19.Final]
        at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56) [resteasy-jaxrs-3.0.19.Final.jar:3.0.19.Final]
        at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51) [resteasy-jaxrs-3.0.19.Final.jar:3.0.19.Final]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) [jboss-servlet-api_3.1_spec-1.0.0.Final.jar:1.0.0.Final]
        at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:81) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:274) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.handlers.ServletInitialHandler.dispatchToPath(ServletInitialHandler.java:209) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        at io.undertow.servlet.spec.RequestDispatcherImpl.forwardImpl(RequestDispatcherImpl.java:221) [undertow-servlet-1.4.0.Final.jar:1.4.0.Final]
        ... 73 more
Caused by: java.lang.NullPointerException

Expected results:

engine should not produce errors

Additional info:

Comment 1 Martin Perina 2016-11-22 13:56:22 UTC
Juan/Ravi any ideas how to prevent this NPE?

Comment 2 Juan Hernández 2016-11-22 16:45:18 UTC
Unfortunately that stack trace doesn't provide useful information, as it is the same for any null pointer exception.

Markus, can you provide the rest of the stack trace? The interesting part should be just after the last line that you pasted:

  Caused by: java.lang.NullPointerException
    ... <-- This is what tells us where that exception happens

Comment 3 Markus Stockhausen 2016-11-22 18:37:40 UTC
And the rest: 

        at org.ovirt.engine.api.restapi.types.VersionMapper.map(VersionMapper.java:34) [restapi-types.jar:]
        at org.ovirt.engine.api.restapi.resource.BackendApiResource.getVersion(BackendApiResource.java:337) [restapi-jaxrs.jar:]
        at org.ovirt.engine.api.restapi.resource.BackendApiResource.addSystemVersion(BackendApiResource.java:351) [restapi-jaxrs.jar:]
        at org.ovirt.engine.api.restapi.resource.BackendApiResource.get(BackendApiResource.java:290) [restapi-jaxrs.jar:]
        at org.ovirt.engine.api.v3.V3Server.adaptResponse(V3Server.java:117) [restapi-jaxrs.jar:]
        at org.ovirt.engine.api.v3.servers.V3SystemServer.get(V3SystemServer.java:71) [restapi-jaxrs.jar:]
        at sun.reflect.GeneratedMethodAccessor314.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.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:139) [resteasy-jaxrs-3.0.19.Final.jar:3.0.19.Final]
        at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:295) [resteasy-jaxrs-3.0.19.Final.jar:3.0.19.Final]
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:249) [resteasy-jaxrs-3.0.19.Final.jar:3.0.19.Final]
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:236) [resteasy-jaxrs-3.0.19.Final.jar:3.0.19.Final]
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:402) [resteasy-jaxrs-3.0.19.Final.jar:3.0.19.Final]
        ... 88 more

Comment 4 Juan Hernández 2016-11-22 19:03:47 UTC
Apparently this is failing when parsing the version of the RPM, which is stored in the database in the ProductRPMVersion and VdcVersion configuration parameters. With the normal values for those configuration parameters the code should not fail. Can you share the values that you have in your system? Run the following:

  # su - postgres
  $ psql
  postgres=# \c engine
  engine=# select option_value from vdc_options where option_name in ('ProductRPMVersion', 'VdcVersion');

The result should be something like this:

                  option_value                
  --------------------------------------------
   4.0.5.4
   4.0.0.0
  (2 rows)

If you see something different, then you probably can workaround the problem updating the database manually:

  engine=# update vdc_options set option_value = '4.0.5.4' where option_name = 'ProductRPMVersion';

  engine=# update vdc_options set option_value = '4.0.0.0' where option_name = 'VdcVersion';

Regardless, we should make the code more reliable, so that it doesn't fail even if the data in the database isn't correct.

Comment 5 Markus Stockhausen 2016-11-22 19:12:11 UTC
engine=# select option_name, option_value from vdc_options where option_name in ('ProductRPMVersion', 'VdcVersion');

    option_name    |     option_value
-------------------+----------------------
 ProductRPMVersion | 4.0.5.5-1.el7.centos
 VdcVersion        | 4.0.0.0

Comment 6 Juan Hernández 2016-11-22 19:52:46 UTC
Those values seem correct. Can you repeat the query showing all the columns of the table?

  engine=# select * from vdc_options where option_name in ('ProductRPMVersion', 'VdcVersion');

Also, it is a bit strange that you reported the error for version 4.0.5.4 but the database says 4.0.5.5. Can you double check the version that you have installed?

  # rpm -q ovirt-engine

Are there any other errors in server.log or engine.log?

Comment 7 Markus Stockhausen 2016-11-22 20:05:05 UTC
You are right, I opened the bug with the wrong version.

engine=# select * from vdc_options where option_name in ('ProductRPMVersion','VdcVersion');
 option_id |    option_name    |     option_value     | version
-----------+-------------------+----------------------+---------
       287 | ProductRPMVersion | 4.0.5.5-1.el7.centos | general
       374 | VdcVersion        | 4.0.0.0              | general

# rpm -q ovirt-engine
ovirt-engine-4.0.5.5-1.el7.centos.noarch

Comment 8 Juan Hernández 2016-11-22 20:24:53 UTC
I don't see anything wrong there.

You also opened bug 1396833 explaining that you get sporadic 500 errors when using the CLI. Those errors could correspond to these exceptions. Are those errors in the same engine than the ones in this bug?

Can you share the complete logs of that engine? In particular /var/log/ovirt-engine/server.log, /var/log/ovirt-engine/engine.log, /var/log/ovirt-engine/boot.log, /var/log/ovirt-engine/console.log and /var/log/httpd/ssl_access_log.

Comment 9 Markus Stockhausen 2016-11-22 20:42:02 UTC
sorry my infos from comment where copied wrong.

You are right this seems to be related to bug 1396833. 

Interesting in the logs is that after the "Caused by: java.lang.NullPointerException" line there art no furhter log lines for the timestamp.

Comment 10 Markus Stockhausen 2016-11-22 20:43:01 UTC

*** This bug has been marked as a duplicate of bug 1396833 ***


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