New Description: The problem here is that I've defined Event tracking on the agent.log. Also, I've defined an alert def on ERROR events. The agent is suffering from the following types of errors: 2008-05-05 13:42:56,686 ERROR [ClientCommandSenderTask Timer Thread #1] (enterprise.communications.command.client.JBossRemotingRemoteCommunicator)- {JBossRemotingRemoteCommunicator.comm-cce}The remote server did not reply with a valid command response. Reply was: CORRUPT org.rhq.enterprise.communications.command.impl.remotepojo.RemotePojoInvocationCommandResponse CORRUPT rg.rhq.enterprise.communications.command.AbstractCommandResponse CORRUPT With the null bytes removed for readability (notepad does this) : 2008-05-05 13:42:56,686 ERROR [ClientCommandSenderTask Timer Thread #1] (enterprise.communications.command.client.JBossRemotingRemoteCommunicator)- {JBossRemotingRemoteCommunicator.comm-cce}The remote server did not reply with a valid command response. Reply was: [189¬í ysr ]org.rhq.enterprise.communications.command.impl.remotepojo.RemotePojoInvocationCommandResponse xr Aorg.rhq.enterprise.communications.command.AbstractCommandResponse Z m_successfulL m_commandt 3Lorg/rhq/enterprise/communications/command/Command;L m_exceptiont Ljava/lang/Throwable;L m_resultst Ljava/lang/Object;xpppsr java.lang.BooleanÍ r€Õœúî Z valuexp0] When the log message is communicated as the event text it fails to be stored in the db due to its corrupted nature: So, two problems here, corrupted agent data and the inability to handle events with bad/null chars in the log. 11:57:55,937 WARN [EventManagerBean] addEventData: Insert of events failed : Batch entry 0 INSERT INTO RHQ_Event (id, e vent_source_id, timestamp, severity, detail) VALUES ((SELECT nextval('RHQ_EVENT_id_seq'::text)), (SELECT id FROM RHQ_Eve nt_Source WHERE event_def_id = (SELECT id FROM RHQ_Event_Def WHERE name = logEntry AND resource_type_id = (SELECT id FRO M RHQ_Resource_Type WHERE name = JBossAS Server AND plugin = JBossAS)) AND resource_id = 500052 AND location = C:\Users\ jshaughnessy\App\jon-agent-2.0.0.GA-RC7\logs\agent.log), 2008-05-05 11:56:55.901000 -04:00:00, ERROR, [ClientCommandSend erTask Timer Thread #1] (enterprise.communications.command.client.JBossRemotingRemoteCommunicator)- {JBossRemotingRemote Communicator.comm-cce}The remote server did not reply with a valid command response. Reply was: [15f¼φ 11:58:19,864 INFO [DiscoveryServerServiceImpl] Processed AV:[jshaughnessy-PC][341][full] - need full=[false] in (160)ms 11:58:55,931 WARN [EventManagerBean] addEventData: Insert of events failed : Batch entry 0 INSERT INTO RHQ_Event (id, e vent_source_id, timestamp, severity, detail) VALUES ((SELECT nextval('RHQ_EVENT_id_seq'::text)), (SELECT id FROM RHQ_Eve nt_Source WHERE event_def_id = (SELECT id FROM RHQ_Event_Def WHERE name = logEntry AND resource_type_id = (SELECT id FRO M RHQ_Resource_Type WHERE name = JBossAS Server AND plugin = JBossAS)) AND resource_id = 500052 AND location = C:\Users\ jshaughnessy\App\jon-agent-2.0.0.GA-RC7\logs\agent.log), 2008-05-05 11:58:17.730000 -04:00:00, ERROR, [RHQ Server Pollin g Thread] (enterprise.communications.command.client.JBossRemotingRemoteCommunicator)- {JBossRemotingRemoteCommunicator.c omm-cce}The remote server did not reply with a valid command response. Reply was: [2b8¼φ 11:58:56,025 WARN [JDBCExceptionReporter] SQL Error: 0, SQLState: null 11:58:56,025 ERROR [JDBCExceptionReporter] Batch entry 0 insert into RHQ_ALERT_CONDITION_LOG (CTIME, VALUE, ALERT_ID, CO NDITION_ID, ID) values (1210003097730, ERROR, extraInfo=[[RHQ Server Polling Thread] (enterprise.communications.command. client.JBossRemotingRemoteCommunicator)- {JBossRemotingRemoteCommunicator.comm-cce}The remote server did not reply with a valid command response. Reply was: [2b8¼φ 11:58:56,025 ERROR [JDBCExceptionReporter] ERROR: invalid byte sequence for encoding "UTF8": 0x00 11:58:56,036 ERROR [AbstractFlushingEventListener] Could not synchronize database state with session org.hibernate.exception.DataException: Could not execute JDBC batch update at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:77) at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43) at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:253) at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:237) at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:141) at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:29 8) at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27) at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000) at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:296) at org.jboss.ejb3.entity.TransactionScopedEntityManager.flush(TransactionScopedEntityManager.java:211) at org.rhq.enterprise.server.alert.AlertConditionLogManagerBean.updateUnmatchedLogByAlertConditionId(AlertCondit ionLogManagerBean.java:110) ... at org.rhq.enterprise.server.authz.RequiredPermissionsInterceptor.checkRequiredPermissions(RequiredPermissionsIn terceptor.java:153) ... at org.rhq.enterprise.server.alert.engine.jms.AlertConditionConsumerBean.onMessage(AlertConditionConsumerBean.ja va:102) ... Caused by: java.sql.BatchUpdateException: Batch entry 0 insert into RHQ_ALERT_CONDITION_LOG (CTIME, VALUE, ALERT_ID, CON DITION_ID, ID) values (1210003097730, ERROR, extraInfo=[[RHQ Server Polling Thread] (enterprise.communications.command.c lient.JBossRemotingRemoteCommunicator)- {JBossRemotingRemoteCommunicator.comm-cce}The remote server did not reply with a valid command response. Reply was: [2b8¼φ ... 77 more 11:58:56,212 ERROR [AlertConditionConsumerBean] Error handling ActiveAlertConditionMessage[ value= ERROR, extraInfo=[[RH Q Server Polling Thread] (enterprise.communications.command.client.JBossRemotingRemoteCommunicator)- {JBossRemotingRemot eCommunicator.comm-cce}The remote server did not reply with a valid command response. Reply was: [2b8¼φ 11:58:56,272 WARN [JDBCExceptionReporter] SQL Error: 0, SQLState: null 11:58:56,272 ERROR [JDBCExceptionReporter] Batch entry 0 insert into RHQ_ALERT_CONDITION_LOG (CTIME, VALUE, ALERT_ID, CO NDITION_ID, ID) values (1210003097730, ERROR, extraInfo=[[RHQ Server Polling Thread] (enterprise.communications.command. client.JBossRemotingRemoteCommunicator)- {JBossRemotingRemoteCommunicator.comm-cce}The remote server did not reply with a valid command response. Reply was: [2b8¼φ 11:58:56,272 ERROR [JDBCExceptionReporter] ERROR: invalid byte sequence for encoding "UTF8": 0x00 11:58:56,272 ERROR [AbstractFlushingEventListener] Could not synchronize database state with session org.hibernate.exception.DataException: Could not execute JDBC batch update at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:77) ... Caused by: java.sql.BatchUpdateException: Batch entry 0 insert into RHQ_ALERT_CONDITION_LOG (CTIME, VALUE, ALERT_ID, CON DITION_ID, ID) values (1210003097730, ERROR, extraInfo=[[RHQ Server Polling Thread] (enterprise.communications.command.c lient.JBossRemotingRemoteCommunicator)- {JBossRemotingRemoteCommunicator.comm-cce}The remote server did not reply with a valid command response. Reply was: [2b8¼φ at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1328) at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:351) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeBatch(AbstractJdbc2Statement.java:2674) at org.jboss.resource.adapter.jdbc.CachedPreparedStatement.executeBatch(CachedPreparedStatement.java:478) at org.jboss.resource.adapter.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:519) at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:48) at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:246) ... 77 more 11:58:56,411 ERROR [AlertConditionConsumerBean] Error handling ActiveAlertConditionMessage[ value= ERROR, extraInfo=[[RH Q Server Polling Thread] (enterprise.communications.command.client.JBossRemotingRemoteCommunicator)- {JBossRemotingRemot eCommunicator.comm-cce}The remote server did not reply with a valid command response. Reply was: [2b8¼φ
This might be a dup of http://jira.rhq-project.org/browse/RHQ-307.
This may need to be split into two Jiras
the interesting thing about this jira is that both the in-band and out-band processes get to execute. you'd think that if the event log message couldn't be persisted, that the persist into the quartz table for out-of-band processing by the alert condition consumer would have failed too. however, that seems to succeed, because it then fails when the MDB picks it up for processing. so, we're persisting it incorrect into the raw table, persisting it correctly for the quartz tables, but persisting it incorrect for the alerts audit tables.
pushing to 1.1 to see if fady can make progress on this while he's looking into the other half dozen or so alerts-related jiras
This bug was previously known as http://jira.rhq-project.org/browse/RHQ-442
Temporarily adding the keyword "SubBug" so we can be sure we have accounted for all the bugs. keyword: new = Tracking + FutureFeature + SubBug
making sure we're not missing any bugs in rhq_triage
moving any remaining Alert related bugs to rhq_chainsaw
This bug has now been triaged by Chainsaw on 2/18. The expectation is the bug to be addressed by the end of sprint06 roughly 3/10/10.
closing this, as it has not been seen anytime recently. if it rears its ugly head again, it can be reopened.