search

strands-project / strands_executive

Executive control code for STRANDS robots.
10 stars 19 forks source link

several issues using the correct executor #307

Open marc-hanheide opened 5 years ago

marc-hanheide commented 5 years ago

@francescodelduchetto and I are a bit lost what the "correct" executor/scheduler would be to use for our museum case.

The problem: We have so far tried to use https://github.com/strands-project/strands_executive/blob/kinetic-devel/task_executor/launch/task-scheduler-top.launch as a simple scheduler. However, that one seems to be deprecated, and lacking recent features (e.g. time critical tasks). Also with that one, we had the following issue:

@francescodelduchetto submitted in private issue https://github.com/LCAS/LindIMP/issues/40:

Basically, a task was running and I was trying to cancel it but I wasn't able to do so...bcs of this error I presume @marc-hanheide 

[INFO] [1542370813.904951]: Concurrent state 'MONITORING' returned outcome 'preempted' on termination.
[WARN] [1542370813.923710]: State 'MONITORING' in concurrence did not service preempt.
[INFO] [1542370813.924395]: Concurrent Outcomes: {'MONITORED': 'succeeded', 'MONITORING': 'preempted'}
[INFO] [1542370813.924950]: Action terminated with outcome succeeded
[INFO] [1542370813.931177]: State machine transitioning 'TASK_EXECUTION':'succeeded'-->'TASK_SUCCEEDED'
[INFO] [1542370813.932638]: Preempt requested on state machine before executing the next state.
[INFO] [1542370813.933305]: Last state 'TASK_EXECUTION' did not service preempt. Preempting next state 'TASK_SUCCEEDED' before executing...
[ERROR] [1542370813.941010]: InvalidUserCodeError: Could not execute state 'TASK_SUCCEEDED' of type '<task_executor.sm_base_executor.TaskSucceeded object at 0x7f1a2b95bc$
  File "/opt/ros/kinetic/lib/python2.7/dist-packages/smach/state_machine.py", line 247, in _update_once
    self._remappings[self._current_label]))
  File "/localhome/lcas/workspaces/museum_ws/src/task_executor/src/task_executor/sm_base_executor.py", line 79, in execute
    self.executor.task_succeeded(completed)
  File "/localhome/lcas/workspaces/museum_ws/src/task_executor/scripts/scheduled_task_executor.py", line 139, in task_succeeded
    self.task_complete(task)
  File "/localhome/lcas/workspaces/museum_ws/src/task_executor/scripts/scheduled_task_executor.py", line 135, in task_complete
    self.execution_schedule.task_complete(task)
  File "/localhome/lcas/workspaces/museum_ws/src/task_executor/src/task_executor/execution_schedule.py", line 118, in task_complete
    assert self.current_task is not None
AssertionError

Exception in thread Thread-89:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/opt/ros/kinetic/lib/python2.7/dist-packages/smach/state_machine.py", line 359, in execute
    container_outcome = self._update_once()
  File "/opt/ros/kinetic/lib/python2.7/dist-packages/smach/state_machine.py", line 254, in _update_once
    + traceback.format_exc())
InvalidUserCodeError: Could not execute state 'TASK_SUCCEEDED' of type '<task_executor.sm_base_executor.TaskSucceeded object at 0x7f1a2b95bc10>': Traceback (most recent $
  File "/opt/ros/kinetic/lib/python2.7/dist-packages/smach/state_machine.py", line 247, in _update_once
    self._remappings[self._current_label]))
  File "/localhome/lcas/workspaces/museum_ws/src/task_executor/src/task_executor/sm_base_executor.py", line 79, in execute
    self.executor.task_succeeded(completed)
  File "/localhome/lcas/workspaces/museum_ws/src/task_executor/scripts/scheduled_task_executor.py", line 139, in task_succeeded
    self.task_complete(task)
  File "/localhome/lcas/workspaces/museum_ws/src/task_executor/scripts/scheduled_task_executor.py", line 135, in task_complete
    self.execution_schedule.task_complete(task)
  File "/localhome/lcas/workspaces/museum_ws/src/task_executor/src/task_executor/execution_schedule.py", line 118, in task_complete
    assert self.current_task is not None
AssertionError

So, maybe we should be using the MDP scheduler? That one, however, in the current version uses the a door config file: https://github.com/strands-project/strands_executive/blob/74d4d03754c59c0c90758b54a3aa4238e4c8ab23/task_executor/launch/mdp-executor.launch#L9-L11

And it doesn't seem to work properly. Can @bfalacerda or @hawesie suggest what the correct launch file would be for a "simple" (no doors, no adaptation, no bells and whistles), but robust and full-featured scheduling? I feel we are doing something stupid here. If it helps, I can invite you guys to the private repo to understand our situation better. Simple first questions: Which launch file should we be using?

hawesie commented 5 years ago

Hmm... we run this basic launch file all the time with no problems. If you want no adaptation then take out fremen from top nap and add the following instead:

 <node pkg="topological_navigation" name="speed_based_prediction" type="speed_based_prediction.py" output="screen" respawn="true"/>
hawesie commented 5 years ago

So, assuming you're running this launch file, what's going wrong?

marc-hanheide commented 5 years ago

for starters, we are not sure which task_executor to actually launch ;-) So, if you could tell us which one to use, then we say what's not working with it. @francescodelduchetto can say more about it, I'm sure, but if I recall, launching the MDP one the first hurdle was that it requested some door config...

hawesie commented 5 years ago

Run mdp-executor.launch which is the MDP one. The door config defaults to empty which works just fine normally.

francescodelduchetto commented 5 years ago

Yes, the mdp-executor.launch seems to work fine also for us.

I just tested it and got this error/warning fo the doors 

WARN] [1542384778.726317]: Error loading yaml config for door waits: [Errno 2] No such file or directory: ''. Using default values for all doors.

and yet it seems to schedule and start demanded tasks properly.

hawesie commented 5 years ago

Yep, it's a bit cryptic, but Using default values for all doors looks good.

marc-hanheide commented 5 years ago

Hooray, sorry for bothering you @hawesie I thought we tried that one and it wouldn't run anything... So, that's the recommended one. Perfect. Thanks.

marc-hanheide commented 5 years ago

We are still struggling with it, sorry. Whenever we submit a task, it ends with "Adding Doors" and then hangs, and also other services we call never return. There is an explicit_doors flag that is true in this setup, but I don't quite understand all the stuff it does. I would feel more comfortable if we could turn it off. But @hawesie said it shouldn't have any impact as long as the file isn't found, but it still seems to call a /door_predict service which we don't have, I think. Any idea how we could debug best. The old launch files (the non-extended mdp_executor, for instance) don't start at all. I feel we are still launching it all wrong.

francescodelduchetto commented 5 years ago

The mdp executor actually remains hung every time here: https://github.com/strands-project/strands_executive/blob/d3b5699e43f32a5d300dbf10c06a4b2aa3fd2356/task_executor/scripts/mdp_task_executor.py#L557 that service call never returns. It's odd how it sometimes works (like 3 days ago) and others not. Any idea on why this is happening?

hawesie commented 5 years ago

Could it be that Fremen is crashing and not providing predictions? Sorry away from computer so can't look in detail right now

bfalacerda commented 5 years ago

If you don't have the door_prediction service at /door_prediction/predict_doors running then this will hang. I just checked the code and it needs to be changed to allow you to change the explicit_doors flag to false. Currently you'd need to edit code to change the flag - my bad, this was done during deployment I think. I'll update in 1 hour or so.

marc-hanheide commented 5 years ago

Thanks, @bfalacerda that was our suspicion. Still a bit of a mystery that it looked as if it worked before, but I suspect that was just not running the correct version or something.

bfalacerda commented 5 years ago

I just noticed that it should work. You should get the following warning:

[WARN] [1542656248.319193]: Error calling door expectations prediction service: service [/door_prediction/predict_doors] unavailable

when the door prediction is called, but it shouldn't hang. Maybe it's the edge prediction that died, as @hawesie suggested?

bfalacerda commented 5 years ago

That might explain it working before. Sometimes a new (corrupted) nav_stat makes some fremen prediction node die. When that happens the prediction service remains available, so the executor can call it, but then it hangs there, because it doesn't get a response.

If these prediction services (for edges and doors) aren't provided at all, the executor will spit out warning but it will not hang (contrary to what I said in my first comment).

marc-hanheide commented 5 years ago

I tried the edge prediction and it responded... as it should. But I agree, let's cut another unreliable piece out of the equation. @hawesie already mentions this:

<node pkg="topological_navigation" name="speed_based_prediction" type="speed_based_prediction.py" output="screen" respawn="true"/>

Is that the only thing to start? Do I start it in addition or instead of what?

Instead of this: https://github.com/strands-project/strands_navigation/blob/indigo-devel/topological_navigation/launch/topological_navigation.launch#L37-L38

I'm sure you have a simple test script without fremen etc that can serve as a template for us, right? Somehow, I fail to find it though.

francescodelduchetto commented 5 years ago

@marc-hanheide did you tried edge prediction on your notebook or on the robot? Because on the robot is not working. I will describe here what happens given I don't know too much abotu fremen. This is what happen on the robot:

  1. fremenserver dies and restart every time it is called, log: 
    [fremenserver-10] process has died [pid 30847, exit code -11, cmd /opt/ros/kinetic/lib/fremenserver    /fremenserver __name:=fremenserver __log:=/localhome/lcas/.ros/log/d4cd242c-ec09-11e8-a80e-901b0ebe0a0e/fremenserver-10.log].
log file: /localhome/lcas/.ros/log/d4cd242c-ec09-11e8-a80e-901b0ebe0a0e/fremenserver-10*.log
[fremenserver-10] restarting process
process[fremenserver-10]: started with pid [32704]
[WARN] [1542659138.672887]: FREMENSERVER restart detected will generate new models now
  2. /topological_prediction/edge_entropies seem to work and returns but causes the following error: 
    [ERROR] [1542659323.582683]: bad callback: <bound method TopologicalNavPred.fremen_start_cb of <__main__.TopologicalNavPred object at 0x7f27dbef3690>>
Traceback (most recent call last):
File "/opt/ros/kinetic/lib/python2.7/dist-packages/rospy/topics.py", line 750, in _invoke_callback
cb(msg)
File "/opt/ros/kinetic/lib/topological_navigation/topological_prediction.py", line 145, in fremen_start_cb
self.create_temporal_models()
File "/opt/ros/kinetic/lib/topological_navigation/topological_prediction.py", line 244, in create_temporal_models
self.create_fremen_models(to_add)
File "/opt/ros/kinetic/lib/topological_navigation/topological_prediction.py", line 388, in create_fremen_models
i["t_order"] = self.add_and_eval_value_models(tmid,stimes,speeds)
File "/opt/ros/kinetic/lib/topological_navigation/topological_prediction.py", line 543, in add_and_eval_value_models
return pse.errors.index(min(pse.errors))
ValueError: min() arg is an empty sequence

    ...and then the error number one again and fremen restarts.

  3. /topological_prediction/predict_edges does not return.
marc-hanheide commented 5 years ago

Hah! I checked it on the robot, but I probably checked the wrong one! I hate it when @hawesie is correct ;-) OK, then fremen appears to be the problem indeed. We should cut it out for now. Maybe @Jailander can help with this then. Indeed, we should for now not use fremen, but try the solution @hawesie mentioned above. @bfalacerda it would still be good to make the door-stuff more optional, if possible, please. But @francescodelduchetto, then I suppose it is related to your new way of disabling some nodes temporarily, where indeed fremen might be in some undefined state.

That said, in @francescodelduchetto's use case, we need to "ban" some nodes for navigation temporarily. But I suppose the MDP is assuming a static topo map, right? Can it deal with a changing topological map @bfalacerda ?

bfalacerda commented 5 years ago

@marc-hanheide it can deal with topo map changes, it subscribes to /topological_map and updates the MDP when something is published there. we needed this for AAF if I remember correctly.

Jailander commented 5 years ago

Hi I just saw this, will take a look tomorrow, it could be a problem on the stats, it looks like there is something weird there

francescodelduchetto commented 5 years ago

@marc-hanheide The errors happen also with the upstream code without my modifications, so it is not caused by that. But, indeed what I added may still cause other problems to fremen (for example I can imagine that some of the estimates will be wrong when some nodes are banned).

francescodelduchetto commented 5 years ago

And my modification now does not change the topological map, it just ignores the banned nodes when planning the topological path. However, if fremen supports changes in the map it may be worth modifying the map online? So that the predictions and statistics should be more accurate...right?

hawesie commented 5 years ago

If you want certain nodes not to be traversed during task execution then those should be part of the task. That's exactly what our planning system is built for. We may need to extend the interface a bit, but our task specification language supports nice exclusions naturally.

We also built blacklisting into the routine node due to some annoyed office workers.

francescodelduchetto commented 5 years ago

@hawesie that's awesome, I was trying to reinvent the wheel then. Is there some documentation on how to exclude and blacklist nodes?

hawesie commented 5 years ago

@francescodelduchetto currently excluding tasks is only possible if you use LTL tasks directly, which may not be convenient for you. We can find a way to make it easy though, e.g. by you providing a service which lists excluded nodes. The blacklisting is only available if you manage tasks by the routine (https://github.com/strands-project/strands_executive_behaviours/blob/hydro-devel/routine_behaviours/src/routine_behaviours/robot_routine.py). Maybe we could have a quick call to discuss this... http://doodle.com/nickhawes

Jailander commented 5 years ago

Hi @francescodelduchetto @marc-hanheide , the problem is that the Fremen server crashes every time, I will take a look at it but hope @gestom sees this message too ;)

bfalacerda commented 5 years ago

From our experience there can be issues when building the edge models and a corrupted nav stat is found. I don't know what it makes it corrupted, we usually just look at the stuff printed by the node to figure out which edge has caused the problem and remove that entry from the db.

Jailander commented 5 years ago

@bfalacerda man you are good, how did you know I was just going to find that out? @francescodelduchetto there are two broken stats for edges "edge_id":"WayPoint18_WayPoint19" "edge_id":"WayPoint16_WayPoint18" deleting those fixes the issue. I will look for a more permanent solution anyway.

francescodelduchetto commented 5 years ago

So, removing fremen from topological nav and using speed_based_prediction, as @hawesie suggested, works fine.

Regarding the mdp-executor, I notice that it restarts a task as soon as it is cancelled. The only way to cancel it definitely is to call clear schedule. Is that the expected behavior? How do I stop a task that is currently executing without clearing all the schedule?

francescodelduchetto commented 5 years ago

No I am sorry, ignore the previous comment. I was testing on an old branch (1.0.6) of strands_executive.

francescodelduchetto commented 5 years ago

Another thing: what if we want to demand a task to be started on the spot without going to any topological node? Using scheduled_task_executor that was the default behavior when no start_node_id was provided, with mdp-executor instead the robot goes first to the closes top node.

hawesie commented 5 years ago

Hmmm... I think we'd need to check the code there. @bfalacerda any reason why this shouldn't work? Is there a way to create an LTL task without navigation?

bfalacerda commented 5 years ago

not currently, the behaviour now is moving to the closest waypoint. I could also make that a parameter if you need it @francescodelduchetto .

francescodelduchetto commented 5 years ago

Yes @bfalacerda, that would be really useful for us :)

bfalacerda commented 5 years ago

ok, I'll make a PR tomorrow afternoon that includes this and allows for ignoring doors.

bfalacerda commented 5 years ago

please check #308 . You should run roslaunch task_executor mdp-executor.launch combined_sort:=true explicit_doors:=false nav_before_action_exec:=false to get the behaviour you want.

Let me know if this is what you need.

francescodelduchetto commented 5 years ago

@bfalacerda your pull-req solves our problem. Thank you

francescodelduchetto commented 5 years ago

Another thing I notice by using the MDP navigation is that: sometimes the path choosen are not seemingly optimal (taking long paths to reach the goal) and sometimes the robot loops between 3 nodes without reaching the goal. Here is the logs during looping:


[WARN] [1542889195.858787]: Cancelling individual tasks is not yet implemented
[WARN] [1542889196.870135]: Task /roam_task_server did not have expected_duration set, using max_duration
[INFO] [1542889197.168296]: Checking for normal tasks to fit into available time: 1200.00 secs
[INFO] [1542889197.233704]: The specification is partial(R{"time"}min=? [ ((F executed_n2492__roam_task_server_at_WayPoint38=1)) ])
received: partial_sat_guarantees

Type:        MDP
Modules:     M
Variables:   waypoint executed_n2492__roam_task_server_at_WayPoint38

---------------------------------------------------------------------

Model checking: partial(R{"time"}min=? [ ((F executed_n2492__roam_task_server_at_WayPoint38=1)) ])

Building model...

Computing reachable states... 76 states
Reachable states exploration and model construction done in 0.026 secs.
Sorting reachable states list...

Time for model construction: 0.039 seconds.

Warning: Deadlocks detected and fixed in 2 states

Type:        MDP
States:      76 (1 initial)
Transitions: 471
Choices:     371
Max/avg:     10/4.88
Building cost structure...

Building deterministic automaton (for ((F "L0")))...
DFA has 2 states, 1 goal states.
Time for DFA translation: 0.052 seconds.
Exporting DFA to file "/tmp/prism-robots/guarantees_estimator//prod.aut"...

Automaton state distances to an accepting state: [1.0, 0.0]
Time for DFA distance to acceptance metric calculation: 0.0 seconds.

Skipping accepting MEC computation since acceptance is defined via goal states...
Time for lifting progression reward from automaton to product: 0.001 seconds.
Time for lifting cost function from original model to product: 0.0 seconds.

Cleared costs for 0 states where no more progression towards goal is possible.
Time for cost trimming: 0.001 seconds.

Exporting product transition matrix to file "/tmp/prism-robots/guarantees_estimator//prod.tra"...

Exporting product state space to file "/tmp/prism-robots/guarantees_estimator//prod.sta"...

Computing reachability probability, expected progression, and expected cost...

Exporting target states info to file "/tmp/prism-robots/guarantees_estimator//prod.lab"...
Starting Prob0 (max)...
Prob0 (max) took 9 iterations and 0.001 seconds.
Starting Prob1 (max)...
Prob1 (max) took 27 iterations and 0.004 seconds.
target=38, yes=73, no=1, maybe=2
Starting prioritised value iteration (max)...
Prioritised value iteration (max) took 10 iterations and 0.005 seconds.
Overall policy calculation took  0.011 seconds.

Maximum probability to satisfy specification is 1.0

Exporting success probabilites over product to file "/tmp/prism-robots/guarantees_estimator//guarantees1.vect"...

For p = 1.0, the maximum expected progression reward is 1.0

Exporting expected progression reward over product to file "/tmp/prism-robots/guarantees_estimator//guarantees2.vect"...

For p = 1.0, r = 1.0 the minimum expected cummulative cost until no more progression reward can be gathered is 397.937918408

Exporting expected times until no more progression over product to file "/tmp/prism-robots/guarantees_estimator//guarantees3.vect"...

Value in the initial state: 397.937918408

Time for model checking: 0.152 seconds.

Result: 397.937918408 (value in the initial state)
[INFO] [1542889197.692820]: /roam_task_server, with reward 0.00, will take 397.94 secs with prio 1 and prob 1.0000 ending before 2018-11-22 12:25:00
[INFO] [1542889197.693254]: Executing normal batch: (F executed_n2492__roam_task_server_at_WayPoint38=1)
[INFO] [1542889197.731381]: Sent goal for (F executed_n2492__roam_task_server_at_WayPoint38=1)
[INFO] [1542889197.768075]: The specification is: partial(R{"time"}min=? [ ((F executed_n2492__roam_task_server_at_WayPoint38=1)) ])
received: partial_sat_guarantees

Type:        MDP
Modules:     M
Variables:   waypoint executed_n2492__roam_task_server_at_WayPoint38

---------------------------------------------------------------------

Model checking: partial(R{"time"}min=? [ ((F executed_n2492__roam_task_server_at_WayPoint38=1)) ])

Building model...

Computing reachable states... 76 states
Reachable states exploration and model construction done in 0.024 secs.
Sorting reachable states list...

Time for model construction: 0.032 seconds.

Warning: Deadlocks detected and fixed in 2 states

Type:        MDP
States:      76 (1 initial)
Transitions: 471
Choices:     371
Max/avg:     10/4.88
Building cost structure...

Building deterministic automaton (for ((F "L0")))...
DFA has 2 states, 1 goal states.
Time for DFA translation: 0.033 seconds.
Exporting DFA to file "/tmp/prism-robots/policy_executor_extended//prod.aut"...

Automaton state distances to an accepting state: [1.0, 0.0]
Time for DFA distance to acceptance metric calculation: 0.0 seconds.

Skipping accepting MEC computation since acceptance is defined via goal states...
Time for lifting progression reward from automaton to product: 0.0 seconds.
Time for lifting cost function from original model to product: 0.0 seconds.

Cleared costs for 0 states where no more progression towards goal is possible.
Time for cost trimming: 0.001 seconds.

Exporting product transition matrix to file "/tmp/prism-robots/policy_executor_extended//prod.tra"...

Exporting product state space to file "/tmp/prism-robots/policy_executor_extended//prod.sta"...

Computing reachability probability, expected progression, and expected cost...

Exporting target states info to file "/tmp/prism-robots/policy_executor_extended//prod.lab"...
Starting Prob0 (max)...
Prob0 (max) took 9 iterations and 0.001 seconds.
Starting Prob1 (max)...
Prob1 (max) took 27 iterations and 0.004 seconds.
target=38, yes=73, no=1, maybe=2
Starting prioritised value iteration (max)...
Prioritised value iteration (max) took 10 iterations and 0.003 seconds.
Overall policy calculation took  0.008 seconds.

Maximum probability to satisfy specification is 1.0

Exporting success probabilites over product to file "/tmp/prism-robots/policy_executor_extended//guarantees1.vect"...

For p = 1.0, the maximum expected progression reward is 1.0

Exporting expected progression reward over product to file "/tmp/prism-robots/policy_executor_extended//guarantees2.vect"...

For p = 1.0, r = 1.0 the minimum expected cummulative cost until no more progression reward can be gathered is 397.937918408

Exporting expected times until no more progression over product to file "/tmp/prism-robots/policy_executor_extended//guarantees3.vect"...

Value in the initial state: 397.937918408

Time for model checking: 0.113 seconds.

Result: 397.937918408 (value in the initial state)
[0]
[2]
[6]
[15]
[19]
[16]
[22]
[30]
[29]
[34]
[33]
[37]
[INFO] [1542889198.151992]:  received feedback _has_header, 397.937918407
[INFO] [1542889202.732554]: Another 297.27 seconds until expected policy completion
[INFO] [1542889212.366545]: Reached waypoint WayPoint2
{'_da': 0, 'waypoint': 17, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 28, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889212.367397]: WayPoint4_WayPoint2 received feedback SUCCEEDED, 387.5888723
[INFO] [1542889217.734942]: Another 282.27 seconds until expected policy completion
[INFO] [1542889218.966420]: Reached waypoint WayPoint30
{'_da': 0, 'waypoint': 17, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 28, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 24, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 12, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889218.967554]: WayPoint2_WayPoint30 received feedback SUCCEEDED, 381.476029399
[INFO] [1542889227.966529]: Reached waypoint WayPoint20
{'_da': 0, 'waypoint': 17, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 28, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 24, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 12, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 29, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889227.967342]: WayPoint30_WayPoint20 received feedback SUCCEEDED, 372.443267377
[INFO] [1542889232.736339]: Another 267.26 seconds until expected policy completion
[INFO] [1542889235.466658]: Reached waypoint WayPoint34
{'_da': 0, 'waypoint': 17, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 28, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 24, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 12, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 29, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 31, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 14, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889235.467579]: WayPoint20_WayPoint34 received feedback SUCCEEDED, 364.303709353
[INFO] [1542889240.266677]: Reached waypoint WayPoint28
{'_da': 0, 'waypoint': 17, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 28, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 24, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 12, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 29, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 31, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 14, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 36, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 26, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 5, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[WARN] [1542889240.267275]: Error getting MDP next state: There is no transition modelling the state evolution. Looking for state in full state list...
[INFO] [1542889240.267809]: Found state {'_da': 0, 'waypoint': 35, 'executed_n2492__roam_task_server_at_WayPoint38': 0}. Updating.
[INFO] [1542889240.272052]: WayPoint34_WayPoint23 received feedback SUCCEEDED, 372.259088736
[18]
[17]
[16]
[22]
[30]
[29]
[34]
[33]
[37]
source: [WayPoint28, WayPoint37, WayPoint23, WayPoint22, WayPoint15, WayPoint14, WayPoint16,
  WayPoint17]
edge_id: [WayPoint28_WayPoint37, WayPoint37_WayPoint23, WayPoint23_WayPoint22, WayPoint22_WayPoint15,
  WayPoint15_WayPoint14, WayPoint14_WayPoint16, WayPoint16_WayPoint17, WayPoint17_WayPoint38]
[INFO] [1542889247.737497]: Another 252.26 seconds until expected policy completion
[INFO] [1542889250.766646]: Reached waypoint WayPoint37
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 24, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 31, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 23, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889250.767891]: WayPoint28_WayPoint37 received feedback SUCCEEDED, 358.277110517
[INFO] [1542889260.366619]: Reached waypoint WayPoint23
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 24, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 31, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889260.367638]: WayPoint37_WayPoint23 received feedback SUCCEEDED, 350.836232954
[INFO] [1542889262.738882]: Another 237.26 seconds until expected policy completion
[INFO] [1542889270.566394]: Reached waypoint WayPoint22
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 24, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 31, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 23, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 35, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 36, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889270.567166]: WayPoint23_WayPoint22 received feedback SUCCEEDED, 338.903386379
[INFO] [1542889277.740278]: Another 222.26 seconds until expected policy completion
[INFO] [1542889280.166796]: Reached waypoint WayPoint15
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 24, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 31, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 23, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 35, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 36, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 26, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 5, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889280.167878]: WayPoint22_WayPoint15 received feedback SUCCEEDED, 329.414265142
[INFO] [1542889283.468016]: Reached waypoint WayPoint14
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 24, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 31, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 23, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 35, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 36, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 26, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889283.469591]: WayPoint15_WayPoint14 received feedback SUCCEEDED, 327.644346684
[INFO] [1542889292.741574]: Another 207.26 seconds until expected policy completion
[INFO] [1542889299.966539]: Reached waypoint WayPoint16
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889299.967476]: WayPoint14_WayPoint16 received feedback SUCCEEDED, 312.179932353
[INFO] [1542889307.743023]: Another 192.26 seconds until expected policy completion
[INFO] [1542889308.666635]: Reached waypoint WayPoint17
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889308.667413]: WayPoint16_WayPoint17 received feedback SUCCEEDED, 308.097005923
[INFO] [1542889312.866927]: Reached waypoint WayPoint18
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 24, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 31, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 23, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 35, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 36, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 26, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 5, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[WARN] [1542889312.867549]: Error getting MDP next state: There is no transition modelling the state evolution. Looking for state in full state list...
[INFO] [1542889312.868116]: Found state {'_da': 0, 'waypoint': 7, 'executed_n2492__roam_task_server_at_WayPoint38': 0}. Updating.
[INFO] [1542889312.868945]: WayPoint17_WayPoint38 received feedback SUCCEEDED, 315.846559289
[35]
[34]
[33]
[37]
source: [WayPoint18, WayPoint16, WayPoint17]
edge_id: [WayPoint18_WayPoint16, WayPoint16_WayPoint17, WayPoint17_WayPoint38]
[INFO] [1542889316.466533]: Reached waypoint WayPoint16
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889316.467404]: WayPoint18_WayPoint16 received feedback SUCCEEDED, 312.179932353
[INFO] [1542889321.266680]: Reached waypoint WayPoint17
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889321.267505]: WayPoint16_WayPoint17 received feedback SUCCEEDED, 308.097005923
[INFO] [1542889322.744807]: Another 177.26 seconds until expected policy completion
[INFO] [1542889325.166804]: Reached waypoint WayPoint18
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 7, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889325.167985]: WayPoint17_WayPoint38 received feedback SUCCEEDED, 315.846559289
[INFO] [1542889328.766660]: Reached waypoint WayPoint16
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889328.767776]: WayPoint18_WayPoint16 received feedback SUCCEEDED, 312.179932353
[INFO] [1542889333.266568]: Reached waypoint WayPoint17
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889333.267429]: WayPoint16_WayPoint17 received feedback SUCCEEDED, 308.097005923
[INFO] [1542889337.747164]: Another 162.25 seconds until expected policy completion
[INFO] [1542889337.766990]: Reached waypoint WayPoint18
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 7, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889337.768423]: WayPoint17_WayPoint38 received feedback SUCCEEDED, 315.846559289
[INFO] [1542889341.666706]: Reached waypoint WayPoint16
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889341.667540]: WayPoint18_WayPoint16 received feedback SUCCEEDED, 312.179932353
[INFO] [1542889346.168374]: Reached waypoint WayPoint17
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889346.169197]: WayPoint16_WayPoint17 received feedback SUCCEEDED, 308.097005923
[INFO] [1542889350.366561]: Reached waypoint WayPoint18
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 7, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889350.367836]: WayPoint17_WayPoint38 received feedback SUCCEEDED, 315.846559289
[INFO] [1542889352.748714]: Another 147.25 seconds until expected policy completion
[INFO] [1542889354.267929]: Reached waypoint WayPoint16
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889354.269919]: WayPoint18_WayPoint16 received feedback SUCCEEDED, 312.179932353
[INFO] [1542889359.066347]: Reached waypoint WayPoint17
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889359.067083]: WayPoint16_WayPoint17 received feedback SUCCEEDED, 308.097005923
[INFO] [1542889363.266500]: Reached waypoint WayPoint18
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 7, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889363.267246]: WayPoint17_WayPoint38 received feedback SUCCEEDED, 315.846559289
[INFO] [1542889367.466859]: Reached waypoint WayPoint16
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889367.467731]: WayPoint18_WayPoint16 received feedback SUCCEEDED, 312.179932353
[INFO] [1542889367.750861]: Another 132.25 seconds until expected policy completion
[INFO] [1542889372.266471]: Reached waypoint WayPoint17
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889372.267386]: WayPoint16_WayPoint17 received feedback SUCCEEDED, 308.097005923
[INFO] [1542889376.166548]: Reached waypoint WayPoint18
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 7, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889376.167402]: WayPoint17_WayPoint38 received feedback SUCCEEDED, 315.846559289
[INFO] [1542889380.066439]: Reached waypoint WayPoint16
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889380.067346]: WayPoint18_WayPoint16 received feedback SUCCEEDED, 312.179932353
[INFO] [1542889382.753374]: Another 117.25 seconds until expected policy completion
[INFO] [1542889385.166914]: Reached waypoint WayPoint17
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889385.167940]: WayPoint16_WayPoint17 received feedback SUCCEEDED, 308.097005923
[INFO] [1542889389.966658]: Reached waypoint WayPoint18
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 7, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889389.967432]: WayPoint17_WayPoint38 received feedback SUCCEEDED, 315.846559289
[INFO] [1542889393.866727]: Reached waypoint WayPoint16
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889393.867462]: WayPoint18_WayPoint16 received feedback SUCCEEDED, 312.179932353
[INFO] [1542889397.754784]: Another 102.25 seconds until expected policy completion
[INFO] [1542889398.366441]: Reached waypoint WayPoint17
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889398.367193]: WayPoint16_WayPoint17 received feedback SUCCEEDED, 308.097005923
[INFO] [1542889402.566695]: Reached waypoint WayPoint18
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 7, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889402.567777]: WayPoint17_WayPoint38 received feedback SUCCEEDED, 315.846559289
[INFO] [1542889406.166429]: Reached waypoint WayPoint16
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889406.167274]: WayPoint18_WayPoint16 received feedback SUCCEEDED, 312.179932353
[INFO] [1542889410.966546]: Reached waypoint WayPoint17
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889410.967306]: WayPoint16_WayPoint17 received feedback SUCCEEDED, 308.097005923
[INFO] [1542889412.756196]: Another 87.24 seconds until expected policy completion
[INFO] [1542889414.867075]: Reached waypoint WayPoint18
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 7, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889414.871533]: WayPoint17_WayPoint38 received feedback SUCCEEDED, 315.846559289
[INFO] [1542889418.766729]: Reached waypoint WayPoint16
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889418.767579]: WayPoint18_WayPoint16 received feedback SUCCEEDED, 312.179932353
[INFO] [1542889423.566575]: Reached waypoint WayPoint17
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889423.567341]: WayPoint16_WayPoint17 received feedback SUCCEEDED, 308.097005923
[INFO] [1542889427.757548]: Another 72.24 seconds until expected policy completion
[INFO] [1542889428.366436]: Reached waypoint WayPoint18
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 7, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889428.367425]: WayPoint17_WayPoint38 received feedback SUCCEEDED, 315.846559289
[INFO] [1542889432.267215]: Reached waypoint WayPoint16
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889432.268313]: WayPoint18_WayPoint16 received feedback SUCCEEDED, 312.179932353
[INFO] [1542889436.766433]: Reached waypoint WayPoint17
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889436.767300]: WayPoint16_WayPoint17 received feedback SUCCEEDED, 308.097005923
[INFO] [1542889440.966846]: Reached waypoint WayPoint18
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 7, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889440.967880]: WayPoint17_WayPoint38 received feedback SUCCEEDED, 315.846559289
[INFO] [1542889442.758949]: Another 57.24 seconds until expected policy completion
[INFO] [1542889444.866617]: Reached waypoint WayPoint16
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889444.867759]: WayPoint18_WayPoint16 received feedback SUCCEEDED, 312.179932353
[INFO] [1542889449.666755]: Reached waypoint WayPoint17
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889449.667577]: WayPoint16_WayPoint17 received feedback SUCCEEDED, 308.097005923
[INFO] [1542889454.166750]: Reached waypoint WayPoint18
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 7, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889454.167600]: WayPoint17_WayPoint38 received feedback SUCCEEDED, 315.846559289
[INFO] [1542889457.760295]: Another 42.24 seconds until expected policy completion
[INFO] [1542889458.366749]: Reached waypoint WayPoint16
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889458.367984]: WayPoint18_WayPoint16 received feedback SUCCEEDED, 312.179932353
[INFO] [1542889462.867173]: Reached waypoint WayPoint17
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889462.868575]: WayPoint16_WayPoint17 received feedback SUCCEEDED, 308.097005923
[INFO] [1542889467.066738]: Reached waypoint WayPoint18
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 7, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889467.067566]: WayPoint17_WayPoint38 received feedback SUCCEEDED, 315.846559289
[INFO] [1542889470.966796]: Reached waypoint WayPoint16
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889470.967777]: WayPoint18_WayPoint16 received feedback SUCCEEDED, 312.179932353
[INFO] [1542889472.761727]: Another 27.24 seconds until expected policy completion
[INFO] [1542889475.766484]: Reached waypoint WayPoint17
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889475.767357]: WayPoint16_WayPoint17 received feedback SUCCEEDED, 308.097005923
[INFO] [1542889479.966403]: Reached waypoint WayPoint18
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 7, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889479.967216]: WayPoint17_WayPoint38 received feedback SUCCEEDED, 315.846559289
[INFO] [1542889483.566424]: Reached waypoint WayPoint16
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889483.567160]: WayPoint18_WayPoint16 received feedback SUCCEEDED, 312.179932353
[INFO] [1542889487.764095]: Another 12.24 seconds until expected policy completion
[INFO] [1542889488.366695]: Reached waypoint WayPoint17
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889488.367526]: WayPoint16_WayPoint17 received feedback SUCCEEDED, 308.097005923
[INFO] [1542889492.266531]: Reached waypoint WayPoint18
{'_da': 0, 'waypoint': 27, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 6, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
{'_da': 0, 'waypoint': 7, 'executed_n2492__roam_task_server_at_WayPoint38': 0}
[INFO] [1542889492.267496]: WayPoint17_WayPoint38 received feedback SUCCEEDED, 315.846559289
[INFO] [1542889495.907333]: Cancelling policy execution
[INFO] [1542889496.086170]: Topological navigation execute policy action server exited with status: PREEMPTED
[INFO] [1542889496.101894]: Dropped 1 task(s) after execution due to cancellation
bfalacerda commented 5 years ago

The planner is using the straight line distance between nodes as the cost function to minimise.

Can you paste a screenshot of the topological map?

francescodelduchetto commented 5 years ago

This is the entire topological map image

This is the focus on the waypoints 16, 17 and 18 where the robot was looping image

bfalacerda commented 5 years ago

The MDP planner assumes that two nodes are connected in the topological map iff the robot can navigate between the two nodes without visiting any other node. You have many edges here that don't satisfy this property

marc-hanheide commented 5 years ago

Oh, yes, @francescodelduchetto those edges should be removed.

francescodelduchetto commented 5 years ago

Ok, I cleaned some edges. Does it looks good to you? image

I will let you know if the looping still happens

bfalacerda commented 5 years ago

yes, it looks good.

Jailander commented 5 years ago

@francescodelduchetto don't forget to delete the nav_stats collection. Or we will be back at the beginning ;)

Jailander commented 5 years ago

Also just out of curiosity what action is that red edge to the right?

francescodelduchetto commented 5 years ago

@Jailander oh nothing is just that I didn't assigned any action to that, but now it is black as the rest;) Strangely I didn't get any error from fremen without removing the nav stats...

Jailander commented 5 years ago

Ok, but you should remove them just to be safe. You can do it from robomongo or you can do it from terminal as follows:

francescodelduchetto commented 5 years ago

Hi @hawesie, I just deployed on the robot the last version of strands_executive with the node blacklisting and I noticed that the feature of starting a task without going to the closest node, introduced in #308 by @bfalacerda, disappeared!

I tried passing nav_before_action_exec=false but it seems the parameter is not read anymore by the new code.

hawesie commented 5 years ago

Yikes, I must have merged badly. I’ll look into this later this week.

hawesie commented 5 years ago

@bfalacerda is the above parameter needed with your updated code? I notice that this line looks similar in purpose to the old parameter https://github.com/strands-project/strands_executive/blob/kinetic-devel/mdp_plan_exec/scripts/mdp_robot_policy_executor.py#L97