Resetting error: Updating ModelState: model does not exist

[YumengXiu]

I was using the pedsim entity_manager with Gazebo Simulator, for the first few epochs it works well, but the simulator shows the error after resetting:

[ WARN] [1715895663.979357211, 63.634000000]: Map update loop missed its desired rate of 5.0000Hz... the loop actually took 0.2490 seconds
[WARN] [1715895666.423746, 64.375000]: REACHED 60.0
[INFO] [1715895666.454231, 64.379000]: resetting
[ERROR] [1715895667.837760847, 64.379000000]: Updating ModelState: model [D_actor1_5] does not exist

Looks like it only shows the error when I use the Gazebo simulator, How can I fix this issue?

[voshch]

Hey, this is caused by Gazebo's ModelState requests being asynchronous, sometimes causing write-after-writes.
This shouldn't affect your simulation though, except for printing error messages. Does this cause any other issues?

[YumengXiu]

Thanks for the reply, the issue is that the simulator and Rviz will stop resetting and get frozen after printing the error message, looks like it only happens when I use Gazebo, fitland seems to be more stable.

[voshch]

When the simulation gets stuck and you manually kill it (with SIGINT/SIGHUP), a python stack trace from task_generator_node.py should be printed in the terminal (as white text) after a few seconds. Can you share that segment or your entire terminal output?

[YumengXiu]

Here's the entire terminal output when I manually kill it.

[INFO] [1718676168.928679, 7.570000]: resetting
[ERROR] [1718676170.839208149, 7.570000000]: Updating ModelState: model [D_actor1_1] does not exist
[ERROR] [1718676170.839569126, 7.570000000]: Updating ModelState: model [D_actor1_2] does not exist
[ERROR] [1718676170.839967197, 7.570000000]: Updating ModelState: model [D_actor1_3] does not exist
[ERROR] [1718676170.840322791, 7.570000000]: Updating ModelState: model [D_actor1_4] does not exist
[INFO] [1718676170.879787, 7.574000]: =============
[INFO] [1718676170.882457, 7.577000]: Task Reset!
[INFO] [1718676170.888916, 7.584000]: =============
[ERROR] [1718676170.904646, 7.600000]: Characters replaced when decoding message pedsim_msgs/AgentStates (will print only once): 'utf-8' codec can't decode byte 0xff in position 0: invalid start byte
[ERROR] [1718676170.906722, 7.602000]: Characters replaced when decoding message rosgraph_msgs/Clock (will print only once): 'utf-8' codec can't decode byte 0xff in position 0: invalid start byte
[INFO] [1718676170.907697, 7.603000]: Spawning dynamic obstacle: actor_id = D_actor1_1
[ WARN] [1718676170.923829257, 7.619000000]: The origin for the sensor at (9.74, 6.19) is out of map bounds. So, the costmap cannot raytrace for it.
[ WARN] [1718676171.082641643, 7.761000000]: Could not find <model> or <world> element in sdf, so name and initial position cannot be applied
[INFO] [1718676172.239145, 7.961000]: Spawning dynamic obstacle: actor_id = D_actor1_2
[ WARN] [1718676172.741508077, 8.087000000]: Could not find <model> or <world> element in sdf, so name and initial position cannot be applied
[INFO] [1718676173.336911, 8.182000]: Spawning dynamic obstacle: actor_id = D_actor1_3
[ WARN] [1718676173.778875620, 8.363000000]: Could not find <model> or <world> element in sdf, so name and initial position cannot be applied
[INFO] [1718676174.435203, 8.412000]: Spawning dynamic obstacle: actor_id = D_actor1_4
[ WARN] [1718676174.864677130, 8.537000000]: Could not find <model> or <world> element in sdf, so name and initial position cannot be applied
[ WARN] [1718676177.642092093, 9.126000000]: WARNING: package://spencer_tracking_rviz_plugin/media/animated_walking_man.mesh is an older format ([MeshSerializer_v1.41]); you should upgrade it as soon as possible using the OgreMeshUpgrade tool.
[ WARN] [1718676177.642217707, 9.126000000]: Can't assign material male_base_lambert1 to SubEntity of mesh_person_visual0 because this Material does not exist. Have you forgotten to define it in a .material script?
[ WARN] [1718676177.644330547, 9.128000000]: Can't assign material male_base_lambert1 to SubEntity of mesh_person_visual1 because this Material does not exist. Have you forgotten to define it in a .material script?
[ WARN] [1718676177.644500525, 9.128000000]: Can't assign material male_base_lambert1 to SubEntity of mesh_person_visual2 because this Material does not exist. Have you forgotten to define it in a .material script?
[ WARN] [1718676177.644632967, 9.128000000]: Can't assign material male_base_lambert1 to SubEntity of mesh_person_visual3 because this Material does not exist. Have you forgotten to define it in a .material script?
[Wrn] [Publisher.cc:135] Queue limit reached for topic /gazebo/default/pose/local/info, deleting message. This warning is printed only once.
[ WARN] [1718676307.292479341, 52.384000000]: The controller is oscillating for 10.001s
[ WARN] [1718676307.292531993, 52.384000000]: Controller defers handling cancel; force it and wait until the current control cycle finished
[ WARN] [1718676307.388782689, 52.482000000]: Recovery behaviors are disabled!
[ WARN] [1718676307.388812282, 52.482000000]: Abort the execution of the controller: Oscillation detected!
[ERROR] [1718676338.618420, 62.093000]: Characters replaced when decoding message gazebo_msgs/SetModelStateResponse (will print only once): 'utf-8' codec can't decode byte 0xff in position 0: invalid start byte
[INFO] [1718676352.846049, 67.313000]: resetting
[ERROR] [1718676355.352659, 67.313000]: Characters replaced when decoding message pedsim_msgs/Walls (will print only once): 'utf-8' codec can't decode byte 0xff in position 0: invalid start byte
[ERROR] [1718676355.483482978, 67.313000000]: Updating ModelState: model [D_actor1_5] does not exist
^C[visualize_robot_model-15] killing on exit
[rviz_config_file_creator-14] killing on exit
[task_generator_filewatcher-13] killing on exit
[task_generator_node-11] killing on exit
[map_to_odom_tfpublisher-10] killing on exit
[task_generator_server-12] killing on exit
[map_server-7] killing on exit
[map_clock_simulator-9] killing on exit
[distance_server-8] killing on exit
[rviz-5] killing on exit
[burger_0_2/map_to_odom_tfpublisher-6] killing on exit
[burger_0_2/move_base_legacy_relay-5] killing on exit
[burger_0_2/move_base_flex-4] killing on exit
[burger_0_2/mbf_cmd_vel_relay-3] killing on exit
[burger_0_2/rob_st_pub-2] killing on exit
[burger_0_2/transform_broadcaster-1] killing on exit
[ WARN] [1718676475.904215371, 67.313000000]: Controller defers handling cancel; force it and wait until the current control cycle finished
[pedsim_visualizer-3] killing on exit
[gazebo-4] killing on exit
[ERROR] [1718676476.387484, 67.313000]: ServiceException("transport error completing service call: unable to receive data from sender, check sender's logs for details")
[ WARN] [1718676476.404530770, 67.313000000]: Timeout while waiting for control cycle to stop; immediately sent goals can get stuck
[ERROR] [1718676476.413714, 67.313000]: bad callback: <bound method PedsimManager._obstacle_callback of <task_generator.manager.entity_manager.pedsim_manager.PedsimManager object at 0x7f84f1525a90>>
Traceback (most recent call last):
  File "/opt/ros/noetic/lib/python3/dist-packages/rospy/impl/tcpros_service.py", line 523, in call
    responses = transport.receive_once()
  File "/opt/ros/noetic/lib/python3/dist-packages/rospy/impl/tcpros_base.py", line 744, in receive_once
    self.stat_bytes += recv_buff(sock, b, p.buff_size)
  File "/opt/ros/noetic/lib/python3/dist-packages/rospy/impl/tcpros_base.py", line 111, in recv_buff
    raise TransportTerminated("unable to receive data from sender, check sender's logs for details")
rospy.exceptions.TransportTerminated: unable to receive data from sender, check sender's logs for details

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/ros/noetic/lib/python3/dist-packages/rospy/topics.py", line 750, in _invoke_callback
    cb(msg)
  File "/home/yumengxiu/arena_ws/src/arena/arena-rosnav/task_generator/task_generator/manager/entity_manager/pedsim_manager.py", line 629, in _obstacle_callback
    self._simulator.move_entity(
  File "/home/yumengxiu/arena_ws/src/arena/arena-rosnav/task_generator/task_generator/simulators/gazebo_simulator.py", line 97, in move_entity
    return bool(self._move_model_srv(request).success)
  File "/opt/ros/noetic/lib/python3/dist-packages/rospy/impl/tcpros_service.py", line 442, in __call__
    return self.call(*args, **kwds)
  File "/opt/ros/noetic/lib/python3/dist-packages/rospy/impl/tcpros_service.py", line 533, in call
    raise ServiceException("transport error completing service call: %s"%(str(e)))
rospy.service.ServiceException: transport error completing service call: unable to receive data from sender, check sender's logs for details

[pedsim_simulator-2] killing on exit
terminate called without an active exception
Exception in thread Thread-40:
Traceback (most recent call last):
  File "/opt/ros/noetic/lib/python3/dist-packages/rospy/impl/tcpros_service.py", line 523, in call
    responses = transport.receive_once()
  File "/opt/ros/noetic/lib/python3/dist-packages/rospy/impl/tcpros_base.py", line 744, in receive_once
    self.stat_bytes += recv_buff(sock, b, p.buff_size)
  File "/opt/ros/noetic/lib/python3/dist-packages/rospy/impl/tcpros_base.py", line 111, in recv_buff
    raise TransportTerminated("unable to receive data from sender, check sender's logs for details")
rospy.exceptions.TransportTerminated: unable to receive data from sender, check sender's logs for details

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/yumengxiu/arena_ws/src/arena/arena-rosnav/task_generator/task_generator/tasks/task_factory.py", line 225, in _reset_task
    self.obstacle_manager.respawn(respawn)
  File "/home/yumengxiu/arena_ws/src/arena/arena-rosnav/task_generator/task_generator/manager/obstacle_manager.py", line 68, in respawn
    self._entity_manager.remove_obstacles(purge=ObstacleLayer.UNUSED)
  File "/home/yumengxiu/arena_ws/src/arena/arena-rosnav/task_generator/task_generator/manager/entity_manager/pedsim_manager.py", line 563, in remove_obstacles
    action()
  File "/home/yumengxiu/arena_ws/src/arena/arena-rosnav/task_generator/task_generator/manager/entity_manager/pedsim_manager.py", line 535, in anon1
    self._simulator.move_entity(
  File "/home/yumengxiu/arena_ws/src/arena/arena-rosnav/task_generator/task_generator/simulators/gazebo_simulator.py", line 97, in move_entity
    return bool(self._move_model_srv(request).success)
  File "/opt/ros/noetic/lib/python3/dist-packages/rospy/impl/tcpros_service.py", line 442, in __call__
    return self.call(*args, **kwds)
  File "/opt/ros/noetic/lib/python3/dist-packages/rospy/impl/tcpros_service.py", line 533, in call
    raise ServiceException("transport error completing service call: %s"%(str(e)))
rospy.service.ServiceException: transport error completing service call: unable to receive data from sender, check sender's logs for details

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/opt/ros/noetic/lib/python3/dist-packages/rospy/timer.py", line 237, in run
    self._callback(TimerEvent(last_expected, last_real, current_expected, current_real, last_duration))
  File "/home/yumengxiu/arena_ws/src/arena/arena-rosnav/task_generator/task_generator/task_generator_node.py", line 336, in _check_task_status
    self.reset_task()
  File "/home/yumengxiu/arena_ws/src/arena/arena-rosnav/task_generator/task_generator/task_generator_node.py", line 320, in reset_task
    is_end = self._task.reset(callback=lambda: False, **kwargs)
  File "/home/yumengxiu/arena_ws/src/arena/arena-rosnav/task_generator/task_generator/tasks/task_factory.py", line 282, in reset
    self._mutex_reset_task(**kwargs)
  File "/home/yumengxiu/arena_ws/src/arena/arena-rosnav/task_generator/task_generator/tasks/task_factory.py", line 265, in _mutex_reset_task
    raise e
  File "/home/yumengxiu/arena_ws/src/arena/arena-rosnav/task_generator/task_generator/tasks/task_factory.py", line 262, in _mutex_reset_task
    self._reset_task()
  File "/home/yumengxiu/arena_ws/src/arena/arena-rosnav/task_generator/task_generator/tasks/task_factory.py", line 235, in _reset_task
    raise Exception("reset error!") from e
Exception: reset error!
[rviz-5] escalating to SIGTERM
[task_generator_node-11] escalating to SIGTERM
[burger_0_2/move_base_flex-4] escalating to SIGTERM
[gazebo-4] escalating to SIGTERM
[burger_1_2/map_to_odom_tfpublisher-12] killing on exit
[burger_1_2/move_base_legacy_relay-11] killing on exit
[burger_1_2/move_base_flex-10] killing on exit
[burger_1_2/mbf_cmd_vel_relay-9] killing on exit
[ WARN] [1718676491.250533213, 67.313000000]: Controller defers handling cancel; force it and wait until the current control cycle finished
[burger_1_2/rob_st_pub-8] killing on exit
[burger_1_2/transform_broadcaster-7] killing on exit
[ WARN] [1718676491.750932941, 67.313000000]: Timeout while waiting for control cycle to stop; immediately sent goals can get stuck
[task_generator_node-11] escalating to SIGKILL
[rviz-5] escalating to SIGKILL
[rosout-1] killing on exit
[master] killing on exit
Shutdown errors:
 * process[task_generator_node-11, pid 7565]: required SIGKILL. May still be running.
 * process[rviz-5, pid 7545]: required SIGKILL. May still be running.
shutting down processing monitor...
... shutting down processing monitor complete
done