Recently (over the past few days) I've been experiencing unusual behaviour from the OLT Agent. I have a set of saved scenarios using both the main (controller) agent and a second (remote) agent to run a total of 9 scripts. Intermittently the agents fail to start with an error "Error communicating with Oracle Load Testing Agent Manager on oats-am://CONTROLLERBOX:9001: Timed out after 60 seconds." (and "Stopped Autopilot because of error on agent "CONTROLLERBOX".") It's the local agent that appears to be failing (the scenario aborts before the remote agent is even called into use).
I've tried the obvious things like re-starting the application service (and the agent service) and even re-booting the server, but can't find a pattern to this. The same scenario will work one day but fail the next. I have also seen it "just start working again" (with no apparent changes). Don't you just hate it when that happens!
Has anyone had similar issues? (I'm on OATS v9.10.0.0 but OLT shows as v9.10.0182)
It's not an authentication issue as the agentmanager_auth.log shows sucessful authentication. In fact you do see one script in the scenario appear to load and start, but then the agent fails. However I have noticed the following in the agentmanager_ath.log file again showing the agent starting then stopping:
13:59:11,891 INFO [EmpStartAuthenticator] Authentication config has been updated on Mon Jun 07 10:57:24 BST 2010
13:59:11,922 INFO [AgentProcessDescriptorManager] Loaded process descriptor <AgentProcessDescriptor
descriptorFile=C:\OracleATS\agentmanager\processDescriptors\DataCollector.properties
typeId=service.exe
exe=C:\OracleATS\DataCollector\bin\service.exe
workingDir=C:\OracleATS\DataCollector\bin
settingsHandler=oracle.oats.agents.processDescriptors.DataCollector.SettingsHandler />
13:59:11,922 INFO [AgentProcessDescriptorManager] Loaded process descriptor <AgentProcessDescriptor
descriptorFile=C:\OracleATS\agentmanager\processDescriptors\ETesterEx.properties
typeId=eTesterEx.exe
exe=C:\OracleATS\OFT\ETesterEx.exe
workingDir=C:\OracleATS\OFT
settingsHandler=oracle.oats.agents.processDescriptors.ETesterEx.SettingsHandler />
13:59:12,047 INFO [AgentProcessDescriptorManager] Loaded process descriptor <AgentProcessDescriptor
descriptorFile=C:\OracleATS\agentmanager\processDescriptors\JavaAgent.properties
typeId=empJAgent.exe
exe=C:\OracleATS\jdk\jre\bin\olt-agent.exe
workingDir=C:\OracleATS\agent
settingsHandler=oracle.oats.agents.processDescriptors.JavaAgent.SettingsHandler />
13:59:12,047 INFO [AgentProcessDescriptorManager] Loaded process descriptor <AgentProcessDescriptor
descriptorFile=C:\OracleATS\agentmanager\processDescriptors\OpenScript.properties
typeId=openScriptCML.exe
exe=C:\OracleATS\jdk\jre\bin\otm-ose-agent.exe
workingDir=C:\OracleATS\agent
settingsHandler=oracle.oats.agents.processDescriptors.OpenScript.SettingsHandler />
13:59:12,062 INFO [AgentProcessDescriptorManager] Loaded process descriptor <AgentProcessDescriptor
descriptorFile=C:\OracleATS\agentmanager\processDescriptors\RswMint.properties
typeId=RswMint.exe
exe=C:\OracleATS\OFT\RswMint.exe
workingDir=C:\OracleATS\OFT
settingsHandler=oracle.oats.agents.processDescriptors.RswMint.SettingsHandler />
13:59:12,062 INFO [AgentProcessDescriptorManager] Loaded process descriptor <AgentProcessDescriptor
descriptorFile=C:\OracleATS\agentmanager\processDescriptors\ThirdPartyTest.properties
typeId=thirdPartyTest.exe
exe=C:\OracleATS\jdk\jre\bin\otm-3rdparty-agent.exe
workingDir=C:\OracleATS\agent
settingsHandler=oracle.oats.agents.processDescriptors.ThirdPartyTest.SettingsHandler />
13:59:12,078 INFO [AgentProcessDescriptorManager] Loaded process descriptor <AgentProcessDescriptor
descriptorFile=C:\OracleATS\agentmanager\processDescriptors\WgPro.properties
typeId=WgPro.exe
exe=C:\OracleATS\OFT\WgPro.exe
workingDir=C:\OracleATS\OFT
settingsHandler=oracle.oats.agents.processDescriptors.WgPro.SettingsHandler />
13:59:12,078 INFO [Messenger] Messenger Loaded....
13:59:12,078 INFO [EmpStartMain] PortListener Loaded....
13:59:12,203 INFO [ProcessRunnerFactory] Constructed Generic process runner
13:59:12,219 INFO [EmpStartMain] EmpStart initialization complete: port=9001, agentManagerDir=C:\OracleATS\agentmanager, version=9.10.0182.000
13:59:14,766 INFO [EmpStartMain] Listening on port: 9001
13:59:31,266 INFO [Messenger] Try server=t3://oldcsstestvm13:8088 queue=oracle/oats/queue/AgentPoolNotificationQueue
13:59:32,219 INFO [Messenger] Got ConnectionFactory
13:59:32,266 INFO [Messenger] Got queue oracle/oats/queue/AgentPoolNotificationQueue
13:59:46,812 INFO [Messenger] Created queue connection.
13:59:47,062 INFO [Messenger] Created queue session.
13:59:47,094 INFO [Messenger] Connected to server=t3://oldcsstestvm13:8088 queue=oracle/oats/queue/AgentPoolNotificationQueue
13:59:47,094 INFO [Request] [URL:t3://oldcsstestvm13:8088;Requestor Username: oats-agent;Requestor Key:09e865e3-40aa-4520-a9cd-f759db7137b0;Requestor Queue:oracle/oats/queue/AgentPoolNotificationQueue;Request ID:3;Request:startagent;] - authentication successful
13:59:47,109 INFO [EmpStartMain] handleStartAgentRequestRequest ID: 3, RKey: 09e865e3-40aa-4520-a9cd-f759db7137b0, RUrl: t3://oldcsstestvm13:8088, RUsername: oats-agent, RQueue : oracle/oats/queue/AgentPoolNotificationQueue, Request: startagent, Agent Type: empJAgent.exe, Agent ID: agId8_rnd059878b3-0abf-441a-8a4e-8dc2475b2270, Agent Cmd : empJAgent.exe -Xmx512m -classpath determinedAtRunTime oracle.oats.jagent.EntryPoint jms /token: /id:agId8_rnd059878b3-0abf-441a-8a4e-8dc2475b2270 /version:9.10.0182.000 /clusterurl:t3://oldcsstestvm13:8088 /clusterhttpurl:http://oldcsstestvm13:8088 /pooltopic:oracle/oats/topic/AgentPoolControlTopic /poolqueue:oracle/oats/queue/AgentPoolNotificationQueue, Agent Checksum: [], Agent Credential Type: default, Version: 9.10.0182.000
13:59:47,109 INFO [SettingsHandler] extracted 'debug' command line params for null: -Xmx512m
13:59:47,109 INFO [ProcessRunner]
startAgent(
pathToExe=C:\OracleATS\jdk\jre\bin\olt-agent.exe
cmdLineArgs=-jrockit -Xrs -XgcPrio:deterministic -XpauseTarget=50ms -XlargePages -XXaggressive -XXcallProfiling -XXexitOnOutOfMemory -XX:+UseThreadPriorities -Xmx512M -Xms512M -Xmx512m -classpath ;C:\OracleATS\agent\jars\EntryPointWrapper.jar;C:\OracleATS\agent\jars\Framework.jar oracle.oats.jagent.EntryPointWrapper oracle.oats.jagent.EntryPoint -installdir C:\OracleATS\jdk\jre\..\.. jms /token: /id:agId8_rnd059878b3-0abf-441a-8a4e-8dc2475b2270 /version:9.10.0182.000 /clusterurl:t3://oldcsstestvm13:8088 /clusterhttpurl:http://oldcsstestvm13:8088 /pooltopic:oracle/oats/topic/AgentPoolControlTopic /poolqueue:oracle/oats/queue/AgentPoolNotificationQueue
workingDir=C:\OracleATS\agent
agentId=agId8_rnd059878b3-0abf-441a-8a4e-8dc2475b2270
requestor=09e865e3-40aa-4520-a9cd-f759db7137b0), returning ID 1)
13:59:47,141 INFO [AgentProcess] Launching agent 09e865e3-40aa-4520-a9cd-f759db7137b0:agId8_rnd059878b3-0abf-441a-8a4e-8dc2475b2270
cmdLine=C:\OracleATS\jdk\jre\bin\olt-agent.exe -jrockit -Xrs -XgcPrio:deterministic -XpauseTarget=50ms -XlargePages -XXaggressive -XXcallProfiling -XXexitOnOutOfMemory -XX:+UseThreadPriorities -Xmx512M -Xms512M -Xmx512m -classpath ;C:\OracleATS\agent\jars\EntryPointWrapper.jar;C:\OracleATS\agent\jars\Framework.jar oracle.oats.jagent.EntryPointWrapper oracle.oats.jagent.EntryPoint -installdir C:\OracleATS\jdk\jre\..\.. jms /token: /id:agId8_rnd059878b3-0abf-441a-8a4e-8dc2475b2270 /version:9.10.0182.000 /clusterurl:t3://oldcsstestvm13:8088 /clusterhttpurl:http://oldcsstestvm13:8088 /pooltopic:oracle/oats/topic/AgentPoolControlTopic /poolqueue:oracle/oats/queue/AgentPoolNotificationQueue
workingDir=C:\OracleATS\agent
13:59:47,188 INFO [AgentProcess] Launched process 253217861 for agent agId8_rnd059878b3-0abf-441a-8a4e-8dc2475b2270
14:00:32,125 INFO [Messenger] Try server=t3://oldcsstestvm13:8088 queue=oracle/oats/queue/AgentPoolNotificationQueue
14:00:33,094 INFO [Messenger] Got ConnectionFactory
14:00:33,094 INFO [Messenger] Got queue oracle/oats/queue/AgentPoolNotificationQueue
14:00:33,109 INFO [Messenger] Created queue connection.
14:00:33,109 INFO [Messenger] Created queue session.
14:00:33,109 INFO [Messenger] Connected to server=t3://oldcsstestvm13:8088 queue=oracle/oats/queue/AgentPoolNotificationQueue
14:00:33,109 INFO [Request] [URL:t3://oldcsstestvm13:8088;Requestor Username: oats-agent;Requestor Key:09e865e3-40aa-4520-a9cd-f759db7137b0;Requestor Queue:oracle/oats/queue/AgentPoolNotificationQueue;Request ID:4;Request:stopagent;] - authentication successful
14:00:33,109 INFO [ProcessRunner] stopAgent(requestor=09e865e3-40aa-4520-a9cd-f759db7137b0,agentID=agId8_rnd059878b3-0abf-441a-8a4e-8dc2475b2270)
14:00:33,109 INFO [ProcessRunner] Stopping agent 09e865e3-40aa-4520-a9cd-f759db7137b0:agId8_rnd059878b3-0abf-441a-8a4e-8dc2475b2270
14:00:33,109 WARN [AgentProcess] Forcibly terminating process 253217861 for agent agId8_rnd059878b3-0abf-441a-8a4e-8dc2475b2270
14:00:33,125 INFO [AgentProcess] Exited process 253217861 for agent agId8_rnd059878b3-0abf-441a-8a4e-8dc2475b2270
14:00:33,125 INFO [ProcessRunner] Agent 09e865e3-40aa-4520-a9cd-f759db7137b0:agId8_rnd059878b3-0abf-441a-8a4e-8dc2475b2270 exited, code = 1
14:00:33,125 INFO [Messenger] Messenger Loaded....
14:00:33,141 INFO [Messenger] Try server=t3://oldcsstestvm13:8088 queue=oracle/oats/queue/AgentPoolNotificationQueue
14:00:33,141 INFO [Messenger] Got ConnectionFactory
14:00:33,141 INFO [Messenger] Got queue oracle/oats/queue/AgentPoolNotificationQueue
14:00:33,141 INFO [Messenger] Created queue connection.
14:00:33,141 INFO [Messenger] Created queue session.
14:00:33,141 INFO [Messenger] Connected to server=t3://oldcsstestvm13:8088 queue=oracle/oats/queue/AgentPoolNotificationQueue
14:02:21,531 INFO [Messenger] Try server=t3://oldcsstestvm13:8088 queue=oracle/oats/queue/AgentPoolNotificationQueue
14:02:21,547 INFO [Messenger] Got ConnectionFactory
14:02:21,547 INFO [Messenger] Got queue oracle/oats/queue/AgentPoolNotificationQueue
14:02:21,547 INFO [Messenger] Created queue connection.
14:02:21,547 INFO [Messenger] Created queue session.
14:02:21,562 INFO [Messenger] Connected to server=t3://oldcsstestvm13:8088 queue=oracle/oats/queue/AgentPoolNotificationQueue
14:02:21,562 INFO [Request] [URL:t3://oldcsstestvm13:8088;Requestor Username: oats-agent;Requestor Key:09e865e3-40aa-4520-a9cd-f759db7137b0;Requestor Queue:oracle/oats/queue/AgentPoolNotificationQueue;Request ID:5;Request:startagent;] - authentication successful
14:02:21,562 INFO [EmpStartMain] handleStartAgentRequestRequest ID: 5, RKey: 09e865e3-40aa-4520-a9cd-f759db7137b0, RUrl: t3://oldcsstestvm13:8088, RUsername: oats-agent, RQueue : oracle/oats/queue/AgentPoolNotificationQueue, Request: startagent, Agent Type: empJAgent.exe, Agent ID: agId14_rnda3788b78-06fa-4adb-8945-1e9f36c4e8f9, Agent Cmd : empJAgent.exe -Xmx512m -classpath determinedAtRunTime oracle.oats.jagent.EntryPoint jms /token: /id:agId14_rnda3788b78-06fa-4adb-8945-1e9f36c4e8f9 /version:9.10.0182.000 /clusterurl:t3://oldcsstestvm13:8088 /clusterhttpurl:http://oldcsstestvm13:8088 /pooltopic:oracle/oats/topic/AgentPoolControlTopic /poolqueue:oracle/oats/queue/AgentPoolNotificationQueue, Agent Checksum: [], Agent Credential Type: default, Version: 9.10.0182.000
14:02:21,562 INFO [SettingsHandler] extracted 'debug' command line params for null: -Xmx512m
14:02:21,562 INFO [ProcessRunner]
startAgent(
pathToExe=C:\OracleATS\jdk\jre\bin\olt-agent.exe
cmdLineArgs=-jrockit -Xrs -XgcPrio:deterministic -XpauseTarget=50ms -XlargePages -XXaggressive -XXcallProfiling -XXexitOnOutOfMemory -XX:+UseThreadPriorities -Xmx512M -Xms512M -Xmx512m -classpath ;C:\OracleATS\agent\jars\EntryPointWrapper.jar;C:\OracleATS\agent\jars\Framework.jar oracle.oats.jagent.EntryPointWrapper oracle.oats.jagent.EntryPoint -installdir C:\OracleATS\jdk\jre\..\.. jms /token: /id:agId14_rnda3788b78-06fa-4adb-8945-1e9f36c4e8f9 /version:9.10.0182.000 /clusterurl:t3://oldcsstestvm13:8088 /clusterhttpurl:http://oldcsstestvm13:8088 /pooltopic:oracle/oats/topic/AgentPoolControlTopic /poolqueue:oracle/oats/queue/AgentPoolNotificationQueue
workingDir=C:\OracleATS\agent
agentId=agId14_rnda3788b78-06fa-4adb-8945-1e9f36c4e8f9
requestor=09e865e3-40aa-4520-a9cd-f759db7137b0), returning ID 1)
14:02:21,562 INFO [AgentProcess] Launching agent 09e865e3-40aa-4520-a9cd-f759db7137b0:agId14_rnda3788b78-06fa-4adb-8945-1e9f36c4e8f9
cmdLine=C:\OracleATS\jdk\jre\bin\olt-agent.exe -jrockit -Xrs -XgcPrio:deterministic -XpauseTarget=50ms -XlargePages -XXaggressive -XXcallProfiling -XXexitOnOutOfMemory -XX:+UseThreadPriorities -Xmx512M -Xms512M -Xmx512m -classpath ;C:\OracleATS\agent\jars\EntryPointWrapper.jar;C:\OracleATS\agent\jars\Framework.jar oracle.oats.jagent.EntryPointWrapper oracle.oats.jagent.EntryPoint -installdir C:\OracleATS\jdk\jre\..\.. jms /token: /id:agId14_rnda3788b78-06fa-4adb-8945-1e9f36c4e8f9 /version:9.10.0182.000 /clusterurl:t3://oldcsstestvm13:8088 /clusterhttpurl:http://oldcsstestvm13:8088 /pooltopic:oracle/oats/topic/AgentPoolControlTopic /poolqueue:oracle/oats/queue/AgentPoolNotificationQueue
workingDir=C:\OracleATS\agent
14:02:21,562 INFO [AgentProcess] Launched process 252156369 for agent agId14_rnda3788b78-06fa-4adb-8945-1e9f36c4e8f9
14:03:21,625 INFO [Messenger] Try server=t3://oldcsstestvm13:8088 queue=oracle/oats/queue/AgentPoolNotificationQueue
14:03:21,625 INFO [Messenger] Got ConnectionFactory
14:03:21,625 INFO [Messenger] Got queue oracle/oats/queue/AgentPoolNotificationQueue
14:03:21,656 INFO [Messenger] Created queue connection.
14:03:21,672 INFO [Messenger] Created queue session.
14:03:21,672 INFO [Messenger] Connected to server=t3://oldcsstestvm13:8088 queue=oracle/oats/queue/AgentPoolNotificationQueue
14:03:21,672 INFO [Request] [URL:t3://oldcsstestvm13:8088;Requestor Username: oats-agent;Requestor Key:09e865e3-40aa-4520-a9cd-f759db7137b0;Requestor Queue:oracle/oats/queue/AgentPoolNotificationQueue;Request ID:6;Request:stopagent;] - authentication successful
14:03:21,672 INFO [ProcessRunner] stopAgent(requestor=09e865e3-40aa-4520-a9cd-f759db7137b0,agentID=agId14_rnda3788b78-06fa-4adb-8945-1e9f36c4e8f9)
14:03:21,672 INFO [ProcessRunner] Stopping agent 09e865e3-40aa-4520-a9cd-f759db7137b0:agId14_rnda3788b78-06fa-4adb-8945-1e9f36c4e8f9
14:03:21,672 WARN [AgentProcess] Forcibly terminating process 252156369 for agent agId14_rnda3788b78-06fa-4adb-8945-1e9f36c4e8f9
14:03:21,672 INFO [AgentProcess] Exited process 252156369 for agent agId14_rnda3788b78-06fa-4adb-8945-1e9f36c4e8f9
14:03:21,734 INFO [ProcessRunner] Agent 09e865e3-40aa-4520-a9cd-f759db7137b0:agId14_rnda3788b78-06fa-4adb-8945-1e9f36c4e8f9 exited, code = 1
14:03:21,734 INFO [Messenger] Messenger Loaded....
14:03:21,734 INFO [Messenger] Try server=t3://oldcsstestvm13:8088 queue=oracle/oats/queue/AgentPoolNotificationQueue
14:03:21,766 INFO [Messenger] Got ConnectionFactory
14:03:21,766 INFO [Messenger] Got queue oracle/oats/queue/AgentPoolNotificationQueue
14:03:21,781 INFO [Messenger] Created queue connection.
14:03:21,781 INFO [Messenger] Created queue session.
14:03:21,781 INFO [Messenger] Connected to server=t3://oldcsstestvm13:8088 queue=oracle/oats/queue/AgentPoolNotificationQueue