Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Test 'test_models_paper' fails in branch split_mros1_reasoner #98

Open
chcorbato opened this issue Sep 16, 2020 · 7 comments
Open

Test 'test_models_paper' fails in branch split_mros1_reasoner #98

chcorbato opened this issue Sep 16, 2020 · 7 comments
Assignees
Labels
help wanted Extra attention is needed

Comments

@chcorbato
Copy link
Contributor

A similar issue to #97. I forgot to try this test before merging.
I am looking into it. Probably test conditions in rosout have changed.

This is the output I get went things go "wrong"

[WARN] [1600241074.669626]: Objectives in status ERROR: ['o_navigateA']
[WARN] [1600241074.677111]: New Configuration requested: f1_v1_r1
[WARN] [1600241074.682421]: No value in rosparam server for rosgraph_manipulator/configs, setting it to  ['f1_v1_r1','f1_v1_r2',f1_v1_r3']
[ERROR] [1600241074.791180]: Got a result when we were already in the DONE state
[ERROR] [1600241074.793033]: Got a result when we were already in the DONE state
[WARN] [1600241074.794382]: = RECONFIGURATION SUCCEEDED =
Exception in thread Thread-4:
Traceback (most recent call last):
  File "/usr/lib/python3.6/threading.py", line 916, in _bootstrap_inner
    self.run()
  File "/opt/ros/melodic/lib/python2.7/dist-packages/rospy/timer.py", line 234, in run
    self._callback(TimerEvent(last_expected, last_real, current_expected, current_real, last_duration))
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 215, in timer_cb
    grounded_configuration = updateGrounding(o, fd, onto) # Set new grounded_configuration
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/tomasys.py", line 123, in updateGrounding
    fg = tomasys.FunctionGrounding(
NameError: name 'tomasys' is not defined

[WARN] [1600241076.314516]: --- D --- Max steps 6.999999999999999 
[WARN] [1600241076.316249]: QA value received for               TYPE: safety    VALUE: 1.0
[WARN] [1600241076.317980]: QA message refers to a FG not found in the KB, we asume it refers to the current grounded_configuration (1st fg found in the KB)
[ERROR] [1600241076.320033]: bad callback: <function callbackDiagnostics at 0x7fa3a8432598>
Traceback (most recent call last):
  File "/opt/ros/melodic/lib/python2.7/dist-packages/rospy/topics.py", line 750, in _invoke_callback
    cb(msg)
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 120, in callbackDiagnostics
    updateQA(diagnostic_status)
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 145, in updateQA
    fg = tomasys.FunctionGrounding.instances()[0]
  File "/home/parallels/tests_mros_reasoner_ws/devel/.private/mros1_reasoner/share/mros1_reasoner/venv/lib/python3.6/site-packages/owlready2/util.py", line 169, in __getitem__
    return self[i]
IndexError: list index out of range

[WARN] [1600241078.319197]: QA value received for               TYPE: safety    VALUE: 0.9
[WARN] [1600241078.321424]: QA message refers to a FG not found in the KB, we asume it refers to the current grounded_configuration (1st fg found in the KB)
[ERROR] [1600241078.323005]: bad callback: <function callbackDiagnostics at 0x7fa3a8432598>
Traceback (most recent call last):
  File "/opt/ros/melodic/lib/python2.7/dist-packages/rospy/topics.py", line 750, in _invoke_callback
    cb(msg)
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 120, in callbackDiagnostics
    updateQA(diagnostic_status)
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 145, in updateQA
    fg = tomasys.FunctionGrounding.instances()[0]
  File "/home/parallels/tests_mros_reasoner_ws/devel/.private/mros1_reasoner/share/mros1_reasoner/venv/lib/python3.6/site-packages/owlready2/util.py", line 169, in __getitem__
    return self[i]
IndexError: list index out of range

[WARN] [1600241080.321429]: QA value received for               TYPE: safety    VALUE: 0.8
[WARN] [1600241080.323315]: QA message refers to a FG not found in the KB, we asume it refers to the current grounded_configuration (1st fg found in the KB)
[ERROR] [1600241080.324823]: bad callback: <function callbackDiagnostics at 0x7fa3a8432598>
Traceback (most recent call last):
  File "/opt/ros/melodic/lib/python2.7/dist-packages/rospy/topics.py", line 750, in _invoke_callback
    cb(msg)
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 120, in callbackDiagnostics
    updateQA(diagnostic_status)
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 145, in updateQA
    fg = tomasys.FunctionGrounding.instances()[0]
  File "/home/parallels/tests_mros_reasoner_ws/devel/.private/mros1_reasoner/share/mros1_reasoner/venv/lib/python3.6/site-packages/owlready2/util.py", line 169, in __getitem__
    return self[i]
IndexError: list index out of range

[WARN] [1600241082.323078]: QA value received for               TYPE: safety    VALUE: 0.7000000000000001
[WARN] [1600241082.324497]: QA message refers to a FG not found in the KB, we asume it refers to the current grounded_configuration (1st fg found in the KB)
[ERROR] [1600241082.325796]: bad callback: <function callbackDiagnostics at 0x7fa3a8432598>
Traceback (most recent call last):
  File "/opt/ros/melodic/lib/python2.7/dist-packages/rospy/topics.py", line 750, in _invoke_callback
    cb(msg)
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 120, in callbackDiagnostics
    updateQA(diagnostic_status)
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 145, in updateQA
    fg = tomasys.FunctionGrounding.instances()[0]
  File "/home/parallels/tests_mros_reasoner_ws/devel/.private/mros1_reasoner/share/mros1_reasoner/venv/lib/python3.6/site-packages/owlready2/util.py", line 169, in __getitem__
    return self[i]
IndexError: list index out of range

[WARN] [1600241084.324508]: QA value received for               TYPE: safety    VALUE: 0.6000000000000001
[WARN] [1600241084.325939]: QA message refers to a FG not found in the KB, we asume it refers to the current grounded_configuration (1st fg found in the KB)
[ERROR] [1600241084.327182]: bad callback: <function callbackDiagnostics at 0x7fa3a8432598>
Traceback (most recent call last):
  File "/opt/ros/melodic/lib/python2.7/dist-packages/rospy/topics.py", line 750, in _invoke_callback
    cb(msg)
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 120, in callbackDiagnostics
    updateQA(diagnostic_status)
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 145, in updateQA
    fg = tomasys.FunctionGrounding.instances()[0]
  File "/home/parallels/tests_mros_reasoner_ws/devel/.private/mros1_reasoner/share/mros1_reasoner/venv/lib/python3.6/site-packages/owlready2/util.py", line 169, in __getitem__
    return self[i]
IndexError: list index out of range

[WARN] [1600241086.328419]: QA value received for               TYPE: safety    VALUE: 0.5000000000000001
[WARN] [1600241086.330622]: QA message refers to a FG not found in the KB, we asume it refers to the current grounded_configuration (1st fg found in the KB)
[ERROR] [1600241086.332351]: bad callback: <function callbackDiagnostics at 0x7fa3a8432598>
Traceback (most recent call last):
  File "/opt/ros/melodic/lib/python2.7/dist-packages/rospy/topics.py", line 750, in _invoke_callback
    cb(msg)
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 120, in callbackDiagnostics
    updateQA(diagnostic_status)
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 145, in updateQA
    fg = tomasys.FunctionGrounding.instances()[0]
  File "/home/parallels/tests_mros_reasoner_ws/devel/.private/mros1_reasoner/share/mros1_reasoner/venv/lib/python3.6/site-packages/owlready2/util.py", line 169, in __getitem__
    return self[i]
IndexError: list index out of range

[WARN] [1600241088.330429]: QA value received for               TYPE: safety    VALUE: 0.40000000000000013
[WARN] [1600241088.332143]: QA message refers to a FG not found in the KB, we asume it refers to the current grounded_configuration (1st fg found in the KB)
[ERROR] [1600241088.333525]: bad callback: <function callbackDiagnostics at 0x7fa3a8432598>
Traceback (most recent call last):
  File "/opt/ros/melodic/lib/python2.7/dist-packages/rospy/topics.py", line 750, in _invoke_callback
    cb(msg)
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 120, in callbackDiagnostics
    updateQA(diagnostic_status)
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 145, in updateQA
    fg = tomasys.FunctionGrounding.instances()[0]
  File "/home/parallels/tests_mros_reasoner_ws/devel/.private/mros1_reasoner/share/mros1_reasoner/venv/lib/python3.6/site-packages/owlready2/util.py", line 169, in __getitem__
    return self[i]
IndexError: list index out of range

[Testcase: testtest_models_paper] ... ok

[ROSTEST]-----------------------------------------------------------------------

[mros1_reasoner.rosunit-test_models_paper/test_one_equals_one][passed]
[mros1_reasoner.rosunit-test_models_paper/test_publish_energy_qa_value][passed]
[mros1_reasoner.rosunit-test_models_paper/test_publish_safety_qa_value][FAILURE]
False is not true
  File "/usr/lib/python3.6/unittest/case.py", line 59, in testPartExecutor
    yield
  File "/usr/lib/python3.6/unittest/case.py", line 605, in run
    testMethod()
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/test/test_models_paper.py", line 125, in test_publish_safety_qa_value
    self.assert_(self.success)
  File "/usr/lib/python3.6/unittest/case.py", line 1321, in deprecated_func
    return original_func(*args, **kwargs)
  File "/usr/lib/python3.6/unittest/case.py", line 682, in assertTrue
    raise self.failureException(msg)
--------------------------------------------------------------------------------


SUMMARY
 * RESULT: FAIL
 * TESTS: 3
 * ERRORS: 0
 * FAILURES: 1
@chcorbato chcorbato added the help wanted Extra attention is needed label Sep 16, 2020
chcorbato added a commit that referenced this issue Sep 16, 2020
@chcorbato
Copy link
Contributor Author

After some fixes in a5256fc

There is still an error that I do not understand, because it relates to rosgraph_manipulator_client.get_result()

[WARN] [1600242183.260293]: Objectives in status ERROR: ['o_navigateA']
[WARN] [1600242183.265628]: New Configuration requested: f1_v1_r2
Exception in thread Thread-4:
Traceback (most recent call last):
  File "/usr/lib/python3.6/threading.py", line 916, in _bootstrap_inner
    self.run()
  File "/opt/ros/melodic/lib/python2.7/dist-packages/rospy/timer.py", line 234, in run
    self._callback(TimerEvent(last_expected, last_real, current_expected, current_real, last_duration))
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 209, in timer_cb
    result = request_configuration(fd)
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 232, in request_configuration
    result = rosgraph_manipulator_client.get_result().result
AttributeError: 'NoneType' object has no attribute 'result'

[Testcase: testtest_models_paper] ... ok

[ROSTEST]-----------------------------------------------------------------------

[mros1_reasoner.rosunit-test_models_paper/test_one_equals_one][passed]
[mros1_reasoner.rosunit-test_models_paper/test_publish_energy_qa_value][passed]
[mros1_reasoner.rosunit-test_models_paper/test_publish_safety_qa_value][FAILURE]
False is not true
  File "/usr/lib/python3.6/unittest/case.py", line 59, in testPartExecutor
    yield
  File "/usr/lib/python3.6/unittest/case.py", line 605, in run
    testMethod()
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/test/test_models_paper.py", line 125, in test_publish_safety_qa_value
    self.assert_(self.success)
  File "/usr/lib/python3.6/unittest/case.py", line 1321, in deprecated_func
    return original_func(*args, **kwargs)
  File "/usr/lib/python3.6/unittest/case.py", line 682, in assertTrue
    raise self.failureException(msg)
--------------------------------------------------------------------------------


SUMMARY
 * RESULT: FAIL
 * TESTS: 3
 * ERRORS: 0
 * FAILURES: 1

@marioney
Copy link
Contributor

For me the test is passing. So I'm just guessing here.

result = rosgraph_manipulator_client.get_result().result
AttributeError: 'NoneType' object has no attribute 'result'

It may be that this is trying to access the result before it's there, so it may be a timing issue. We can check that it's not None before accessing it to handle this. But it's strange because the wait_for_result() was supposed to take care of that.

@chcorbato
Copy link
Contributor Author

Looks indeed a timing issue. Now I got the test SUCCEED, but I keep the same exception when the reconfiguration is requested:

[WARN] [1600286684.060666]: Objectives in status ERROR: ['o_navigateA']
[WARN] [1600286684.065911]: New Configuration requested: f1_v1_r2
Exception in thread Thread-4:
Traceback (most recent call last):
  File "/usr/lib/python3.6/threading.py", line 916, in _bootstrap_inner
    self.run()
  File "/opt/ros/melodic/lib/python2.7/dist-packages/rospy/timer.py", line 234, in run
    self._callback(TimerEvent(last_expected, last_real, current_expected, current_real, last_duration))
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 209, in timer_cb
    result = request_configuration(fd)
  File "/home/parallels/tests_mros_reasoner_ws/src/mros1_reasoner/mros1_reasoner/scripts/mros1_reasoner.py", line 232, in request_configuration
    result = rosgraph_manipulator_client.get_result().result
AttributeError: 'NoneType' object has no attribute 'result'

[Testcase: testtest_models_paper] ... ok

[ROSTEST]-----------------------------------------------------------------------

[mros1_reasoner.rosunit-test_models_paper/test_one_equals_one][passed]
[mros1_reasoner.rosunit-test_models_paper/test_publish_energy_qa_value][passed]
[mros1_reasoner.rosunit-test_models_paper/test_publish_safety_qa_value][passed]

SUMMARY
 * RESULT: SUCCESS
 * TESTS: 3
 * ERRORS: 0
 * FAILURES: 0

rostest log file is in /home/parallels/.ros/log/rostest-parallelsu18-30348.log`

@chcorbato chcorbato self-assigned this Sep 21, 2020
@chcorbato
Copy link
Contributor Author

chcorbato commented Sep 21, 2020

I think I know what the problem is:

Sometimes there is a second reconfiguration, and that one is failing, probably because we are not handling properly the new grounding and related name of the configuration for the rosgraph_manipulator
so this relates to #91

marioney added a commit that referenced this issue Sep 22, 2020
This just avoids the program to break with an error when the connection 
to the action_server is lost, as related in #98

Still need to find out why it's been lost in the first place
@marioney
Copy link
Contributor

Update: This is still happening from time to time.

Seems that the issue is that the connection to the action server is lost. I've added a check on 85a0f0a to avoid the crash, but still don't know how to avoid losing the connection.

Also, each time it fails I'm getting this warning

[WARN] [1600775984.326498]: Inbound TCP/IP connection failed: connection from sender terminated before handshake header received. 0 bytes were received. Please check sender for additional details.

So it's definitely related to ros_comm

@chcorbato
Copy link
Contributor Author

This is still happening from time to time.

@marioney can you confirm is it happens when there is a 2nd reconfiguration action requested?

@marioney
Copy link
Contributor

@marioney can you confirm is it happens when there is a 2nd reconfiguration action requested?

Yes, I think it happens always on the second reconfiguration action. At least I haven't seen it fail on the first one.

chcorbato added a commit that referenced this issue Apr 2, 2021
chcorbato pushed a commit that referenced this issue Apr 2, 2021
This just avoids the program to break with an error when the connection 
to the action_server is lost, as related in #98

Still need to find out why it's been lost in the first place
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
help wanted Extra attention is needed
Projects
None yet
Development

No branches or pull requests

2 participants