Problems loading pre-built map

Barry_Hendy · July 7, 2019, 8:09am

Hi.

I am making some good progress but I am having some problems trying to use a pre-built map.

I have built a map using webgui and rviz then saved the map with:

rosrun map_server map_saver -f ~/maps/my_map

Now I am trying to start with this saved map loaded. I have tried a few ways but mainly I have created a new .launch file based on demo_rosbot_pro.launch and added at the end:

This almost works … but it seems as soon as I ask it to do anything - and sometimes within a second of starting - the map reverts to the new, being-built-as-it-goes map, like i hadn’t loaded my map.

I can force the loading of my map with

rosrun map_server map_server ~/maps/my_map.yaml

while it is running and my pre-made map does load (in rviz view) but as soon as I try and move in my pre-built map, it reverts back to the new-being-built map.

So it is trying to load my pre-made map, but it looks like the 'making a new map as I go" task is still running and reverts when he has a change. Do i need to turn off the ‘make a map’ so it just works with the loaded map?

Also - probably not related but - I cant get 2D pose estimate to do anything. It prints:

Setting pose: 3.247 -0.130 1.452 [frame=map]

in the window it was started in, but it doesn’t seem to be taking any action or attempt to re-locate with this.

Thanks again for your help.

Barry

lukasz.mitka · July 8, 2019, 6:56am

Hello Barry,

The map_server node is loading and publishing map only once.
The gmapping node is publishing map with each position or observation update.

When you use demo_rosbot_pro.launch, you are launching gmapping among other nodes. End effect is that map loaded by map_server gets overridden by gmapping.

To change that behaviour, disable gmapping in demo_rosbot_pro.launch. Find line

<node pkg="rosbot_webui" type="gmapping_supervisor.py" name="gmapping_supervisor" output="screen"/>

and comment it out or delete it.

Only loading the map will not be sufficient, as you will probably also want to get ROSbot position relative to map. For determining position on static map, you could use amcl, please refer to amcl_demo.launch for example usage.

Regards,
Łukasz

Barry_Hendy · July 8, 2019, 9:07am

Thanks.

Can I just use 2d pose estimate to locate on the map? Except that doesn’t appear to work…

lukasz.mitka · July 8, 2019, 9:21am

2d pose estimate itself will not be sufficient, it is necessary to use localization system like amcl.

Regards,
Łukasz

Barry_Hendy · July 11, 2019, 12:28pm

Hi Lucasz.

I see another thread under software on the same point!

You might also see my post about the wheel rubbing which has been a major breakthrough in opertion and not getting lost.

Today I was able to make a good map of my house and navigate from one end to the other from the Webgui Launch running rviz. It was working MUCH better with the wheels not dragging.

I saved the map then launched again with the new launch file to load the map and activate amcl as you explained. The map is loading (in rviz) and 2D pose estimate appears to align the scan with the map - indicating pose estimate is working.

But navigation from there is terrible. There seems to be no attempt to locate (no sign of the scan data aligning to the map) and align. If I send it on a task the scan and trajectory in rviz just get totally lost and I cant seem to get it to do any successful localisation. re-issueing a 2D pose estimate can re-align the scan with the map - but then he is lost again.

here is my Launch file:

<include file="$(find rplidar_ros)/launch/rplidar_a3.launch"></include>

<node pkg="rosbot_webui" type="serial_bridge.sh" name="bridge" output="screen"/>

<include file="$(find husarion_ros)/launch/wifi.launch"></include>

<node pkg="tf" type="static_transform_publisher" name="ROSbot2_laser" args="0 0 0 3.14 0 0 base_link laser 10" />

<node pkg="tf" type="static_transform_publisher" name="ROSbot2_camera" args="-0.04 0 0.15 0 0 0 base_link camera_link 10" />

<node pkg="rosbot_webui" type="pose_to_tf_transform" name="pose_to_tf_transform" required="true"/>

<node pkg="rosbot_webui" type="tf_to_pose" name="tf_to_pose" required="true" output="screen" />

<node pkg="husarion_ros" type="depth_clipping_node" name="depth_clipping_node"/>

<node pkg="move_base" type="move_base" name="move_base" output="screen">
    <param name="recovery_behavior_enabled" value="true"/>
    <param name="controller_frequency" value="10.0"/>
    <rosparam file="$(find rosbot_webui)/conf/costmap_common_params.yaml" command="load" ns="global_costmap" />
    <rosparam file="$(find rosbot_webui)/conf/costmap_common_params.yaml" command="load" ns="local_costmap" />
    <rosparam file="$(find rosbot_webui)/conf/local_costmap_params.yaml" command="load" />
    <rosparam file="$(find rosbot_webui)/conf/global_costmap_params.yaml" command="load" />
    <rosparam file="$(find rosbot_webui)/conf/trajectory_planner.yaml" command="load" />
</node>

<remap from="cmd_vel" to="cmd_vel"/>
<remap from="odom" to="odom"/>
<remap from="scan" to="/scan"/>
<param name="move_base/DWAPlannerROS/yaw_goal_tolerance" value="1.0"/>
<param name="move_base/DWAPlannerROS/xy_goal_tolerance" value="1.0"/>


<arg name="map_file" value="/home/husarion/maps/my_map.yaml">
</arg> 
<node pkg="map_server" type="map_server" name="map_server" args="$(arg map_file)"> 
</node>

<node pkg="frontier_exploration" type="explore_client" name="explore_client" output="screen"/>

<node pkg="frontier_exploration" type="explore_server" name="explore_server" output="screen">
    <param name="frequency" type="double" value="1.0"/>
    <param name="goal_aliasing" type="double" value="0.1"/>
    <rosparam ns="explore_costmap" subst_value="true" file="$(find rosbot_webui)/conf/exploration.yaml" command="load" />
</node>

<node pkg="web_video_server" type="web_video_server" name="webvideo4">
    <param name="address" value="::" />
    <param name="port" value="8082" />
</node>

<include file="$(find rosbridge_server)/launch/rosbridge_websocket.launch">
    <arg name="port" value="9090"/>
</include>

Thanks in advance.

lukasz.mitka · July 11, 2019, 12:42pm

Hello Barry,

Are you getting any warnings or errors from AMCL?
What is the output of rqt_graph?

Regards,
Łukasz

Barry_Hendy · July 12, 2019, 10:26am

Here is the rqt graph. Can you read this OK? I am not sure how to attached the other file types (Being refused upload).

Where do i find the AMCL warnings and errors? I ran my start command through grep and the only amcl messages were;

husarion@husarion:~$ ros_startmap | grep “amcl”

/amcl/base_frame_id: base_link
/amcl/odom_frame_id: odom
/amcl/odom_model_type: diff-corrected
/amcl/update_min_a: 1.0
/amcl/update_min_d: 0.5
amcl (amcl/amcl)

or is there a log file to review??

Barry_Hendy · July 12, 2019, 10:35am

I have grep’d a few of the log files but can’t see any warnings.

lukasz.mitka · July 12, 2019, 10:46am

Hello Barry,

The rqt_graph is clear enough.
Warnings or errors could be visible in two places

In terminal after roslaunch command
In ~/.ros/log/latest directory

Regards,
Łukasz

Barry_Hendy · July 12, 2019, 11:12am

I have filtered both the terminal output looking for amcl and can only see INFO:

husarion@husarion:~$ ros_startmap | grep “amcl”

/amcl/base_frame_id: base_link
/amcl/odom_frame_id: odom
/amcl/odom_model_type: diff-corrected
/amcl/update_min_a: 1.0
/amcl/update_min_d: 0.5
amcl (amcl/amcl)

I have also look at the main logs also with only INFO shown.

So i cant see any amcl errors or warnings.

lukasz.mitka · July 12, 2019, 11:40am

Messages do not need to contain phrase “amcl” if they are regarding amcl.
You could filter if for “error” or “warning”.
Or better paste here full logs to check.

Regards,
Łukasz

Barry_Hendy · July 12, 2019, 11:42am

Do you want me to post just the terminal output or is there a log file you would also like to see?

lukasz.mitka · July 12, 2019, 11:46am

Terminal output and log file for amcl node (it will have amcl in it’s name).

Barry_Hendy · July 12, 2019, 12:39pm

I cant see any logs from amcl. I cant attach a ZIP so I have uploaded all the log files to a drive folder you should be able to see here: Logs – Google Drive

And here is the terminal output when I run roslaunch rosbot_webui demo_rosbot_mymap.launch

… logging to /home/husarion/.ros/log/8b6ccc30-a49e-11e9-9cfd-7cdd90dcb3c5/roslaunch-husarion-8362.log
Checking log directory for disk usage. This may take awhile.
Press Ctrl-C to interrupt
Done checking log file disk usage. Usage is <1GB.
e]2;/home/husarion/ros_workspace/src/rosbot_webui/launch/demo_rosbot_mymap.launcha
e[1mstarted roslaunch server http://husarion:41155/e[0m

SUMMARY

PARAMETERS

/amcl/base_frame_id: base_link
/amcl/odom_frame_id: odom
/amcl/odom_model_type: diff-corrected
/amcl/update_min_a: 1.0
/amcl/update_min_d: 0.5
/camera/camera_nodelet_manager/num_worker_threads: 4
/camera/depth_rectify_depth/interpolation: 0
/camera/driver/auto_exposure: True
/camera/driver/auto_white_balance: True
/camera/driver/bootorder: 0
/camera/driver/color_depth_synchronization: False
/camera/driver/depth_camera_info_url:
/camera/driver/depth_frame_id: camera_depth_opti…
/camera/driver/depth_registration: False
/camera/driver/device_id: #1
/camera/driver/devnums: 1
/camera/driver/rgb_camera_info_url:
/camera/driver/rgb_frame_id: camera_rgb_optica…
/explore_server/explore_costmap/explore_boundary/explore_clear_space: False
/explore_server/explore_costmap/explore_boundary/frontier_travel_point: middle
/explore_server/explore_costmap/explore_boundary/resize_to_boundary: False
/explore_server/explore_costmap/footprint: [[0.1, 0.12], [0…
/explore_server/explore_costmap/global_frame: map
/explore_server/explore_costmap/inflation/inflation_radius: 0.2
/explore_server/explore_costmap/plugins: [{‘type’: 'costma…
/explore_server/explore_costmap/publish_frequency: 5
/explore_server/explore_costmap/robot_base_frame: base_link
/explore_server/explore_costmap/static/map_topic: /map
/explore_server/explore_costmap/static/subscribe_to_updates: True
/explore_server/explore_costmap/transform_tolerance: 5
/explore_server/explore_costmap/update_frequency: 5
/explore_server/frequency: 1.0
/explore_server/goal_aliasing: 0.1
/move_base/DWAPlannerROS/xy_goal_tolerance: 1.0
/move_base/DWAPlannerROS/yaw_goal_tolerance: 1.0
/move_base/TrajectoryPlannerROS/acc_lim_Y: 2.5
/move_base/TrajectoryPlannerROS/acc_lim_theta: 0.25
/move_base/TrajectoryPlannerROS/acc_lim_x: 2.5
/move_base/TrajectoryPlannerROS/holonomic_robot: False
/move_base/TrajectoryPlannerROS/max_vel_theta: 0.35
/move_base/TrajectoryPlannerROS/max_vel_x: 0.2
/move_base/TrajectoryPlannerROS/meter_scoring: True
/move_base/TrajectoryPlannerROS/min_in_place_vel_theta: 0.25
/move_base/TrajectoryPlannerROS/min_vel_theta: -0.35
/move_base/TrajectoryPlannerROS/min_vel_x: 0.1
/move_base/TrajectoryPlannerROS/xy_goal_tolerance: 0.15
/move_base/TrajectoryPlannerROS/yaw_goal_tolerance: 0.25
/move_base/controller_frequency: 10.0
/move_base/global_costmap/always_send_full_costmap: True
/move_base/global_costmap/footprint: [[0.1, 0.12], [0…
/move_base/global_costmap/global_frame: map
/move_base/global_costmap/height: 50
/move_base/global_costmap/inflation_radius: 0.7
/move_base/global_costmap/laser_scan_sensor/clearing: True
/move_base/global_costmap/laser_scan_sensor/data_type: LaserScan
/move_base/global_costmap/laser_scan_sensor/marking: True
/move_base/global_costmap/laser_scan_sensor/sensor_frame: laser
/move_base/global_costmap/laser_scan_sensor/topic: scan
/move_base/global_costmap/map_topic: /map
/move_base/global_costmap/observation_sources: laser_scan_sensor
/move_base/global_costmap/obstacle_range: 6.0
/move_base/global_costmap/origin_x: -2.5
/move_base/global_costmap/origin_y: -2.5
/move_base/global_costmap/publish_frequency: 1
/move_base/global_costmap/raytrace_range: 8.0
/move_base/global_costmap/resolution: 0.01
/move_base/global_costmap/robot_base_frame: base_link
/move_base/global_costmap/rolling_window: True
/move_base/global_costmap/static_map: False
/move_base/global_costmap/subscribe_to_updates: True
/move_base/global_costmap/transform_tolerance: 5
/move_base/global_costmap/update_frequency: 1
/move_base/global_costmap/width: 50
/move_base/local_costmap/always_send_full_costmap: True
/move_base/local_costmap/footprint: [[0.1, 0.12], [0…
/move_base/local_costmap/global_frame: map
/move_base/local_costmap/height: 3
/move_base/local_costmap/inflation_radius: 0.4
/move_base/local_costmap/laser_scan_sensor/clearing: True
/move_base/local_costmap/laser_scan_sensor/data_type: LaserScan
/move_base/local_costmap/laser_scan_sensor/marking: True
/move_base/local_costmap/laser_scan_sensor/sensor_frame: laser
/move_base/local_costmap/laser_scan_sensor/topic: scan
/move_base/local_costmap/map_topic: /map
/move_base/local_costmap/observation_sources: laser_scan_sensor
/move_base/local_costmap/obstacle_range: 6.0
/move_base/local_costmap/origin_x: -1.5
/move_base/local_costmap/origin_y: -1.5
/move_base/local_costmap/publish_frequency: 2.5
/move_base/local_costmap/raytrace_range: 8.0
/move_base/local_costmap/resolution: 0.01
/move_base/local_costmap/robot_base_frame: base_link
/move_base/local_costmap/rolling_window: True
/move_base/local_costmap/static_map: False
/move_base/local_costmap/subscribe_to_updates: True
/move_base/local_costmap/transform_tolerance: 5
/move_base/local_costmap/update_frequency: 2.5
/move_base/local_costmap/width: 3
/move_base/recovery_behavior_enabled: True
/rosapi/params_glob: [*]
/rosapi/services_glob: [*]
/rosapi/topics_glob: [*]
/rosbridge_websocket/address:
/rosbridge_websocket/authenticate: False
/rosbridge_websocket/bson_only_mode: False
/rosbridge_websocket/delay_between_messages: 0
/rosbridge_websocket/fragment_timeout: 600
/rosbridge_websocket/max_message_size: None
/rosbridge_websocket/params_glob: [*]
/rosbridge_websocket/port: 9090
/rosbridge_websocket/retry_startup_delay: 5
/rosbridge_websocket/services_glob: [*]
/rosbridge_websocket/topics_glob: [*]
/rosbridge_websocket/unregister_timeout: 10
/rosbridge_websocket/use_compression: False
/rosdistro: kinetic
/rosversion: 1.12.14
/rplidarNode/angle_compensate: True
/rplidarNode/frame_id: laser
/rplidarNode/inverted: False
/rplidarNode/scan_mode: Sensitivity
/rplidarNode/serial_baudrate: 256000
/rplidarNode/serial_port: /dev/ttyUSB0
/webvideo4/address: ::
/webvideo4/port: 8082

NODES
/camera/
camera_nodelet_manager (nodelet/nodelet)
depth_metric (nodelet/nodelet)
depth_metric_rect (nodelet/nodelet)
depth_points (nodelet/nodelet)
depth_rectify_depth (nodelet/nodelet)
depth_registered_sw_metric_rect (nodelet/nodelet)
driver (nodelet/nodelet)
points_xyzrgb_sw_registered (nodelet/nodelet)
register_depth_rgb (nodelet/nodelet)
rgb_rectify_color (nodelet/nodelet)
/
ROSbot2_camera (tf/static_transform_publisher)
ROSbot2_laser (tf/static_transform_publisher)
amcl (amcl/amcl)
bridge (rosbot_webui/serial_bridge.sh)
camera_base_link (tf/static_transform_publisher)
camera_base_link1 (tf/static_transform_publisher)
camera_base_link2 (tf/static_transform_publisher)
camera_base_link3 (tf/static_transform_publisher)
depth_clipping_node (husarion_ros/depth_clipping_node)
explore_client (frontier_exploration/explore_client)
explore_server (frontier_exploration/explore_server)
map_server (map_server/map_server)
move_base (move_base/move_base)
pose_to_tf_transform (rosbot_webui/pose_to_tf_transform)
rosapi (rosapi/rosapi_node)
rosbridge_websocket (rosbridge_server/rosbridge_websocket)
rplidarNode (rplidar_ros/rplidarNode)
tf_to_pose (rosbot_webui/tf_to_pose)
webvideo4 (web_video_server/web_video_server)
wifi_publisher (husarion_ros/wifi.py)

auto-starting new master
e[1mprocess[master]: started with pid [8472]e[0m
e[1mROS_MASTER_URI=http://master:11311e[0m
e]2;/home/husarion/ros_workspace/src/rosbot_webui/launch/demo_rosbot_mymap.launch http://master:11311a
e[1msetting /run_id to 8b6ccc30-a49e-11e9-9cfd-7cdd90dcb3c5e[0m
e[1mprocess[roe[0m[ INFO] [1562933656.902190723]: Loading from pre-hydro parameter stylee[0m
e[0m[ INFO] [1562933657.133730428]: Using plugin "obstacle_layer"e[0m
e[0m[ INFO] [1562933657.174304197]: Subscribed to Topics: laser_scan_sensore[0m
e[0m[ INFO] [1562933657.386889630]: Using plugin "inflation_layer"e[0m
e[0m[ INFO] [1562933658.445139835]: Loading from pre-hydro parameter stylee[0m
e[0m[ INFO] [1562933658.614242545]: Using plugin "obstacle_layer"e[0m
e[0m[ INFO] [1562933658.629361039]: Subscribed to Topics: laser_scan_sensore[0m
e[0m[ INFO] [1562933658.806764693]: Using plugin "inflation_layer"e[0m
e[0m[ INFO] [1562933659.229847569]: Created local_planner base_local_planner/TrajectoryPlannerROSe[0m
e[0m[ INFO] [1562933659.313285472]: Sim period is set to 0.10e[0m
e[0m[ INFO] [1562933660.377212242]: Recovery behavior will clear layer obstaclese[0m
e[0m[ INFO] [1562933660.420314283]: Recovery behavior will clear layer obstaclese[0m
e[0m[ INFO] [1562933660.774381215]: odom received!e[0m
e[33m[ WARN] [1562933727.584835314]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2800 secondse[0m
e[33m[ WARN] [1562933727.768908477]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1841 secondse[0m
e[33m[ WARN] [1562933727.995550690]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.3106 secondse[0m
e[33m[ WARN] [1562933728.137660134]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1422 secondse[0m
e[33m[ WARN] [1562933728.222026563]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1266 secondse[0m
e[33m[ WARN] [1562933728.315901113]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 2.3359 secondse[0m
e[33m[ WARN] [1562933728.338791039]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1433 secondse[0m
e[33m[ WARN] [1562933728.455994755]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1604 secondse[0m
e[33m[ WARN] [1562933728.655446672]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2599 secondse[0m
e[33m[ WARN] [1562933728.760249320]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1049 secondse[0m
e[33m[ WARN] [1562933728.983373010]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2280 secondse[0m
e[33m[ WARN] [1562933729.128137527]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1447 secondse[0m
e[33m[ WARN] [1562933729.414323922]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.3309 secondse[0m
e[33m[ WARN] [1562933729.538083786]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1237 secondse[0m
e[33m[ WARN] [1562933729.633921209]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1196 secondse[0m
e[33m[ WARN] [1562933729.756879319]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1423 secondse[0m
e[33m[ WARN] [1562933729.763404303]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 1.4489 secondse[0m
e[33m[ WARN] [1562933729.978167268]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2636 secondse[0m
e[33m[ WARN] [1562933730.248690326]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2651 secondse[0m
e[33m[ WARN] [1562933730.641005659]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2979 secondse[0m
e[33m[ WARN] [1562933730.899937357]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2589 secondse[0m
e[33m[ WARN] [1562933731.044099820]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 1.7296 secondse[0m
e[33m[ WARN] [1562933731.268344881]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.3684 secondse[0m
e[33m[ WARN] [1562933731.499338329]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2310 secondse[0m
e[33m[ WARN] [1562933731.640354877]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1356 secondse[0m
e[33m[ WARN] [1562933731.684817997]: Map update loop missed its desired rate of 2.5000Hz… the loop actually took 0.9767 secondse[0m
e[33m[ WARN] [1562933731.877848015]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2785 secondse[0m
e[33m[ WARN] [1562933732.186433258]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.3086 secondse[0m
e[33m[ WARN] [1562933732.261669097]: Map update loop missed its desired rate of 2.5000Hz… the loop actually took 0.5768 secondse[0m
e[33m[ WARN] [1562933732.269283285]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 1.9548 secondse[0m
e[33m[ WARN] [1562933732.452728654]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2663 secondse[0m
e[33m[ WARN] [1562933732.497685951]: Map update loop missed its desired rate of 2.5000Hz… the loop actually took 0.4129 secondse[0m
e[33m[ WARN] [1562933732.675344840]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2226 secondse[0m
e[33m[ WARN] [1562933732.964393444]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2890 secondse[0m
e[33m[ WARN] [1562933733.365040921]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.3006 secondse[0m
e[33m[ WARN] [1562933733.483932849]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 2.1695 secondse[0m
e[33m[ WARN] [1562933733.704710391]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.3397 secondse[0m
e[33m[ WARN] [1562933733.833593989]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1289 secondse[0m
e[33m[ WARN] [1562933733.912276554]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1046 secondse[0m
e[33m[ WARN] [1562933734.237108611]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2324 secondse[0m
e[33m[ WARN] [1562933734.444313603]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2072 secondse[0m
e[33m[ WARN] [1562933734.606235731]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 1.1223 secondse[0m
e[33m[ WARN] [1562933734.613151422]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1688 secondse[0m
e[33m[ WARN] [1562933734.769610484]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2253 secondse[0m
e[33m[ WARN] [1562933734.928434880]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1583 secondse[0m
e[33m[ WARN] [1562933735.149749190]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2801 secondse[0m
e[33m[ WARN] [1562933735.314149521]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1644 secondse[0m
e[33m[ WARN] [1562933735.379877821]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1301 secondse[0m
e[33m[ WARN] [1562933735.636505991]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2867 secondse[0m
e[33m[ WARN] [1562933735.826741845]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1903 secondse[0m
e[33m[ WARN] [1562933736.162707855]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.4263 secondse[0m
e[33m[ WARN] [1562933736.184785883]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 1.7009 secondse[0m
e[33m[ WARN] [1562933736.405002098]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2423 secondse[0m
e[33m[ WARN] [1562933736.530087112]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1251 secondse[0m
e[33m[ WARN] [1562933736.663282556]: Map update loop missed its desired rate of 2.5000Hz… the loop actually took 0.5785 secondse[0m
e[33m[ WARN] [1562933736.824058218]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2190 secondse[0m
e[33m[ WARN] [1562933737.087468518]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2634 secondse[0m
e[33m[ WARN] [1562933737.311275852]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2238 secondse[0m
e[33m[ WARN] [1562933737.487281506]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1760 secondse[0m
e[33m[ WARN] [1562933737.702583588]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2912 secondse[0m
e[33m[ WARN] [1562933737.918085809]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 2.4342 secondse[0m
e[33m[ WARN] [1562933738.042974407]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.3405 secondse[0m
e[33m[ WARN] [1562933738.196391477]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1534 secondse[0m
e[33m[ WARN] [1562933738.267459445]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1245 secondse[0m
e[33m[ WARN] [1562933738.364621411]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1216 secondse[0m
e[33m[ WARN] [1562933738.458643259]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1155 secondse[0m
e[33m[ WARN] [1562933738.582695854]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1397 secondse[0m
e[33m[ WARN] [1562933738.754520937]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2115 secondse[0m
e[33m[ WARN] [1562933738.878906792]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1244 secondse[0m
e[33m[ WARN] [1562933738.998325784]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1438 secondse[0m
e[33m[ WARN] [1562933739.132888474]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1784 secondse[0m
e[33m[ WARN] [1562933739.277453644]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2229 secondse[0m
e[33m[ WARN] [1562933739.405162369]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1276 secondse[0m
e[33m[ WARN] [1562933739.488428313]: Map update loop missed its desired rate of 2.5000Hz… the loop actually took 0.6036 secondse[0m
e[33m[ WARN] [1562933739.568678388]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 1.6506 secondse[0m
e[33m[ WARN] [1562933739.605304390]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2279 secondse[0m
e[33m[ WARN] [1562933739.735558042]: Map update loop missed its desired rate of 2.5000Hz… the loop actually took 0.4507 secondse[0m
e[33m[ WARN] [1562933739.990851719]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.3723 secondse[0m
e[33m[ WARN] [1562933740.203300667]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2257 secondse[0m
e[33m[ WARN] [1562933740.345723571]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1424 secondse[0m
e[33m[ WARN] [1562933740.515879834]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2126 secondse[0m
e[33m[ WARN] [1562933740.694288627]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1784 secondse[0m
e[33m[ WARN] [1562933740.843780867]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2279 secondse[0m
e[33m[ WARN] [1562933740.991875735]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1466 secondse[0m
e[33m[ WARN] [1562933741.074233428]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 2.1562 secondse[0m
e[33m[ WARN] [1562933741.303686935]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.3594 secondse[0m
e[33m[ WARN] [1562933741.543100898]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2399 secondse[0m
e[33m[ WARN] [1562933741.745118935]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2020 secondse[0m
e[33m[ WARN] [1562933742.105012785]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.3599 secondse[0m
e[33m[ WARN] [1562933742.152372739]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 1.0781 secondse[0m
e[33m[ WARN] [1562933742.323642387]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2186 secondse[0m
e[33m[ WARN] [1562933742.536099646]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2124 secondse[0m
e[33m[ WARN] [1562933742.669148763]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1331 secondse[0m
e[33m[ WARN] [1562933742.822779604]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1867 secondse[0m
e[33m[ WARN] [1562933742.873638251]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1375 secondse[0m
e[33m[ WARN] [1562933743.112374403]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2763 secondse[0m
e[33m[ WARN] [1562933743.274190480]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1618 secondse[0m
e[33m[ WARN] [1562933743.486731660]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2744 secondse[0m
e[33m[ WARN] [1562933743.533901482]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 1.4597 secondse[0m
e[33m[ WARN] [1562933743.707645517]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2209 secondse[0m
e[33m[ WARN] [1562933743.870419032]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1628 secondse[0m
e[33m[ WARN] [1562933744.005981254]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1983 secondse[0m
e[33m[ WARN] [1562933744.193014526]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.2853 secondse[0m
e[33m[ WARN] [1562933744.295813988]: Control loop missed its desired rate of 10.0000Hz… the loop actually took 0.1028 secondse[0m
e[33m[ WARN] [1562933744.668320514]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 1.5941 secondse[0m
e[33m[ WARN] [1562933745.467890395]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 1.3936 secondse[0m
e[33m[ WARN] [1562933746.492215115]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 1.4180 secondse[0m
e[33m[ WARN] [1562933747.417280540]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 1.3430 secondse[0m
e[33m[ WARN] [1562933748.322648944]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 1.2484 secondse[0m
e[33m[ WARN] [1562933749.128702518]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 1.0545 secondse[0m
e[33m[ WARN] [1562933750.314063763]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 1.2398 secondse[0m
e[33m[ WARN] [1562933751.176985477]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 1.1027 secondse[0m
e[33m[ WARN] [1562933754.206610089]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 1.1304 secondse[0m
e[33m[ WARN] [1562933755.174480676]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 1.0987 secondse[0m
e[33m[ WARN] [1562933779.155280816]: Clearing costmap to unstuck robot (3.000000m).e[0m
e[33m[ WARN] [1562933780.112254130]: Map update loop missed its desired rate of 1.0000Hz… the loop actually took 25.0380 secondse[0m
e[33m[ WARN] [1562933805.954386278]: Rotate recovery beh[ERROR] [1562933822.042249]: Lost sync with device, restarting…
e[31m[ERROR] [1562933822.305850289]: Extrapolation Error looking up robot pose: Lookup would require extrapolation at time 1562933808.309126964, but only time 1562933822.289796552 is in the buffer, when looking up transform from frame [base_link] to frame [map]
e[0m
e[31m[ERROR] [1562933822.344530127]: Extrapolation Error looking up robot pose: Lookup would require extrapolation into the past. Requested time 1562933808.309126964 but the earliest data is at time 1562933822.289796552, when looking up transform from frame [base_link] to frame [map]
e[0m

lukasz.mitka · July 12, 2019, 1:10pm

Thank you for sharing the logs, all of them seem to be correct.

Could you record and share a .bag file showing the issue? I will try to reproduce and debug it.

To record a rosbag use:

rosbag record -a

Regards,
Łukasz

Barry_Hendy · July 13, 2019, 1:07am

Hi Lukasz.

OK, I have captured a rosbag - wow it is a big file! I have ZIPed it (from 6GB down to 1.5GB) and you should find it here: https://drive.google.com/open?id=1hJi5Jv-cioF9YOru0kAW5swaapTreCSN

To create this I loaded my ‘mymap’ launch file then started rosbag. (This is webui just with the amcl added as above) I started rviz (via remote desktop) and used 2D pose estimate to locate the vehicle in my map. I got it very close first hit - the scan was very close to the map. I then set 3 successive Target Pose - quite close, just a meter or 2 down the hall. (I waited for each to finish before setting the next) It got progressivly more lost - you could see the scan diverging from the map, and by the 3rd it was more than a meter and 90 degrees out and completly lost. It seems to be making no attempt to localise.

FYI - I am a little suspicious about possible differential in the wheels/drive. I suspect it might not be going in a straight line when it wants to. Not bad - but when i use Webui to drive it doesnt seem to go super straight. I would expect this to be a small challenge though - and localisation should manage (Like it does quite well when building the map with the defaut webui).

I look forward to your thoughts. Thanks again.

Barry

lukasz.mitka · July 16, 2019, 10:17am

Hello Barry,

I managed to investigate your rosbag and reproduce the issue.
Parameters for amcl may fail for some environments or maps. Based on your .bag file, I tuned amcl for your case.

Change your configuration to:

<node pkg="amcl" type="amcl" name="amcl" output="screen">
    <param name="odom_frame_id" value="odom"/>
    <param name="odom_model_type" value="diff"/>
    <param name="base_frame_id" value="base_link"/>
    <param name="update_min_d" value="0.05"/>
    <param name="update_min_a" value="0.1"/>
    <param name="min_particles" value="500"/>
</node>

It will perform much better.

Regards,
Łukasz

Barry_Hendy · July 16, 2019, 12:42pm

Thanks Lukasz.

I have tried these parameters but it doesn’t appear much better. It might ‘lock in’ a few times (not certain but maybe), but quite quickly gets lost. Even though the scan looks close to the map - it doesn’t lock in (converge) as I expected.

I have tired a few different settings but not much changes. I will keep trying, but do you have have any suggestions on the key parameters?

Also, is there a way to confirm it is working and connected correctly - I am not seeing much change by adjusting parameters dramatically so I wonder if it is connected?

Thanks again. (and again …)

Barry

lukasz.mitka · July 16, 2019, 2:00pm

Hello Barry,

Most important parameters are:

<param name="update_min_d" value="0.05"/>
<param name="update_min_a" value="0.1"/>

They define how often pose will be updated.

There are much more parameters to tune, you can find them in official documentation.

To present and compare the expected quality of localization, I have recorded my screen.
It is available here.
Red arrow is odometry based on encoders.
Green arrow is amcl output from .bag that you provided.
Blue arrow is amcl output with tuned parameters.

In above example I changed only amcl params, all other data is from .bag file.
How far is your output from presented above?

Regards,
Łukasz

Barry_Hendy · July 17, 2019, 11:22am

Hi Lukasz,

With your proposed setting it got immediately lost, but I doubled the 2 update_min values and I am now getting pretty good localisation. This is certainly a much better base line so I can now do some more fine-tuning and comparison. As i type he is successfully navigating from one end of my house to the other… with the following amcl settings:

So this is looking pretty good.

Thanks for your help.