DX Application Performance Management

Hi,

We are trying to use wily APM agent 10.3 with weblogic 10.3.x using JDK 1.6 IBM on AIX. The issue has been persistently around "Agent not available". Now we use node manager to start/stop the applications, startup script is not used, so we used server administration to do following:

1. added startup class 

2. added WebAppSupport.jar in classpath arguments of the application -classpath /bea/agent/wily/WebAppSupport.jar

3. added java agent arguments -javaagent:/bea/agent/wily/Agent.jar

restarted the server and got following exception:

<Jun 8, 2017 4:02:36 PM> <INFO> <NodeManager> <Server output log file is '/bea/bea/user_projects/domains/CCSDomain/servers/CCSManaged/logs/CCSManaged.out'>
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Agent Release 10.3.0.15 (Build 990015)
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Using Java VM version "IBM J9 VM 1.6.0" from IBM Corporation
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Trying to load agent profile based on system property "com.wily.introscope.agentProfile"
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Unable to load agent profile because the system property could not be found
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Trying to load agent profile based on system property "agentProfile"
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Trying to load file from /bea/agent/wily/core/config/IntroscopeAgent.profile
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Loaded file from /bea/agent/wily/core/config/IntroscopeAgent.profile
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Agent using old configuration (introscope.agent.configuration.old) set to default value of "false"
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Canonical Key Map Thread Local (introscope.agent.reduceAgentMemoryOverhead.usecanonicalkeysthreadlocal) set to default value of "false"
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Thread priority (introscope.agent.thread.all.priority) set to default value of "5"
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Agent Transaction Trace Limit (introscope.agent.ttClamp) set to "50"
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Configuration property (introscope.agent.tracer.sampling.maxrate) set to default value of "10"
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Configuration property (introscope.agent.tracer.sampling.initial.period) set to default value of "100"
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Configuration property (introscope.agent.tracer.sampling.reset.period) set to default value of "10000"
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Configuration property (introscope.agent.transactiontracer.tailfilterPropagate.enable) set to "true"
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Configuration property (introscope.agent.transactiontracer.parameter.capture.sessionid) set to default value of "true"
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Agent Metric Aging (introscope.agent.metricAging.turnOn) set to "true"
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Agent Metric Aging Interval (introscope.agent.metricAging.heartbeatInterval) set to default value of "86400" seconds
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Agent Metric Aging Data Chunk (introscope.agent.metricAging.dataChunk) set to default value of "500"
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Agent Metric Aging Exclusion List (introscope.agent.metricAging.metricExclude.ignore) set to "[Threads*, ChangeDetector.AgentID, File System*]"
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Agent Metric Agent Timeslice Intervals (introscope.agent.metricAging.numberTimeslices) set to default value of "180000"
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Looking for agent profile property "introscope.agent.extensions.directory" to locate the extensions directory.
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] The agent extensions directory /bea/agent/wily/core/ext was successfully located
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] EagerClassLoader(ProbeBuilder.jar): Pre-loaded 701 classes.
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] EagerClassLoader(DynInstrSupport15.jar): Pre-loaded 133 classes.
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] EagerClassLoader(Java15DynamicInstrumentation.jar): Pre-loaded 99 classes.
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] EagerClassLoader(DynInstrBootstrap.jar): Pre-loaded 69 classes.
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] EagerClassLoader(Inheritance.jar): Pre-loaded 22 classes.
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] EagerClassLoader(BasicDirectiveLoader.jar): Pre-loaded 9 classes.
6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] EagerClassLoader(IntelligentInstrumentation.jar): Pre-loaded 234 classes.
6/08/17 04:02:41 PM PKT [ERROR] [IntroscopeAgent] A problem occurred while attempting to create the delegate agent
6/08/17 04:02:41 PM PKT [ERROR] [IntroscopeAgent] Agent Unavailable
<Jun 8, 2017 4:02:41 PM PKT> <Notice> <WebLogicServer> <BEA-000395> <Following extensions directory contents added to the end of the classpath:
/bea/bea/user_projects/domains/CCSDomain/lib/WebAppSupport.jar>
<Jun 8, 2017 4:02:41 PM PKT> <Info> <WebLogicServer> <BEA-000377> <Starting WebLogic Server with IBM J9 VM Version 2.4 from IBM Corporation>
<Jun 8, 2017 4:02:42 PM PKT> <Info> <Management> <BEA-141107> <Version: WebLogic Server 10.3.3.0 Fri Apr 9 00:05:28 PDT 2010 1321401 >
<Jun 8, 2017 4:02:44 PM PKT> <Notice> <WebLogicServer> <BEA-000365> <Server state changed to STARTING>
<Jun 8, 2017 4:02:44 PM PKT> <Info> <WorkManager> <BEA-002900> <Initializing self-tuning thread pool>
<Jun 8, 2017 4:02:44 PM PKT> <Notice> <Log Management> <BEA-170019> <The server log file /bea/bea/user_projects/domains/CCSDomain/servers/CCSManaged/logs/CCSManaged.log is opened. All server side log events will be written to this file.>
<Jun 8, 2017 4:02:47 PM PKT> <Notice> <Security> <BEA-090082> <Security initializing using security realm myrealm.>
<Jun 8, 2017 4:02:48 PM PKT> <Critical> <WebLogicServer> <BEA-000286> <Failed to invoke startup class "APM-StartupClass", com.wily.introscope.agent.AgentNotAvailableException
com.wily.introscope.agent.AgentNotAvailableException
at com.wily.introscope.agent.AgentShim.IAgentShim_getAgent(AgentShim.java:696)
at com.wily.introscope.api.weblogic.IntroscopeStartupClass.startup(IntroscopeStartupClass.java:70)
at weblogic.management.deploy.classdeployment.ClassDeploymentManager.invokeStartup(ClassDeploymentManager.java:287)
at weblogic.management.deploy.classdeployment.ClassDeploymentManager.invokeClass(ClassDeploymentManager.java:265)
at weblogic.management.deploy.classdeployment.ClassDeploymentManager.access$000(ClassDeploymentManager.java:54)
Truncated. see log file for complete stacktrace
>
<Jun 8, 2017 4:02:49 PM PKT> <Notice> <WebLogicServer> <BEA-000365> <Server state changed to STANDBY>
<Jun 8, 2017 4:02:49 PM PKT> <Notice> <WebLogicServer> <BEA-000365> <Server state changed to STARTING>

We have not received ClassNotFound exception, which we get if WebAppSupport.jar is not at the specified location, can someone help us figuring out by looking at the exception that what could be the reason?

Startup section logs is below:

JAVA Memory arguments:
.
WLS Start Mode=Production
.
CLASSPATH=/bea/bea/patch_wls1033/profiles/default/sys_manifest_classpath/weblogic_patch.jar:/bea/bea/patch_ocp353/profiles/default/sys_manifest_classpath/weblogic_patch.jar:/usr/java6_64/lib/tools.jar:/bea/bea/wlserver_10.3/server/lib/weblogic_sp.jar:/bea/bea/wlserver_10.3/server/lib/weblogic.jar:/bea/bea/modules/features/weblogic.server.modules_10.3.3.0.jar:/bea/bea/wlserver_10.3/server/lib/webservices.jar:/bea/bea/modules/org.apache.ant_1.7.1/lib/ant-all.jar:/bea/bea/modules/net.sf.antcontrib_1.1.0.0_1-0b2/lib/ant-contrib.jar:/bea/bea/wlserver_10.3/common/derby/lib/derbyclient.jar:/bea/bea/wlserver_10.3/server/lib/xqrl.jar:/bea/agent/wily/WebAppSupport.jar /bea/bea/wlserver_10.3/server/lib/weblogic.jar
.
PATH=/bea/bea/wlserver_10.3/server/bin:/bea/bea/modules/org.apache.ant_1.7.1/bin:/usr/java6_64/jre/bin:/usr/java6_64/bin:/bea/bea/wlserver_10.3/server/bin:/bea/bea/modules/org.apache.ant_1.7.1/bin:/usr/java6_64/jre/bin:/usr/java6_64/bin:/bea/bea/wlserver_10.3/server/bin:/bea/bea/modules/org.apache.ant_1.7.1/bin:/usr/java6_64/jre/bin:/usr/java6_64/bin:/usr/java6_64/bin:/usr/bin:/etc:/usr/sbin:/usr/ucb:/bea/bin:/usr/bin/X11:/sbin:/usr/bin:/etc:/usr/sbin:/usr/ucb:/usr/bin/X11:/sbin:/usr/java6_64/jre/bin:/usr/java6_64/bin:/usr/java6_64/bin/:/opt/CA/SharedComponents/bin:/opt/CA/SharedComponents/ccs/cam/bin.:.:/usr/java6_64/bin
.
***************************************************
* To start WebLogic Server, use a username and *
* password assigned to an admin-level user. For *
* server administration, use the WebLogic Server *
* console at http://hostname:port/console *
***************************************************
starting weblogic with Java version:
java version "1.6.0"
Java(TM) SE Runtime Environment (build pap6460sr12-20121025_01(SR12))
IBM J9 VM (build 2.4, JRE 1.6.0 IBM J9 2.4 AIX ppc64-64 jvmap6460sr12-20121024_126067 (JIT enabled, AOT enabled)
J9VM - 20121024_126067
JIT - r9_20120914_26057
GC - 20120928_AA)
JCL - 20121014_01
Starting WLS with line:
/usr/java6_64/bin/java -Dweblogic.Name=CCSManaged -Djava.security.policy=/bea/bea/wlserver_10.3/server/lib/weblogic.policy -Dweblogic.ProductionModeEnabled=true -javaagent:/bea/agent/wily/Agent.jar -Dcom.wily.introscope.agentProfile=/bea/agent/wily/core/config/IntroscopeAgent.profile -da -Dplatform.home=/bea/bea/wlserver_10.3 -Dwls.home=/bea/bea/wlserver_10.3/server -Dweblogic.home=/bea/bea/wlserver_10.3/server -Dweblogic.management.discover=false -Dweblogic.management.server=http://10.254.166.125:7102 -Dwlw.iterativeDev=false -Dwlw.testConsole=false -Dwlw.logErrorsToConsole=false -Dweblogic.ext.dirs=/bea/bea/patch_wls1033/profiles/default/sysext_manifest_classpath:/bea/bea/patch_ocp353/profiles/default/sysext_manifest_classpath weblogic.Server

thanks

K

First thing to do is correct this problem.

6/08/17 04:02:41 PM PKT [INFO] [IntroscopeAgent.Agent] Unable to load agent profile because the system property could not be found

You have added the agent.jar to the jvm arguments but not the profile.  You need to add -Dcom.wily.introscope.agentProfie=<path to IntroscopeAgent.profile> and then restart.

3. added java agent arguments -javaagent:/bea/agent/wily/Agent.jar

Hi:
Was Matt's response helpful in resolving your issue? Did you get the agent to start up successfully? If not, what issues are taking place? Please let us know either way

Thanks

Hal German

Hi, this looked strange to me as well, but if you look at the startup log:

/usr/java6_64/bin/java -Dweblogic.Name=CCSManaged -Djava.security.policy=/bea/bea/wlserver_10.3/server/lib/weblogic.policy -Dweblogic.ProductionModeEnabled=true -javaagent:/bea/agent/wily/Agent.jar -Dcom.wily.introscope.agentProfile=/bea/agent/wily/core/config/IntroscopeAgent.profile -da -Dplatform.home=/bea/bea/wlserver_10.3 -Dwls.home=/bea/bea/wlserver_10.3/server -Dweblogic.home=/bea/bea/wlserver_10.3/server -Dweblogic.management.discover=false -Dweblogic.management.server=http://10.254.166.125:7102 -Dwlw.iterativeDev=false -Dwlw.testConsole=false -Dwlw.logErrorsToConsole=false -Dweblogic.ext.dirs=/bea/bea/patch_wls1033/profiles/default/sysext_manifest_classpath:/bea/bea/patch_ocp353/profiles/default/sysext_manifest_classpath weblogic.Server

and also for some reason it resorted back to checking agentProfile property instead and loaded the right file, subsequent log also showed no error indication and all properties, extension folder is pointing to right location in logs, do you still see this as the reason why agent would fail on startup?

It would be more helpful to review the whole log. Please attach it here.

Also what version is this agent? Java 6 support was dropped in 10.5.

Agent is 10.3, we used the one support Java 1.6, the log and screenshots of admin view where startup class is configured are in this zip file: Archive.zip - Box  

thanks, 

FYI-- jvm1.6 support with 10.5 has been reintroduced starting with 10.5.1 hotfix#6 and this support is also available in latest 10.5.2.
If you need access to this 10.5.1 hotfix, contact CA Support

Something is throwing off the profile.  According to the above and I know its a cut and paste and that sometimes throws off things, double check that the -Dcom.wily.introscope.agentProfile has the - and D together.  Also at the end of that line, what is the -da for?  I'm wondering if that could be throwing it off.

Also double check your path below and make sure it is correct.  Since the below is a UNIX path, make sure that all directory and file names are correct in their capital or lower case versus what you have below.

/bea/agent/wily/core/config/IntroscopeAgent.profile

Another thing to check is if the agent profile is indeed there, run the command file IntroscopeAgent.profile and make sure its a unix file.  If not, then use dos2unix to convert it.  

Basically either the path is wrong or the profile is corrupted and cannot be opened by our Agent.jar.

If the above still doesn't help, I would suggest opening a case for a webex.

I did already try the pointers here, checked the profile path with cat and copying the path info as printed in runtime command and the contents are printed fine. The next line right after initial property lookup failure indicates that agentProfile was defaulted back to the config path and it indeed find/parsed and ran the IntroscopeAgent.profile. Having said that I will give it try to modify -da etc, I think you are right that there is something off about it. 

It does look like opening a case for webex may be the last resort to give it a try. Thanks for the help here, I will post back my results around this issue.

thanks

Hi:

  An answer was given on what was the cause of the original exception. So marking correct.Normally would create a new branch. But I don't trust that right "branch" will be captured. I will make sure your log gets reviewed

Thanks

Hal German

6/08/17 04:02:41 PM PKT [ERROR] [IntroscopeAgent] Agent Unavailable
<Jun 8, 2017 4:02:41 PM PKT> <Notice> <WebLogicServer> <BEA-000395> <Following extensions directory contents added to the end of the classpath:
/bea/bea/user_projects/domains/CCSDomain/lib/WebAppSupport.jar>

is /bea/bea/user_projects/domains/CCSDomain/lib/WebAppSupport.jar linked to /bea/agent/wily/WebAppSupport.jar?

we initially thought that may be webAppSupport.jar in domain folder would make any difference, but we reverted this line back to original i.e. /bea/agent/wily/ (checked it with recent changes as well but results remained same)

Try to remove the startup class and check if you are still unable to startup the appserver

Thanks, we did try with this approach, removed the startup class and restarted weblogic application, same result:

a. the server starts up fine and does not crash

b. but the AgentNotAvailable exception is seen in logs right after loading jar classes from extension folder (it is always same point of failure i.e. [IntroscopeAgent.Agent] EagerClassLoader(IntelligentInstrumentation.jar): Pre-loaded 234 classes. After this line, the ERROR is shown "[IntroscopeAgent] Agent Unavailable")

c. There is no logs in the agent's log folder

d. agent also does not show any indication that it ever start on the EM

If I have the startup class, the only difference is that the startup class throws an extra error of AgentNotAvailable Exception. i.e.

<Critical> <WebLogicServer> <BEA-000286> <Failed to invoke startup class "APM-StartupClass", com.wily.introscope.agent.AgentNotAvailableException
com.wily.introscope.agent.AgentNotAvailableException
at com.wily.introscope.agent.AgentShim.IAgentShim_getAgent(AgentShim.java:696)
at com.wily.introscope.api.weblogic.IntroscopeStartupClass.startup(IntroscopeStartupClass.java:70)
at weblogic.management.deploy.classdeployment.ClassDeploymentManager.invokeStartup(ClassDeploymentManager.java:287)
at weblogic.management.deploy.classdeployment.ClassDeploymentManager.invokeClass(ClassDeploymentManager.java:265)
at weblogic.management.deploy.classdeployment.ClassDeploymentManager.access$000(ClassDeploymentManager.java:54)
Truncated. see log file for complete stacktrace

Thanks Muhammad. Have other customers seen this same issue? If so, please let us all know what you did to resolve. 

I see that Support Case 00763834 has been created to further assist with the troubleshooting of the issue.
I agree with Sergio's suggestion to try removing the startup class configuration and see if the start up is successful.
You may also want to check in the config.xml file to see if the Startup Class has indeed been configured correctly.

FYI, Resolution:
Had webex session with the customer. Deployed a debug jar. Agent is not able to get attached to the JVM. Then we noticed it to be IBM JVM on AIX. Recommended the customer to use AgentNoRedefNoRetrans.jar & IntroscopeAgent.NoRedef.profile and provided them Websphere Agent installation. With this configuration the issue is resolved and agent is working. 

This has also come up for other users and I have created a new knowledge document TEC1176763:

The APM documentation recommends using AgentNoRedefNoRetrans.jar instead of Agent.jar for WebSphere Application Server running an IBM JVM. Is that also true for any other type of Application Server running an IBM JVM e.g. WebLogic.