LynxModule command timeout randomly duing Autonomous

[technova12611]

We are trying to figure out why our autonomous suddenly started throwing "timeout: abandoning waiting 250ms for response" error. It was working fine before our InterLeague event, but we had experienced this issue the night before the competition and didn't have time to resolve it.

Now we are trying to figure it out, the weird thing is that this seemed impacting only autonomous and it can happen at anytime and last for less than a second or the 20+ seconds, once it switched to TeleOps, it seemed working fine, although we've seen this error occationally in TeleOps too.

Could this be related to bad USB cables, bad REV Expansion Hub? Or could this be related to SDK bug or our team code.

Our robot info:

• Two Moto E4 phones for RC and DS
• Two REV Expansion Hub with latest 1.8.2 firmware
• Runing latest 4.3 FTC SDK
• 8 Motors, 5 servos on REV Servo Power Module
• Rev 2m Distance and Color sensor on I2C bus

Again, we've been using the same code for quite a while with no issues, this issue came on suddenly and remained.

Thank you for your help.

LogCat for one of the matches enclosed. Robot stopped after landing and dislogged the gold mineral and had no issues during TeleOps.

12-15 16:04:44.210  8684  8898 I RoverRuckusCraterDoubleSamplingAuto: BLUE | State:               2 [TOUCH_DOWN] |    End | 8744.3 |  8426 | IMU: -86.1 | Gold Loc:RIGHT | ToWall: 255.00 | TOF: 255.00 | Battery: 13.60 | Rev Color (R,G,B): (20, 21,18)
12-15 16:04:44.267  8684  8898 I RoverRuckusCraterDoubleSamplingAuto: TechNova: BLUE | State:            3 [DRIVE_FORWARD] |  Start | 8795.1 |     0 | IMU: -88.9 | Gold Loc:RIGHT | ToWall: 255.00 | TOF: 255.00 | Battery: 13.78 | Rev Color (R,G,B): (21, 22,18)
12-15 16:04:44.267  8684  8898 : MecanumRobot: Encoder: | 67.91 | 509
12-15 16:04:45.003  8684  8898 I RoverRuckusCraterDoubleSamplingAuto: TechNova: BLUE | State:            3 [DRIVE_FORWARD] |    End | 9535.4 |   740 | IMU: -92.8 | Gold Loc:RIGHT | ToWall: 17.80 | TOF: 255.00 | Battery: 13.76 | Rev Color (R,G,B): (23, 23,19)
12-15 16:04:45.068  8684  8898 I RoverRuckusCraterDoubleSamplingAuto: TechNova: BLUE | State:            4 [DISPLACE_GOLD] |  Start | 9588.3 |     0 | IMU: -92.8 | Gold Loc:RIGHT | ToWall: 18.54 | TOF: 255.00 | Battery: 13.77 | Rev Color (R,G,B): (23, 23,19)
12-15 16:04:45.069  8684  8898 I RobotCore: ### Gold Location: --- RIGHT
12-15 16:04:45.070  8684  8898 : RoverRuckusCraterDoubleSamplingAuto:  Strafe left: | 18.00, 0.45, 2.00 |  Runtime: 9.65 
12-15 16:04:46.124  8684  8898 : RoverRuckusCraterDoubleSamplingAuto: Encoder drive | 0.976 (s) |  Runtime: 10.71 
12-15 16:04:46.124  8684  8898 : MecanumRobot: Encoder: | 67.91 | 1018
12-15 16:04:46.460  8684  8898 V LynxModule: retransmitting: mod=3 cmd=0x1015 msg#=159 ref#=0 
12-15 16:04:46.561  8684  8898 V LynxModule: retransmitting: mod=3 cmd=0x1015 msg#=159 ref#=0 
12-15 16:04:46.609  8684  8898 V LynxModule: retransmitting: mod=3 cmd=0x1015 msg#=159 ref#=0 
12-15 16:04:46.610  8684  8898 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxIsMotorAtTargetCommand mod=3 msg#=159
12-15 16:04:46.611  8684  8898 V RobotCore: nack rec'd mod=3 msg#=159 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
12-15 16:04:46.611  8684  8898 W LynxMotor: LynxIsMotorAtTargetCommand was abandoned waiting for response
12-15 16:04:46.738  8684  8898 V LynxModule: retransmitting: mod=3 cmd=0x1014 msg#=162 ref#=0 
12-15 16:04:46.839  8684  8898 V LynxModule: retransmitting: mod=3 cmd=0x1014 msg#=162 ref#=0 
12-15 16:04:46.887  8684  8898 V LynxModule: retransmitting: mod=3 cmd=0x1014 msg#=162 ref#=0 
12-15 16:04:46.888  8684  8898 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorTargetPositionCommand mod=3 msg#=162
12-15 16:04:46.888  8684  8898 V RobotCore: nack rec'd mod=3 msg#=162 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
12-15 16:04:46.889  8684  8898 W LynxMotor: LynxGetMotorTargetPositionCommand was abandoned waiting for response
12-15 16:04:47.029  8684  8898 : MecanumRobot: Encoder: | 67.91 | 611
12-15 16:04:47.179  8684  8898 V LynxModule: retransmitting: mod=3 cmd=0x1008 msg#=188 ref#=0 
12-15 16:04:47.281  8684  8898 V LynxModule: retransmitting: mod=3 cmd=0x1008 msg#=188 ref#=0 
12-15 16:04:47.329  8684  8898 V LynxModule: retransmitting: mod=3 cmd=0x1008 msg#=188 ref#=0 
12-15 16:04:47.329  8684  8898 V RobotCore: timeout: abandoning waiting 250ms for ack: cmd=LynxSetMotorChannelModeCommand mod=3 msg#=188
12-15 16:04:47.330  8684  8898 V RobotCore: nack rec'd mod=3 msg#=188 ref#=0 reason=ABANDONED_WAITING_FOR_ACK:257
12-15 16:04:47.330  8684  8898 W LynxMotor: LynxSetMotorChannelModeCommand was abandoned waiting for ack
12-15 16:04:47.643  8684  8898 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=221 ref#=0 
12-15 16:04:47.747  8684  8898 V LynxModule: retransmitting: mod=3 cmd=0x1014 msg#=222 ref#=0 
12-15 16:04:47.848  8684  8898 V LynxModule: retransmitting: mod=3 cmd=0x1014 msg#=222 ref#=0 
12-15 16:04:47.896  8684  8898 V LynxModule: retransmitting: mod=3 cmd=0x1014 msg#=222 ref#=0 
12-15 16:04:47.897  8684  8898 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorTargetPositionCommand mod=3 msg#=222
12-15 16:04:47.897  8684  8898 V RobotCore: nack rec'd mod=3 msg#=222 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
12-15 16:04:47.898  8684  8898 W LynxMotor: LynxGetMotorTargetPositionCommand was abandoned waiting for response
12-15 16:05:05.440  8684  8753 V Robocol : received command: CMD_INIT_OP_MODE(12552) $Stop$Robot$

[cmacfarl]

Has all the hallmarks of a bad usb port on one end. Those ports do wear. Do you have a spare expansion hub you can swap in? I presume your E4's are rather new and hence will not have worn usb ports.

Note that I try to encourage the teams that I mentor, who aren't using Blocks or OnBot Java to use adb wireless for deploying software in an effort to reduce wear on that port.

[technova12611]

It might not be the REV expansion hub since we are using USB retention mount. The most likely culprit is the micro USB to the phone, we have been using it since the season starts and plug/unplug a lot. It will be very easy to change. We thought if it was USB cable, it shouldn't have worked at all.

We will report back with the results when we meet on Friday!

[gearsincorg]

One possible difference between Auto and Teleop is that you are probably interrogating the motor encoders more in Auto. eg: to determine distance traveled. or possibly using your distance sensor. Would this be correct?

Which of your Expansion hubs have the drive motors, and/or distance sensors on it? Does that portion or auto require more than the typical number of inter-hub commands?

A few days ago, we noticed that our robot seemed to be developing high driving latencies. Inspecting the log files indicated a large number of command retried. We eventually fixed the problem by replacing the RS485 cable that joins the two Expansion hubs. There was no apparent problems with that cable, but the latencies went away. Odd coincidence.

[technova12611]

Yes, we do use I2C sensors, they are both on the same expansion hub, our motors are split equally into two hubs, we did see "Problem with ..." issues too.

Ok, I think we got a plan, basically replace cables, USB adapter cable, RS 485 cable, hopefully, this will fix our issue.

[cmacfarl]

If @gearsincorg is fingering the RS485 cable I'd replace that first. Note the mod=3 in this log message.

12-15 16:04:47.179  8684  8898 V LynxModule: retransmitting: mod=3 cmd=0x1008 msg#=188 ref#=0 

Is the module address of the downstream expansion hub 3 perchance?

[technova12611]

yes, 3 is the downstream expansion hub address. We will replace the RS 485 and test it out.

[Windwoes]

@cmacfarl @gearsincorg

Regarding RS-485 re-transmissions, see the related issue Noah opened here: https://github.com/ftctechnh/ftc_app/issues/491

[technova12611]

After replacing the RS 485 cable, everything is working properly.