while demo was running the don_bot brain died

[sunava]

@airballking @amaldo @ichumuh

log from the brain:

[INFO] [1526990894.096743]: counting objects on floor http://knowrob.org/kb/dm-market.owl#DMShelfLayer4TilesFront_JFBWLGUY
sending cram_start_action('http://knowrob.org/kb/shop.owl#ShelfLayerCounting', '1526990894.1', 'http://knowrob.org/kb/shop.owl#FindingShelfLayerParts_EDFNGCRS', R)
solutions [{u'R': u"'http://knowrob.org/kb/shop.owl#ShelfLayerCounting_MFZEHQRT'"}]
----------------------
sending rdf_assert('http://knowrob.org/kb/shop.owl#ShelfLayerMapping_NLJGDCYU', knowrob:subAction, 'http://knowrob.org/kb/shop.owl#ShelfLayerCounting_MFZEHQRT', 'LoggingGraph')
solutions [True]
----------------------
sending findall([F, P, W, L], (shelf_facing('http://knowrob.org/kb/dm-market.owl#DMShelfLayer4TilesFront_JFBWLGUY', F), shelf_facing_product_type(F,P), comp_facingWidth(F,literal(type(_, W))), (rdf_has(F, shop:leftSeparator, L); rdf_has(F, shop:mountingBarOfFacing, L))),Facings).
solutions [{u'P': u"'_3439'", u'L': u"'_3441'", u'Facings': [[u'http://knowrob.org/kb/shop.owl#ProductFacingStanding_FKRHLCQW', u'http://knowrob.org/kb/shop.owl#ProductWithAN522991', u'0.19539768357999998', u'http://knowrob.org/kb/dm-market.owl#DMShelfSeparator4Tiles_KJSLWRNI'], [u'http://knowrob.org/kb/shop.owl#ProductFacingStanding_NJUSBPWT', u'http://knowrob.org/kb/shop.owl#ProductWithAN523009', u'0.189730284767', u'http://knowrob.org/kb/dm-market.owl#DMShelfSeparator4Tiles_OWMBSEQN'], [u'http://knowrob.org/kb/shop.owl#ProductFacingStanding_IFZUPEGT', u'http://knowrob.org/kb/shop.owl#ProductWithAN522985', u'0.19917339827000002', u'http://knowrob.org/kb/dm-market.owl#DMShelfSeparator4Tiles_KGQCBEJT'], [u'http://knowrob.org/kb/shop.owl#ProductFacingStanding_CXROSNDW', u'http://knowrob.org/kb/shop.owl#ProductWithAN522990', u'0.19393382479890897', u'http://knowrob.org/kb/dm-market.owl#DMShelfSeparator4Tiles_NDELXHFT'], [u'http://knowrob.org/kb/shop.owl#ProductFacingStanding_PRKOILSC', u'http://knowrob.org/kb/shop.owl#ProductWithAN523010', u'0.21994662676599996', u'http://knowrob.org/kb/dm-market.owl#DMShelfSeparator4Tiles_XGRNTUJI']], u'W': u"'_3440'", u'F': u"'_3438'"}]
----------------------
sending object_frame_name('http://knowrob.org/kb/shop.owl#ProductFacingStanding_FKRHLCQW', R).
solutions [{u'R': u"'ProductFacingStanding_FKRHLCQW'"}]
----------------------
Traceback (most recent call last):
  File "/home/refills/workspace/rs_ws/src/refills_first_review/scripts/donbot_brain.py", line 106, in action_cb
    self.scan_shelf(shelf_id)
  File "/home/refills/workspace/rs_ws/src/refills_first_review/scripts/donbot_brain.py", line 193, in scan_shelf
    self.shelf_layer_mapping(shelf_id, floor_id)
  File "/home/refills/workspace/rs_ws/src/refills_first_review/scripts/donbot_brain.py", line 224, in shelf_layer_mapping
    self.count_floor(shelf_id, floor_id)
  File "/home/refills/workspace/rs_ws/src/refills_first_review/scripts/donbot_brain.py", line 286, in count_floor
    facings = self.knowrob.get_facings(floor_id)
  File "/home/refills/workspace/rs_ws/src/refills_first_review/src/refills_first_review/knowrob_wrapper.py", line 367, in get_facings
    self.get_object_frame_id(facing_id))
  File "/home/refills/workspace/rs_ws/src/refills_first_review/src/refills_first_review/tfwrapper.py", line 35, in lookup_transform
    return self.transform_pose(target_frame, p)
  File "/home/refills/workspace/rs_ws/src/refills_first_review/src/refills_first_review/tfwrapper.py", line 25, in transform_pose
    rospy.Duration(2.0))
  File "/opt/ros/kinetic/lib/python2.7/dist-packages/tf2_ros/buffer.py", line 87, in lookup_transform
    return self.lookup_transform_core(target_frame, source_frame, time)
LookupException: "ProductFacingStanding_FKRHLCQW" passed to lookupTransform argument source_frame does not exist. 
[INFO] [1526990896.131010]: preempted
[INFO] [1526990896.131296]: waiting for scanning action goal
[WARN] [1526990896.131519]: Your executeCallback did not set the goal to a terminal status.  This is a bug in your ActionServer implementation. Fix your code!  For now, the ActionServer will set this goal to aborted

[daniel86]

this could happen in case the object_state_publisher is behind and has not yet published the frame of the facing on TF topic.

[airballking]

Aha, interesting idea. @ichumuh what do you think?

[ichumuh]

I agree that the object state publisher is probably the problem. Knowrob knows about this facing since it returned it, but the frame doesn't exist. But it's strange I don't remember that we ever had this problem. I think we should see if it happens again.

[daniel86]

Well it wouldn't happen deterministically.
You can avoid it by asking KnowRob for the pose instead,
since KnowRob has an internal pose representation that does not
rely on TF frame to be published.

[ichumuh]

True but tf is more convenient. The brain is already waiting for 2 seconds for the transform to become available. I think increasing that number is an easier fix.

[daniel86]

But it would not be a safe fix. It would just decrease the risk of it to happen.

I could also add a predicate in knowrob that triggers TF publishing and blocks until message sended.

[ichumuh]

I don't think thats necessary after seeing you latest object state publisher changes. Since you now send all the transforms with the service call, we should now be able to publish the frames within that service call without getting into a deadlock.

[daniel86]

well the object state publisher is also not processing the stuff right away but has a separate thread for processing the queued "dirty" objects. It's up to the OS when the CPU is switching to this thread again. Surely, shouldn't be seconds but rather milliseconds. But in case other processes occupy CPU, it's not entirely predictable when this thread will be active next time

[ichumuh]

I know but we only did this to prevent deadlocks, because prolog was called to get the object information. We don't have to do this anymore because you are sending all the information we need, so we could update the objects in the callback again. Right?

[daniel86]

yeah possible. But only if the call is fast. I don't want people complaining about slow KnowRob queries... That's why I would prefer to stick to threaded object state publisher. But potentially the call is "fast enough" anyway. Would be nice to look into how much time is spend when calling the "mark_dirty_object" service.

[ichumuh]

Good point. I can do a runtime analysis when the static transform bug is fixed.