search

meta-control / mc_mros_reasoner

library for metacontrol-based self-adaptation using ontological reasoning, with wrappers for robotic systems based on ROS1 and ROS2
Apache License 2.0
7 stars 10 forks source link

Test 'test_models_paper' fails in branch split_mros1_reasoner #98

Open chcorbato opened 3 years ago

chcorbato commented 3 years ago

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 commented 3 years ago

After some fixes in a5256fcf199874bb717ae19895b68ee4ffc4f372

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 https://github.com/tud-cor/mc_mros_reasoner/commit/85a0f0aa747ea1822a2b3eb90ebf49186133b1fb 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 commented 3 years ago

This is still happening from time to time.

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

marioney commented 3 years ago

@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.