Mysterious Test Failures

[T045T]

There seems to be something strange going on with the automated tests. Maybe a race condition?

This line could cause one, but why would it, with the fibonacci server inserting pauses in between feedback updates?

[rctoris]

Should we kill the fib test given that all of are PR are now failing?

[megawac]

Another option would be to set up retries -- anyway, watching the data in the websocket, its not at this that this is failing

{"topic": "/fibonacci/status", "msg": {"header": {"stamp": {"secs": 1412346145, "nsecs": 100562626}, "frame_id": "", "seq": 802}, "status_list": [{"status": 3, "text": "", "goal_id": {"stamp": {"secs": 1412346130, "nsecs": 416565477}, "id": "goal_0.21390089532360435_1412346130341"}}, {"status": 1, "text": "This goal has been accepted by the simple action server", "goal_id": {"stamp": {"secs": 1412346145, "nsecs": 86608049}, "id": "goal_0.6893968519289047_1412346145035"}}]}, "op": "publish"}

{"topic": "/fibonacci/status", "msg": {"header": {"stamp": {"secs": 1412346145, "nsecs": 300727733}, "frame_id": "", "seq": 803}, "status_list": [{"status": 3, "text": "", "goal_id": {"stamp": {"secs": 1412346130, "nsecs": 416565477}, "id": "goal_0.21390089532360435_1412346130341"}}, {"status": 1, "text": "This goal has been accepted by the simple action server", "goal_id": {"stamp": {"secs": 1412346145, "nsecs": 86608049}, "id": "goal_0.6893968519289047_1412346145035"}}]}, "op": "publish"}

{"topic": "/fibonacci/status", "msg": {"header": {"stamp": {"secs": 1412346145, "nsecs": 500904001}, "frame_id": "", "seq": 804}, "status_list": [{"status": 3, "text": "", "goal_id": {"stamp": {"secs": 1412346130, "nsecs": 416565477}, "id": "goal_0.21390089532360435_1412346130341"}}, {"status": 1, "text": "This goal has been accepted by the simple action server", "goal_id": {"stamp": {"secs": 1412346145, "nsecs": 86608049}, "id": "goal_0.6893968519289047_1412346145035"}}]}, "op": "publish"}

{"topic": "/fibonacci/status", "msg": {"header": {"stamp": {"secs": 1412346145, "nsecs": 701073095}, "frame_id": "", "seq": 805}, "status_list": [{"status": 3, "text": "", "goal_id": {"stamp": {"secs": 1412346130, "nsecs": 416565477}, "id": "goal_0.21390089532360435_1412346130341"}}, {"status": 1, "text": "This goal has been accepted by the simple action server", "goal_id": {"stamp": {"secs": 1412346145, "nsecs": 86608049}, "id": "goal_0.6893968519289047_1412346145035"}}]}, "op": "publish"}

{"topic": "/fibonacci/status", "msg": {"header": {"stamp": {"secs": 1412346145, "nsecs": 900314644}, "frame_id": "", "seq": 806}, "status_list": [{"status": 3, "text": "", "goal_id": {"stamp": {"secs": 1412346130, "nsecs": 416565477}, "id": "goal_0.21390089532360435_1412346130341"}}, {"status": 1, "text": "This goal has been accepted by the simple action server", "goal_id": {"stamp": {"secs": 1412346145, "nsecs": 86608049}, "id": "goal_0.6893968519289047_1412346145035"}}]}, "op": "publish"}

{"topic": "/fibonacci/feedback", "msg": {"status": {"status": 1, "text": "This goal has been accepted by the simple action server", "goal_id": {"stamp": {"secs": 1412346145, "nsecs": 86608049}, "id": "goal_0.6893968519289047_1412346145035"}}, "header": {"stamp": {"secs": 1412346146, "nsecs": 86700196}, "frame_id": "", "seq": 29}, "feedback": {"sequence": [0, 1, 1, 2]}}, "op": "publish"}

Looks like a bug in either bridge or that tutorial example as the websocket never receives "feedback": {"sequence": [0, 1, 1]}

[T045T]

It looks like the ROS nodes started by setup_examples.sh aren't 100% reliable themselves.

This build failed with ECONNREFUSED, and I encountered the same on my machine (hydro on Precise). Re-running setup_examples.sh fixed it, including all the tf and quaternion tests.

I think it's a good idea to exclude these tests from the Travis build for the time being.

[megawac]

I suppose the other option is to configure it to use rostest proper like
instead of that dirty shell script. Could also build rosbridge from source
(in travis) to fix #111

On Fri, Oct 3, 2014 at 10:52 AM, Nils Berg notifications@github.com wrote:

It looks like the ROS nodes started by setup_examples.sh aren't 100%
reliable themselves.

This build https://travis-ci.org/RobotWebTools/roslibjs/builds/36919524
failed with ECONNREFUSED, and I encountered the same on my machine (hydro
on Precise). Re-running setup_examples.sh fixed it, including all the tf
and quaternion tests.

I think it's a good idea to exclude these tests from the Travis build for
the time being.

—
Reply to this email directly or view it on GitHub
#114 (comment)
.

[T045T]

Well, we could replace the shell script with a roslaunch file, but I'm not sure rostest is really what we want. Looks like it's for testing roscpp/rospy nodes.

By the way, where did you record the raw websocket data? On my machine, all the tests pass (most the time), but I'd like to reproduce that bug and look at rosbridge to figure out why part of the feedback never makes it to roslibjs.

[megawac]

/I relaunched the test until it failed (mocha fibonacci.example.js) and
then dumped everything that went through that socket. The alternative would
be to just add a console.log statement in the onmessage listener
for core/Ros.js

On Fri, Oct 3, 2014 at 11:44 AM, Nils Berg notifications@github.com wrote:

Well, we could replace the shell script with a roslaunch file, but I'm not
sure rostest is really what we want. Looks like it's for testing
roscpp/rospy nodes.

By the way, where did you record the raw websocket data? On my machine,
all the tests pass (most the time), but I'd like to reproduce that bug and
look at rosbridge to figure out why part of the feedback never makes it to
roslibjs.

—
Reply to this email directly or view it on GitHub
#114 (comment)
.

[T045T]

I believe the problem with the fibonacci test is that rosbridge doesn't subscribe to the feedback topic in time to catch the first feedback message.

Interestingly, the subscription is logged in the ROS master.log as occurring about 30ms before the first feedback message, but that doesn't seem to be enough for rospy to get its ducks in a row. In the cases where the test passes, the time difference between subscription and first feedback message is closer to 150ms.

Changing

goal.send();

to

setTimeout(function(){
  goal.send();
}, 100);

in the test evidently makes the failures disappear, at least on my testing setup. It's been running in a loop for the past half hour, with no failures.

[rctoris]

Are these still failing for people?

[rctoris]

Closing for inactivity / better stability noticed in travis builds