[GLASSFISH-19677] EJB Monitoring problems in 3.x beans Created: 14/Feb/13  Updated: 19/Sep/14  Resolved: 15/May/13

Status: Resolved
Project: glassfish
Component/s: ejb_container
Affects Version/s: 3.1.2.2
Fix Version/s: 4.1

Type: Bug Priority: Major
Reporter: abien Assignee: marina vatkina
Resolution: Fixed Votes: 3
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

All



 Description   

I wasn't able to monitor EJBs with GFv3. In GF v2 it worked fine. I have exactly the same issue described here: http://www.java.net/forum/topic/glassfish/glassfish/warning-flashlight-listener-registration-failed-log-level

I found in the log files WARNINGS:

WARNING: MNTG0201:Flashlight listener registration failed for listener class : com.sun.ejb.monitoring.stats.StatelessSessionBeanStatsProvider , will retry later

The EJB appear in the via the REST API, but come with default values. The monitoring of all components is set to "HIGH":

<map>
<entry key="extraProperties">
<map>
<entry key="entity">
<map>
<entry key="methodstatistic">
<map>
<entry key="maxtime">
<number>0</number>
</entry>
<entry key="unit" value="unit"/>
<entry key="starttime">
<number>1360858556226</number>
</entry>
<entry key="count">
<number>0</number>
</entry>
<entry key="description" value="Provides the number of times an operation was called, the total time that was spent during the invocation and so on"/>
<entry key="name" value="MethodStatistic"/>
<entry key="lastsampletime">
<number>-1</number>
</entry>
<entry key="totaltime">
<number>0</number>
</entry>
<entry key="mintime">
<number>0</number>
</entry>
</map>
</entry>
<entry key="executiontime">
<map>
<entry key="unit" value="Milliseconds"/>
<entry key="starttime">
<number>1360858556226</number>
</entry>
<entry key="count">
<number>0</number>
</entry>
<entry key="description" value="Provides the time in milliseconds spent during the last successful/unsuccessful attempt to execute the operation."/>
<entry key="name" value="ExecutionTime"/>
<entry key="lastsampletime">
<number>-1</number>
</entry>
</map>
</entry>
<entry key="totalnumsuccess">
<map>
<entry key="unit" value="count"/>
<entry key="starttime">
<number>1360858556226</number>
</entry>
<entry key="count">
<number>0</number>
</entry>
<entry key="description" value="Provides the total number of successful invocations of the method."/>
<entry key="name" value="TotalNumSuccess"/>
<entry key="lastsampletime">
<number>-1</number>
</entry>
</map>
</entry>
<entry key="totalnumerrors">
<map>
<entry key="unit" value="count"/>
<entry key="starttime">
<number>1360858556226</number>
</entry>
<entry key="count">
<number>0</number>
</entry>
<entry key="description" value="Provides the total number of errors that occured during invocation or execution of an operation."/>
<entry key="name" value="TotalNumErrors"/>
<entry key="lastsampletime">
<number>-1</number>
</entry>
</map>
</entry>
</map>
</entry>
<entry key="childResources">
<map/>
</entry>
</map>
</entry>
<entry key="message" value=""/>
<entry key="exit_code" value="SUCCESS"/>
<entry key="command" value="Monitoring Data"/>
</map>

What causes the issue?

Reproducer: Any Java EE 6 application containing an EJB

Thanks in advance!



 Comments   
Comment by dimaki [ 19/Feb/13 ]

Problem is also discussed here: http://stackoverflow.com/questions/13747147/glassfish-3-1-2-monitoring-ejb-container-bean-methods

Comment by csteingen [ 21/Feb/13 ]

What I found out so far:

Steps to recreate the Behaviour:

Preparations:
Undeploy everything you have, just to make sure everything is clean.

Step 1: Enable GF ejb-container monitoring
Go to AdminConsole and navigate to Configurations-yourconfigname-Monitoring, select All Items and set the level to HIGH.
Save.

One could expect that now the EJB monitoring should work as described in the documentation.
To see what's happening while the monitoring api is creating the listeners and handlers on the EJB you have to do Step 2, which changes the loglevel for the monitoring components.

Step 2: Change monitoring log level
Go to AdminConsole and navigate to Configurations-yourconfignameLoggerSettings>Log Levels, select "Add Logger" and enter "javax.enterprise.system.tools.monitor" as the Logger's name. Then set the level to FINE
Save.

Now it's time for a test project, Netbeans is used here.

Step 3:
Create any new project than can contain an EJB, for example an EJB Module (Java EE --> EJB Module). Give it any name, doesn't matter. Leave everything at default values.

Step 4:
Add a SessionBean to the project, Stateless / Stateful does not matter and add a simple method to the EJB.
Here is a example EJB code:

package org.some.test;

import javax.ejb.Stateless;

@Stateless
public class TestBean {

public void sayHello()

{ System.out.println("Hello"); }


}

Step 5:
Start your GF server and clear the log window in Netbeans when the server is up (just to make it easier to read the log in the next step)

Step 6:
Deploy the EJB Module

Step 7:
During Deployment, the following exception will occur:

INFO: EJB5181:Portable JNDI names for EJB TestBean: [java:global/MonTest/TestBean!org.some.test.TestBean, java:global/MonTest/TestBean]
FINE: registering a statsProvider
FINE: enabled is true
FINE: Enabling the statsProvider - com.sun.ejb.monitoring.stats.StatelessSessionBeanStatsProvider
WARNING: MNTG0201:Flashlight listener registration failed for listener class : com.sun.ejb.monitoring.stats.StatelessSessionBeanStatsProvider , will retry later
FINE: Listener registration failed
java.lang.RuntimeException: Probe is not yet registered: glassfish:ejb:bean_null_MonTest_TestBean:methodEndEvent
at org.glassfish.flashlight.impl.client.FlashlightProbeClientMediator.handleListenerAnnotations(FlashlightProbeClientMediator.java:245)
at org.glassfish.flashlight.impl.client.FlashlightProbeClientMediator.registerJavaListener(FlashlightProbeClientMediator.java:139)
at org.glassfish.flashlight.impl.client.FlashlightProbeClientMediator.registerListener(FlashlightProbeClientMediator.java:116)
at org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.registerStatsProviderToFlashlight(StatsProviderManagerDelegateImpl.java:643)
at org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.enableStatsProvider(StatsProviderManagerDelegateImpl.java:394)
at org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.tryToRegister(StatsProviderManagerDelegateImpl.java:191)
at org.glassfish.admin.monitor.StatsProviderManagerDelegateImpl.register(StatsProviderManagerDelegateImpl.java:157)
at org.glassfish.external.probe.provider.StatsProviderManager.registerStatsProvider(StatsProviderManager.java:91)
at org.glassfish.external.probe.provider.StatsProviderManager.register(StatsProviderManager.java:82)
at com.sun.ejb.monitoring.stats.EjbMonitoringUtils.registerComponent(EjbMonitoringUtils.java:75)
at com.sun.ejb.monitoring.stats.EjbMonitoringStatsProvider.register(EjbMonitoringStatsProvider.java:118)
at com.sun.ejb.containers.BaseContainer.createMonitoringRegistryMediator(BaseContainer.java:5456)
at com.sun.ejb.containers.BaseContainer.registerMonitorableComponents(BaseContainer.java:5543)
at com.sun.ejb.containers.StatelessSessionContainer.registerMonitorableComponents(StatelessSessionContainer.java:283)
at com.sun.ejb.containers.StatelessSessionContainer.initializeHome(StatelessSessionContainer.java:261)
at com.sun.ejb.containers.ContainerFactoryImpl.createContainer(ContainerFactoryImpl.java:167)
at org.glassfish.ejb.startup.EjbApplication.loadContainers(EjbApplication.java:230)
at org.glassfish.ejb.startup.EjbDeployer.load(EjbDeployer.java:305)
at org.glassfish.ejb.startup.EjbDeployer.load(EjbDeployer.java:108)
at org.glassfish.internal.data.ModuleInfo.load(ModuleInfo.java:186)
at org.glassfish.internal.data.ApplicationInfo.load(ApplicationInfo.java:264)
at com.sun.enterprise.v3.server.ApplicationLifecycle.deploy(ApplicationLifecycle.java:460)
at com.sun.enterprise.v3.server.ApplicationLifecycle.deploy(ApplicationLifecycle.java:240)
at org.glassfish.deployment.admin.DeployCommand.execute(DeployCommand.java:389)
at com.sun.enterprise.v3.admin.CommandRunnerImpl$1.execute(CommandRunnerImpl.java:348)
at com.sun.enterprise.v3.admin.CommandRunnerImpl.doCommand(CommandRunnerImpl.java:363)
at com.sun.enterprise.v3.admin.CommandRunnerImpl.doCommand(CommandRunnerImpl.java:1085)
at com.sun.enterprise.v3.admin.CommandRunnerImpl.access$1200(CommandRunnerImpl.java:95)
at com.sun.enterprise.v3.admin.CommandRunnerImpl$ExecutionContext.execute(CommandRunnerImpl.java:1291)
at com.sun.enterprise.v3.admin.CommandRunnerImpl$ExecutionContext.execute(CommandRunnerImpl.java:1259)
at com.sun.enterprise.v3.admin.AdminAdapter.doCommand(AdminAdapter.java:461)
at com.sun.enterprise.v3.admin.AdminAdapter.service(AdminAdapter.java:212)
at com.sun.grizzly.tcp.http11.GrizzlyAdapter.service(GrizzlyAdapter.java:179)
at com.sun.enterprise.v3.server.HK2Dispatcher.dispath(HK2Dispatcher.java:117)
at com.sun.enterprise.v3.services.impl.ContainerMapper$Hk2DispatcherCallable.call(ContainerMapper.java:354)
at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:195)
at com.sun.grizzly.http.ProcessorTask.invokeAdapter(ProcessorTask.java:860)
at com.sun.grizzly.http.ProcessorTask.doProcess(ProcessorTask.java:757)
at com.sun.grizzly.http.ProcessorTask.process(ProcessorTask.java:1056)
at com.sun.grizzly.http.DefaultProtocolFilter.execute(DefaultProtocolFilter.java:229)
at com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:137)
at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:104)
at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:90)
at com.sun.grizzly.http.HttpProtocolChain.execute(HttpProtocolChain.java:79)
at com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:54)
at com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:59)
at com.sun.grizzly.ContextTask.run(ContextTask.java:71)
at com.sun.grizzly.util.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:532)
at com.sun.grizzly.util.AbstractThreadPool$Worker.run(AbstractThreadPool.java:513)
at java.lang.Thread.run(Thread.java:722)

// ...

After digging through the classes, that's the corresponding code in org.glassfish.flashlight.impl.client.FlashlightProbeClientMediator:

private List<MethodProbe> handleListenerAnnotations(Class listenerClass, String invokerId) {

List<MethodProbe> mp = new LinkedList<MethodProbe>();

for (Method method : listenerClass.getMethods()) {
Annotation[] anns = method.getAnnotations();
ProbeListener probeAnn = method.getAnnotation(ProbeListener.class);

if (probeAnn == null)
continue;

String probeString = probeAnn.value();

if ((probeString != null) && (invokerId != null))

{ String[] strArr = probeString.split(":"); probeString = strArr[0] + ":" + strArr[1] + ":" + strArr[2] + invokerId + ":" + strArr[3]; }

FlashlightProbe probe = probeRegistry.getProbe(probeString);
if (probe == null) {
String errStr = localStrings.getLocalString("probeNotRegistered",
"Probe is not registered:

{0}

", probeString);
throw new RuntimeException(errStr);
}
mp.add(new MethodProbe(method, probe));
}

return mp;
}

As per the exception's message probeString must be "glassfish:ejb:bean_null_MonTest_TestBean:methodEndEvent".
I wonder where the "null" in the string comes from, where "_null_MonTest_TestBean" probably is the invokerId in the code where probeString is constructed.
I guess because that "null" somehow is not correct, the FlashlightProbe probe cannot be fetched from the probeRegistry, and therefore evaluates to null, which then leads into the exception.

Hope this helps.

Cheers,

Chris

Comment by marina vatkina [ 22/Feb/13 ]

null is probably the app-name - if you are deploying a jar or a war file, the app-name is null. EJB container concatenates the app-name/module-name/ejb-name into an id, which converts null into "null". Try adding that "null" to the path

Comment by marina vatkina [ 10/May/13 ]

1. app-name "null" for a module deployment doesn't seem to affect anything, but let's fix it.
2. not all SLSB creation is reported
3. method monitoring for 3.x beans seems broken.

1 & 2 fixed with:
Sending ejb-container/src/main/java/com/sun/ejb/containers/AbstractSingletonContainer.java
Sending ejb-container/src/main/java/com/sun/ejb/containers/BaseContainer.java
Sending ejb-container/src/main/java/com/sun/ejb/containers/StatelessSessionContainer.java
Sending ejb-container/src/main/java/com/sun/ejb/monitoring/stats/EjbMonitoringStatsProvider.java
Sending ejb-container/src/main/java/com/sun/ejb/monitoring/stats/EjbMonitoringUtils.java
Transmitting file data .....
Committed revision 61949.

Comment by marina vatkina [ 13/May/13 ]

the problems seem to be with 3.x beans as all monitoring infrastructure is geared towards 2.x style

Comment by marina vatkina [ 14/May/13 ]

With this change, #3 is fixed by looking up monitors via the method's stringified view:
Sending ejb-container/src/main/java/com/sun/ejb/monitoring/stats/EjbMonitoringStatsProvider.java
Transmitting file data .
Committed revision 61970.

Next step to try to store the stringified view, not to create it every time.

Comment by marina vatkina [ 15/May/13 ]

With these changes the stringified method signature is precreated at bean loading time:

Sending ejb-container/src/main/java/com/sun/ejb/InvocationInfo.java
Sending ejb-container/src/main/java/com/sun/ejb/containers/BaseContainer.java
Sending ejb-container/src/main/java/com/sun/ejb/monitoring/probes/EjbMonitoringProbeProvider.java
Sending ejb-container/src/main/java/com/sun/ejb/monitoring/stats/EjbMonitoringStatsProvider.java
Sending ejb-container/src/main/java/com/sun/ejb/monitoring/stats/EjbMonitoringUtils.java
Transmitting file data .....
Committed revision 61995.

Comment by abien [ 06/Jun/13 ]

Just tested with b89 and it is still not working. Is it supposed to work with 4.0.1 only?

Comment by marina vatkina [ 06/Jun/13 ]

It's marked as fixed in 4.0.1. It missed the 4.0 window.

Generated at Thu Sep 03 13:31:45 UTC 2015 using JIRA 6.2.3#6260-sha1:63ef1d6dac3f4f4d7db4c1effd405ba38ccdc558.