Bug 536051 (RHQ-442) - The remote server did not reply with a valid command response. Reply was: CORRUPT / Unable to handle Event with invalid chars in log message
Summary: The remote server did not reply with a valid command response. Reply was: COR...
Keywords:
Status: CLOSED WORKSFORME
Alias: RHQ-442
Product: RHQ Project
Classification: Other
Component: Alerts
Version: 1.0
Hardware: All
OS: All
medium
medium
Target Milestone: ---
: ---
Assignee: RHQ Project Maintainer
QA Contact:
URL: http://jira.rhq-project.org/browse/RH...
Whiteboard:
Depends On:
Blocks: rhq_spearhead
TreeView+ depends on / blocked
 
Reported: 2008-05-05 17:10 UTC by Jay Shaughnessy
Modified: 2010-12-23 14:51 UTC (History)
2 users (show)

Fixed In Version:
Clone Of:
Environment:
Vista, Postgres 8.3, RC11 (Jon RC7)
Last Closed: 2010-12-23 14:51:24 UTC
Embargoed:


Attachments (Terms of Use)

Description Jay Shaughnessy 2008-05-05 17:10:00 UTC
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¼φ


Comment 1 Ian Springer 2008-05-05 17:32:13 UTC
This might be a dup of http://jira.rhq-project.org/browse/RHQ-307.


Comment 2 Jay Shaughnessy 2008-05-05 18:08:06 UTC
This may need to be split into two Jiras

Comment 3 Joseph Marques 2008-05-05 18:27:04 UTC
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.

Comment 4 Joseph Marques 2008-07-02 18:28:34 UTC
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

Comment 5 Red Hat Bugzilla 2009-11-10 21:09:22 UTC
This bug was previously known as http://jira.rhq-project.org/browse/RHQ-442


Comment 6 wes hayutin 2010-02-16 16:53:47 UTC
Temporarily adding the keyword "SubBug" so we can be sure we have accounted for all the bugs.

keyword:
new = Tracking + FutureFeature + SubBug

Comment 7 wes hayutin 2010-02-16 16:59:01 UTC
making sure we're not missing any bugs in rhq_triage

Comment 8 wes hayutin 2010-02-17 13:36:12 UTC
moving any remaining Alert related bugs to rhq_chainsaw

Comment 9 wes hayutin 2010-02-18 14:49:58 UTC
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.

Comment 10 Corey Welton 2010-12-23 14:51:24 UTC
closing this, as it has not been seen anytime recently.  if it rears its ugly head again, it can be reopened.


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