Bug 1315466

Summary: Agent is throwing Error while JON server executing Operations on JBoss server.
Product: [JBoss] JBoss Operations Network Reporter: Prachi <pyadav>
Component: Plugin -- JBoss EAP 7Assignee: Josejulio Martínez <jmartine>
Status: CLOSED CURRENTRELEASE QA Contact: vsorokin <vsorokin>
Severity: medium Docs Contact:
Priority: medium    
Version: JON 3.3.5CC: fbrychta, hrupp, jmartine, loleary, mfoley, miburman, spinder, vprusa, vsorokin
Target Milestone: CR01Keywords: Triaged
Target Release: One-off release   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-06-06 18:57:15 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Bug Depends On:    
Bug Blocks: 1314853    

Description Prachi 2016-03-07 20:02:23 UTC
Description of problem:

Agent is throwing Error while JON server executing Operations(start/shutdown/restart) on JBoss server.


******************************
2016-03-07 13:50:28,371 ERROR [ResourceContainer.invoker.nonDaemon-3] (rhq.modules.plugins.jbossas7.ASConnection)- Failed to deserialize response to Operation{operation='read-attribute', address=Address{path: }, additionalProperties={name=release-version}} to JsonNode - response status was 503 Service Unavailable, and body was [<html><head><title>Error</title></head><body>503 - Service Unavailable</body></html>]: org.codehaus.jackson.JsonParseException: Unexpected character ('<' (code 60)): expected a valid value (number, String, array, object, 'true', 'false' or 'null')
 at [Source: java.io.StringReader@7fe7140f; line: 1, column: 2]



2016-03-07 13:50:29,412 ERROR [ResourceContainer.invoker.nonDaemon-3] (rhq.modules.plugins.jbossas7.ASConnection)- Failed to deserialize response to Operation{operation='read-attribute', address=Address{path: }, additionalProperties={name=release-version}} to JsonNode - response status was 503 Service Unavailable, and body was [<html><head><title>Error</title></head><body>503 - Service Unavailable</body></html>]: org.codehaus.jackson.JsonParseException: Unexpected character ('<' (code 60)): expected a valid value (number, String, array, object, 'true', 'false' or 'null')
 at [Source: java.io.StringReader@43403c93; line: 1, column: 2]

******************************

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


How reproducible:


Steps to Reproduce:
1. Navigate to Standalone server
2. Click on Operations
3. Schedule Operation (shutdown/start/restart/reload)
4. check JON agent log (agent.log)

Actual results:

Error:

*******************************
2016-03-07 13:50:28,371 ERROR [ResourceContainer.invoker.nonDaemon-3] (rhq.modules.plugins.jbossas7.ASConnection)- Failed to deserialize response to Operation{operation='read-attribute', address=Address{path: }, additionalProperties={name=release-version}} to JsonNode - response status was 503 Service Unavailable, and body was [<html><head><title>Error</title></head><body>503 - Service Unavailable</body></html>]: org.codehaus.jackson.JsonParseException: Unexpected character ('<' (code 60)): expected a valid value (number, String, array, object, 'true', 'false' or 'null')
 at [Source: java.io.StringReader@7fe7140f; line: 1, column: 2]



2016-03-07 13:50:29,412 ERROR [ResourceContainer.invoker.nonDaemon-3] (rhq.modules.plugins.jbossas7.ASConnection)- Failed to deserialize response to Operation{operation='read-attribute', address=Address{path: }, additionalProperties={name=release-version}} to JsonNode - response status was 503 Service Unavailable, and body was [<html><head><title>Error</title></head><body>503 - Service Unavailable</body></html>]: org.codehaus.jackson.JsonParseException: Unexpected character ('<' (code 60)): expected a valid value (number, String, array, object, 'true', 'false' or 'null')
 at [Source: java.io.StringReader@43403c93; line: 1, column: 2]

*******************************

Expected results:
Agent should not have any error while executing any operation

Additional info:

Comment 1 Michael Burman 2016-03-08 13:57:33 UTC
That error is coming from the EAP7 server, which doesn't seem to be in alright shape (error 503). That error message should be there as agent can't execute the operation when EAP can't (and it's not even returning correct JSON response).

NOTABUG.

Comment 2 Heiko W. Rupp 2016-03-10 16:09:14 UTC
[17:07:45]  <@pilhuhn>	so we just said on the call, that this is indeed more a cosmetic thing, but 
[17:08:39]  <@pilhuhn>	as this shows up as ERROR in the log, customers are very likely to call support because they are confused. So we need to detect if the server returns a 503 code and just log "server {id} is currently unavailable"

Comment 3 Josejulio Martínez 2016-03-17 17:31:32 UTC
commit e8ca78a0747c61359f01d6008be0f187e754f117
Merge: 449d6b1 63257bf
Author: Michael Burman <yak>
Date:   Thu Mar 17 11:28:47 2016 +0200

    Merge pull request #218 from josejulio/bugs/1315466
    
    Bug 1315466 - Agent is throwing Error while JON server executing Oper…

commit 63257bfe3fa2a4c718752a581152dd9a4f4bf77f
Author: Josejulio Martínez <jmartine>
Date:   Mon Mar 14 19:19:45 2016 -0600

    Bug 1315466 - Agent is throwing Error while JON server executing Operations on JBoss server.
    
    Detects if error code is 503 and returns a failure operation result with "server not available" message.

Comment 4 Mike McCune 2016-03-28 22:47:43 UTC
This bug was accidentally moved from POST to MODIFIED via an error in automation, please see mmccune with any questions

Comment 7 vsorokin 2016-04-13 16:15:11 UTC
Bug repeated with EAP-plugin-update04-ER01:

2016-04-13 12:13:00,448 ERROR [ResourceContainer.invoker.nonDaemon-4] (rhq.modules.plugins.wildfly10.ASConnection)- Failed to deserialize response to Operation{operation='read-attribute', address=Address{path: }, additionalProperties={name=release-version}} to JsonNode - response status was 503 Service Unavailable, and body was [<html><head><title>Error</title></head><body>503 - Service Unavailable</body></html>]: org.codehaus.jackson.JsonParseException: Unexpected character ('<' (code 60)): expected a valid value (number, String, array, object, 'true', 'false' or 'null')
 at [Source: java.io.StringReader@428f9128; line: 1, column: 2]
2016-04-13 12:13:00,486 ERROR [ResourceContainer.invoker.nonDaemon-4] (rhq.modules.plugins.wildfly10.ASConnection)- Failed to deserialize response to Operation{operation='read-attribute', address=Address{path: core-service=server-environment}, additionalProperties={name=config-file}} to JsonNode - response status was 503 Service Unavailable, and body was [<html><head><title>Error</title></head><body>503 - Service Unavailable</body></html>]: org.codehaus.jackson.JsonParseException: Unexpected character ('<' (code 60)): expected a valid value (number, String, array, object, 'true', 'false' or 'null')
 at [Source: java.io.StringReader@46b00da1; line: 1, column: 2]

Comment 8 vsorokin 2016-04-13 16:17:27 UTC
Cannot be verified so far.

Comment 9 vsorokin 2016-04-13 16:25:50 UTC
Bug reproduced for operation 'Restart'.

Comment 10 Josejulio Martínez 2016-04-13 17:01:41 UTC
Could you please elaborate more the way to reproduce it? I tried on that build and I'm getting:

2016-04-13 11:59:11,706 ERROR [ResourceContainer.invoker.nonDaemon-8] (rhq.modules.plugins.wildfly10.ASConnection)- Server not available [503 Service Unavailable]

Comment 11 vsorokin 2016-04-13 17:16:27 UTC
Tested on configuration:

EAP7 instance built from http://download.devel.redhat.com/devel/candidates/JBEAP/JBEAP-7.0.0.CR1/jboss-eap-7.0.0.CR1.zip

JON Plugin pack - http://web.bc.jonqe.lab.eng.bos.redhat.com/jon-plugin-pack-eap-3.3.0.GA-update-04.zip

JON - of 'JON/Server/JON 3.3.0/CR4_CR01' hostgroup.

--

Will recreate instance from scratch and recheck it!

Comment 12 vsorokin 2016-04-13 21:06:56 UTC
Results:

On operations 'Start' and 'Restart' in agent log:
-----------------------
2016-04-13 17:03:43,945 ERROR [ResourceContainer.invoker.nonDaemon-3] (rhq.modules.plugins.wildfly10.ASConnection)- Server not available [503 Service Unavailable]
2016-04-13 17:03:43,951 ERROR [ResourceContainer.invoker.nonDaemon-3] (rhq.modules.plugins.wildfly10.ASConnection)- Server not available [503 Service Unavailable]
2016-04-13 17:03:45,318 INFO  [ResourceContainer.invoker.nonDaemon-3] (modules.plugins.wildfly10.util.ProcessExecutionLogger)- Exit code from process execution: null
2016-04-13 17:03:45,318 INFO  [ResourceContainer.invoker.nonDaemon-3] (modules.plugins.wildfly10.util.ProcessExecutionLogger)- Output from process execution: 
-----------------------

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

2016-04-13 17:03:52,534 ERROR [ResourceContainer.invoker.nonDaemon-3] (rhq.modules.plugins.wildfly10.ASConnection)- Server not available [503 Service Unavailable]
2016-04-13 17:03:53,705 INFO  [MeasurementManager.collector-1] (rhq.core.pc.measurement.MeasurementCollectorRunner)- [PERF] Collection of measurements for [Resource[id=15623, uuid=c74ccf97-7108-45ce-a27d-39cf0ea152d1, type={EAP7}EAP7 Standalone Server, key=hostConfig: /home/hudson/jboss-eap7-standalone/standalone/configuration/standalone-full-changed.xml, name=EAP 7 (0.0.0.0:10090), parent=vso-eap7-2.bc.jonqe.lab.eng.bos.redhat.com, version=EAP 7.0.0.GA]] (component=[org.rhq.modules.plugins.wildfly10.StandaloneASComponent@373e5240]) took [2438]ms

Comment 13 vsorokin 2016-04-14 13:51:59 UTC
Rechecked: 
Original error message fixed.

BUT:
Other message 'ERROR' still present. It  worth consider, is such message acceptable in log file after user scheduled operation 'Restart':
---------------------------------------------------

2016-04-14 09:50:24,168 ERROR [ResourceContainer.invoker.nonDaemon-1] (rhq.modules.plugins.wildfly10.ASConnection)- Server not available [503 Service Unavailable]
2016-04-14 09:50:24,195 ERROR [ResourceContainer.invoker.nonDaemon-1] (rhq.modules.plugins.wildfly10.ASConnection)- Server not available [503 Service Unavailable]
2016-04-14 09:50:25,689 INFO  [ResourceContainer.invoker.nonDaemon-1] (modules.plugins.wildfly10.util.ProcessExecutionLogger)- Exit code from process execution: null
2016-04-14 09:50:25,689 INFO  [ResourceContainer.invoker.nonDaemon-1] (modules.plugins.wildfly10.util.ProcessExecutionLogger)- Output from process execution: 
-----------------------

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

2016-04-14 09:50:33,842 ERROR [ResourceContainer.invoker.nonDaemon-1] (rhq.modules.plugins.wildfly10.ASConnection)- Server not available [503 Service Unavailable]
2016-04-14 09:50:34,898 ERROR [ResourceContainer.invoker.nonDaemon-1] (rhq.modules.plugins.wildfly10.ASConnection)- Server not available [503 Service Unavailable]

Comment 14 Josejulio Martínez 2016-04-14 15:00:23 UTC
Are you talking about these: 

2016-04-14 09:50:25,689 INFO  [ResourceContainer.invoker.nonDaemon-1] (modules.plugins.wildfly10.util.ProcessExecutionLogger)- Exit code from process execution: null
2016-04-14 09:50:25,689 INFO  [ResourceContainer.invoker.nonDaemon-1] (modules.plugins.wildfly10.util.ProcessExecutionLogger)- Output from process execution: 

?

The other messages are meant to be there as per comment #2

Comment 15 vsorokin 2016-04-14 15:19:09 UTC
Not. I meant such like these ones: 

2016-04-14 09:50:33,842 ERROR [ResourceContainer.invoker.nonDaemon-1] (rhq.modules.plugins.wildfly10.ASConnection)- Server not available [503 Service Unavailable]
2016-04-14 09:50:34,898 ERROR [ResourceContainer.invoker.nonDaemon-1] (rhq.modules.plugins.wildfly10.ASConnection)- Server not available [503 Service Unavailable]

--
It were repeated - because I rechecked issue this newly updated plugins, and issue was repeated.

Comment 16 Josejulio Martínez 2016-04-14 15:43:05 UTC
According to Comment #1 the original error message was being show because EAP7 wasn't in a good shape, so it was agreed ( Comment #2 )  to show the message in a less verbose mode.

Comment 17 vsorokin 2016-04-18 13:32:44 UTC
Could we just replace the logging level ERROR with INFO/WARN for not to confuse customer?

Comment 18 Josejulio Martínez 2016-04-18 16:14:42 UTC
Sure, I'll replace the logging level with WARN.

Comment 19 Josejulio Martínez 2016-04-20 17:53:28 UTC
commit 2a0a15ea5e7d437bd08677a542c0d3d3baad9d84
Author: Josejulio Martínez <jmartine>
Date:   Mon Apr 18 12:07:56 2016 -0500

    Bug 1315466 - Changes logging level from ERROR to WARN.

Comment 22 vsorokin 2016-05-01 15:03:17 UTC
Execution steps:

For operation 'Restart' got:
-----------------------
2016-05-01 11:00:57,546 WARN  [ResourceContainer.invoker.nonDaemon-2] (rhq.modules.plugins.wildfly10.ASConnection)- Server not available [503 Service Unavailable]
2016-05-01 11:00:57,553 WARN  [ResourceContainer.invoker.nonDaemon-2] (rhq.modules.plugins.wildfly10.ASConnection)- Server not available [503 Service Unavailable]
2016-05-01 11:00:58,736 INFO  [ResourceContainer.invoker.nonDaemon-2] (modules.plugins.wildfly10.util.ProcessExecutionLogger)- Exit code from process execution: null
2016-05-01 11:00:58,736 INFO  [ResourceContainer.invoker.nonDaemon-2] (modules.plugins.wildfly10.util.ProcessExecutionLogger)- Output from process execution: 
-----------------------