FIRST-Tech-Challenge / FIRST-Tech-Challenge/FtcRobotController

Expansion Hub Disconnecting/Becoming Unresponsive

Open
#473 5 comments 0 reactions 0 assignees View on GitHub
Dominant language
Java
Stars
1.3k
Forks
9.9k
Avg merge
18m
Merged PRs (30d)
1

Description

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

```

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.