Grinder agent communication shut down when worker process launched
"alfinhaji ." <[email protected]> Thu, 19 Nov 2015 16:00:52 -0500
| Newsgroups | gmane.comp.java.grinder.user |
|---|---|
| Message-ID | <CACqy2TpPkGe9sSJOatkRf_+fKhH4sQA7xVM8DkUMts8r3-7uRQ@mail.gmail.com> |
--===============2931705456745035957==
Content-Type: multipart/alternative; boundary=001a1147bf20e71b290524eb0d88
--001a1147bf20e71b290524eb0d88
Content-Type: text/plain; charset=UTF-8
Hi all,
Looking for an issue we have been troubleshooting for a few days now. This
issue has exposed itself after our client moved over to a new data center
requiring us to rebuild our grinder environments. Our grinder test
infrastructure is fully functional in the old environment, and these issues
have exposed themselves in the new environment only. Here is a run down of
the issue.
1. Running headless console as we haven't been provided with X11 terminal
emulation. (this is new compared to the old environment, where we ran the
Console UI)
2. Console starts up fine, agent starts up fine, and connects to the
console.
$ tail -f grinderAgentoutput.log
Setting argument grinder.consolePort=6372
+ JAVA_ARGS=' -Dgrinder.useConsole=true -Dgrinder.consoleHost=L-01942-C5F
-Dgrinder.consolePort=6372'
+ java -cp /test_data/grinder_artifacts/grinder/lib/grinder.jar:
-Dgrinder.useConsole=true -Dgrinder.consoleHost=L-01942-C5F
-Dgrinder.consolePort=6372 net.grinder.Grinder -daemon 10
2015-11-19 15:26:41,336 INFO agent: The Grinder 3.11
2015-11-19 15:26:41,358 ERROR agent: Failed to connect to 'L-01942-C5F/
10.237.119.71:6372'
2015-11-19 15:26:41,358 INFO agent: agent finished
2015-11-19 15:26:41,358 INFO agent: sleeping for 10000 ms
2015-11-19 15:26:51,358 INFO agent: The Grinder 3.11
2015-11-19 15:26:51,404 INFO agent: connected to console at L-01942-C5F/
10.237.119.71:6372
2015-11-19 15:26:51,405 INFO agent: waiting for console signal
3. At this point I can test the agent service and get a valid JSON
response back:
$ curl http://L-01942-C5F:6373/agents/status
[{"id":"L-01942-C5F:1509753335|1447964801332|1679207110:0","name":"L-01942-C5F","number":0,"state":"RUNNING","workers":[]}]
4. I kick off our test automation, which eventually makes a call to start
the worker process:
http://L-01942-C5F:6373/agents/start-workers (we pass the grinder
properties in when we make this POST call using the REST API)
5. As soon as the worker process is started, we see the test kick off
perfectly fine, validated from the agent log file:
2015-11-19 15:28:04,320 INFO agent: received a start message
*2015-11-19 15:28:04,325 INFO agent: communication shut down*
2015-11-19 15:28:04,473 INFO agent: Worker process command line:
/test_data/grinder_artifacts/java/jdk1.7.0_25/jre/bin/java
'-javaagent:/test_data/grinder_artifacts/grinder/lib/grinder-dcr-agent-3.11.jar'
'-Dpython.path=/test_data/projects/common/src'
'-Dpython.cachedir=/tmp/cachedir' '-Xms2g' '-Xmx2g' '-XX:NewSize=1g'
'-XX:MaxNewSize=1g' '-verbose:gc' '-XX:+PrintGCDetails'
'-XX:+PrintGCTimeStamps' '-XX:+UseConcMarkSweepGC' '-XX:+UseParNewGC'
'-XX:+ExplicitGCInvokesConcurrent' '-XX:+CMSConcurrentMTEnabled'
'-XX:+AlwaysPreTouch' '-XX:+UseCompressedOops' -classpath
'/test_data/grinder_artifacts/lib/jsoup-1.6.1.jar:/test_data/grinder_artifacts/lib/jyson-1.0.2.jar:/test_data/grinder_artifacts/grinder/lib/grinder.jar'
net.grinder.engine.process.WorkerProcessEntryPoint
2015-11-19 15:28:04,493 INFO agent: worker L-01942-C5F-0 started
10.940: [GC 10.940: [ParNew: 838912K->32398K(943744K), 0.0570450 secs]
838912K->32398K(1992320K), 0.0572580 secs] [Times: user=0.10 sys=0.00,
real=0.06 secs]
2015-11-19 15:28:18,767 INFO L-01942-C5F-0: starting threads
14.306: [GC 14.306: [ParNew: 871310K->39438K(943744K), 0.0550070 secs]
871310K->39438K(1992320K), 0.0551420 secs] [Times: user=0.11 sys=0.00,
real=0.06 secs]
2015-11-19 15:28:19,128 INFO L-01942-C5F-0: will shut down after 900000 ms
2015-11-19 15:28:56,156 INFO L-01942-C5F-0: finished
Heap
par new generation total 943744K, used 179113K [0x000000077ae00000,
0x00000007bae00000, 0x00000007bae00000)
eden space 838912K, 14% used [0x000000077ae00000, 0x00000007821cf968,
0x00000007ae140000)
from space 104832K, 57% used [0x00000007b47a0000, 0x00000007b82badb0,
0x00000007bae00000)
to space 104832K, 0% used [0x00000007ae140000, 0x00000007ae140000,
0x00000007b47a0000)
concurrent mark-sweep generation total 1048576K, used 0K
[0x00000007bae00000, 0x00000007fae00000, 0x00000007fae00000)
concurrent-mark-sweep perm gen total 35456K, used 35295K
[0x00000007fae00000, 0x00000007fd0a0000, 0x0000000800000000)
2015-11-19 15:28:56,503 INFO agent: agent finished
2015-11-19 15:28:56,503 INFO agent: sleeping for 10000 ms
Our custom test automation we have built, however, polls the agent status
on a regular basis to see if the worker process has completed. We do this
to automate multiple tests in sequence, once a test ends (worker process
complete), our automation will immediately kick off another worker process
to start the next test we have defined. Unfortunately, what I am seeing
since moving to this "new" grinder environment is this polling of the agent
status comes back with a valid HTTP 200 with nothing in the JSON body,
completely blank, while the worker process is executing the test. Here is
what I see when I continuously send the CURL request off to check the agent
status just as the worker process is starting:
$ curl http://L-01942-C5F:6373/agents/status
[{"id":"L-01942-C5F:1509753335|1447964801332|1679207110:0","name":"L-01942-C5F","number":0,"state":"
*RUNNING*","workers":[]}]
$ curl http://L-01942-C5F:6373/agents/status
[{"id":"L-01942-C5F:1509753335|1447964801332|1679207110:0","name":"L-01942-C5F","number":0,"state":"
*FINISHED*","workers":[]}]
$ curl http://L-01942-C5F:6373/agents/status
[] <---- *blank JSON response*
Also note in the agent log above we see a "communication is shut down"
message (which we don't see in the old environment).
As soon as the worker process completes the grinder test, we see the agent
re-establish connection to the console and start getting a valid RUNNING
status on the agent status:
Agent log file:
2015-11-19 15:29:06,504 INFO agent: The Grinder 3.11
2015-11-19 15:29:06,505 INFO agent: connected to console at L-01942-C5F/
10.237.119.71:6372
2015-11-19 15:29:06,505 INFO agent: waiting for console signal
Curl output
$ curl http://L-01942-C5F:6373/agents/status
[{"id":"L-01942-C5F:1509753335|1447964801332|1679207110:0","name":"L-01942-C5F","number":0,"state":"
*RUNNING*","workers":[]}]
Some more info:
Running console, agent, and worker process info:
$ ps -ef | grep java
grinder 28379 1 1 15:26 pts/0 00:00:17
/test_data/grinder_artifacts/java/jdk1.7.0_25/bin/java -cp
/test_data/grinder_artifacts/grinder/lib/grinder.jar:
-Dgrinder.console.httpHost=L-01942-C5F net.grinder.Console -headless
grinder 28385 28380 0 15:26 pts/0 00:00:03 java -cp
/test_data/grinder_artifacts/grinder/lib/grinder.jar:
-Dgrinder.useConsole=true -Dgrinder.consoleHost=L-01942-C5F
-Dgrinder.consolePort=6372 net.grinder.Grinder -daemon 10
grinder 29190 28385 42 15:53 pts/0 00:00:00
/test_data/grinder_artifacts/java/jdk1.7.0_25/jre/bin/java
-javaagent:/test_data/grinder_artifacts/grinder/lib/grinder-dcr-agent-3.11.jar
-Dpython.path=/test_data/projects/common/src
-Dpython.cachedir=/tmp/cachedir -Xms2g -Xmx2g -XX:NewSize=1g
-XX:MaxNewSize=1g -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps
-XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+ExplicitGCInvokesConcurrent
-XX:+CMSConcurrentMTEnabled -XX:+AlwaysPreTouch -XX:+UseCompressedOops
-classpath
/test_data/grinder_artifacts/lib/jsoup-1.6.1.jar:/test_data/grinder_artifacts/lib/jyson-1.0.2.jar:/test_data/grinder_artifacts/grinder/lib/grinder.jar
net.grinder.engine.process.WorkerProcessEntryPoint
So the million dollar question, why is it that the agent loses
communication with the console when the worker process starts executing?
This is essentially causing our call the /agent/status to fail, and our
test automation fails out even though worker process kicks off the test
just fine.
Any assistance or input would be greatly appreciated.
Thanks,
Alfin Haji
--001a1147bf20e71b290524eb0d88
Content-Type: text/html; charset=UTF-8
Content-Transfer-Encoding: quoted-printable
<div dir=3D"ltr"><div>Hi all,</div><div><br></div><div>Looking for an issue=
we have been troubleshooting for a few days now.=C2=A0 This issue has expo=
sed itself after our client moved over to a new data center requiring us to=
rebuild our grinder environments.=C2=A0 Our grinder test infrastructure is=
fully functional in the old environment, and these issues have exposed the=
mselves in the new environment only.=C2=A0 Here is a run down of the issue.=
</div><div><br></div><div>1.=C2=A0 Running headless console as we haven'=
;t been provided with X11 terminal emulation. (this is new compared to the =
old environment, where we ran the Console UI)</div><div>2.=C2=A0 Console st=
arts up fine, agent starts up fine, and connects to the console.</div><div>=
<br></div><div>$ tail -f grinderAgentoutput.log<br>Setting argument grinder=
.consolePort=3D6372<br>+ JAVA_ARGS=3D' -Dgrinder.useConsole=3Dtrue -Dgr=
inder.consoleHost=3DL-01942-C5F -Dgrinder.consolePort=3D6372'<br>+ java=
-cp /test_data/grinder_artifacts/grinder/lib/grinder.jar: -Dgrinder.useCon=
sole=3Dtrue -Dgrinder.consoleHost=3DL-01942-C5F -Dgrinder.consolePort=3D637=
2 net.grinder.Grinder -daemon 10<br>2015-11-19 15:26:41,336 INFO=C2=A0 agen=
t: The Grinder 3.11<br>2015-11-19 15:26:41,358 ERROR agent: Failed to conne=
ct to 'L-01942-C5F/<a href=3D"http://10.237.119.71:6372">10.237.119.71:=
6372</a>'<br>2015-11-19 15:26:41,358 INFO=C2=A0 agent: agent finished<b=
r>2015-11-19 15:26:41,358 INFO=C2=A0 agent: sleeping for 10000 ms<br>2015-1=
1-19 15:26:51,358 INFO=C2=A0 agent: The Grinder 3.11<br>2015-11-19 15:26:51=
,404 INFO=C2=A0 agent: connected to console at L-01942-C5F/<a href=3D"http:=
//10.237.119.71:6372">10.237.119.71:6372</a><br>2015-11-19 15:26:51,405 INF=
O=C2=A0 agent: waiting for console signal</div><div><br></div><div>3.=C2=A0=
At this point I can test the agent service and get a valid JSON response b=
ack:</div><div><br></div><div>$ curl <a href=3D"http://L-01942-C5F:6373/age=
nts/status">http://L-01942-C5F:6373/agents/status</a><br>[{"id":&=
quot;L-01942-C5F:1509753335|1447964801332|1679207110:0","name&quo=
t;:"L-01942-C5F","number":0,"state":"RUN=
NING","workers":[]}]</div><div><br></div><div>4.=C2=A0 I kic=
k off our test automation, which eventually makes a call to start the worke=
r process:</div><div><br></div><div><a href=3D"http://L-01942-C5F:6373/agen=
ts/start-workers">http://L-01942-C5F:6373/agents/start-workers</a>=C2=A0 (w=
e pass the grinder properties in when we make this POST call using the REST=
API)</div><div><br></div><div>5. As soon as the worker process is started,=
we see the test kick off perfectly fine, validated from the agent log file=
:</div><div><br></div><div>2015-11-19 15:28:04,320 INFO=C2=A0 agent: receiv=
ed a start message<br><strong><font size=3D"4">2015-11-19 15:28:04,325 INFO=
=C2=A0 agent: communication shut down</font></strong><br>2015-11-19 15:28:0=
4,473 INFO=C2=A0 agent: Worker process command line: /test_data/grinder_art=
ifacts/java/jdk1.7.0_25/jre/bin/java '-javaagent:/test_data/grinder_art=
ifacts/grinder/lib/grinder-dcr-agent-3.11.jar' '-Dpython.path=3D/te=
st_data/projects/common/src' '-Dpython.cachedir=3D/tmp/cachedir'=
; '-Xms2g' '-Xmx2g' '-XX:NewSize=3D1g' '-XX:Max=
NewSize=3D1g' '-verbose:gc' '-XX:+PrintGCDetails' '=
-XX:+PrintGCTimeStamps' '-XX:+UseConcMarkSweepGC' '-XX:+Use=
ParNewGC' '-XX:+ExplicitGCInvokesConcurrent' '-XX:+CMSConcu=
rrentMTEnabled' '-XX:+AlwaysPreTouch' '-XX:+UseCompressedOo=
ps' -classpath '/test_data/grinder_artifacts/lib/jsoup-1.6.1.jar:/t=
est_data/grinder_artifacts/lib/jyson-1.0.2.jar:/test_data/grinder_artifacts=
/grinder/lib/grinder.jar' net.grinder.engine.process.WorkerProcessEntry=
Point<br>2015-11-19 15:28:04,493 INFO=C2=A0 agent: worker L-01942-C5F-0 sta=
rted<br>10.940: [GC 10.940: [ParNew: 838912K->32398K(943744K), 0.0570450=
secs] 838912K->32398K(1992320K), 0.0572580 secs] [Times: user=3D0.10 sy=
s=3D0.00, real=3D0.06 secs]<br>2015-11-19 15:28:18,767 INFO=C2=A0 L-01942-C=
5F-0: starting threads<br>14.306: [GC 14.306: [ParNew: 871310K->39438K(9=
43744K), 0.0550070 secs] 871310K->39438K(1992320K), 0.0551420 secs] [Tim=
es: user=3D0.11 sys=3D0.00, real=3D0.06 secs]<br>2015-11-19 15:28:19,128 IN=
FO=C2=A0 L-01942-C5F-0: will shut down after 900000 ms<br>2015-11-19 15:28:=
56,156 INFO=C2=A0 L-01942-C5F-0: finished<br>Heap<br>=C2=A0par new generati=
on=C2=A0=C2=A0 total 943744K, used 179113K [0x000000077ae00000, 0x00000007b=
ae00000, 0x00000007bae00000)<br>=C2=A0 eden space 838912K,=C2=A0 14% used [=
0x000000077ae00000, 0x00000007821cf968, 0x00000007ae140000)<br>=C2=A0 from =
space 104832K,=C2=A0 57% used [0x00000007b47a0000, 0x00000007b82badb0, 0x00=
000007bae00000)<br>=C2=A0 to=C2=A0=C2=A0 space 104832K,=C2=A0=C2=A0 0% used=
[0x00000007ae140000, 0x00000007ae140000, 0x00000007b47a0000)<br>=C2=A0conc=
urrent mark-sweep generation total 1048576K, used 0K [0x00000007bae00000, 0=
x00000007fae00000, 0x00000007fae00000)<br>=C2=A0concurrent-mark-sweep perm =
gen total 35456K, used 35295K [0x00000007fae00000, 0x00000007fd0a0000, 0x00=
00000800000000)<br>2015-11-19 15:28:56,503 INFO=C2=A0 agent: agent finished=
<br>2015-11-19 15:28:56,503 INFO=C2=A0 agent: sleeping for 10000 ms<br><br>=
</div><div><br></div><div><br></div><div>Our custom test automation we have=
built, however,=C2=A0polls the agent status on a regular basis to see if t=
he worker process has completed.=C2=A0 We do this to automate multiple test=
s in sequence, once a test ends (worker process complete), our automation w=
ill immediately kick off another worker process to start the next test we h=
ave defined.=C2=A0 Unfortunately, what I am seeing since moving to this &qu=
ot;new" grinder environment=C2=A0is this polling of the agent status c=
omes back with a valid HTTP 200 with nothing in the JSON body, completely b=
lank, while the worker process is executing the test.=C2=A0 Here is what I =
see when I continuously send the CURL request off to check the agent status=
just as the worker process is starting:</div><div><br></div><div><br></div=
><div>$ curl <a href=3D"http://L-01942-C5F:6373/agents/status">http://L-019=
42-C5F:6373/agents/status</a><br>[{"id":"L-01942-C5F:1509753=
335|1447964801332|1679207110:0","name":"L-01942-C5F&quo=
t;,"number":0,"state":"<strong>RUNNING</strong>&qu=
ot;,"workers":[]}]</div><div>$ curl <a href=3D"http://L-01942-C5F=
:6373/agents/status">http://L-01942-C5F:6373/agents/status</a><br>[{"i=
d":"L-01942-C5F:1509753335|1447964801332|1679207110:0","=
;name":"L-01942-C5F","number":0,"state":=
"<strong>FINISHED</strong>","workers":[]}]</div><div>$ =
curl <a href=3D"http://L-01942-C5F:6373/agents/status">http://L-01942-C5F:6=
373/agents/status</a><br>[]=C2=A0=C2=A0 =C2=A0<---- <strong>blank JSON r=
esponse</strong></div><div><br></div><div>Also note in the agent log above =
we see a "communication is shut down" message (which we don't=
see in the old environment).</div><div><br></div><div>As soon as the worke=
r process completes the grinder test,=C2=A0we see the agent re-establish co=
nnection to the console and=C2=A0start getting a valid RUNNING status on th=
e agent status:</div><div><br></div><div>Agent log file:</div><div><br></di=
v><div>2015-11-19 15:29:06,504 INFO=C2=A0 agent: The Grinder 3.11<br>2015-1=
1-19 15:29:06,505 INFO=C2=A0 agent: connected to console at L-01942-C5F/<a =
href=3D"http://10.237.119.71:6372">10.237.119.71:6372</a><br>2015-11-19 15:=
29:06,505 INFO=C2=A0 agent: waiting for console signal</div><div><br></div>=
<div>Curl output</div><div><div><br></div><div>$ curl <a href=3D"http://L-0=
1942-C5F:6373/agents/status">http://L-01942-C5F:6373/agents/status</a><br>[=
{"id":"L-01942-C5F:1509753335|1447964801332|1679207110:0&quo=
t;,"name":"L-01942-C5F","number":0,"stat=
e":"<strong>RUNNING</strong>","workers":[]}]</div>=
<div><br></div><div><br></div><div>Some more info:</div><div><br></div><div=
>Running console, agent, and worker process info:</div><div><br></div><div>=
<br></div><div>$ ps -ef | grep java<br>grinder=C2=A0 28379=C2=A0=C2=A0=C2=
=A0=C2=A0 1=C2=A0 1 15:26 pts/0=C2=A0=C2=A0=C2=A0 00:00:17 /test_data/grind=
er_artifacts/java/jdk1.7.0_25/bin/java -cp /test_data/grinder_artifacts/gri=
nder/lib/grinder.jar: -Dgrinder.console.httpHost=3DL-01942-C5F net.grinder.=
Console -headless<br>grinder=C2=A0 28385 28380=C2=A0 0 15:26 pts/0=C2=A0=C2=
=A0=C2=A0 00:00:03 java -cp /test_data/grinder_artifacts/grinder/lib/grinde=
r.jar: -Dgrinder.useConsole=3Dtrue -Dgrinder.consoleHost=3DL-01942-C5F -Dgr=
inder.consolePort=3D6372 net.grinder.Grinder -daemon 10<br>grinder=C2=A0 29=
190 28385 42 15:53 pts/0=C2=A0=C2=A0=C2=A0 00:00:00 /test_data/grinder_arti=
facts/java/jdk1.7.0_25/jre/bin/java -javaagent:/test_data/grinder_artifacts=
/grinder/lib/grinder-dcr-agent-3.11.jar -Dpython.path=3D/test_data/projects=
/common/src -Dpython.cachedir=3D/tmp/cachedir -Xms2g -Xmx2g -XX:NewSize=3D1=
g -XX:MaxNewSize=3D1g -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamp=
s -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+ExplicitGCInvokesConcurrent=
-XX:+CMSConcurrentMTEnabled -XX:+AlwaysPreTouch -XX:+UseCompressedOops -cl=
asspath /test_data/grinder_artifacts/lib/jsoup-1.6.1.jar:/test_data/grinder=
_artifacts/lib/jyson-1.0.2.jar:/test_data/grinder_artifacts/grinder/lib/gri=
nder.jar net.grinder.engine.process.WorkerProcessEntryPoint<br></div><div><=
br></div><div><br></div><div><br></div><div>So the million dollar question,=
why is it that the agent loses communication with the console when the wor=
ker process starts executing?=C2=A0 This is essentially causing our call th=
e /agent/status to fail, and our test automation fails out even though work=
er process kicks off the test just fine.</div><div><br></div><div>Any assis=
tance or input would be greatly appreciated.<br></div><div><br></div><div>T=
hanks,</div><div>Alfin Haji<br></div></div></div>
--001a1147bf20e71b290524eb0d88--
--===============2931705456745035957==
Content-Type: text/plain; charset="us-ascii"
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Content-Disposition: inline
------------------------------------------------------------------------------
--===============2931705456745035957==
Content-Type: text/plain; charset="us-ascii"
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Content-Disposition: inline
_______________________________________________
grinder-use mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/grinder-use
--===============2931705456745035957==--