Re: Agent not responding after initial startup

Here is the log from the console -

2015-04-22 19:32:36,695 INFO  console: The Grinder 3.12-SNAPSHOT
2015-04-22 19:32:40,487 DEBUG net.grinder.console.web.livedata: (push
:process-state) 0
2015-04-22 19:32:40,500 DEBUG net.grinder.console.web.livedata: (push
:threads) 0
2015-04-22 19:32:40,703 DEBUG net.grinder.console.web.livedata: (push
:statistics) 0
2015-04-22 19:32:40,705 DEBUG net.grinder.console.web.livedata: (push :sample) 0
2015-04-22 19:32:40,721 DEBUG
net.grinder.console.service.bootstrap_impl: Starting HTTP server at
0.0.0.0:6373
2015-04-22 19:33:20,575 INFO  console: Agent i-9544d563 [Connected]
2015-04-22 19:33:20,667 DEBUG net.grinder.console.web.livedata: (push
:process-state) 1
2015-04-22 19:33:20,668 DEBUG net.grinder.console.web.livedata: (push
:threads) 1
2015-04-22 19:33:21,640 DEBUG net.grinder.console.web.livedata: (push
:process-state) 2
2015-04-22 19:33:21,641 DEBUG net.grinder.console.web.livedata: (push
:threads) 2
2015-04-22 19:33:26,574 INFO  console: Agent i-9a44d56c [Connected],
Agent i-9544d563 [Connected]
2015-04-22 19:33:26,648 DEBUG net.grinder.console.web.livedata: (push
:process-state) 3
2015-04-22 19:33:26,648 DEBUG net.grinder.console.web.livedata: (push
:threads) 3
2015-04-22 19:33:27,573 INFO  console: Agent i-9544d563 [Connected],
Agent i-9a44d56c [Connected]
2015-04-22 19:33:27,643 DEBUG net.grinder.console.web.livedata: (push
:process-state) 4
2015-04-22 19:33:27,643 DEBUG net.grinder.console.web.livedata: (push
:threads) 4
2015-04-22 19:33:34,575 INFO  console: Agent i-9b44d56d [Connected],
Agent i-9544d563 [Connected], Agent i-9a44d56c [Connected]
2015-04-22 19:33:34,675 DEBUG net.grinder.console.web.livedata: (push
:process-state) 5
2015-04-22 19:33:34,676 DEBUG net.grinder.console.web.livedata: (push
:threads) 5
2015-04-22 19:33:35,575 INFO  console: Agent i-9544d563 [Connected],
Agent i-9a44d56c [Connected], Agent i-9b44d56d [Connected]
2015-04-22 19:33:35,709 DEBUG net.grinder.console.web.livedata: (push
:process-state) 6
2015-04-22 19:33:35,710 DEBUG net.grinder.console.web.livedata: (push
:threads) 6
2015-04-22 19:33:37,076 INFO  console: Agent i-9844d56e [Connected],
Agent i-9544d563 [Connected], Agent i-9a44d56c [Connected], Agent
i-9b44d56d [Connected]
2015-04-22 19:33:37,188 DEBUG net.grinder.console.web.livedata: (push
:process-state) 7
2015-04-22 19:33:37,189 DEBUG net.grinder.console.web.livedata: (push
:threads) 7
2015-04-22 19:33:38,076 INFO  console: Agent i-9544d563 [Connected],
Agent i-9844d56e [Connected], Agent i-9a44d56c [Connected], Agent
i-9b44d56d [Connected]
2015-04-22 19:33:38,190 DEBUG net.grinder.console.web.livedata: (push
:process-state) 8
2015-04-22 19:33:38,193 DEBUG net.grinder.console.web.livedata: (push
:threads) 8
2015-04-22 19:33:44,077 INFO  console: Agent i-9944d56f [Connected],
Agent i-9544d563 [Connected], Agent i-9844d56e [Connected], Agent
i-9a44d56c [Connected], Agent i-9b44d56d [Connected]
2015-04-22 19:33:44,187 DEBUG net.grinder.console.web.livedata: (push
:process-state) 9
2015-04-22 19:33:44,188 DEBUG net.grinder.console.web.livedata: (push
:threads) 9
2015-04-22 19:33:45,078 INFO  console: Agent i-9544d563 [Connected],
Agent i-9844d56e [Connected], Agent i-9944d56f [Connected], Agent
i-9a44d56c [Connected], Agent i-9b44d56d [Connected]
2015-04-22 19:33:45,195 DEBUG net.grinder.console.web.livedata: (push
:process-state) 10
2015-04-22 19:33:45,198 DEBUG net.grinder.console.web.livedata: (push
:threads) 10
2015-04-22 19:34:35,175 DEBUG net.grinder.console.service.app: request
:put /properties -> 200 (30.55 ms)
2015-04-22 19:34:46,999 DEBUG net.grinder.console.service.app: request
:post /files/distribute -> 200 (6.09 ms)
2015-04-22 19:34:55,028 DEBUG net.grinder.console.service.app: request
:post /files/status -> 404 (2.15 ms)
2015-04-22 19:35:37,921 DEBUG net.grinder.console.service.app: request
:get /files/status -> 200 (2.20 ms)
2015-04-22 19:37:32,144 DEBUG net.grinder.console.service.app: request
:get /agents/status -> 200 (5.33 ms)
2015-04-22 19:37:52,431 DEBUG net.grinder.console.service.app: request
:post /files/distribute -> 200 (7.75 ms)
2015-04-22 19:38:01,189 DEBUG net.grinder.console.service.app: request
:get /agents/status -> 200 (2.70 ms)
2015-04-22 19:38:08,091 DEBUG net.grinder.console.service.app: request
:get /files/status -> 200 (1.44 ms)
2015-04-22 19:41:14,753 DEBUG net.grinder.console.service.app: request
:post /files/distribute -> 200 (3.32 ms)
2015-04-22 19:41:39,761 DEBUG net.grinder.console.service.app: request
:get /files/status -> 200 (1.97 ms)
2015-04-22 19:47:18,880 DEBUG net.grinder.console.service.app: request
:get /files/status -> 200 (1.25 ms)
2015-04-22 19:47:33,724 DEBUG net.grinder.console.service.app: request
:get /agents/status -> 200 (2.17 ms)
2015-04-22 19:49:10,419 DEBUG net.grinder.console.service.app: request
:get /files/status -> 200 (1.37 ms)
2015-04-22 19:49:35,158 DEBUG net.grinder.console.service.app: request
:post /files/distribute -> 200 (2.16 ms)
2015-04-22 19:49:38,938 DEBUG net.grinder.console.service.app: request
:get /files/status -> 200 (1.23 ms)

On Wed, Apr 22, 2015 at 3:45 PM, Darren Ball <[email protected]> wrote:
> Here is an update on this;
>
> I have five agents actively connected
>
> [grinder@ip-10-82-151-77 ~]$ curl --noproxy localhost -s -X GET
> http://localhost:6373/agents/status
>
> [{"id":"ip-10-82-151-68.localdomain:396883763|1429731199058|-581571585:0","name":"i-9544d563","number":-1,"state":"running","workers":[]},{"id":"ip-10-82-151-67.localdomain:396883763|1429731216470|948975004:0","name":"i-9844d56e","number":-1,"state":"running","workers":[]},{"id":"ip-10-82-151-66.localdomain:396883763|1429731223428|118753153:0","name":"i-9944d56f","number":-1,"state":"running","workers":[]},{"id":"ip-10-82-151-65.localdomain:396883763|1429731205574|-2087968126:0","name":"i-9a44d56c","number":-1,"state":"running","workers":[]},{"id":"ip-10-82-151-64.localdomain:396883763|1429731213895|-520891325:0","name":"i-9b44d56d","number":-1,"state":"running","workers":[]}]
>
> From the console:
> [grinder@ip-10-82-151-77 ~]$ netstat -an | grep 637
> tcp        0      0 0.0.0.0:6372                0.0.0.0:*
>      LISTEN
> tcp        0      0 0.0.0.0:6373                0.0.0.0:*
>      LISTEN
> tcp        0      0 10.82.151.77:6372           10.82.151.68:49863
>      ESTABLISHED
> tcp        0      0 10.82.151.77:6372           10.82.151.66:35165
>      ESTABLISHED
> tcp        0      0 10.82.151.77:6372           10.82.151.67:59181
>      ESTABLISHED
> tcp        0      0 10.82.151.77:6372           10.82.151.65:33245
>      ESTABLISHED
> tcp        0      0 10.82.151.77:6372           10.82.151.64:34232
>      ESTABLISHED
>
> [grinder@ip-10-82-151-77 ~]$ curl --noproxy localhost -s -X POST
> http://localhost:6373/files/distribute
> {"id":3,"state":"started","files":[]}
>
> Files status - per-cent-complete 100, but stale is true?
> [grinder@ip-10-82-151-77 ~]$ curl --noproxy localhost -s -X GET
> http://localhost:6373/files/status
> {"stale":true,"last-distribution":{"per-cent-complete":100,"id":3,"state":"finished","files":["README.md","createapp.py","grinder.properties"]}}
>
> On one of the agents - the log is just sitting waiting for console
> signal - no files have been distributed:
>
> [grinder@ip-10-82-151-66]$ cat grinderagent.log
> SLF4J: Class path contains multiple SLF4J bindings.
> SLF4J: Found binding in
> [jar:file:/home/grinder/uber/logback-classic-1.0.7.jar!/org/slf4j/impl/StaticLoggerBinder.class]
> SLF4J: Found binding in
> [jar:file:/home/grinder/uber/slf4j-nop-1.7.5.jar!/org/slf4j/impl/StaticLoggerBinder.class]
> SLF4J: Found binding in
> [jar:file:/opt/grinder/lib/logback-classic-1.0.13.jar!/org/slf4j/impl/StaticLoggerBinder.class]
> SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
> SLF4J: Actual binding is of type
> [ch.qos.logback.classic.util.ContextSelectorStaticBinder]
> {"timestamp":"2015-04-22T19:33:43.430+00:00","logger":"agent","thread":"main","level":"INFO","HOSTNAME":"ip-10-82-151-66.localdomain","message":"The
> Grinder 3.12-SNAPSHOT"}
> {"timestamp":"2015-04-22T19:33:43.505+00:00","logger":"agent","thread":"main","level":"INFO","HOSTNAME":"ip-10-82-151-66.localdomain","message":"connected
> to console at grinderconsole1/10.82.151.77:6372"}
> {"timestamp":"2015-04-22T19:33:43.505+00:00","logger":"agent","thread":"main","level":"INFO","HOSTNAME":"ip-10-82-151-66.localdomain","message":"waiting
> for console signal"}
>
> [grinder@ip-10-82-151-66 ~]$ netstat -an | grep 637
> tcp        0      0 10.82.151.66:35165          10.82.151.77:6372
>      ESTABLISHED
>
>
> Any ideas?
>
>
> -Darren
>
>
> On Wed, Apr 22, 2015 at 12:40 PM, Darren Ball <[email protected]> wrote:
>> Hi All,
>>
>> I currently have jenkins jobs that are used to fire up the console on a
>> remote machine via SSH.
>> After the console is up and ports are listening, I wait and then fire up
>> agents remotely via SSH as well.
>>
>> Console comes up and I can talk to it via service interface.  It looks like
>> the agents are all up.  Java processes are there, port is connected and
>> logging indicates that it is waiting for a console signal.
>>
>> My startup for the agents is scripted as follows:
>> java -classpath
>> "/home/grinder/uber/*":/home/grinder/myapp-uber.jar:/opt/grinder/lib/grinder.jar
>> \
>>  -Dlogback.configurationFile=/home/grinder/logback.xml \
>>  -Dgrinder.consoleHost=$1 \
>>  -Dgrinder.hostID=$2 \
>>  -Dgrinder.logDirectory="/var/log/appbase/$(date +%y%m%d)" \
>>  net.grinder.Grinder -daemon 30 > /var/log/qbase/grinderagent.log 2>&1 &
>>
>>
>> I have the agent logging out to a file of which contains:
>>
>> SLF4J: Class path contains multiple SLF4J bindings.
>> SLF4J: Found binding in
>> [jar:file:/home/grinder/uber/logback-classic-1.0.7.jar!/org/slf4j/impl/StaticLoggerBinder.class]
>> SLF4J: Found binding in
>> [jar:file:/home/grinder/uber/slf4j-nop-1.7.5.jar!/org/slf4j/impl/StaticLoggerBinder.class]
>> SLF4J: Found binding in
>> [jar:file:/opt/grinder/lib/logback-classic-1.0.13.jar!/org/slf4j/impl/StaticLoggerBinder.class]
>> SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an
>> explanation.
>> SLF4J: Actual binding is of type
>> [ch.qos.logback.classic.util.ContextSelectorStaticBinder]
>> {"timestamp":"2015-04-22T16:18:59.373+00:00","logger":"agent","thread":"main","level":"INFO","HOSTNAME":"ip-10-82-151-41.localdomain","message":"The
>> Grinder 3.12-SNAPSHOT"}
>> {"timestamp":"2015-04-22T16:18:59.439+00:00","logger":"agent","thread":"main","level":"INFO","HOSTNAME":"ip-10-82-151-41.localdomain","message":"connected
>> to console at grinderconsole1/10.82.151.109:6372"}
>> {"timestamp":"2015-04-22T16:18:59.439+00:00","logger":"agent","thread":"main","level":"INFO","HOSTNAME":"ip-10-82-151-41.localdomain","message":"waiting
>> for console signal"}
>>
>>
>> When I attempt to distribute files, the agents are not responding (or
>> accepting the request to distribute).
>>
>> If I kill the process and re-run the startup script a second time directly
>> on the machine, everything seems to work fine.
>> Maybe this is due to launching from within a Jenkins job via SSH, but if
>> that was the case, I would assume the console would have similar issues as
>> well?
>>
>> Weird antics here.
>>
>> Looks like the process is coming up orphaned as well (most likely due to the
>> non terminal launch) when launched from the CI.
>>
>> [grinder@ip-10-82-151-41]$ netstat -an | grep 637
>>
>> tcp        0      0 10.82.151.41:54335          10.82.151.109:6372
>> ESTABLISHED
>>
>> [grinder@ip-10-82-151-41]$ ps -ef | grep grinder
>>
>> grinder    3722      1  1 16:11 ?        00:00:02 java -classpath
>> /home/grinder/uber/*:/home/grinder/myapp-uber.jar:/opt/grinder/lib/grinder.jar
>> -Dlogback.configurationFile=/home/grinder/logback.xml
>> -Dgrinder.consoleHost=grinderconsole1 -Dgrinder.hostID=i-a9b7265f
>> -Dgrinder.logDirectory=/var/log/qbase/150422 net.grinder.Grinder -daemon 30
>>
>>
>> Any insight on how to get the agents to continue to be listening or how to
>> debug this would be great.
>>
>> Thanks,
>> Darren

------------------------------------------------------------------------------
BPM Camp - Free Virtual Workshop May 6th at 10am PDT/1PM EDT
Develop your own process in accordance with the BPMN 2 standard
Learn Process modeling best practices with Bonita BPM through live exercises
http://www.bonitasoft.com/be-part-of-it/events/bpm-camp-virtual- event?utm_
source=Sourceforge_BPM_Camp_5_6_15&utm_medium=email&utm_campaign=VA_SF