Closed ToMadoRe closed 9 years ago
We arrived this morning and Karl was standing around doing nothing as well. Parts of the errors you had seem familiar, although I am not sure if it is exactly the same:
[ INFO] [1384915862.241462013]: Got new plan
[ INFO] [1384915862.741472691]: Got new plan
[ INFO] [1384915862.941661058]: Goal reached
[INFO] [WallTime: 1384915862.942496] State machine terminating 'MOVE_BASE':'succeeded':'succeeded'
[INFO] [WallTime: 1384915862.944166] Concurrent state 'MOVE_BASE_SM' returned outcome 'succeeded' on termination.
[INFO] [WallTime: 1384915862.945252] Concurrent state 'NAV_PAUSE_MONITOR' returned outcome 'preempted' on termination.
[INFO] [WallTime: 1384915862.946178] Concurrent state 'BUMPER_MONITOR' returned outcome 'preempted' on termination.
[INFO] [WallTime: 1384915862.951881] Concurrent state 'STUCK_ON_CARPET_MONITOR' returned outcome 'preempted' on termination.
[INFO] [WallTime: 1384915862.952466] Concurrent state 'BATTERY_MONITOR' returned outcome 'preempted' on termination.
[INFO] [WallTime: 1384915862.953143] Concurrent Outcomes: {'BUMPER_MONITOR': 'preempted', 'NAV_PAUSE_MONITOR': 'preempted', 'MOVE_BASE_SM': 'succeeded', 'STUCK_ON_CARPET_MONITOR': 'preempted', 'BATTERY_MONITOR': 'preempted'}
[INFO] [WallTime: 1384915862.953520] State machine terminating 'MONITORED_MOVE_BASE':'succeeded':'succeeded'
[INFO] [WallTime: 1384915862.953821] State machine transitioning 'PATROL_POINT':'succeeded'-->'POINT_CHOOSER'
[ERROR] [WallTime: 1384915862.954833] InvalidUserCodeError: Could not execute child termination callback: Traceback (most recent call last):
File "/opt/strands/strands_catkin_ws/src/catkinized_smach/smach/src/smach/concurrence.py", line 348, in _state_runner
preempt_others = self._child_termination_cb(self._child_outcomes)
File "/opt/strands/strands_catkin_ws/src/autonomous_patrolling/waypoint_patroller/src/waypoint_patroller/navigation.py", line 157, in child_term_cb
if ( outcome_map['BUMPER_MONITOR'] == 'invalid' or
KeyError: 'BUMPER_MONITOR'
Exception in thread concurrent_split:BATTERY_MONITOR:
Traceback (most recent call last):
File "/usr/lib/python2.7/threading.py", line 551, in __bootstrap_inner
self.run()
File "/usr/lib/python2.7/threading.py", line 504, in run
self.__target(*self.__args, **self.__kwargs)
File "/opt/strands/strands_catkin_ws/src/catkinized_smach/smach/src/smach/concurrence.py", line 350, in _state_runner
raise smach.InvalidUserCodeError("Could not execute child termination callback: "+traceback.format_exc())
InvalidUserCodeError: <smach.exceptions.InvalidUserCodeError instance at 0x3af46c8>
[INFO] [WallTime: 1384915863.959108] Wed Nov 20 03:51:03 [initandlisten] connection accepted from 127.0.0.1:40100 #392
[INFO] [WallTime: 1384915863.960895] Wed Nov 20 03:51:03 [conn392] end connection 127.0.0.1:40100
[INFO] [WallTime: 1384915863.961346] State machine transitioning 'POINT_CHOOSER':'patrol'-->'PATROL_POINT'
[INFO] [WallTime: 1384915863.962346] State machine starting in initial state 'MONITORED_MOVE_BASE' with userdata:
['goal_pose']
[INFO] [WallTime: 1384915863.962868] Concurrence starting with userdata:
['goal_pose']
[INFO] [WallTime: 1384915863.968537] State machine starting in initial state 'MOVE_BASE' with userdata:
['goal_pose', 'n_move_base_fails']
[ INFO] [1384915864.072496966]: Got new plan
[ INFO] [1384915864.272612072]: Got new plan
[ INFO] [1384915864.772638319]: Got new plan
[ INFO] [1384915865.272599761]: Got new plan
[ INFO] [1384915865.772577105]: Got new plan
[ INFO] [1384915866.272648330]: Got new plan
[ INFO] [1384915866.772774740]: Got new plan
[ INFO] [1384915867.272610656]: Got new plan
[ INFO] [1384915867.774943752]: Got new plan
[ INFO] [1384915868.272664173]: Got new plan
[ INFO] [1384915868.772562999]: Got new plan
[ INFO] [1384915869.272611129]: Got new plan
[ INFO] [1384915869.772590155]: Got new plan
[ INFO] [1384915870.277087519]: Got new plan
[ INFO] [1384915870.772575485]: Got new plan
[ INFO] [1384915871.272596253]: Got new plan
[ INFO] [1384915871.772819474]: Got new plan
[ INFO] [1384915872.272515765]: Got new plan
[ INFO] [1384915872.772633869]: Got new plan
[ INFO] [1384915873.272574297]: Got new plan
[ INFO] [1384915873.772536023]: Got new plan
[ INFO] [1384915874.275749413]: Got new plan
[ INFO] [1384915874.772638395]: Got new plan
[ INFO] [1384915875.272705328]: Got new plan
[ INFO] [1384915875.772881346]: Got new plan
[ INFO] [1384915876.272517184]: Got new plan
[ INFO] [1384915876.772512236]: Got new plan
[ INFO] [1384915877.179355662]: Got new plan
[ INFO] [1384915877.672526689]: Goal reached
[INFO] [WallTime: 1384915877.673881] State machine terminating 'MOVE_BASE':'succeeded':'succeeded'
[INFO] [WallTime: 1384915877.675081] Concurrent state 'MOVE_BASE_SM' returned outcome 'succeeded' on termination.
[INFO] [WallTime: 1384915877.676184] Concurrent state 'BUMPER_MONITOR' returned outcome 'preempted' on termination.
[INFO] [WallTime: 1384915877.677493] Concurrent state 'NAV_PAUSE_MONITOR' returned outcome 'preempted' on termination.
[INFO] [WallTime: 1384915877.682558] Concurrent state 'STUCK_ON_CARPET_MONITOR' returned outcome 'preempted' on termination.
[INFO] [WallTime: 1384915877.685053] Concurrent state 'BATTERY_MONITOR' returned outcome 'preempted' on termination.
[INFO] [WallTime: 1384915877.686368] Concurrent Outcomes: {'BUMPER_MONITOR': 'preempted', 'NAV_PAUSE_MONITOR': 'preempted', 'MOVE_BASE_SM': 'succeeded', 'STUCK_ON_CARPET_MONITOR': 'preempted', 'BATTERY_MONITOR': 'preempted'}
[INFO] [WallTime: 1384915877.686707] State machine terminating 'MONITORED_MOVE_BASE':'succeeded':'succeeded'
[INFO] [WallTime: 1384915877.687015] State machine transitioning 'PATROL_POINT':'succeeded'-->'POINT_CHOOSER'
[INFO] [WallTime: 1384915878.692992] Wed Nov 20 03:51:18 [initandlisten] connection accepted from 127.0.0.1:40333 #393
[INFO] [WallTime: 1384915878.694991] Wed Nov 20 03:51:18 [conn393] end connection 127.0.0.1:40333
[INFO] [WallTime: 1384915878.695612] State machine transitioning 'POINT_CHOOSER':'patrol'-->'PATROL_POINT'
[INFO] [WallTime: 1384915878.696552] State machine starting in initial state 'MONITORED_MOVE_BASE' with userdata:
['goal_pose']
[INFO] [WallTime: 1384915878.696908] Concurrence starting with userdata:
['goal_pose']
[INFO] [WallTime: 1384915878.700518] State machine starting in initial state 'MOVE_BASE' with userdata:
['goal_pose', 'n_move_base_fails']
[ INFO] [1384915878.702863435]: Got new plan
[ INFO] [1384915878.803723747]: Got new plan
[ INFO] [1384915879.203057525]: Got new plan
[ INFO] [1384915879.702982949]: Got new plan
[ INFO] [1384915880.206785215]: Got new plan
[ INFO] [1384915880.702990147]: Got new plan
[ INFO] [1384915881.203019967]: Got new plan
[ INFO] [1384915881.707909492]: Got new plan
[ INFO] [1384915882.204338783]: Got new plan
[ INFO] [1384915882.703091882]: Got new plan
[ INFO] [1384915883.202957516]: Got new plan
[ INFO] [1384915883.703730508]: Got new plan
[ INFO] [1384915884.203108091]: Got new plan
[ INFO] [1384915884.703197185]: Got new plan
[ INFO] [1384915885.203189551]: Got new plan
[ INFO] [1384915885.703296998]: Got new plan
[ INFO] [1384915886.203047561]: Got new plan
[ INFO] [1384915886.703229830]: Got new plan
[ INFO] [1384915887.203016529]: Got new plan
[ INFO] [1384915887.702963624]: Got new plan
[ INFO] [1384915888.202968566]: Got new plan
[ INFO] [1384915888.802989338]: Got new plan
[ INFO] [1384915889.203877291]: Got new plan
[ INFO] [1384915889.503211314]: Goal reached
[INFO] [WallTime: 1384915889.504907] State machine terminating 'MOVE_BASE':'succeeded':'succeeded'
[INFO] [WallTime: 1384915889.511915] Concurrent state 'MOVE_BASE_SM' returned outcome 'succeeded' on termination.
[INFO] [WallTime: 1384915889.517199] Concurrent state 'BUMPER_MONITOR' returned outcome 'preempted' on termination.
[INFO] [WallTime: 1384915889.523308] Concurrent state 'NAV_PAUSE_MONITOR' returned outcome 'preempted' on termination.
[INFO] [WallTime: 1384915889.531613] Concurrent state 'STUCK_ON_CARPET_MONITOR' returned outcome 'preempted' on termination.
[INFO] [WallTime: 1384915889.533013] Concurrent state 'BATTERY_MONITOR' returned outcome 'preempted' on termination.
[INFO] [WallTime: 1384915969.042704] Wed Nov 20 03:52:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384916269.058534] Wed Nov 20 03:57:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384916569.079988] Wed Nov 20 04:02:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384916869.104136] Wed Nov 20 04:07:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[ WARN] [1384917015.920784865]: (MIRA) Dropping data (slot) in channel '/robot/RobotFrame' since slot with same timestamp already exists
[WARNING ] 2013-Nov-20 04:10:15.920711 Dropping data (slot) in channel '/robot/RobotFrame' since slot with same timestamp already exists
[ WARN] [1384917015.920986641]: (MIRA) Dropping data (slot) in channel '/robot/Mileage' since slot with same timestamp already exists
[WARNING ] 2013-Nov-20 04:10:15.920975 Dropping data (slot) in channel '/robot/Mileage' since slot with same timestamp already exists
[ WARN] [1384917015.921032396]: (MIRA) Dropping data (slot) in channel '/robot/Odometry' since slot with same timestamp already exists
[WARNING ] 2013-Nov-20 04:10:15.921023 Dropping data (slot) in channel '/robot/Odometry' since slot with same timestamp already exists
[INFO] [WallTime: 1384917169.172932] Wed Nov 20 04:12:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384917469.205504] Wed Nov 20 04:17:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384917769.254029] Wed Nov 20 04:22:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384918069.274840] Wed Nov 20 04:27:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384918369.298461] Wed Nov 20 04:32:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384918669.355161] Wed Nov 20 04:37:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384918969.375316] Wed Nov 20 04:42:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384919269.403878] Wed Nov 20 04:47:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384919569.428488] Wed Nov 20 04:52:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384919869.461946] Wed Nov 20 04:57:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384920169.472549] Wed Nov 20 05:02:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384920469.491897] Wed Nov 20 05:07:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384920769.505672] Wed Nov 20 05:12:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384921069.537971] Wed Nov 20 05:17:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384921369.570239] Wed Nov 20 05:22:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384921669.585611] Wed Nov 20 05:27:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384921969.600428] Wed Nov 20 05:32:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384922269.630511] Wed Nov 20 05:37:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384922569.650308] Wed Nov 20 05:42:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384922869.668858] Wed Nov 20 05:47:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384923169.691725] Wed Nov 20 05:52:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384923469.738729] Wed Nov 20 05:57:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384923769.754600] Wed Nov 20 06:02:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384924069.778235] Wed Nov 20 06:07:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384924369.809863] Wed Nov 20 06:12:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384924669.846856] Wed Nov 20 06:17:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384924969.865392] Wed Nov 20 06:22:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384925269.885877] Wed Nov 20 06:27:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384925569.906092] Wed Nov 20 06:32:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384925869.954760] Wed Nov 20 06:37:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384926169.984953] Wed Nov 20 06:42:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384926470.003611] Wed Nov 20 06:47:49 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384926770.021903] Wed Nov 20 06:52:50 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384927070.038887] Wed Nov 20 06:57:50 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384927370.061452] Wed Nov 20 07:02:50 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384927670.086981] Wed Nov 20 07:07:50 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384927970.111586] Wed Nov 20 07:12:50 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384928270.170665] Wed Nov 20 07:17:50 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384928570.242993] Wed Nov 20 07:22:50 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384928870.278125] Wed Nov 20 07:27:50 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384929170.301401] Wed Nov 20 07:32:50 [clientcursormon] mem (MB) res:63 virt:3454 mapped:1136
[INFO] [WallTime: 1384929470.323007] Wed Nov 20 07:37:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384929770.361280] Wed Nov 20 07:42:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384930070.380473] Wed Nov 20 07:47:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384930370.393281] Wed Nov 20 07:52:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384930670.408900] Wed Nov 20 07:57:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384930970.425577] Wed Nov 20 08:02:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384931270.443431] Wed Nov 20 08:07:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384931570.466061] Wed Nov 20 08:12:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[ WARN] [1384931590.521747021]: (MIRA) Dropping data (slot) in channel '/robot/RobotFrame' since slot with same timestamp already exists
[WARNING ] 2013-Nov-20 08:13:10.521685 Dropping data (slot) in channel '/robot/RobotFrame' since slot with same timestamp already exists
[ WARN] [1384931590.522136974]: (MIRA) Dropping data (slot) in channel '/robot/Mileage' since slot with same timestamp already exists
[WARNING ] 2013-Nov-20 08:13:10.522120 Dropping data (slot) in channel '/robot/Mileage' since slot with same timestamp already exists
[ WARN] [1384931590.522292933]: (MIRA) Dropping data (slot) in channel '/robot/Odometry' since slot with same timestamp already exists
[WARNING ] 2013-Nov-20 08:13:10.522268 Dropping data (slot) in channel '/robot/Odometry' since slot with same timestamp already exists
[INFO] [WallTime: 1384931870.492776] Wed Nov 20 08:17:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384932170.518352] Wed Nov 20 08:22:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384932470.550978] Wed Nov 20 08:27:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[ WARN] [1384932744.314974559]: (MIRA) Dropping data (slot) in channel '/robot/RobotFrame' since slot with same timestamp already exists
[WARNING ] 2013-Nov-20 08:32:24.314912 Dropping data (slot) in channel '/robot/RobotFrame' since slot with same timestamp already exists
[ WARN] [1384932744.315143249]: (MIRA) Dropping data (slot) in channel '/robot/Mileage' since slot with same timestamp already exists
[WARNING ] 2013-Nov-20 08:32:24.315129 Dropping data (slot) in channel '/robot/Mileage' since slot with same timestamp already exists
[ WARN] [1384932744.315200848]: (MIRA) Dropping data (slot) in channel '/robot/Odometry' since slot with same timestamp already exists
[WARNING ] 2013-Nov-20 08:32:24.315189 Dropping data (slot) in channel '/robot/Odometry' since slot with same timestamp already exists
[INFO] [WallTime: 1384932770.584377] Wed Nov 20 08:32:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384933070.609961] Wed Nov 20 08:37:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384933370.635249] Wed Nov 20 08:42:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384933670.649982] Wed Nov 20 08:47:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[ WARN] [1384933904.921895589]: (MIRA) Dropping data (slot) in channel '/robot/RobotFrame' since slot with same timestamp already exists
[WARNING ] 2013-Nov-20 08:51:44.921839 Dropping data (slot) in channel '/robot/RobotFrame' since slot with same timestamp already exists
[ WARN] [1384933904.922076924]: (MIRA) Dropping data (slot) in channel '/robot/Mileage' since slot with same timestamp already exists
[WARNING ] 2013-Nov-20 08:51:44.922057 Dropping data (slot) in channel '/robot/Mileage' since slot with same timestamp already exists
[ WARN] [1384933904.922142942]: (MIRA) Dropping data (slot) in channel '/robot/Odometry' since slot with same timestamp already exists
[WARNING ] 2013-Nov-20 08:51:44.922129 Dropping data (slot) in channel '/robot/Odometry' since slot with same timestamp already exists
[INFO] [WallTime: 1384933970.664004] Wed Nov 20 08:52:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384934270.679605] Wed Nov 20 08:57:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384934570.694571] Wed Nov 20 09:02:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384934870.730182] Wed Nov 20 09:07:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384935170.755407] Wed Nov 20 09:12:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384935470.780830] Wed Nov 20 09:17:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384935770.797004] Wed Nov 20 09:22:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[ WARN] [1384935949.301209312]: (MIRA) Dropping data (slot) in channel '/robot/RobotFrame' since slot with same timestamp already exists
[WARNING ] 2013-Nov-20 09:25:49.301158 Dropping data (slot) in channel '/robot/RobotFrame' since slot with same timestamp already exists
[ WARN] [1384935949.301391335]: (MIRA) Dropping data (slot) in channel '/robot/Mileage' since slot with same timestamp already exists
[WARNING ] 2013-Nov-20 09:25:49.301375 Dropping data (slot) in channel '/robot/Mileage' since slot with same timestamp already exists
[ WARN] [1384935949.301464017]: (MIRA) Dropping data (slot) in channel '/robot/Odometry' since slot with same timestamp already exists
[WARNING ] 2013-Nov-20 09:25:49.301447 Dropping data (slot) in channel '/robot/Odometry' since slot with same timestamp already exists
[INFO] [WallTime: 1384936070.809483] Wed Nov 20 09:27:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384936370.828543] Wed Nov 20 09:32:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384936670.850130] Wed Nov 20 09:37:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384936970.869971] Wed Nov 20 09:42:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384937270.886171] Wed Nov 20 09:47:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384937570.901487] Wed Nov 20 09:52:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384937870.939753] Wed Nov 20 09:57:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384938170.957339] Wed Nov 20 10:02:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384938470.981520] Wed Nov 20 10:07:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
Device "1d27/0601@3/4" error state changed to 1
Device "1d27/0601@3/4" error state changed to 0
Device "1d27/0601@3/4" error state changed to 1
Device "1d27/0601@3/4" error state changed to 0
[INFO] [WallTime: 1384938770.993453] Wed Nov 20 10:12:50 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384939071.016952] Wed Nov 20 10:17:51 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384939371.064673] Wed Nov 20 10:22:51 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384939671.093450] Wed Nov 20 10:27:51 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384939971.110774] Wed Nov 20 10:32:51 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
[INFO] [WallTime: 1384940271.170134] Wed Nov 20 10:37:51 [clientcursormon] mem (MB) res:55 virt:3454 mapped:1136
@cburbridge please can you check the scitos node etc. logs above?
Device "1d27/0601@2/3" error state changed to 2 Device "1d27/0601@2/3" error state changed to 0 Device "1d27/0601@2/3" error state changed to 2 Device "1d27/0601@2/3" error state changed to 0 Device "1d27/0601@2/3" error state changed to 2 Device "1d27/0601@2/3" error state changed to 0 Device "1d27/0601@2/3" error state changed to 2 Device "1d27/0601@2/3" error state changed to 0
looks to be coming from the camera; the error with the CAN bus might be related, was the CPU load very high?
I can just say that it took minutes to get back logged in because of the slow performance of the system. But it could be that the second camera is causing these problems. It is quite tricky to even get the robot starting with two cameras connected. During the boot process of the robot with the two cameras connected, it sometimes tells me that there is an address issue on the bus. Haven't managed to get a picture yet, because the message disappears very quickly.
I think this two camera setup is the issue. Maybe they are causing the bus to slow down too much for the USB CAN->RS232 adapter to work. I don't know what to suggest, I think in the long run we need to only have one camera per computer.
That could be, but we tested the two camera setup for quite some time and without the navigation processes running we didn't get any CAN bus issues and we could still teleoperate the robot. But the two camera setup definitely eats a lot of resources.
Btw are you using both cameras at Birmingham ?
alright, we are using a chest_xtion and a webcam instead of the head_xtion and got a similar problem last night. The robot didn't know what to do (was just standing in a corner) and the GUI didn't update anymore (no stats shown either). Could maybe anyone help who knows how to fix this?
bringup:
[ INFO] [1385480808.252753206]: Going into main loop.
[ INFO] [1385480815.963275888]: Stopping to publish chest transform after 10 seconds, quitting...
[chest_calibration_publisher-18] process has finished cleanly
log file: /localhome/strands/.ros/log/ebd0167c-56b1-11e3-9ed1-6c8814462a8c/chest_calibration_publisher-18*.log
[ WARN] [1385488386.418815839]: (MIRA) Dropping data (slot) in channel '/robot/can/OutgoingCAN' since slot with same timestamp already exists
[WARNING ] 2013-Nov-26 18:53:06.247698 Dropping data (slot) in channel '/robot/can/OutgoingCAN' since slot with same timestamp already exists
[ WARN] [1385501166.447471605]: (MIRA) Dropping data (slot) in channel '/robot/RobotFrame' since slot with same timestamp already exists
[WARNING ] 2013-Nov-26 22:26:06.385260 Dropping data (slot) in channel '/robot/RobotFrame' since slot with same timestamp already exists
[ WARN] [1385501166.676318992]: (MIRA) Dropping data (slot) in channel '/robot/Mileage' since slot with same timestamp already exists
[WARNING ] 2013-Nov-26 22:26:06.676220 Dropping data (slot) in channel '/robot/Mileage' since slot with same timestamp already exists
[ WARN] [1385516017.456121255]: (MIRA) Invalid message length on MetraLabs CAN-to-Serial Adapter
[WARNING ] 2013-Nov-27 02:33:37.456085 Invalid message length on MetraLabs CAN-to-Serial Adapter
[ WARN] [1385516018.283074157]: Missing head angle publication as MIRA parameter error.
[ WARN] [1385516025.139924756]: (MIRA) Invalid message length on MetraLabs CAN-to-Serial Adapter
SerialCommS300: Checksum's dont match, thats bad (data packet size 1104)
SerialCommS300: Checksum's dont match, thats bad (data packet size 1104)
[WARNING ] 2013-Nov-27 02:33:45.116927 Invalid message length on MetraLabs CAN-to-Serial Adapter
[ WARN] [1385516026.268073429]: (MIRA) Invalid CRC on MetraLabs CAN-to-Serial Adapter. Is 0x59aa should 0x84dc
[WARNING ] 2013-Nov-27 02:33:46.268034 Invalid CRC on MetraLabs CAN-to-Serial Adapter. Is 0x59aa should 0x84dc
[ WARN] [1385516159.168692758]: Missing head angle publication as MIRA parameter error.
[ WARN] [1385516159.420047460]: Missing head angle publication as MIRA parameter error.
[ERROR] [1385516159.546886808]: (MIRA) /robot/can/CANDriver Recovering: : Incoming message watchdog triggered. No incoming messages.
[ERROR ] 2013-Nov-27 02:35:59.430441 /robot/can/CANDriver Recovering: : Incoming message watchdog triggered. No incoming messages.
[ WARN] [1385516159.672079859]: Missing head angle publication as MIRA parameter error.
[ WARN] [1385516159.923711710]: Missing head angle publication as MIRA parameter error.
[ WARN] [1385516160.518237237]: Missing head angle publication as MIRA parameter error.
[ERROR] [1385516165.490293614]: Exception thrown while processing service call: Failed to write SDO node(0x04) index(0x2004) subindex (0x05) (/home/chmartin/release/MIRA-commercial/toolboxes/CAN/include/can/CANOpenSDOClient.h:197)
[ WARN] [1385516165.927962158]: Missing head angle publication as MIRA parameter error.
scitos_2d_navigation with_camera:=true
[ WARN] [1385548215.127833274]: Could not get robot pose, cancelling reconfiguration
[ERROR] [1385548215.527455150]: Extrapolation Error looking up robot pose: Unable to lookup transform, cache is empty, when looking up transform from frame [/base_link] to frame [/map]
[ WARN] [1385548216.132158619]: Could not get robot pose, cancelling reconfiguration
[ WARN] [1385548216.308574554]: No laser scan received (and thus no pose updates have been published) for 32062.001048 seconds. Verify that data is being published on the /scan topic.
[ERROR] [1385548216.626958571]: Extrapolation Error looking up robot pose: Unable to lookup transform, cache is empty, when looking up transform from frame [/base_link] to frame [/map]
[ WARN] [1385548217.227106622]: Could not get robot pose, cancelling reconfiguration
[ERROR] [1385548217.628394891]: Extrapolation Error looking up robot pose: Unable to lookup transform, cache is empty, when looking up transform from frame [/base_link] to frame [/map]
waypoint_patroller:
[INFO] [WallTime: 1385516102.016688] State machine transitioning 'MOVE_BASE':'aborted'-->'RECOVER_MOVE_BASE'
[INFO] [WallTime: 1385516102.598708] action triggered: say I am having problems moving. Please push me to a clear area.
[INFO] [WallTime: 1385516102.599087] finished speaking...
[INFO] [WallTime: 1385516102.630971] say I am having problems moving. Please push me to a clear area.
[INFO] [WallTime: 1385516125.919192] played
[INFO] [WallTime: 1385516144.470340] State machine transitioning 'RECOVER_MOVE_BASE':'succeeded'-->'MOVE_BASE'
[INFO] [WallTime: 1385516159.880638] State machine transitioning 'MOVE_BASE':'aborted'-->'RECOVER_MOVE_BASE'
[ERROR] [WallTime: 1385516168.102658] InvalidUserCodeError: Could not execute state 'RECOVER_MOVE_BASE' of type '<waypoint_patroller.recover_states.RecoverMoveBase object at 0x1ce35d0>': Traceback (most recent call last):
File "/opt/strands/strands_catkin_ws/src/catkinized_smach/smach/src/smach/state_machine.py", line 241, in _update_once
self._remappings[self._current_label]))
File "/opt/strands/strands_catkin_ws/src/autonomous_patrolling/waypoint_patroller/src/waypoint_patroller/recover_states.py", line 83, in execute
self.enable_motors(False)
File "/opt/ros/groovy/lib/python2.7/dist-packages/rospy/impl/tcpros_service.py", line 435, in __call__
return self.call(*args, **kwds)
File "/opt/ros/groovy/lib/python2.7/dist-packages/rospy/impl/tcpros_service.py", line 515, in call
responses = transport.receive_once()
File "/opt/ros/groovy/lib/python2.7/dist-packages/rospy/impl/tcpros_base.py", line 667, in receive_once
p.read_messages(b, msg_queue, sock)
File "/opt/ros/groovy/lib/python2.7/dist-packages/rospy/impl/tcpros_service.py", line 353, in read_messages
self._read_ok_byte(b, sock)
File "/opt/ros/groovy/lib/python2.7/dist-packages/rospy/impl/tcpros_service.py", line 336, in _read_ok_byte
raise ServiceException("service [%s] responded with an error: %s"%(self.resolved_name, str))
ServiceException: service [/enable_motors] responded with an error: Failed to write SDO node(0x04) index(0x2004) subindex (0x05) (/home/chmartin/release/MIRA-commercial/toolboxes/CAN/include/can/CANOpenSDOClient.h:197)
[INFO] [WallTime: 1385516168.103556] Concurrent state 'STUCK_ON_CARPET_MONITOR' returned outcome 'preempted' on termination.
[INFO] [WallTime: 1385516168.105120] Concurrent state 'BATTERY_MONITOR' returned outcome 'preempted' on termination.
[INFO] [WallTime: 1385516168.105646] Concurrent state 'BUMPER_MONITOR' returned outcome 'preempted' on termination.
[ERROR] [WallTime: 1385516168.106139] InvalidStateError: Could not execute child state 'MOVE_BASE_SM': Traceback (most recent call last):
File "/opt/strands/strands_catkin_ws/src/catkinized_smach/smach/src/smach/concurrence.py", line 326, in _state_runner
self._remappings[label]))
File "/opt/strands/strands_catkin_ws/src/autonomous_patrolling/waypoint_patroller/src/waypoint_patroller/navigation.py", line 105, in execute
outcome = smach.StateMachine.execute(self, userdata)
File "/opt/strands/strands_catkin_ws/src/catkinized_smach/smach/src/smach/state_machine.py", line 347, in execute
container_outcome = self._update_once()
File "/opt/strands/strands_catkin_ws/src/catkinized_smach/smach/src/smach/state_machine.py", line 246, in _update_once
raise smach.InvalidUserCodeError("Could not execute state '%s' of type '%s': " % ( self._current_label, self._current_state ) + traceback.format_exc())
InvalidUserCodeError: <smach.exceptions.InvalidUserCodeError instance at 0x7f87ec1bcf38>
[INFO] [WallTime: 1385516168.449908] Concurrent state 'NAV_PAUSE_MONITOR' returned outcome 'preempted' on termination.
Exception in thread concurrent_split:MOVE_BASE_SM:
Traceback (most recent call last):
File "/usr/lib/python2.7/threading.py", line 551, in __bootstrap_inner
self.run()
File "/usr/lib/python2.7/threading.py", line 504, in run
self.__target(*self.__args, **self.__kwargs)
File "/opt/strands/strands_catkin_ws/src/catkinized_smach/smach/src/smach/concurrence.py", line 331, in _state_runner
raise smach.InvalidStateError(("Could not execute child state '%s': " % label)+traceback.format_exc())
InvalidStateError: <smach.exceptions.InvalidStateError instance at 0x1d6dab8>
I'll close this issue as is outdated patroller code.
Our robot didn't quite make it through the night. This morning I was just right there before the batteries got completely flat. Don't know how long it had been standing there and what really was the problem. Anyway, this is the output of the bringup file. Maybe someone can help. Some side notes, Ubuntu's performance was really slow, /head_xtion stopped publishing, rostopic echo /mileage doesn't output anymore,...
and scitos_2d_nav.launch says: