Created attachment 1199187 [details] engine and server logs Description of problem: GET to ovirt-engine/api/events return Operation Failed Version-Release number of selected component (if applicable): rhevm-4.0.4.2-0.1.el7ev.noarch Steps to Reproduce: 1. GET ovirt-engine/api/events Additional info: Engine log: 2016-09-08 21:48:39,390 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-12) [] Operation Failed: 2016-09-08 21:48:39,390 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-12) [] Exception: org.ovirt.engine.api.restapi.resource.BaseBackendResource$Backen dFailureException: at org.ovirt.engine.api.restapi.resource.BackendResource.backendFailure(BackendResource.java:433) [restapi-jaxrs.jar:] at org.ovirt.engine.api.restapi.resource.BackendResource.getBackendCollection(BackendResource.java:155) [restapi-jaxrs.jar:] at org.ovirt.engine.api.restapi.resource.AbstractBackendCollectionResource.getBackendCollection(AbstractBackendCollectionResource.java:43) [restapi-jaxrs.jar:] at org.ovirt.engine.api.restapi.resource.AbstractBackendCollectionResource.getBackendCollection(AbstractBackendCollectionResource.java:39) [restapi-jaxrs.jar:] at org.ovirt.engine.api.restapi.resource.BackendEventsResource.getBackendCollection(BackendEventsResource.java:57) [restapi-jaxrs.jar:] at org.ovirt.engine.api.restapi.resource.BackendEventsResource.list(BackendEventsResource.java:32) [restapi-jaxrs.jar:] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.8.0_102] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) [rt.jar:1.8.0_102] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_102] at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_102] at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:139) [resteasy-jaxrs.jar:3.0.18.Final-redhat-1] at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:295) [resteasy-jaxrs.jar:3.0.18.Final-redhat-1] at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:249) [resteasy-jaxrs.jar:3.0.18.Final-redhat-1] at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:138) [resteasy-jaxrs.jar:3.0.18.Final-redhat-1] at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:101) [resteasy-jaxrs.jar:3.0.18.Final-redhat-1] at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:402) [resteasy-jaxrs.jar:3.0.18.Final-redhat-1] at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:209) [resteasy-jaxrs.jar:3.0.18.Final-redhat-1] at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:221) [resteasy-jaxrs.jar:3.0.18.Final-redhat-1] at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56) [resteasy-jaxrs.jar:3.0.18.Final-redhat-1] at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51) [resteasy-jaxrs.jar:3.0.18.Final-redhat-1] at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) [jboss-servlet-api_3.1_spec.jar:1.0.0.Final-redhat-1] at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85) [undertow-servlet.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:81) [undertow-servlet.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62) [undertow-servlet.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36) [undertow-servlet.jar:1.3.24.Final-redhat-1] at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core.jar:1.3.24.Final-redhat-1] at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core.jar:1.3.24.Final-redhat-1] at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:266) [undertow-servlet.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.handlers.ServletInitialHandler.dispatchToPath(ServletInitialHandler.java:201) [undertow-servlet.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.spec.RequestDispatcherImpl.forwardImpl(RequestDispatcherImpl.java:202) [undertow-servlet.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.spec.RequestDispatcherImpl.forward(RequestDispatcherImpl.java:109) [undertow-servlet.jar:1.3.24.Final-redhat-1] 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.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) [undertow-servlet.jar:1.3.24.Final-redhat-1] at org.ovirt.engine.api.restapi.invocation.CurrentFilter.doFilter(CurrentFilter.java:84) [restapi-jaxrs.jar:] Server log: 2016-09-08 21:31:34,675 ERROR [io.undertow.servlet] (default task-20) Exception while dispatching incoming RPC call: com.google.gwt.user.client.rpc.SerializationException: Can't find the ser ialization policy file. This probably means that the user has an old version of the application loaded in the browser. To solve the issue the user needs to close the browser and open it agai n, so that the application is reloaded. at org.ovirt.engine.ui.frontend.server.gwt.GenericApiGWTServiceImpl.doUnexpectedFailure(GenericApiGWTServiceImpl.java:176) [frontend.jar:] at com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doPost(AbstractRemoteServiceServlet.java:67) [gwt-servlet.jar:] at javax.servlet.http.HttpServlet.service(HttpServlet.java:707) [jboss-servlet-api_3.1_spec.jar:1.0.0.Final-redhat-1] at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) [jboss-servlet-api_3.1_spec.jar:1.0.0.Final-redhat-1] at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85) [undertow-servlet.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129) [undertow-servlet.jar:1.3.24.Final-redhat-1] at org.ovirt.engine.core.utils.servlet.HeaderFilter.doFilter(HeaderFilter.java:94) [utils.jar:] at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) [undertow-servlet.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) [undertow-servlet.jar:1.3.24.Final-redhat-1] at org.ovirt.engine.ui.frontend.server.gwt.GwtCachingFilter.doFilter(GwtCachingFilter.java:132) [frontend.jar:] at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) [undertow-servlet.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) [undertow-servlet.jar:1.3.24.Final-redhat-1] at org.ovirt.engine.core.branding.BrandingFilter.doFilter(BrandingFilter.java:73) [branding.jar:] at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) [undertow-servlet.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) [undertow-servlet.jar:1.3.24.Final-redhat-1] at org.ovirt.engine.core.utils.servlet.LocaleFilter.doFilter(LocaleFilter.java:66) [utils.jar:] at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) [undertow-servlet.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) [undertow-servlet.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84) [undertow-servlet.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62) [undertow-servlet.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36) [undertow-servlet.jar:1.3.24.Final-redhat-1] at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131) [undertow-servlet.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57) [undertow-servlet.jar:1.3.24.Final-redhat-1] at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) [undertow-core.jar:1.3.24.Final-redhat-1] at io.undertow.security.handlers.AuthenticationConstraintHandler.handleRequest(AuthenticationConstraintHandler.java:51) [undertow-core.jar:1.3.24.Final-redhat-1] at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46) [undertow-core.jar:1.3.24.Final-redhat-1] at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64) [undertow-servlet.jar:1.3.24.Final-redhat-1]
I think that the relevant error messages from engine.log are the following: 2016-09-08 21:47:34,066 ERROR [org.ovirt.engine.core.bll.SearchQuery] (default task-32) [] Exception: java.lang.NullPointerException at org.ovirt.engine.core.common.businessentities.AuditLog.setLogType(AuditLog.java:323) [common.jar:] at org.ovirt.engine.core.dao.AuditLogDaoImpl$AuditLogRowMapper.mapRow(AuditLogDaoImpl.java:285) [dal.jar:] That means that when loading the events from the database there are certain events that have a code that doesn't correspond to any value of the values of the AuditLog enum. I see that a patch has recently been merged that added new audit log types: engine: add finish report on multi-host network commands https://gerrit.ovirt.org/#/q/I93eeccdd6695ddabbcfe26517fc372134ddc0e6a The patch has also been recently reverted: Revert "engine: add finish report on multi-host network commands" https://gerrit.ovirt.org/63286 While this was merged the engine may have generated events with the new ids, which will then cease to exist when the engine is updated to the version where the patch was reverted. The result will be this failure. I think this can be solved changing the type of the offending events: update audit_log set log_type = 0 where log_type in (10905, 10906, 10907, 10908, 10909) This should probably be part of an upgrade script. I would also suggest, for the future, to make the audit log DAO more resilient, so that it doesn't fail in this cases: diff --git a/backend/manager/modules/common/src/main/java/org/ovirt/engine/core/common/AuditLogType.java b/backend/manager/modules/common/src/main/java/org/ovirt/engine/core/common/AuditLogType.java index 2b1a08c..4a336c0 100644 --- a/backend/manager/modules/common/src/main/java/org/ovirt/engine/core/common/AuditLogType.java +++ b/backend/manager/modules/common/src/main/java/org/ovirt/engine/core/common/AuditLogType.java @@ -3,6 +3,9 @@ package org.ovirt.engine.core.common; import java.util.HashMap; import java.util.Map; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + public enum AuditLogType { UNASSIGNED(0), // -- VDC Log types -- @@ -1334,6 +1337,9 @@ public enum AuditLogType { SYSTEM_CHANGE_STORAGE_POOL_STATUS_UP_REPORTING_HOSTS(10810, AuditLogSeverity.NORMAL), SYSTEM_CHANGE_STORAGE_POOL_STATUS_NON_RESPONSIVE_NO_REPORTING_HOSTS(10811, AuditLogSeverity.ALERT); + // The logger used by this class: + private static final Logger log = LoggerFactory.getLogger(AuditLogType.class); + private int intValue; // indicates time interval in seconds on which identical events from same instance are suppressed. private int eventFloodRate; @@ -1385,7 +1391,16 @@ public enum AuditLogType { } public static AuditLogType forValue(int value) { - return mappings.get(value); + AuditLogType type = mappings.get(value); + if (type == null) { + log.error( + "Can't find an audit log type for value '" + value + "'. That probably means that the audit log type " + + "has been removed from the system but there are still audit log messages in the database that use " + + "it. Will use the '" + UNASSIGNED.name() + "' type." + ); + type = AuditLogType.UNASSIGNED; + } + return type; } }
Martin, can you please take a look and confirm/reject my hypothesis?
After deleting the removed events for DB I can GET /api/events delete from audit_log where log_type in (10905, 10906, 10907, 10908, 10909);
This will work to: update audit_log set log_type=0 where log_type in (10905, 10906, 10907, 10908, 10909);
(In reply to Juan Hernández from comment #2) > Martin, can you please take a look and confirm/reject my hypothesis? Your hypothesis is correct, that's why we use to deprecate (with @Deprecated) entries in the AuditLogType enum, and to remove them completely when an upgrade script removes those entries from the db as well. Since this is done as part of reverting network patch, I'm setting the 'network' key on the whiteboard - for them to provide an upgrade script to delete those entries for which the audit-log-id is no longer exists.
No production users d/s or u/s should have the faulty audit logs in their DB, so there's no urgency in pushing this into 4.0.4.
Note that the patch that added the new types was back-ported to 3.6.9: engine: add finish report on multi-host network commands https://gerrit.ovirt.org/62902 But the patch that reverts that change wasn't back ported, as far as I know. So if 3.6.9 is ever released to users, they will potentially end up having the offending event types in the database, and then this problem will appear when/if they upgrade to version 4.0.z where z < 5.
Disregard my latest comment, Dan informed me that the revert was merged to the 3.6 and 3.6.9 branches: Revert "engine: add finish report on multi-host network commands" and "core: add setCustomValues to AuditLogableBase" https://gerrit.ovirt.org/63239 I apologize for the noise.
This made it into the 4.0.4 build: 29 hours ago Sandro Bonazzola build: ovirt-engine-4.0.4.3 55/63755/1 ovirt-engine-4.0.4.3 46 hours ago Lev Veyde packaging: setup: Handle the case when HE option is... 41/63741/1 4 days ago Martin Mucha core: delete audit log records of reverted audit log... 19/63619/2 6 days ago Simone Tiraboschi build: post ovirt-engine-4.0.4.2 44/63544/3 6 days ago Simone Tiraboschi build: ovirt-engine-4.0.4.2 43/63543/2 ovirt-engine-4.0.4.2
I am unable to reproduce this, and I am successfully able to get all the events on the 4.0.4-2 build. Can you please provide some verification steps?
you need to have older environment, with log types 10905, 10906, 10907, 10908, 10909 in audit log, and then perform engine update, which should perform following update.
"older environemnt" as 3.6 or older 4.0?
no. the version with the "evil" logtypes was never released. I believe that all you should do, Lukas, is test for sanity: perform a multi-host network operation (e.g. changing vlan), restart Engine, and see that the events API is alive.
sanity only, verified in ovirt-engine-4.0.4.3-0.1.el7ev.noarch