Re: Grinder agent communication shut down when worker process launched
Ouray Viney <[email protected]> Thu, 19 Nov 2015 17:09:03 -0500
| Newsgroups | gmane.comp.java.grinder.user |
|---|---|
| Message-ID | <CAM5wVfgjL2Ltdxv6JtLiLFBkPUrYhfH-iV-0ZNVRO-ZUzi83Gw@mail.gmail.com> |
--===============1555888672492115442== Content-Type: multipart/alternative; boundary=001a11443346b6433e0524ec01bd --001a11443346b6433e0524ec01bd Content-Type: text/plain; charset=UTF-8 Hi Alfin , How restrictive are the firewall rules between the agent and the console? Cheers, Ouray On Thursday, November 19, 2015, alfinhaji . <[email protected]> wrote: > 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 > -- Sent from Gmail Mobile Ouray Viney Blog: https://www.viney.ca Skype: Ouray Viney LinkedIn: https://ca.linkedin.com/in/ourayvine --001a11443346b6433e0524ec01bd Content-Type: text/html; charset=UTF-8 Content-Transfer-Encoding: quoted-printable Hi Alfin ,<div><br></div><div>How restrictive are the firewall rules betwee= n the agent and the console?</div><div><br></div><div>Cheers,</div><div><br= ></div><div>Ouray<span></span><br><br>On Thursday, November 19, 2015, alfin= haji . <<a href=3D"mailto:[email protected]">[email protected]</a>&g= t; wrote:<br><blockquote class=3D"gmail_quote" style=3D"margin:0 0 0 .8ex;b= order-left:1px #ccc solid;padding-left:1ex"><div dir=3D"ltr"><div>Hi all,</= div><div><br></div><div>Looking for an issue we have been troubleshooting f= or a few days now.=C2=A0 This issue has exposed itself after our client mov= ed over to a new data center requiring us to rebuild our grinder environmen= ts.=C2=A0 Our grinder test infrastructure is fully functional in the old en= vironment, and these issues have exposed themselves 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 termi= nal emulation. (this is new compared to the old environment, where we ran t= he Console UI)</div><div>2.=C2=A0 Console starts up fine, agent starts up f= ine, and connects to the console.</div><div><br></div><div>$ tail -f grinde= rAgentoutput.log<br>Setting argument grinder.consolePort=3D6372<br>+ JAVA_A= RGS=3D' -Dgrinder.useConsole=3Dtrue -Dgrinder.consoleHost=3DL-01942-C5F= -Dgrinder.consolePort=3D6372'<br>+ java -cp /test_data/grinder_artifac= ts/grinder/lib/grinder.jar: -Dgrinder.useConsole=3Dtrue -Dgrinder.consoleHo= st=3DL-01942-C5F -Dgrinder.consolePort=3D6372 net.grinder.Grinder -daemon 1= 0<br>2015-11-19 15:26:41,336 INFO=C2=A0 agent: The Grinder 3.11<br>2015-11-= 19 15:26:41,358 ERROR agent: Failed to connect to 'L-01942-C5F/<a href= =3D"http://10.237.119.71:6372" target=3D"_blank">10.237.119.71:6372</a>'= ;<br>2015-11-19 15:26:41,358 INFO=C2=A0 agent: agent finished<br>2015-11-19= 15:26:41,358 INFO=C2=A0 agent: sleeping for 10000 ms<br>2015-11-19 15:26:5= 1,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" target=3D"_blank">10.237.119.71:6372</a><br>2015-11-19 15:26:51,4= 05 INFO=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 resp= onse back:</div><div><br></div><div>$ curl <a href=3D"http://L-01942-C5F:63= 73/agents/status" target=3D"_blank">http://L-01942-C5F:6373/agents/status</= a><br>[{"id":"L-01942-C5F:1509753335|1447964801332|167920711= 0:0","name":"L-01942-C5F","number":0,&qu= ot;state":"RUNNING","workers":[]}]</div><div><br><= /div><div>4.=C2=A0 I kick off our test automation, which eventually makes a= call to start the worker process:</div><div><br></div><div><a href=3D"http= ://L-01942-C5F:6373/agents/start-workers" target=3D"_blank">http://L-01942-= C5F:6373/agents/start-workers</a>=C2=A0 (we 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 perfect= ly fine, validated from the agent log file:</div><div><br></div><div>2015-1= 1-19 15:28:04,320 INFO=C2=A0 agent: received a start message<br><strong><fo= nt 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:04,473 INFO=C2=A0 agent: Worker pr= ocess command line: /test_data/grinder_artifacts/java/jdk1.7.0_25/jre/bin/j= ava '-javaagent:/test_data/grinder_artifacts/grinder/lib/grinder-dcr-ag= ent-3.11.jar' '-Dpython.path=3D/test_data/projects/common/src' = '-Dpython.cachedir=3D/tmp/cachedir' '-Xms2g' '-Xmx2g= 9; '-XX:NewSize=3D1g' '-XX:MaxNewSize=3D1g' '-verbose:g= c' '-XX:+PrintGCDetails' '-XX:+PrintGCTimeStamps' '= -XX:+UseConcMarkSweepGC' '-XX:+UseParNewGC' '-XX:+ExplicitG= CInvokesConcurrent' '-XX:+CMSConcurrentMTEnabled' '-XX:+Alw= aysPreTouch' '-XX:+UseCompressedOops' -classpath '/test_dat= a/grinder_artifacts/lib/jsoup-1.6.1.jar:/test_data/grinder_artifacts/lib/jy= son-1.0.2.jar:/test_data/grinder_artifacts/grinder/lib/grinder.jar' net= .grinder.engine.process.WorkerProcessEntryPoint<br>2015-11-19 15:28:04,493 = INFO=C2=A0 agent: worker L-01942-C5F-0 started<br>10.940: [GC 10.940: [ParN= ew: 838912K->32398K(943744K), 0.0570450 secs] 838912K->32398K(1992320= K), 0.0572580 secs] [Times: user=3D0.10 sys=3D0.00, real=3D0.06 secs]<br>20= 15-11-19 15:28:18,767 INFO=C2=A0 L-01942-C5F-0: starting threads<br>14.306:= [GC 14.306: [ParNew: 871310K->39438K(943744K), 0.0550070 secs] 871310K-= >39438K(1992320K), 0.0551420 secs] [Times: user=3D0.11 sys=3D0.00, real= =3D0.06 secs]<br>2015-11-19 15:28:19,128 INFO=C2=A0 L-01942-C5F-0: will shu= t 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 generation=C2=A0=C2=A0 total 943744K, us= ed 179113K [0x000000077ae00000, 0x00000007bae00000, 0x00000007bae00000)<br>= =C2=A0 eden space 838912K,=C2=A0 14% used [0x000000077ae00000, 0x0000000782= 1cf968, 0x00000007ae140000)<br>=C2=A0 from space 104832K,=C2=A0 57% used [0= x00000007b47a0000, 0x00000007b82badb0, 0x00000007bae00000)<br>=C2=A0 to=C2= =A0=C2=A0 space 104832K,=C2=A0=C2=A0 0% used [0x00000007ae140000, 0x0000000= 7ae140000, 0x00000007b47a0000)<br>=C2=A0concurrent mark-sweep generation to= tal 1048576K, used 0K [0x00000007bae00000, 0x00000007fae00000, 0x00000007fa= e00000)<br>=C2=A0concurrent-mark-sweep perm gen total 35456K, used 35295K [= 0x00000007fae00000, 0x00000007fd0a0000, 0x0000000800000000)<br>2015-11-19 1= 5:28:56,503 INFO=C2=A0 agent: agent finished<br>2015-11-19 15:28:56,503 INF= O=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 the worker process has completed= .=C2=A0 We do this to automate multiple tests in sequence, once a test ends= (worker process complete), our automation will immediately kick off anothe= r worker process to start the next test we have defined.=C2=A0 Unfortunatel= y, what I am seeing since moving to this "new" grinder environmen= t=C2=A0is 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.=C2=A0 Here is what I see when I continuously send th= e 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" target=3D"_blank">http://L-01942-C5F:6373/a= gents/status</a><br>[{"id":"L-01942-C5F:1509753335|144796480= 1332|1679207110:0","name":"L-01942-C5F","numb= er":0,"state":"<strong>RUNNING</strong>","wor= kers":[]}]</div><div>$ curl <a href=3D"http://L-01942-C5F:6373/agents/= status" target=3D"_blank">http://L-01942-C5F:6373/agents/status</a><br>[{&q= uot;id":"L-01942-C5F:1509753335|1447964801332|1679207110:0",= "name":"L-01942-C5F","number":0,"state&q= uot;:"<strong>FINISHED</strong>","workers":[]}]</div><d= iv>$ curl <a href=3D"http://L-01942-C5F:6373/agents/status" target=3D"_blan= k">http://L-01942-C5F:6373/agents/status</a><br>[]=C2=A0=C2=A0 =C2=A0<--= -- <strong>blank JSON response</strong></div><div><br></div><div>Also note = in the agent log above we see a "communication is shut down" mess= age (which we don't see in the old environment).</div><div><br></div><d= iv>As soon as the worker process completes the grinder test,=C2=A0we see th= e agent re-establish connection to the console and=C2=A0start getting a val= id RUNNING status on the agent status:</div><div><br></div><div>Agent log f= ile:</div><div><br></div><div>2015-11-19 15:29:06,504 INFO=C2=A0 agent: The= Grinder 3.11<br>2015-11-19 15:29:06,505 INFO=C2=A0 agent: connected to con= sole at L-01942-C5F/<a href=3D"http://10.237.119.71:6372" target=3D"_blank"= >10.237.119.71:6372</a><br>2015-11-19 15:29:06,505 INFO=C2=A0 agent: waitin= g for console signal</div><div><br></div><div>Curl output</div><div><div><b= r></div><div>$ curl <a href=3D"http://L-01942-C5F:6373/agents/status" targe= t=3D"_blank">http://L-01942-C5F:6373/agents/status</a><br>[{"id":= "L-01942-C5F:1509753335|1447964801332|1679207110:0","name&qu= ot;:"L-01942-C5F","number":0,"state":"<s= trong>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/grinder_artifacts/java/= jdk1.7.0_25/bin/java -cp /test_data/grinder_artifacts/grinder/lib/grinder.j= ar: -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/grinder.jar: -Dgrinder.u= seConsole=3Dtrue -Dgrinder.consoleHost=3DL-01942-C5F -Dgrinder.consolePort= =3D6372 net.grinder.Grinder -daemon 10<br>grinder=C2=A0 29190 28385 42 15:5= 3 pts/0=C2=A0=C2=A0=C2=A0 00:00:00 /test_data/grinder_artifacts/java/jdk1.7= .0_25/jre/bin/java -javaagent:/test_data/grinder_artifacts/grinder/lib/grin= der-dcr-agent-3.11.jar -Dpython.path=3D/test_data/projects/common/src -Dpyt= hon.cachedir=3D/tmp/cachedir -Xms2g -Xmx2g -XX:NewSize=3D1g -XX:MaxNewSize= =3D1g -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseConcMa= rkSweepGC -XX:+UseParNewGC -XX:+ExplicitGCInvokesConcurrent -XX:+CMSConcurr= entMTEnabled -XX:+AlwaysPreTouch -XX:+UseCompressedOops -classpath /test_da= ta/grinder_artifacts/lib/jsoup-1.6.1.jar:/test_data/grinder_artifacts/lib/j= yson-1.0.2.jar:/test_data/grinder_artifacts/grinder/lib/grinder.jar net.gri= nder.engine.process.WorkerProcessEntryPoint<br></div><div><br></div><div><b= r></div><div><br></div><div>So the million dollar question, why is it that = the agent loses communication with the console when the worker process star= ts executing?=C2=A0 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.</div><div><br></div><div>Any assistance or input w= ould be greatly appreciated.<br></div><div><br></div><div>Thanks,</div><div= >Alfin Haji<br></div></div></div> </blockquote></div><br><br>-- <br>Sent from Gmail Mobile<p>Ouray Viney<br>B= log: <a href=3D"https://www.viney.ca">https://www.viney.ca</a><br>Skype: O= uray Viney<br>LinkedIn: <a href=3D"https://ca.linkedin.com/in/ourayvine">ht= tps://ca.linkedin.com/in/ourayvine</a><br></p> --001a11443346b6433e0524ec01bd-- --===============1555888672492115442== Content-Type: text/plain; charset="us-ascii" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit Content-Disposition: inline ------------------------------------------------------------------------------ --===============1555888672492115442== 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 --===============1555888672492115442==--