Expansion Hub Disconnecting/Becoming Unresponsive

[shishghate]

For the past couple days we've had our expansion hub disconnect and then have the robot become unresponsive. It comes back, but takes a few seconds for the robot to reboot.

We've pulled the logs and we see it marking the hub as unresponsive as well as telling us it's losing connection to the webcam. Any suggestions on what we can try as we have replaced the expansion hub and replaced the power cord. TIA

11-12 13:45:59.949   976  1200 E LynxModule: Marking module #9 as unresponsive until we receive some data back
11-12 13:45:59.950   976  1200 W RobotCore: Expansion Hub 9 is currently unresponsive.
11-12 13:45:59.959   976  1203 D RobotCore: system telemetry: key=$System$Warning$ msg="Unable to find webcam "Webcam 1" with serial number FE0F8850.
11-12 13:45:59.959   976  1203 D RobotCore: 
11-12 13:45:59.959   976  1203 D RobotCore: Expansion Hub 9 not currently responding to commands."
11-12 13:45:59.973   976  1184 D SoundPlayer: playing volume=0.000000 samp=4|ms=2509
11-12 13:45:59.998   976  1181 V Robocol : sending CMD_PLAY_SOUND(25319), attempt: 0
11-12 13:46:00.060   976  1196 V LynxModule: REV Hub #9 has reconnected
11-12 13:46:00.060   976  1196 E LynxModule: unable to find originating LynxRespondable for mod=9 msg#=127 ref#=123
11-12 13:46:00.068   976  1203 D RobotCore: system telemetry: key=$System$Warning$ msg="Unable to find webcam "Webcam 1" with serial number FE0F8850."
11-12 13:46:00.504   976  4455 V LynxUsb : discovery waiting complete: #modules=2
11-12 13:46:00.504   976  4455 V LynxModule: close(#0)
11-12 13:46:00.507   976  4455 V LynxUsb : ...lynx discovery completed
11-12 13:46:00.508   976  4455 V FtcEventLoop: assessing LynxModuleMeta(#9,false,ImuType.UNKNOWN)
11-12 13:46:00.508   976  4455 V FtcEventLoop: assessing LynxModuleMeta(#173,true,ImuType.UNKNOWN)
11-12 13:46:00.511   976  4455 V LynxUsb : addConfiguredModule() module#=173
11-12 13:46:00.511   976  4455 V LynxUsb : addConfiguredModule() module#=173: already exists
11-12 13:46:00.515   976  4455 V LynxUsb : 0x067ee8cc on 0x0f8f9b52: releasing delegate to [(embedded)]
11-12 13:46:00.516   976  4455 V FtcEventLoop: getUSBAccessibleLynxDevices(): 1 modules found
11-12 13:46:00.516   976  4455 V FtcEventLoop: ...getUSBAccessibleLynxDevices()
11-12 13:46:00.520   976  4455 V Robocol : locally injecting CMD_GET_USB_ACCESSIBLE_LYNX_MODULES_RESP
11-12 13:46:02.476   976  1237 W AudioTrack: AUDIO_OUTPUT_FLAG_FAST denied by client; transfer 4, track 48000 Hz, output 44100 Hz
11-12 13:46:02.483   976  1237 D SoundPlayer: playing volume=0.000000 samp=4|ms=2509
11-12 13:46:02.518   976  1181 V Robocol : sending CMD_PLAY_SOUND(25357), attempt: 0
11-12 13:46:08.814   976  1141 V FtcWebSocket: Opening websocket (ip=localhost/127.0.0.1 port=8081)
11-12 13:46:08.818   976  1141 V WebSocketManager: Subscribed websocket (ip=localhost/127.0.0.1 port=8081) to namespace (progress)
11-12 13:46:08.837   976  1141 V FtcWebSocket: Opening websocket (ip=localhost/127.0.0.1 port=8081)
11-12 13:46:08.842   976  1141 V WebSocketManager: Subscribed websocket (ip=localhost/127.0.0.1 port=8081) to namespace (progress)
11-12 13:46:08.844   976  1141 V WebSocketManager: Subscribed websocket (ip=localhost/127.0.0.1 port=8081) to namespace (ControlHubUpdater)
11-12 13:46:08.862   976  1141 V FtcWebSocket: Opening websocket (ip=localhost/127.0.0.1 port=8081)
11-12 13:46:08.866   976  1141 V WebSocketManager: Subscribed websocket (ip=localhost/127.0.0.1 port=8081) to namespace (progress)
11-12 13:46:08.868   976  1141 V WebSocketManager: Subscribed websocket (ip=localhost/127.0.0.1 port=8081) to namespace (ControlHubUpdater)
11-12 13:46:08.886   976  1141 V FtcWebSocket: Opening websocket (ip=localhost/127.0.0.1 port=8081)
11-12 13:46:08.891   976  1141 V WebSocketManager: Subscribed websocket (ip=localhost/127.0.0.1 port=8081) to namespace (progress)
11-12 13:46:08.911   976  1141 V FtcWebSocket: Opening websocket (ip=localhost/127.0.0.1 port=8081)
11-12 13:46:08.915   976  1141 V WebSocketManager: Subscribed websocket (ip=localhost/127.0.0.1 port=8081) to namespace (progress)
11-12 13:46:08.940   976  1141 V FtcWebSocket: Opening websocket (ip=localhost/127.0.0.1 port=8081)
11-12 13:46:08.943   976  1141 V WebSocketManager: Subscribed websocket (ip=localhost/127.0.0.1 port=8081) to namespace (progress)
11-12 13:46:10.534   976  1141 V FtcWebSocket: Opening websocket (ip=localhost/127.0.0.1 port=8081)
11-12 13:46:10.539   976  1141 V WebSocketManager: Subscribed websocket (ip=localhost/127.0.0.1 port=8081) to namespace (progress)
11-12 13:46:10.542   976  1141 V WebSocketManager: Subscribed websocket (ip=localhost/127.0.0.1 port=8081) to namespace (ControlHubUpdater)
11-12 13:46:12.920   976  1141 V FtcWebSocket: Opening websocket (ip=localhost/127.0.0.1 port=8081)
11-12 13:46:12.922   976  1141 V WebSocketManager: Subscribed websocket (ip=localhost/127.0.0.1 port=8081) to namespace (progress)
11-12 13:46:12.925   976  1141 V WebSocketManager: Subscribed websocket (ip=localhost/127.0.0.1 port=8081) to namespace (ControlHubUpdater)
11-12 13:46:15.520   976  4659 V SessionCookie: added SessionCookie: cookie=08d3887d-706c-4cd6-87ab-32ded7f85492 uri='/js/rcInfo.json'
11-12 13:46:15.521   976  4659 I RobotCore: edina3763
11-12 13:46:15.543   976  4660 V SessionCookie: added SessionCookie: cookie=f83de956-0c53-4340-9d32-ae1c155bda4c uri='/revHubsAvailableForUpdate'
11-12 13:46:15.543   976  4660 V Robocol : locally injecting CMD_GET_USB_ACCESSIBLE_LYNX_MODULES
11-12 13:46:15.550   976  4455 V FtcEventLoop: getUSBAccessibleLynxDevices(includeModuleAddresses=true)...
11-12 13:46:15.550   976  4456 V FtcConfigTag: scanning USB bus...
11-12 13:46:15.553   976  4456 V FtDeviceManager: createDeviceInfoList(): 0 USB devices
11-12 13:46:15.553   976  4456 V USBScan : device count=1
11-12 13:46:15.555   976  4661 V USBScan : opening (embedded)...
11-12 13:46:15.555   976  4661 V RobotUsbManagerCombining: FTDI driver failed to open USB device with serial number (embedded) (returned null device)
11-12 13:46:15.555   976  4661 V RobotUsbManagerCombining: (embedded) is already open: unable to open second time
11-12 13:46:15.556   976  4661 V USBScan : RobotCoreException(Unable to open USB device (embedded): Combiner unable to open device with serialNumber = (embedded)) exception while opening (embedded)
11-12 13:46:15.556   976  4661 V USBScan : ... done opening (embedded)
11-12 13:46:15.557   976  4456 V USBScan : added extant device (embedded) type=LYNX_USB_DEVICE
11-12 13:46:15.560   976  4456 D UvcContext: usb device is *not* UVC compatible, /dev/bus/usb/003/016
11-12 13:46:15.560   976  4456 V USBScan : scanForUsbDevices() took 9ms count=1
11-12 13:46:15.560   976  4456 V FtcConfigTag: .. scanning complete: [(embedded)]
11-12 13:46:15.561   976  4455 V FtcEventLoop: getUSBAccessibleLynxDevices: found serial=(embedded)
11-12 13:46:15.561   976  4455 V FtcEventLoop: finding module addresses and current firmware versions
11-12 13:46:15.561   976  4455 V FtcEventLoop: getUSBAccessibleLynxDevices: finding module address for usbModule (embedded)
11-12 13:46:15.562   976  4455 V RobotCore: Creating REV Robotics USB Expansion Hub Portal [(embedded)]
11-12 13:46:15.562   976  4455 V LynxUsb : using existing [(embedded)]: 0x0f8f9b52
11-12 13:46:15.563   976  4455 V LynxUsb : 0x0e12ea3e on 0x0f8f9b52: new delegate to [(embedded)]
11-12 13:46:15.563   976  4455 V LynxUsb : lynx discovery beginning...transmitting LynxDiscoveryCommand()...
11-12 13:46:15.565   976  1196 V LynxUsb : onLynxDiscoveryResponseReceived()... module#=173 isParent=true
11-12 13:46:15.566   976  1196 V LynxUsb : discovered lynx module#=173 isParent=true
11-12 13:46:15.566   976  1196 V LynxUsb : ...onLynxDiscoveryResponseReceived()
11-12 13:46:15.567   976  4455 V LynxUsb : discovery waiting 1012ms and 0ns
11-12 13:46:15.590   976  1196 V LynxUsb : onLynxDiscoveryResponseReceived()... module#=9 isParent=false
11-12 13:46:15.590   976  1196 V LynxUsb : discovered lynx module#=9 isParent=false
11-12 13:46:15.590   976  1196 V LynxUsb : ...onLynxDiscoveryResponseReceived()
11-12 13:46:15.811   976  1203 V LynxModule: retransmitting: mod=9 cmd=0x7f05 msg#=170 ref#=0 
11-12 13:46:15.912   976  1203 V LynxModule: retransmitting: mod=9 cmd=0x7f05 msg#=170 ref#=0 
11-12 13:46:15.961   976  1203 V LynxModule: retransmitting: mod=9 cmd=0x7f05 msg#=170 ref#=0 
11-12 13:46:15.962   976  1203 E LynxModule: timeout: abandoning waiting 250ms for ack: cmd=LynxFailSafeCommand mod=9 msg#=170
11-12 13:46:15.963   976  1203 E LynxModule: Marking module #9 as unresponsive until we receive some data back
11-12 13:46:15.963   976  1203 W RobotCore: Expansion Hub 9 is currently unresponsive.
11-12 13:46:15.972   976  1196 V LynxModule: REV Hub #9 has reconnected
11-12 13:46:15.973   976  1196 E LynxModule: unable to find originating command for packetid=0x9007 msg#=176 ref#=171
11-12 13:46:16.334   976  1203 V LynxModule: retransmitting: mod=9 cmd=0x1007 msg#=176 ref#=0 
11-12 13:46:16.436   976  1203 V LynxModule: retransmitting: mod=9 cmd=0x1007 msg#=176 ref#=0 
11-12 13:46:16.484   976  1203 V LynxModule: retransmitting: mod=9 cmd=0x1007 msg#=176 ref#=0 
11-12 13:46:16.486   976  1203 E LynxModule: timeout: abandoning waiting 250ms for response: cmd=LynxGetADCCommand mod=9 msg#=176
11-12 13:46:16.486   976  1203 E LynxModule: Marking module #9 as unresponsive until we receive some data back
11-12 13:46:16.493   976  1203 D RobotCore: system telemetry: key=$System$Warning$ msg="Unable to find webcam "Webcam 1" with serial number FE0F8850.
11-12 13:46:16.493   976  1203 D RobotCore: 
11-12 13:46:16.493   976  1203 D RobotCore: Expansion Hub 9 not currently responding to commands."
11-12 13:46:16.499   976  1196 V LynxModule: REV Hub #9 has reconnected
11-12 13:46:16.500   976  1196 E LynxModule: unable to find originating LynxRespondable for mod=9 msg#=182 ref#=177
11-12 13:46:16.505   976  1203 D RobotCore: system telemetry: key=$System$Warning$ msg="Unable to find webcam "Webcam 1" with serial number FE0F8850."
11-12 13:46:16.506   976  1184 D SoundPlayer: playing volume=0.000000 samp=4|ms=2509
11-12 13:46:16.524   976  1181 V Robocol : sending CMD_PLAY_SOUND(25552), attempt: 0
11-12 13:46:16.579   976  4455 V LynxUsb : discovery waiting complete: #modules=2
11-12 13:46:16.580   976  4455 V LynxModule: close(#0)
11-12 13:46:16.581   976  4455 V LynxUsb : ...lynx discovery completed
11-12 13:46:16.581   976  4455 V FtcEventLoop: assessing LynxModuleMeta(#9,false,ImuType.UNKNOWN)
11-12 13:46:16.582   976  4455 V FtcEventLoop: assessing LynxModuleMeta(#173,true,ImuType.UNKNOWN)
11-12 13:46:16.583   976  4455 V LynxUsb : addConfiguredModule() module#=173
11-12 13:46:16.583   976  4455 V LynxUsb : addConfiguredModule() module#=173: already exists
11-12 13:46:16.587   976  4455 V LynxUsb : 0x0e12ea3e on 0x0f8f9b52: releasing delegate to [(embedded)]
11-12 13:46:16.587   976  4455 V FtcEventLoop: getUSBAccessibleLynxDevices(): 1 modules found
11-12 13:46:16.587   976  4455 V FtcEventLoop: ...getUSBAccessibleLynxDevices()
11-12 13:46:16.588   976  4455 V Robocol : locally injecting CMD_GET_USB_ACCESSIBLE_LYNX_MODULES_RESP
11-12 13:46:16.627   976  1141 V FtcWebSocket: Opening websocket (ip=localhost/127.0.0.1 port=8081)
11-12 13:46:16.630   976  1141 V WebSocketManager: Subscribed websocket (ip=localhost/127.0.0.1 port=8081) to namespace (progress)
11-12 13:46:16.635   976  1141 V WebSocketManager: Subscribed websocket (ip=localhost/127.0.0.1 port=8081) to namespace (ControlHubUpdater)
11-12 13:46:16.651   976  1141 V FtcWebSocket: Opening websocket (ip=localhost/127.0.0.1 port=8081)
11-12 13:46:16.654   976  1141 V WebSocketManager: Subscribed websocket (ip=localhost/127.0.0.1 port=8081) to namespace (progress)
11-12 13:46:16.675   976  1141 V FtcWebSocket: Opening websocket (ip=localhost/127.0.0.1 port=8081)
11-12 13:46:16.678   976  1141 V WebSocketManager: Subscribed websocket (ip=localhost/127.0.0.1 port=8081) to namespace (progress)
11-12 13:46:16.680   976  1141 V WebSocketManager: Subscribed websocket (ip=localhost/127.0.0.1 port=8081) to namespace (ControlHubUpdater)
11-12 13:46:16.699   976  1141 V FtcWebSocket: Opening websocket (ip=localhost/127.0.0.1 port=8081)
11-12 13:46:16.704   976  1141 V WebSocketManager: Subscribed websocket (ip=localhost/127.0.0.1 port=8081) to namespace (progress)
11-12 13:46:19.011   976  1237 D SoundPlayer: playing volume=0.000000 samp=4|ms=2509
11-12 13:46:19.038   976  1181 V Robocol : sending CMD_PLAY_SOUND(25590), attempt: 0

[texasdiaz]

Can you give us more information about the Electronics configuration? Are you using a Control Hub or a phone as your primary control device? How is the expansion hub connected? Are you using a USB hub, and if so what kind?

I'm leaning towards a USB power issue, if you're not using a powered USB hub between a phone and the expansion hub the camera may consume too much power and it causes the USB subsystem to brown out and reset. But, I don't have enough information yet to say that for certain.

[shishghate]

We are using a control hub as the primary to which the camera, drive motors, and three servors are connected. The expansion hub is connected by the RS 485 port and has two motors and three servos attached to it.

Would a USB connection between the Control Hub and Expansion Hub be better than the 485 port?

Thanks

[texasdiaz]

"Better" is up for debate depending upon the context of the question. In this context, I think you're asking if it's "better" in terms of connection integrity. A USB connection may have less mechanical connection strength than the 3-wire RS485 connection you currently have, though the USB cable would have better shielding/protection for the wires. One of the big problematic areas is wire failure; over time constant bending of the wires or having the wires exposed to other mechanical systems can cause the wires to fail, leading to shorts and other issues. On my team we purchase the shortest 3-wire connector possible for the connection we need to make, and we are incredibly careful to secure the wire and prevent it from moving (constant motion like swaying leads to wire fatigue, especially on thin high-AWG wires). Even then, we replace the wire every 2 seasons AND we've now been double-wiring. Fun fact is that the two RS485 ports on the Control/Expansion hubs are bi-directional and completely redundant, which means you can have two RS485 connections between the Control/Expansion hub and the connections are redundant (meaning if one fails, the other will still carry the signal).

[shishghate]

Hmm, maybe we will have to try the double wire trick also. USB is too flaky and I worry it will get disconnected during a match. Thanks for the tips.

[qwertychouskie]

We had a similar issue last season, and the problem was the RS485 wire was running along with a bunch of motor wires, which was causing EMI and therefore connection dropouts. We just ran the wire elsewhere on the robot and things started working properly again.