Losing connection to camera leads to restart

[shishghate]

Hello,

Lately we have been having an issue where we seem to be losing connection to the camera/second hub. We reached out to Rev and they pointed us to FTC. Logs are below and we are looking for suggestions on what we can try different.

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

[crabigator]

Hello @shishghate,

Did you try the suggestions that texasdiaz suggested in the GitHub issue that was opened on this topic?

Expansion Hub Disconnecting/Becoming Unresponsive

Not mentioned in the GitHub issue was possible power failure on the XT30 pins as described here in relation to Control Hubs.

Control Hub Troubleshooting

If you can reproduce the problem, please monitor and report what the LED on the Expansion Hub is doing before, during, and after the disconnect.

And after all that, relating your experiences here might help others. This forum has more visibility than GitHub issues, which when closed, tend to disappear unless one goes and explicitly searches through closed issues.