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

several issues using the correct executor #307

Open
marc-hanheide opened this issue Nov 16, 2018 · 65 comments
Open

several issues using the correct executor #307

marc-hanheide opened this issue Nov 16, 2018 · 65 comments
Assignees
Labels

Comments

@marc-hanheide
Copy link
Member

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

<include file="$(find mdp_plan_exec)/launch/mdp_plan_exec_extended.launch">
<arg name="door_config_file" value="$(arg door_config_file)"/>
</include>

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
Copy link
Member

hawesie commented Nov 16, 2018

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
Copy link
Member

hawesie commented Nov 16, 2018

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

@marc-hanheide
Copy link
Member Author

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
Copy link
Member

hawesie commented Nov 16, 2018

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

@francescodelduchetto
Copy link
Contributor

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
Copy link
Member

hawesie commented Nov 16, 2018

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

@marc-hanheide
Copy link
Member Author

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
Copy link
Member Author

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.

@marc-hanheide marc-hanheide reopened this Nov 19, 2018
@francescodelduchetto
Copy link
Contributor

francescodelduchetto commented Nov 19, 2018

The mdp executor actually remains hung every time here:

service_response = estimates_service(request)

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
Copy link
Member

hawesie commented Nov 19, 2018

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

@bfalacerda
Copy link
Contributor

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
Copy link
Member Author

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
Copy link
Contributor

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
Copy link
Contributor

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
Copy link
Member Author

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
Copy link
Contributor

francescodelduchetto commented Nov 19, 2018

@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
Copy link
Member Author

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
Copy link
Contributor

@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
Copy link
Member

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
Copy link
Contributor

@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
Copy link
Contributor

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
Copy link
Member

hawesie commented Nov 19, 2018

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
Copy link
Contributor

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

@hawesie
Copy link
Member

hawesie commented Nov 20, 2018

@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
Copy link
Member

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 ;)

@francescodelduchetto
Copy link
Contributor

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
Copy link
Contributor

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
Copy link
Contributor

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
Copy link
Contributor

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
Copy link
Member Author

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

@francescodelduchetto
Copy link
Contributor

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

I will let you know if the looping still happens

@bfalacerda
Copy link
Contributor

yes, it looks good.

@Jailander
Copy link
Member

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

@Jailander
Copy link
Member

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

@francescodelduchetto
Copy link
Contributor

@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
Copy link
Member

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:

  • Open mongo terminal: mongo --pot 62345
  • In mongo terminal send the following instructions:
    • use message_store
    • db.nav_stats.drop()
    • exit

@francescodelduchetto
Copy link
Contributor

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
Copy link
Member

hawesie commented Jan 7, 2019 via email

@hawesie
Copy link
Member

hawesie commented Jan 24, 2019

@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

@bfalacerda
Copy link
Contributor

I don't see any old parameter on that link, is it correct?

@bfalacerda
Copy link
Contributor

bfalacerda commented Jan 24, 2019

But the line you linked first is just me setting the server as aborted when there is no policy, was that what you intended to link?

Looking at the code, I think it's needed: https://github.com/strands-project/strands_executive/blob/kinetic-devel/mdp_plan_exec/scripts/mdp_robot_policy_executor.py#L101

The boolean variable linked above ensures the robot does a navigation action before it executes any other action.

@hawesie
Copy link
Member

hawesie commented Jan 24, 2019

But what does starting_exec do? That looks related to me, and wasn't present in the old code.

@bfalacerda
Copy link
Contributor

it ensures ensures the robot does a navigation action before it executes any other action, i.e., exactly the opposite of what is intended. I don't understand exactly what is old and what is new code. The most up to date code in terms of the logic for navigating (or not) before executing an action is the one in https://github.com/strands-project/strands_executive/blob/deprecated-kinetic-devel/mdp_plan_exec/scripts/mdp_policy_executor_extended.py#L38

@bfalacerda
Copy link
Contributor

I didnt merge the param thing to the fork we were using, that might be why this is confusing.

@hawesie
Copy link
Member

hawesie commented Jan 25, 2019

I'm a bit lost. Let's chat in person.

@hawesie
Copy link
Member

hawesie commented Sep 13, 2019

@francescodelduchetto is this still an open issue for you? We haven't provided any kind of fix, but before I start trying to puzzle through the messages I wanted to check you still cared.

@francescodelduchetto
Copy link
Contributor

francescodelduchetto commented Sep 13, 2019

Hi @hawesie, yes it is still an open issue. We are using my fork of this repo for the robot now, but I guess it would be nice if we can return to the upstream one

@francescodelduchetto
Copy link
Contributor

I guess that the main problem and the reason I started to use my fork is what described in here #307 (comment) .

@hawesie
Copy link
Member

hawesie commented Sep 16, 2019

Thanks, that's super useful. So the task for me is to put back the nav_before_action_exec option?

@francescodelduchetto
Copy link
Contributor

Yes, I think so. Thank you!

@hawesie hawesie removed their assignment Sep 17, 2019
@hawesie
Copy link
Member

hawesie commented Sep 17, 2019

Ok, @bfalacerda is now in charge of this. It's quite a hard thing to change directly, so this probably won't happen immediately.

@bfalacerda
Copy link
Contributor

@francescodelduchetto please check #319. Should be back to the behaviour you asked for.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

5 participants