RHQ 4.5.1, Tomcat 6, Tomcat Server JVM availability problem

[pathduck]

Hi,

we're running RHQ 4.5.1 and Tomcat 6.0.36 on RHEL 6, and have enabled secure JMX on Tomcat to connect from RHQ, using authentication.

There is a problem with the Tomcat Server JVM resources having state Unavailable once in a while, especially after a restart of Tomcat, while the server itself is running fine.

The resources like Class Loading, Compilation, Memory Subsystem etc are unavailable, and the Component Errors log say AVAILABILITY_CHECK = "An error occured" (not very helpful).

I have found a workaround which is to change the connection settings type to something other than "Parent" and then back initiates a new check and fixes things for a while, but it does not always work.

The biggest problem is for us if we want to monitor heap usage this will not be possible while the resource is set unavailable.

Found the following possibly related on bugzilla but not sure how close:

https://bugzilla.redhat.com/show_bug.cgi?id=802003

Any ideas what might cause this?

-Stian

[tsegismont]

Hi Stian,

Do you have nothing in your agent / server logs? If so please post it here.

Cheers,

Thomas

[pathduck]

Hello Thomas, thanks for the reply on this issue.

I am getting a few errors and warnings in the agent and server logs but I am not really sure if they are related or not. Stuff like this:

(names changed to protect the innocent)

Agent.log:

2013-03-13 12:41:36,227 WARN  [MeasurementManager.collector-1] (rhq.core.pc.measurement.MeasurementCollectorRunner)- Failure to collect measurement data for Resource[id=20375, uuid=69c70c94-b779-4ffe-94e9-9d3a40b80764, type={JBossAS7}Web Runtime, key=deployment=application.ear,subdeployment=application.war,subsystem=web, name=web, parent=application.war] - cause: java.lang.UnsupportedOperationException:null
2013-03-13 12:41:36,228 WARN  [MeasurementManager.collector-1] (rhq.core.pc.measurement.MeasurementCollectorRunner)- Failure to collect measurement data for Resource[id=20395, uuid=e9fe7446-56d5-407d-bff4-63b236322953, type={JBossAS7}Web Runtime, key=deployment=application.ear,subdeployment=application.war,subsystem=web, name=web, parent=application.war] - cause: java.lang.UnsupportedOperationException:null

2013-03-13 13:39:06,886 ERROR [ResourceContainer.invoker.daemon-25755] (rhq.modules.plugins.jbossas7.ASConnection)- Operation{operation='test-connection-in-pool', address=Address{path: subsystem=datasources,data-source=OraclePool}, additionalProperties={}} timed out: Read timed out

2013-03-13 16:01:35,884 ERROR [ResourceContainer.invoker.daemon-25828] (rhq.modules.plugins.jbossas7.ASConnection)- Operation{operation='read-resource', address=Address{path: subsystem=datasources,data-source=STIDS}, additionalProperties={recursive=true, include-runtime=true}} timed out: Read timed out

2013-03-13 12:43:44,859 WARN  [ResourceContainer.invoker.daemon-25732] (rhq.modules.plugins.jbossas7.ASConnection)- Received 500 (Internal Server Error) response to Operation{operation='read-attribute', address=Address{path: subsystem=security,security-domain=jboss-ejb-policy}, additionalProperties={name=name}} - response body was [{"outcome" : "failed", "failure-description" : "JBAS014792: Unknown attribute name", "rolled-back" : true}].
2013-03-13 12:43:44,940 WARN  [ResourceContainer.invoker.daemon-25732] (rhq.modules.plugins.jbossas7.ASConnection)- Received 500 (Internal Server Error) response to Operation{operation='read-attribute', address=Address{path: subsystem=security,security-domain=other}, additionalProperties={name=name}} - response body was [{"outcome" : "failed", "failure-description" : "JBAS014792: Unknown attribute name", "rolled-back" : true}].

2013-03-13 12:43:53,518 WARN  [ConfigurationManager.threadpool-1] (rhq.core.pc.configuration.ConfigurationCheckExecutor)- Plugin Error: Invalid Resource Adapter resource configuration returned by JBossAS7 plugin - Required property 'transaction-support' has a null value in Configuration[id=0].

Rhq-server-log4j.log:

2013-03-06 14:16:08,795 ERROR [org.rhq.enterprise.server.discovery.DiscoveryBossBean] Reported resource [Resource[id=0, uuid=46b97701-d4a9-4773-9dc3-32cec982245a, type={JBossAS7}Authentication (Classic), key=subsystem=security,security-domain=other,authentication=classic, name=Authentication (Classic), parent=other]] has an unknown type [{JBossAS7}Authentication (Classic)]. The Agent most likely has a plugin named 'JBossAS7' installed that is not installed on the Server. Resource will be ignored...
2013-03-06 14:16:08,816 ERROR [org.rhq.enterprise.server.discovery.DiscoveryBossBean] Reported resource [Resource[id=0, uuid=7951f1eb-318d-461e-85c8-6a1a0044b205, type={JBossAS7}SFSB Cache, key=subsystem=ejb3,cache=passivating, name=passivating, parent=ejb3]] has an unknown type [{JBossAS7}SFSB Cache]. The Agent most likely has a plugin named 'JBossAS7' installed that is not installed on the Server. Resource will be ignored...

2013-03-11 15:37:05,405 WARN  [org.rhq.enterprise.gui.coregui.server.gwt.ConfigurationGWTServiceImpl] Sending exception to client: [1363012625405]
java.lang.Exception: Current group Resource configuration for 10112 cannot be calculated, because one or more of this group's member Resources are DOWN.
at org.rhq.enterprise.server.configuration.ConfigurationManagerBean.getResourceConfigurationsForCompatibleGroup(ConfigurationManagerBean.java:637)
at sun.reflect.GeneratedMethodAccessor1084.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

The server might have actually been down at that moment, not sure. And these are mostly JBoss7 errors/warnings I guess...

Not sure about those plugin errors, I have thought they were leftovers from older installations and was guessing it would be gone after upgrading but they are still there. We were very early in testing AS7 plugin and used some Snapshots that might have had some bugs that would cause this - possibly?

The error in thq RHQ UI is AVAILABILITY_CHECK: "Failed to start component for resource Resource[id=....type={Tomcat}Tomcat Server JVM,key=JVM...version=1.6.0.37]

[tsegismont]

Stian,

The messages with WARNING level just mean that a node has not been found in the AS 7 managemement tree. It's not necessarily a problem.

Back to your original question:

You mentioned a bug still opened but there is already a fix in master branch. In fact, the fix has been shipped in RHQ 4.5.1.

With RHQ 4.6, tomcat 6.0.36 configured with "secure JMX" (I guess you mean remote JMX with authentication, not SSL) I could not reproduce the problem.

Are the log entries above captured at the time the resource went down with an availability check error?

One last thing: the "EMS connection type" connection settings should NEVER be changed to something else than "Parent". The plugin descriptor file even specify this property as readonly. And you should get errors from the agent if you change it to something else. I will try to see why there is a combox box showing there and maybe file a bug.

Cheers

[tsegismont]

Hi Stian,

So it appears that the ability to change the connection type to something else than "parent" is due to a current limitation of our plugin extension model.

The Tomcat Server JVM resource type is an extension of the JMX Server resource type defined in the JMX plugin. Consequently, it inherits of all its metadata, except name and description. This is why in the Connection Settings tab you can see all of JMX Server resource type configuration properties.

Still, the Tomcat Server JVM resource component will only use the connection type property and expects it to be "PARENT". If it's configured with something else, an InvalidPluginConfigurationException will be thrown.

Please check that all your Tomcat Server JVM resources have the approriate configuration.

There is already a request for enhancement in Bugzilla: https://bugzilla.redhat.com/show_bug.cgi?id=697662

For further details, you can read https://docs.jboss.org/author/display/RHQ/AMPS-Plugin+Extensions (and the caveats section in particular).

Hope it helps.

Cheers,

Thomas

[pathduck]

Yes, I did notice that this changed, I believe from 4.4 to 4.5.1 - I think the guys that set this up originally misunderstood and had it set to the same properties as the Tomcat Server itself (with a service:jmx URL etc).

I went through after upgrading to 4.5 and set it to "parent" since I saw the errors in the logs stating it needed to be Parent. Currently it is set to Parent with all other properties blanked out.

I just did a test, and after a restart of Tomcat RHQ sees the Tomcat as available but the Tomcat Server JVM as unavailable.

Here is the agent logs at the time of restart and a bit on:

2013-03-15 11:20:20,111 INFO  [InventoryManager.availability-1] (rhq.core.pc.inventory.AvailabilityExecutor)- Scan Starting: Fri Mar 15 11:20:20 CET 2013

2013-03-15 11:20:20,117 ERROR [ResourceContainer.invoker.daemon-7894] (jboss.on.plugins.tomcat.TomcatServerComponent)- Error closing Tomcat EMS connection: org.mc4j.ems.connection.EmsConnectException: Could not close connection java.rmi.ConnectException: Connection refused to host: IP; nested exception is:
java.net.ConnectException: Connection refused
2013-03-15 11:20:20,118 INFO  [InventoryManager.availability-1] (rhq.core.pc.inventory.AvailabilityExecutor)- Scan Ended   : Fri Mar 15 11:20:20 CET 2013 : Scan [startTime=1363342820111, endTime=1363342820117, runtime=6, isFull=false, isForced=false, numResources=55, numGetAvailabilityCalls=5, numScheduledRandomly=0, numPushedByInterval=4, numAvailabilityChanges=9, numDeferToParent=22]
2013-03-15 11:20:20,118 INFO  [InventoryManager.availability-1] (rhq.core.pc.inventory.InventoryManager)- Sending availability report to Server...
2013-03-15 11:20:50,409 INFO  [InventoryManager.availability-1] (rhq.core.pc.inventory.AvailabilityExecutor)- Scan Starting: Fri Mar 15 11:20:50 CET 2013
2013-03-15 11:20:50,412 INFO  [InventoryManager.availability-1] (rhq.core.pc.inventory.AvailabilityExecutor)- Scan Ended   : Fri Mar 15 11:20:50 CET 2013 : Scan [startTime=1363342850408, endTime=1363342850412, runtime=4, isFull=false, isForced=false, numResources=55, numGetAvailabilityCalls=2, numScheduledRandomly=0, numPushedByInterval=2, numAvailabilityChanges=0, numDeferToParent=22]
2013-03-15 11:20:58,408 INFO  [InventoryManager.discovery-1] (rhq.core.pc.inventory.AutoDiscoveryExecutor)- Executing server discovery scan...
2013-03-15 11:20:58,925 INFO  [InventoryManager.discovery-1] (rhq.core.pc.inventory.AutoDiscoveryExecutor)- Discovered 0 new server(s).
2013-03-15 11:20:58,926 INFO  [InventoryManager.discovery-1] (rhq.core.pc.inventory.InventoryManager)- Sending [server] inventory report to Server...
2013-03-15 11:20:59,074 INFO  [InventoryManager.discovery-1] (rhq.core.pc.inventory.InventoryManager)- Syncing local inventory with Server inventory...
2013-03-15 11:20:59,074 INFO  [InventoryManager.discovery-1] (rhq.core.pc.inventory.InventoryManager)- Got unknown resource: 11546
2013-03-15 11:20:59,075 INFO  [InventoryManager.discovery-1] (rhq.core.pc.inventory.InventoryManager)- Got unknown resource: 11547
2013-03-15 11:20:59,075 INFO  [InventoryManager.discovery-1] (rhq.core.pc.inventory.InventoryManager)- Got unknown resource: 11551
2013-03-15 11:20:59,075 INFO  [InventoryManager.discovery-1] (rhq.core.pc.inventory.InventoryManager)- Got unknown resource: 11548
2013-03-15 11:20:59,075 INFO  [InventoryManager.discovery-1] (rhq.core.pc.inventory.InventoryManager)- Got unknown resource: 11550
2013-03-15 11:20:59,075 INFO  [InventoryManager.discovery-1] (rhq.core.pc.inventory.InventoryManager)- Got unknown resource: 11558
2013-03-15 11:20:59,075 INFO  [InventoryManager.discovery-1] (rhq.core.pc.inventory.InventoryManager)- Got unknown resource: 11559
2013-03-15 11:20:59,075 INFO  [InventoryManager.discovery-1] (rhq.core.pc.inventory.InventoryManager)- Got unknown resource: 11560
2013-03-15 11:20:59,075 INFO  [InventoryManager.discovery-1] (rhq.core.pc.inventory.InventoryManager)- Got unknown resource: 11563
2013-03-15 11:21:09,808 INFO  [ConfigurationManager.threadpool-1] (rhq.core.pc.configuration.ConfigurationCheckExecutor)- Starting configuration update check...
2013-03-15 11:21:09,811 INFO  [ResourceContainer.invoker.daemon-7894] (org.rhq.plugins.jmx.MBeanResourceComponent)- Configuration management is currently disabled for the {RHQAgent}java.util.logging Resource with key [java.util.logging:type=Logging] - it can be enabled in the Resource's Inventory > Connection tab.
2013-03-15 11:21:09,811 INFO  [ConfigurationManager.threadpool-1] (rhq.core.pc.configuration.ConfigurationCheckExecutor)- Configuration update check completed in 3ms
2013-03-15 11:21:20,413 INFO  [InventoryManager.availability-1] (rhq.core.pc.inventory.AvailabilityExecutor)- Scan Starting: Fri Mar 15 11:21:20 CET 2013
2013-03-15 11:21:20,461 INFO  [ResourceContainer.invoker.daemon-7894] (org.mc4j.ems.connection.ConnectionFactory)- Connection library dependancy [catalina-cluster.jar] not found  in directory: /opt/tomcat
2013-03-15 11:21:20,483 INFO  [ResourceContainer.invoker.daemon-7894] (org.mc4j.ems.connection.ConnectionFactory)- Connection library dependancy [catalina-optional.jar] not found  in directory: /opt/tomcat
2013-03-15 11:21:20,484 INFO  [ResourceContainer.invoker.daemon-7894] (org.mc4j.ems.connection.ConnectionFactory)- Discovered libraries in 70 ms
2013-03-15 11:21:20,484 INFO  [ResourceContainer.invoker.daemon-7894] (jboss.on.plugins.tomcat.TomcatServerComponent)- Loading connection [service:jmx:rmi:///jndi/rmi://localhost:8050/jmxrmi] with install path [/opt/tomcat] and temp directory [/opt/rhq/rhq-agent/data/tmp]
2013-03-15 11:21:20,633 INFO  [ResourceContainer.invoker.daemon-7894] (ems.impl.jmx.connection.DConnection)- Querying MBeanServer for all MBeans...
2013-03-15 11:21:20,640 INFO  [ResourceContainer.invoker.daemon-7894] (ems.impl.jmx.connection.DConnection)- Found 82 MBeans - starting load...
2013-03-15 11:21:20,724 INFO  [InventoryManager.availability-1] (rhq.core.pc.inventory.AvailabilityExecutor)- Scan Ended   : Fri Mar 15 11:21:20 CET 2013 : Scan [startTime=1363342880413, endTime=1363342880724, runtime=311, isFull=false, isForced=false, numResources=55, numGetAvailabilityCalls=20, numScheduledRandomly=22, numPushedByInterval=6, numAvailabilityChanges=6, numDeferToParent=9]
2013-03-15 11:21:20,724 INFO  [InventoryManager.availability-1] (rhq.core.pc.inventory.InventoryManager)- Sending availability report to Server...
2013-03-15 11:21:51,006 INFO  [InventoryManager.availability-1] (rhq.core.pc.inventory.AvailabilityExecutor)- Scan Starting: Fri Mar 15 11:21:51 CET 2013
2013-03-15 11:21:51,008 INFO  [InventoryManager.availability-1] (rhq.core.pc.inventory.AvailabilityExecutor)- Scan Ended   : Fri Mar 15 11:21:51 CET 2013 : Scan [startTime=1363342911005, endTime=1363342911007, runtime=2, isFull=false, isForced=false, numResources=55, numGetAvailabilityCalls=1, numScheduledRandomly=0, numPushedByInterval=0, numAvailabilityChanges=0, numDeferToParent=9]

So, that first message might be an indication, and possibly also the missing jars for EMS ConnectionFactory?

BTW, you are correct in regards to "secure JMX" I meant "JXM with authentication" not SSL

[tsegismont]

Stian,

The first message is here because the Tomcat instance was down. The missing jars are not a problem (those jars are optional tools for Tomcat).

After restarting the server, the JVM resource never goes up again? Can you connect with jconsole to your Tomcat and check java.lang MBeans are exported?

Thanks,

Thomas

[pathduck]

That's the funny thing, the workaround seems to be: Change the connection settings for the JVM so that it can be saved, back to Parent, then wait a bit and hey presto, the JVM is available. It seems saving the settings forces a reconnect of a connection which somehow is broken?

Connecting locally with Jconsole it does look like java.lang Mbeans is available:

Should I try doing a remote JMX connection? EDIT; Remote JXM works as well.