Bug 1264395 - Agent is not started correctly on RHEL 7.1 openJDK 1.6.0_34
Agent is not started correctly on RHEL 7.1 openJDK 1.6.0_34
Status: CLOSED CURRENTRELEASE
Product: JBoss Operations Network
Classification: JBoss
Component: Agent (Show other bugs)
JON 3.3.0
Unspecified Unspecified
medium Severity high
: ER01
: JON 3.3.5
Assigned To: Jay Shaughnessy
Prachi
: Triaged
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2015-09-18 07:16 EDT by Filip Brychta
Modified: 2016-02-18 08:41 EST (History)
6 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2016-02-18 08:41:19 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
agent.log (1.43 MB, text/plain)
2015-09-18 07:16 EDT, Filip Brychta
no flags Details
agent.log after applying CP05 (15.35 KB, text/plain)
2015-12-18 09:53 EST, Prachi
no flags Details
agent discovery (101.07 KB, image/png)
2015-12-18 09:54 EST, Prachi
no flags Details
possible fix (257.11 KB, application/zip)
2015-12-18 16:02 EST, Jay Shaughnessy
no flags Details
agent log after applying new Jar (28.11 KB, text/plain)
2015-12-21 10:19 EST, Prachi
no flags Details

  None (edit)
Description Filip Brychta 2015-09-18 07:16:46 EDT
Created attachment 1074783 [details]
agent.log

Description of problem:
For this 1.6.0_34 specific version of openJDK the agent is not started correctly throwing in log: Could not successfully parse the plugin descriptor [META-INF/rhq-plugin.xml]


Version-Release number of selected component (if applicable):
JON3.3.4.DR01

How reproducible:
2/2

Steps to Reproduce:
1. use RHEL7.1 with openJDK1.6.0_34
2. install JON3.3.0.GA
3. start it (rhqctl start)

Actual results:
Agent is not started correctly and is not discovered in discovery queue.

Exception from agent.log:
2015-09-18 05:44:45,823 ERROR [Plugin Container Reboot Thread] (rhq.core.pc.plugin.PluginManager)- Plugin at [file:/home/hudson/rhq-agent/plugins/rhq-platform-plugin-4.12.0.JON330GA.jar] could not be loaded and will therefore not be deployed.
org.rhq.core.clientapi.agent.PluginContainerException: Could not successfully parse the plugin descriptor [META-INF/rhq-plugin.xml] found in plugin jar at [file:/home/hudson/rhq-agent/plugins/rhq-platform-plugin-4.12.0.JON330GA.jar].
	at org.rhq.core.clientapi.descriptor.AgentPluginDescriptorUtil.loadPluginDescriptorFromUrl(AgentPluginDescriptorUtil.java:398)
	at org.rhq.core.pc.plugin.PluginManager.<init>(PluginManager.java:153)
	at org.rhq.core.pc.PluginContainer.initialize(PluginContainer.java:290)
	at org.rhq.enterprise.agent.AgentMain.startPluginContainer(AgentMain.java:2066)
	at org.rhq.enterprise.agent.AgentMain.start(AgentMain.java:757)
	at org.rhq.enterprise.agent.AgentMain$4.reboot(AgentMain.java:1921)
	at org.rhq.core.pc.PluginContainer$1.run(PluginContainer.java:698)
	at java.lang.Thread.run(Thread.java:701)
Caused by: org.rhq.core.clientapi.agent.PluginContainerException: [Warning] javax.xml.bind.UnmarshalException: [Warning] null
	... 8 more
Caused by: org.rhq.core.util.exception.WrappedRemotingException: [Warning] null
	at org.rhq.core.util.exception.WrappedRemotingException.getCause(WrappedRemotingException.java:121)
	at java.lang.Throwable.printStackTraceAsCause(Throwable.java:560)
	at java.lang.Throwable.printStackTrace(Throwable.java:533)
	at org.apache.log4j.DefaultThrowableRenderer.render(DefaultThrowableRenderer.java:60)
	at org.apache.log4j.spi.ThrowableInformation.getThrowableStrRep(ThrowableInformation.java:87)
	at org.apache.log4j.spi.LoggingEvent.getThrowableStrRep(LoggingEvent.java:413)
	at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:313)
	at org.apache.log4j.RollingFileAppender.subAppend(RollingFileAppender.java:276)
	at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
	at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
	at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
	at org.apache.log4j.Category.callAppenders(Category.java:206)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.log(Category.java:856)
	at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:622)
	at org.apache.commons.logging.impl.Log4jProxy.log(Log4jProxy.java:311)
	at org.apache.commons.logging.impl.Log4jProxy.error(Log4jProxy.java:293)
	at org.apache.commons.logging.impl.Log4JLogger.error(Log4JLogger.java:208)
	at org.rhq.core.pc.plugin.PluginManager.<init>(PluginManager.java:163)
	... 6 more
Caused by: org.rhq.core.util.exception.WrappedRemotingException: [Warning] cvc-enumeration-valid: Value 'Killiseconds' is not facet-valid with respect to enumeration '[none, percentage, bits, kilobits, megabits, gigabits, terabits, petabits, bytes, kilobytes, megabytes, gigabytes, terabytes, petabytes, epoch_milliseconds, epoch_seconds, jiffys, nanoseconds, microseconds, milliseconds, seconds, minutes, hours, days, kelvin, celsius, fahrenheit]'. It must be a value from the enumeration.
	at org.rhq.core.util.exception.WrappedRemotingException.getCause(WrappedRemotingException.java:121)
	at java.lang.Throwable.printStackTraceAsCause(Throwable.java:560)
	at java.lang.Throwable.printStackTraceAsCause(Throwable.java:562)
	... 25 more


Expected results:
No errors

Additional info:
see full agent.log in attachment.
I tried more versions and the issue is not visible in openJDK 1.6.0_32 and 1.6.0_30
Comment 1 Sunil Kondkar 2015-09-18 08:06:50 EDT
Additional Info:
The issue is not visible on Oracle JRE 1.6 (jdk1.6.0_45) on RHEL 7.1
Comment 2 Filip Brychta 2015-09-25 11:53:39 EDT
The issue is visible on openJDK 1.6.0_35 and openJDK 1.6.0_36 as well
openJDK 1.6.0_36 should be the latest version in RHEL 7.1
Comment 6 Jay Shaughnessy 2015-12-05 14:04:07 EST
Ran with Micke's suggestion of skipping validation. After discussing with loleary and spinder the solution is to first attempt validation.  If it fails then, for java versions matching a pattern (for now, OpenJDK 1.6*), re-parse the plugin descriptor without validation.  This is working because the failure is in validation and not in general parsing (thankfully).

This commit is in release/jon3.3.x, it is *not* yet in master and should likely be cherry-picked to the upstream.

The fix is in a client-api class (and therefore in the rhq-core-client-api jar, which I should mention is not limited to an agent). 

release/jon3.3.x commit 4b2d899613d62181d5e48afbb1b9277770ead54
Author: Jay Shaughnessy <jshaughn@redhat.com>
Date:   Sat Dec 5 13:53:20 2015 -0500

 The issue happens during schema validation (of the platform plugin)
 and not during general parsing.  If the validation fails optionally
 re-parse the plugin descriptor skipping the xsl validation if we're
 running a problematic version of java.

 The problematic java versions are controlled with the
    org.rhq.xsl.validation.skip
 sysprop.  If unset it defaults to all OpenJDK 1.6 versions.  It is
 unbounded because the problem is in the most recent released versions. If
 a version is released that fixes the issue, we could update the pattern
 to be bounded to the exact problematic versions.
Comment 7 Simeon Pinder 2015-12-09 01:29:25 EST
Moving to ON_QA as available to test with the following brew build:

JON Cumulative patch build: https://brewweb.devel.redhat.com/buildinfo?buildID=469635
  *Note: jon-server-patch-3.3.0.GA.zip maps to DR01 build of jon-server-3.3.0.GA-update-05.zip.
Comment 8 Prachi 2015-12-10 05:15:07 EST
Still getting error in DR01 build of jon-server-3.3.0.GA-update-05.zip.


Using Open jdk 1.6.0.34
******************************
/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.34.x86_64/jre/bin/java -ea -javaagent:./../lib/jamm-0.2.5.jar -XX:+UseThreadPriorities -XX:ThreadPriorityPolicy=42 -Xms512M -Xmx512M -Xmn128M -XX:+HeapDumpOnOutOfMemoryError -Xss256k -XX:+CMSClassUnloadingEnabled -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -XX:SurvivorRatio=8 -XX:MaxTenuringThreshold=1 -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseTLAB -Djava.rmi.server.hostname=localhost -Dcom.sun.management.jmxremote.port=7299 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -Djava.net.preferIPv4Stack=true -Dlog4j.configuration=log4j-server.properties -Dlog4j.defaultInitOverride=true -Dcassandra-pidfile=/home/hudson/jon-server-3.3.0.GA/rhq-storage/bin/cassandra.pid 

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


Error:

*****************************
 ERROR [main] (rhq.core.clientapi.descriptor.AgentPluginDescriptorUtil)- Validation fatal error while parsing [rhq-platform-plugin-4.12.0.JON330GA.jar:META-INF/rhq-plugin.xml] at line 18, column 165: cvc-enumeration-valid: Value 'Killiseconds' is not facet-valid with respect to enumeration '[none, percentage, bits, kilobits, megabits, gigabits, terabits, petabits, bytes, kilobytes, megabytes, gigabytes, terabytes, petabytes, epoch_milliseconds, epoch_seconds, jiffys, nanoseconds, microseconds, milliseconds, seconds, minutes, hours, days, kelvin, celsius, fahrenheit]'. It must be a value from the enumeration.
2015-12-10 04:13:00,518 ERROR [main] (rhq.core.pc.plugin.PluginManager)- Plugin at [file:/home/hudson/rhq-agent/plugins/rhq-platform-plugin-4.12.0.JON330GA.jar] could not be loaded and will therefore not be deployed.
org.rhq.core.clientapi.agent.PluginContainerException: Could not successfully parse the plugin descriptor [META-INF/rhq-plugin.xml] found in plugin jar at [file:/home/hudson/rhq-agent/plugins/rhq-platform-plugin-4.12.0.JON330GA.jar].
        at org.rhq.core.clientapi.descriptor.AgentPluginDescriptorUtil.loadPluginDescriptorFromUrl(AgentPluginDescriptorUtil.java:398)
        at org.rhq.core.pc.plugin.PluginManager.<init>(PluginManager.java:153)
        at org.rhq.core.pc.PluginContainer.initialize(PluginContainer.java:290)
        at org.rhq.enterprise.agent.AgentMain.startPluginContainer(AgentMain.java:2066)
        at org.rhq.enterprise.agent.AgentMain.start(AgentMain.java:757)
        at org.rhq.enterprise.agent.AgentMain.main(AgentMain.java:461)
Caused by: org.rhq.core.clientapi.agent.PluginContainerException: [Warning] javax.xml.bind.UnmarshalException: [Warning] null
        ... 6 more
Caused by: org.rhq.core.util.exception.WrappedRemotingException: [Warning] null
        at org.rhq.core.util.exception.WrappedRemotingException.getCause(WrappedRemotingException.java:121)
        at java.lang.Throwable.printStackTraceAsCause(Throwable.java:560)
        at java.lang.Throwable.printStackTrace(Throwable.java:533)
        at org.apache.log4j.DefaultThrowableRenderer.render(DefaultThrowableRenderer.java:60)
        at org.apache.log4j.spi.ThrowableInformation.getThrowableStrRep(ThrowableInformation.java:87)
        at org.apache.log4j.spi.LoggingEvent.getThrowableStrRep(LoggingEvent.java:413)
        at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:313)
        at org.apache.log4j.RollingFileAppender.subAppend(RollingFileAppender.java:276)
        at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
        at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
        at org.apache.log4j.Category.callAppenders(Category.java:206)
        at org.apache.log4j.Category.forcedLog(Category.java:391)
        at org.apache.log4j.Category.log(Category.java:856)
        at sun.reflect.GeneratedMethodAccessor25.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:622)
        at org.apache.commons.logging.impl.Log4jProxy.log(Log4jProxy.java:311)
        at org.apache.commons.logging.impl.Log4jProxy.error(Log4jProxy.java:293)
        at org.apache.commons.logging.impl.Log4JLogger.error(Log4JLogger.java:208)
        at org.rhq.core.pc.plugin.PluginManager.<init>(PluginManager.java:163)
        ... 4 more
Caused by: org.rhq.core.util.exception.WrappedRemotingException: [Warning] cvc-enumeration-valid: Value 'Killiseconds' is not facet-valid with respect to enumeration '[none, percentage, bits, kilobits, megabits, gigabits, terabits, petabits, bytes, kilobytes, megabytes, gigabytes, terabytes, petabytes, epoch_milliseconds, epoch_seconds, jiffys, nanoseconds, microseconds, milliseconds, seconds, minutes, hours, days, kelvin, celsius, fahrenheit]'. It must be a value from the enumeration.
        at org.rhq.core.util.exception.WrappedRemotingException.getCause(WrappedRemotingException.java:121)
        at java.lang.Throwable.printStackTraceAsCause(Throwable.java:560)
        at java.lang.Throwable.printStackTraceAsCause(Throwable.java:562)
        ... 23 more
2015-12-10 04:13:01,451 INFO  [main] (core.clientapi.agent.metadata.PluginDependencyGraph)- Optional plugin [Platforms] was requested by plugins [[AntBundlePlugin]] but it does not exist in the dependency graph yet and will be ignored
2015-12-10 04:13:01,451 ERROR [main] (rhq.core.pc.plugin.PluginManager)- Error initializing plugin container
java.lang.IllegalArgumentException: Plugin [Platforms] is required by plugins [[Apache, Augeas]] but it does not exist in the dependency graph yet
        at org.rhq.core.clientapi.agent.metadata.PluginDependencyGraph.getDeepDependencies(PluginDependencyGraph.java:329)
        at org.rhq.core.clientapi.agent.metadata.PluginDependencyGraph.getDeepDependencies(PluginDependencyGraph.java:342)
        at org.rhq.core.clientapi.agent.metadata.PluginDependencyGraph.getDeepDependencies(PluginDependencyGraph.java:342)
        at org.rhq.core.clientapi.agent.metadata.PluginDependencyGraph.getDeploymentOrder(PluginDependencyGraph.java:245)
        at org.rhq.core.pc.plugin.PluginManager.<init>(PluginManager.java:169)
        at org.rhq.core.pc.PluginContainer.initialize(PluginContainer.java:290)
        at org.rhq.enterprise.agent.AgentMain.startPluginContainer(AgentMain.java:2066)
        at org.rhq.enterprise.agent.AgentMain.start(AgentMain.java:757)
        at org.rhq.enterprise.agent.AgentMain.main(AgentMain.java:461)
2015-12-10 04:13:01,451 FATAL [main] (org.rhq.enterprise.agent.AgentMain)- {AgentMain.startup-error}The agent encountered an error during startup and must abort

*****************************
Comment 9 Jay Shaughnessy 2015-12-10 09:08:45 EST
The stack trace:

org.rhq.core.clientapi.descriptor.AgentPluginDescriptorUtil.loadPluginDescriptorFromUrl(AgentPluginDescriptorUtil.java:398)

would indicate that the agent is not updated with the fix.  Either the update contains the fix and the agent was not updated, or the update did not correctly update the fix.

Please verify that the agent was updated prior to the test.  If so, we'll need to look at the update.
Comment 10 Prachi 2015-12-11 04:44:36 EST
Jay,

I am testing it again and will update soon.
Comment 11 Prachi 2015-12-18 09:48:03 EST
Agent is getting discovered on RHEL 7.1 openJDK 1.6.0_34.

But still getting below errors:

*******************************
ERROR [main] (rhq.core.pc.plugin.PluginManager)- Plugin [JDG] at [file:/home/hudson/rhq-agent/plugins/infinispan-server-rhq-plugin-6.1.0.Final-redhat-3.jar] could not be loaded and will therefore not be deployed.
java.lang.NullPointerException
        at org.rhq.core.clientapi.agent.metadata.ConfigurationMetadataParser.parseSimpleProperty(ConfigurationMetadataParser.java:255)
        at org.rhq.core.clientapi.agent.metadata.ConfigurationMetadataParser.parseProperty(ConfigurationMetadataParser.java:209)
        at org.rhq.core.clientapi.agent.metadata.ConfigurationMetadataParser.parseProperties(ConfigurationMetadataParser.java:180)
        at org.rhq.core.clientapi.agent.metadata.ConfigurationMetadataParser.parse(ConfigurationMetadataParser.java:109)
        at org.rhq.core.clientapi.agent.metadata.PluginMetadataParser.parseResourceDescriptor(PluginMetadataParser.java:650)
        at org.rhq.core.clientapi.agent.metadata.PluginMetadataParser.parseServiceDescriptor(PluginMetadataParser.java:486)
        at org.rhq.core.clientapi.agent.metadata.PluginMetadataParser.parseResourceDescriptor(PluginMetadataParser.java:817)
        at org.rhq.core.clientapi.agent.metadata.PluginMetadataParser.parseServiceDescriptor(PluginMetadataParser.java:486)
        at org.rhq.core.clientapi.agent.metadata.PluginMetadataParser.parseDescriptor(PluginMetadataParser.java:172)
        at org.rhq.core.clientapi.agent.metadata.PluginMetadataParser.<init>(PluginMetadataParser.java:109)
        at org.rhq.core.clientapi.agent.metadata.PluginMetadataManager.loadPlugin(PluginMetadataManager.java:186)
        at org.rhq.core.pc.plugin.PluginManager.loadPlugin(PluginManager.java:322)
        at org.rhq.core.pc.plugin.PluginManager.<init>(PluginManager.java:178)
        at org.rhq.core.pc.PluginContainer.initialize(PluginContainer.java:290)
        at org.rhq.enterprise.agent.AgentMain.startPluginContainer(AgentMain.java:2066)
        at org.rhq.enterprise.agent.AgentMain.start(AgentMain.java:757)
        at org.rhq.enterprise.agent.AgentMain.main(AgentMain.java:461)



ERROR [ResourceDiscoveryComponent.invoker.daemon-1] (org.rhq.plugins.cassandra.CassandraNodeDiscoveryComponent)- Error creating path for yaml file.
java.lang.NullPointerException
        at org.rhq.plugins.cassandra.CassandraNodeDiscoveryComponent.getDetails(CassandraNodeDiscoveryComponent.java:143)
        at org.rhq.plugins.cassandra.CassandraNodeDiscoveryComponent.scanForResources(CassandraNodeDiscoveryComponent.java:84)
        at org.rhq.plugins.storage.StorageNodeDiscoveryComponent.discoverResources(StorageNodeDiscoveryComponent.java:54)
        at org.rhq.plugins.storage.StorageNodeDiscoveryComponent.upgrade(StorageNodeDiscoveryComponent.java:104)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:622)
        at org.rhq.core.pc.util.DiscoveryComponentProxyFactory$ComponentInvocationThread.call(DiscoveryComponentProxyFactory.java:305)
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
        at java.util.concurrent.FutureTask.run(FutureTask.java:166)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:701)

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

Steps taken:

1) unzip JON3.0.0GA , 
2) install with rhqctl install, 
3) then apply JON3.3.5 DR01 patch, 
4) start with rhqctl start

Attached agent.log and screen-shot of discovered agent.
Comment 12 Prachi 2015-12-18 09:53 EST
Created attachment 1107185 [details]
agent.log after applying CP05
Comment 13 Prachi 2015-12-18 09:54 EST
Created attachment 1107186 [details]
agent discovery
Comment 14 Jay Shaughnessy 2015-12-18 16:02 EST
Created attachment 1107424 [details]
possible fix
Comment 15 Jay Shaughnessy 2015-12-18 16:07:44 EST
Prachi,

I think this is a different issue from the one before, even if they are both related to behavior using OpenJDK.  So it may merit a different BZ.

But, for now, can you try dropping the jar I attached into your agent environment and see if it makes any difference?

Thanks, Jay
Comment 16 Jay Shaughnessy 2015-12-18 16:10:15 EST
Prachi, 

It was probably clear, but I mean you should replace rhq-agent/lib/rhq-core-client-api-<version>.jar with the one I attached and see if the behavior changes.

-Jay
Comment 17 Prachi 2015-12-21 10:18:56 EST
Jay,

I have replaced the attached jar file with default jar file but still getting the same Error(attached latest agent.log).

As it is different from original Error of this bug and agent is getting discovered, I am opening a new BZ.
Comment 18 Prachi 2015-12-21 10:19 EST
Created attachment 1108328 [details]
agent log after applying new Jar
Comment 19 Jay Shaughnessy 2015-12-21 10:32:51 EST
OK, please link in the new BZ.

I may give you another jar that has some temporary logging.  This could be a serious issue if we can't find a way to parse this plugin descriptor.
Comment 20 Prachi 2015-12-21 10:37:02 EST
verified As we are not getting these ERRORS after applying patch.

For new Error opened BZ 1293377.

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