Control Hub Crashing

Hi, We ran into issue with the control hub and driver station crashing. When this happened we noticed that the control hub has blue lights flashing and did not respond for the next 10 minutes.

We have Logitech C920X HD Pro camera attached to control hub and using Tensor Flow Object detection

We reached out to REV Hub and they recommended that we check-in here to find out more. Any insights with the issue is greatly appreciated
Here is the error log snippet from the controller log

11-19 13:16:11.567 7110 7482 D CameraManager: requesting permission for camera: Webcam(53F51E8F)
11-19 13:16:11.574 7110 7482 D WebcamNameImpl: requesting permission for /dev/bus/usb/001/002
11-19 13:16:11.574 7110 7482 V WebcamNameImpl: asyncRequestUsbPermission()…
11-19 13:16:11.576 7110 7482 D WebcamNameImpl: permission already available for /dev/bus/usb/001/002
11-19 13:16:11.577 7110 7482 V WebcamNameImpl: …asyncRequestUsbPermission()
11-19 13:16:11.577 7110 7469 D WebcamNameImpl: permission for /dev/bus/usb/001/002=true
11-19 13:16:11.577 7110 7482 D ContinuationSynchronizer: awaiting(camera open)…
11-19 13:16:11.577 7110 7469 D CameraManager: permission granted for camera: Webcam(53F51E8F)
11-19 13:16:11.577 7110 7469 D CameraManager: asyncOpenCamera(Webcam(53F51E8F))…
11-19 13:16:11.578 7110 7469 D CameraManager: asyncOpenWebcam(Webcam(53F51E8F))…
11-19 13:16:11.578 7110 7469 V UsbResiliantWebcam: construct(0x04ee7a19)
11-19 13:16:11.579 7110 7469 D UsbResiliantWebcam: openAssumingPermission()…
11-19 13:16:11.582 7110 7469 D UvcContext: usb device is not UVC compatible, /dev/bus/usb/003/013
11-19 13:16:11.582 7110 7469 D UvcContext: usb device is not UVC compatible, /dev/bus/usb/003/003
11-19 13:16:11.582 7110 7469 D UvcContext: found webcam: usbPath=/dev/bus/usb/001/002 vid=0x46D pid=0x8E5 serial=53F51E8F product=HD Pro Webcam C920
11-19 13:16:11.582 7110 7469 D Uvc : [jni_context.cpp:120] Java_org_firstinspires_ftc_robotcore_internal_camera_libuvc_nativeobject_UvcContext_nativeCreateUvcDevice()…
11-19 13:16:11.582 7110 7469 V Uvc : API: Java_org_firstinspires_ftc_robotcore_internal_camera_libuvc_nativeobject_UvcContext_nativeCreateUvcDevice: enter…
11-19 13:16:11.583 7110 7469 D libusb : [62.768991] [00001d2d] libusb: debug [op_create] op_create: szUsbPath=/dev/bus/usb/001/002 szSysfsDir=1-1
11-19 13:16:11.583 7110 7469 D Uvc : [device.cpp:613] uvc_create_uvc_device()…

I’m afraid that this snippet isn’t enough. Please email me your entire log to: ftctech@firstinspires.org and I can post the results of my investigation here.

-Danny

Thank You Danny … shared the controller through the emails. Lookingforward to hear from you

Hey there!

Thanks for the Control Hub log file. There are a couple things going on here - I am going to show you as many of these as possible so that you can look for these things in the future.

When looking at the Log File, there’s a LOT in there - most things in the log file aren’t extremely helpful for non-developers of the SDK. Look for the string RobotCore: - this string will precede most “important” elements in the log file that are important for users.

For example, here are some log file lines that are “normal” and okay:

11-19 13:16:45.557  7110  7624 I RobotCore: exiting match logcat for /storage/emulated/0/FIRST/matchlogs/Match-0-Argo_Auto_Drive.txt

and

11-19 13:16:49.128  7110  7650 V RobotCore: thread: 'LinearOpMode main' starting...

Just watching for those messages (with RobotCore: in them) is helpful in understanding how your OpModes are being started, stopped, terminated, etc… You probably won’t find the specific problem you’re looking for by JUST looking at RobotCore: messages, but you might be able to more quickly hone in on issues.


Now let’s look at this snippet. I initially looked for RobotCore: messages, and I found this series of log messages:

11-19 13:16:48.906  7110  7199 I RobotCore: ******************** START - OPMODE Argo Auto Drive Program ********************
11-19 13:16:48.908  7110  7230 I RobotCore: Attempting to switch to op mode Argo Auto Drive Program
11-19 13:16:49.128  7110  7650 V RobotCore: thread: 'LinearOpMode main' starting...
11-19 13:16:49.129  7110  7650 I I2C     : Automatically initializing I2C device LynxEmbeddedIMU USB (embedded); module 173; bus 0; addr7=0x28
11-19 13:16:49.136  7110  7202 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(1746), attempt: 0
11-19 13:16:49.178  7110  7650 V BNO055  : Suppressing I2C warnings while we check for a BNO055 IMU
11-19 13:16:49.182  7110  7650 V BNO055  : Found BNO055 IMU
11-19 13:16:49.659  7110  7650 V IMU     : Now polling until IMU comes out of reset. It is normal to see I2C failures below
11-19 13:16:49.666  7110  7650 V RobotCore: addr=false data=true arb=false clock=false
11-19 13:16:49.666  7110  7650 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
11-19 13:16:49.666  7110  7650 E LynxI2cDeviceSynch: placeholder: readStatusQuery
11-19 13:16:49.731  7110  7650 V RobotCore: addr=false data=true arb=false clock=false
11-19 13:16:49.732  7110  7650 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
11-19 13:16:49.898  7110  7650 V IMU     : IMU has come out of reset. No more I2C failures should occur.
11-19 13:17:05.137  7110  7200 E Robocol : exception SocketTimeoutException(Receive timed out): no packet received [java.net.PlainDatagramSocketImpl.receive0(Native Method)]
11-19 13:17:06.857  7110  7202 V UpdateUI: Network: active, disconnected
11-19 13:17:06.859  7110  7202 I RobotCore: ******************** STOP - OPMODE /storage/emulated/0/FIRST/matchlogs/Match-0-Argo_Auto_Drive_Program.txt ********************
11-19 13:17:06.871  7110  7202 I EventLoopManager: Lost connection while running op mode: Argo Auto Drive Program
11-19 13:17:06.871  7110  7202 V NetworkConnectionHandler: Peer connection lost
11-19 13:17:06.872  7110  7704 I RobotCore: saving match logcat to /storage/emulated/0/FIRST/matchlogs/Match-0-Argo_Auto_Drive_Program.txt
11-19 13:17:06.872  7110  7704 I RobotCore: logging command line: exec logcat -d -T '11-19 13:16:48.000' -f '/storage/emulated/0/FIRST/matchlogs/Match-0-Argo_Auto_Drive_Program.txt' -n4 -v threadtime UsbRequestJNI:S UsbRequest:S art:W ThreadPool:W System:W ExtendedExtractor:W OMXClient:W MediaPlayer:W dalvikvm:W  *:V
11-19 13:17:06.925  7110  7704 I RobotCore: Done running exec logcat -d -T '11-19 13:16:48.000' -f '/storage/emulated/0/FIRST/matchlogs/Match-0-Argo_Auto_Drive_Program.txt' -n4 -v threadtime UsbRequestJNI:S UsbRequest:S art:W ThreadPool:W System:W ExtendedExtractor:W OMXClient:W MediaPlayer:W dalvikvm:W  *:V
11-19 13:17:06.925  7110  7704 I RobotCore: exiting match logcat for /storage/emulated/0/FIRST/matchlogs/Match-0-Argo_Auto_Drive_Program.txt
11-19 13:17:06.962  7110  7205 V SoundInfo: construct(0x0537aa76)
11-19 13:17:06.990  7110  7204 I MediaCodec: callingProcessName:com.qualcomm.ftcrobotcontroller
11-19 13:17:06.993  7110  7711 I ACodec  : onAllocateComponent:6752 mSoftCodecPref:0 componentName:
11-19 13:17:06.994  7110  7711 I ACodec  : onAllocateComponent:6783 mSoftCodecPref:0 componentName:OMX.google.raw.decoder
11-19 13:17:07.023  7110  7133 D SoundPlayer: onLoadComplete(samp=3|ms=901, samp=3)=0
11-19 13:17:07.025  7110  7205 W AudioTrack: AUDIO_OUTPUT_FLAG_FAST denied by client; transfer 4, track 48000 Hz, output 44100 Hz
11-19 13:17:07.032  7110  7205 D SoundPlayer: playing volume=0.000000 samp=3|ms=901
11-19 13:17:08.287  7110  7119 W BaseTaskApi: Closing an already closed native lib
11-19 13:17:08.288  7110  7119 W BaseTaskApi: Closing an already closed native lib
11-19 13:17:08.376  7110  7237 E RobotCore: OpMode 'Argo Auto Drive Program' stuck in stop(). Restarting robot controller app.
11-19 13:17:08.393  7110  7237 E RobotCore: Successfully sent failsafe commands to Lynx modules before app restart
11-19 13:17:08.393  7110  7237 E RobotCore: Begin thread dump

So here you’ve apparently got an OpMode called “Argo Auto Drive Program”. I can see it’s a Linear OpMode. If we walk through the messages, you can see that at 11-19 13:16:48.908 we launch the OpMode. At 11-19 13:16:49.182 we start initializing the IMU, and then very soon after we are waiting for the IMU to complete initialization. We can see that at 11-19 13:16:49.898 we have completed initialization of the IMU. However, nothing then happens for almost 15 seconds - from 11-19 13:16:49.898 to 11-19 13:17:05.137 there’s absolutely no communication from the Control Hub - that’s forever in terms of a program. At this point, your communication socket times out, your network connection is disconnected, and the Control Hub aborts (stops) your OpMode. At 11-19 13:17:08.376 we can see that your OpMode is having a hard time being stopped, there’s some loop in the code preventing the OpMode from being aborted “naturally”, so it has to be forcibly terminated.

So after this is the thread dumps, so you can see what the robot was doing when the OpMode had to be forcibly stopped. This thread looks like user code:

11-19 13:17:08.442  7110  7237 E RobotCore: thread id=473 tid=7650 name="LinearOpMode main"
11-19 13:17:08.442  7110  7237 E RobotCore:     at java.lang.Thread.sleep(Native Method)
11-19 13:17:08.442  7110  7237 E RobotCore:     at java.lang.Thread.sleep(Thread.java:371)
11-19 13:17:08.442  7110  7237 E RobotCore:     at java.lang.Thread.sleep(Thread.java:313)
11-19 13:17:08.443  7110  7237 E RobotCore:     at org.firstinspires.ftc.teamcode.MecanumDrive.sleep(MecanumDrive.java:832)
11-19 13:17:08.443  7110  7237 E RobotCore:     at org.firstinspires.ftc.teamcode.MecanumDrive.init_IMU(MecanumDrive.java:338)
11-19 13:17:08.443  7110  7237 E RobotCore:     at org.firstinspires.ftc.teamcode.MecanumDrive.init(MecanumDrive.java:253)
11-19 13:17:08.443  7110  7237 E RobotCore:     at org.firstinspires.ftc.teamcode.ArgoAutoDriveControls.runOpMode(ArgoAutoDriveControls.java:128)

So this looks like within your init_IMU method it sleeps - you might want to see about how long it sleeps, you might be sleeping forever?

So then your OpMode was forcibly stopped and the message came up on your Driver Station saying your program had to be forcibly stopped.


Okay, so now let’s look at a situation where everything seemed to go just fine:

11-19 13:20:59.321  8619  8709 I RobotCore: ******************** START - OPMODE Argo Auto Drive ********************
11-19 13:20:59.324  8619  8725 I RobotCore: Attempting to switch to op mode Argo Auto Drive
11-19 13:20:59.528  8619  8755 V RobotCore: thread: 'LinearOpMode main' starting...
11-19 13:20:59.529  8619  8755 I I2C     : Automatically initializing I2C device LynxEmbeddedIMU USB (embedded); module 173; bus 0; addr7=0x00
11-19 13:20:59.552  8619  8742 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(283), attempt: 0
11-19 13:20:59.583  8619  8755 V BNO055  : Suppressing I2C warnings while we check for a BNO055 IMU
11-19 13:20:59.586  8619  8755 V BNO055  : Found BNO055 IMU
11-19 13:21:00.064  8619  8755 V IMU     : Now polling until IMU comes out of reset. It is normal to see I2C failures below
11-19 13:21:00.069  8619  8755 V RobotCore: addr=false data=true arb=false clock=false
11-19 13:21:00.069  8619  8755 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
11-19 13:21:00.069  8619  8755 E LynxI2cDeviceSynch: placeholder: readStatusQuery
11-19 13:21:00.134  8619  8755 V RobotCore: addr=false data=true arb=false clock=false
11-19 13:21:00.134  8619  8755 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
11-19 13:21:00.302  8619  8755 V IMU     : IMU has come out of reset. No more I2C failures should occur.
11-19 13:21:01.497  8619  8755 D Vuforia : using camera by name: Webcam(53F51E8F)
11-19 13:21:01.616  8619  8755 D skia    : JPEG Decode 72
11-19 13:21:01.710  8619  8755 I System.out: Native library libVuforia.so loaded
11-19 13:21:01.711  8619  8755 D Uvc     : [NativeVuforiaWebcam.cpp:176] Java_org_firstinspires_ftc_robotcore_internal_vuforia_externalprovider_VuforiaWebcam_nativePreVuforiaInit()...

And then Vuforia opens and everything seems to be running well.

Then a little bit later in the log file you hit a RobotCoreException, which is guaranteed to ruin your day:

11-19 13:21:23.430  8619  8755 E EventLoopManager: com.qualcomm.robotcore.exception.RobotCoreException: Cannot have more than 255 string data points
11-19 13:21:23.433  8619  8755 E EventLoopManager: 	at com.qualcomm.robotcore.robocol.TelemetryMessage.toByteArray(TelemetryMessage.java:211)
11-19 13:21:23.435  8619  8755 E EventLoopManager: 	at com.qualcomm.robotcore.robocol.RobocolParsableBase.toByteArrayForTransmission(RobocolParsableBase.java:101)
11-19 13:21:23.437  8619  8755 E EventLoopManager: 	at com.qualcomm.robotcore.robocol.RobocolDatagram.<init>(RobocolDatagram.java:50)
11-19 13:21:23.439  8619  8755 E EventLoopManager: 	at org.firstinspires.ftc.robotcore.internal.network.NetworkConnectionHandler.sendDataToPeer(NetworkConnectionHandler.java:572)
11-19 13:21:23.442  8619  8755 E EventLoopManager: 	at com.qualcomm.robotcore.eventloop.EventLoopManager.sendTelemetryData(EventLoopManager.java:549)
11-19 13:21:23.444  8619  8755 E EventLoopManager: 	at com.qualcomm.ftccommon.FtcEventLoopHandler.refreshUserTelemetry(FtcEventLoopHandler.java:422)
11-19 13:21:23.446  8619  8755 E EventLoopManager: 	at com.qualcomm.ftccommon.FtcEventLoop.refreshUserTelemetry(FtcEventLoop.java:266)
11-19 13:21:23.449  8619  8755 E EventLoopManager: 	at com.qualcomm.robotcore.eventloop.opmode.OpModeManagerImpl.refreshUserTelemetry(OpModeManagerImpl.java:821)
11-19 13:21:23.450  8619  8755 E EventLoopManager: 	at com.qualcomm.robotcore.eventloop.opmode.OpMode.internalUpdateTelemetryNow(OpMode.java:235)
11-19 13:21:23.451  8619  8755 E EventLoopManager: 	at com.qualcomm.robotcore.eventloop.opmode.OpModeManagerImpl.updateTelemetryNow(OpModeManagerImpl.java:817)
11-19 13:21:23.452  8619  8755 E EventLoopManager: 	at org.firstinspires.ftc.robotcore.internal.opmode.TelemetryImpl.tryUpdate(TelemetryImpl.java:716)
11-19 13:21:23.454  8619  8755 E EventLoopManager: 	at org.firstinspires.ftc.robotcore.internal.opmode.TelemetryImpl.update(TelemetryImpl.java:676)
11-19 13:21:23.455  8619  8755 E EventLoopManager: 	at org.firstinspires.ftc.teamcode.ArgoAutoDrive.runOpMode(ArgoAutoDrive.java:285)

This exception is saying that the telemetry.update() command is processing a telemetry request that is too long. I think it’s saying to keep telemetry updates under 255 messages. This happens a couple times in a row. Then the OpMode is stopped, and RobotCore says your OpMode is stuck again. Looking at the thread stack, find the LinearOpMode main thread and we see:

11-19 13:21:31.497  8619  8736 E RobotCore: thread id=305 tid=8755 name="LinearOpMode main"
11-19 13:21:31.497  8619  8736 E RobotCore:     at java.util.Formatter$Flags.contains(Formatter.java:4261)
11-19 13:21:31.498  8619  8736 E RobotCore:     at java.util.Formatter$FormatSpecifier.print(Formatter.java:2947)
11-19 13:21:31.498  8619  8736 E RobotCore:     at java.util.Formatter$FormatSpecifier.printString(Formatter.java:2922)
11-19 13:21:31.498  8619  8736 E RobotCore:     at java.util.Formatter$FormatSpecifier.print(Formatter.java:2802)
11-19 13:21:31.498  8619  8736 E RobotCore:     at java.util.Formatter.format(Formatter.java:2491)
11-19 13:21:31.498  8619  8736 E RobotCore:     at java.util.Formatter.format(Formatter.java:2426)
11-19 13:21:31.498  8619  8736 E RobotCore:     at java.lang.String.format(String.java:2626)
11-19 13:21:31.498  8619  8736 E RobotCore:     at org.firstinspires.ftc.robotcore.internal.opmode.TelemetryImpl$ItemImpl.getComposed(TelemetryImpl.java:303)
11-19 13:21:31.498  8619  8736 E RobotCore:     at org.firstinspires.ftc.robotcore.internal.opmode.TelemetryImpl.saveToTransmitter(TelemetryImpl.java:760)
11-19 13:21:31.498  8619  8736 E RobotCore:     at org.firstinspires.ftc.robotcore.internal.opmode.TelemetryImpl.tryUpdate(TelemetryImpl.java:711)
11-19 13:21:31.499  8619  8736 E RobotCore:     at org.firstinspires.ftc.robotcore.internal.opmode.TelemetryImpl.update(TelemetryImpl.java:676)
11-19 13:21:31.499  8619  8736 E RobotCore:     at org.firstinspires.ftc.teamcode.ArgoAutoDrive.runOpMode(ArgoAutoDrive.java:285)

So clearly we can see that the program crashed because it was trying to format telemetry that was just too much.

We crash on the exact same problem here:

11-19 13:26:40.071   983  1208 W EventLoopManager: Failed to send telemetry data
11-19 13:26:40.073   983  1208 E EventLoopManager: com.qualcomm.robotcore.exception.RobotCoreException: Cannot have more than 255 string data points

Except the OpMode is able to stop nicely this time:

11-19 13:32:06.012   983  1208 D LinearOpModeHelper: User runOpModeMethod exited

This appears to happen multiple times throughout the log file, and this is indicated as the reason why things keep crashing on you.

How do I fix this?

So what is the issue? At least in your last 5-6 crashes in your robot log, we can see you have a telemetry issue. Well, it looks like you’re building telemetry in a huge loop without calling telemetry.update(). When you exceed 255 messages without them being sent, you can crash your program. Calling Telemetry.Add() only adds the telemetry message to a queue, and that queue gets flushed and sent to the Driver Station when you call Telemetry.Update(). You can only build that queue for so long before the bubble bursts!

SUMMARY

So what did we learn here?
(1) Search log files for RobotCore: to find important messages (like OpMode start, OpMode stop, OpMode Restarting, etc…), and then look around those messages for weirdness.
(2) Search log files for RobotCoreException to find exceptions in the code that point to bad things happening.
(3) In your case, you might as well be trying to send back The Complete Works of Shakespeare via Telemetry, and that’s not allowed. Keep it under 255 telemetry messages without calling telemetry.update().

This isn’t a complete list of things to do, but in your case it covers all the bases.

-Danny

Danny, thank you so much for your time and valuable inputs. I was able to get to Telemetry issues and fixed them. I did not realize that those telemetry is missing telemetry.update()

We were doing IMU Initialization and waiting till the calibration is complete or returned.
They may be the reason, why you were seeing the sleep / infinite loop or Crash.

Did you notice anything specific to UVC Camera compatibility and the crash actually happened around 15:10+ hours. please see the below entry i see it as a concern on the compatibility. We didn’t notice crash around 13:00 Hours … however the big surprise is in the game with the log entries timestamped 15:09 / 15:10+

could you please suggest camera compatibility. We will fix Telemetry

11-19 15:09:46.117   985  1230 D UvcDevice: ...open()
11-19 15:09:46.118   985  1271 D CameraManager: camera reports opened: CameraImpl(UsbResiliantWebcam(Webcam(53F51E8F)))
11-19 15:09:46.118   985  1230 D UsbResiliantWebcam: ...openAssumingPermission()
11-19 15:09:46.118   985  1230 D CameraManager: ...asyncOpenWebcam(Webcam(53F51E8F))
11-19 15:09:46.118   985  1230 D CameraManager: ...asyncOpenCamera(Webcam(53F51E8F))
11-19 15:09:46.119   985  1271 D ContinuationSynchronizer: finish("camera reports opened: Webcam(53F51E8F)": CameraImpl(UsbResiliantWebcam(Webcam(53F51E8F))))...
11-19 15:09:46.119   985  1271 D ContinuationSynchronizer: ...finish("camera reports opened: Webcam(53F51E8F)": CameraImpl(UsbResiliantWebcam(Webcam(53F51E8F))))
11-19 15:09:46.119   985  1229 D ContinuationSynchronizer: ...awaiting(camera open)
11-19 15:09:46.119   985  1229 D CameraManager: ...doOpenCamera()
11-19 15:09:46.123   985  1229 D UvcContext: usb device is *not* UVC compatible, /dev/bus/usb/003/004
11-19 15:09:46.124   985  1229 D UvcContext: usb device is *not* UVC compatible, /dev/bus/usb/003/003
11-19 15:09:46.124   985  1229 D UvcContext: found webcam: usbPath=/dev/bus/usb/001/002 vid=0x46D pid=0x8E5 serial=53F51E8F product=HD Pro Webcam C920
11-19 15:09:46.124   985  1229 D Uvc     : [jni_context.cpp:120] Java_org_firstinspires_ftc_robotcore_internal_camera_libuvc_nativeobject_UvcContext_nativeCreateUvcDevice()...
11-19 15:09:46.124   985  1229 V Uvc     : API: Java_org_firstinspires_ftc_robotcore_internal_camera_libuvc_nativeobject_UvcContext_nativeCreateUvcDevice: enter...
11-19 15:09:46.125   985  1229 D libusb  : [1668888560.133375] [000004cd] libusb: debug [op_create] op_create: szUsbPath=/dev/bus/usb/001/002 szSysfsDir=1-1
11-19 15:09:46.125   985  1229 D Uvc     : [device.cpp:613] uvc_create_uvc_device()...
11-19 15:09:46.125   985  1229 D Uvc     : [libuvc/libuvc_internal.h:346] uvc_device::uvc_device()...
11-19 15:09:46.125   985  1229 D Uvc     : [libuvc/libuvc_internal.h:375] acquired vid=1133 & pid=2277
11-19 15:09:46.125   985  1229 D Uvc     : [libuvc/libuvc_internal.h:346] ...uvc_device::uvc_device()
11-19 15:09:46.125   985  1229 D Uvc     : [device.cpp:613] ...uvc_create_uvc_device() rc=0
11-19 15:09:46.125   985  1229 V Uvc     : API: Java_org_firstinspires_ftc_robotcore_internal_camera_libuvc_nativeobject_UvcContext_nativeCreateUvcDevice: ...exit
11-19 15:09:46.125   985  1229 D Uvc     : [jni_context.cpp:120] ...Java_org_firstinspires_ftc_robotcore_internal_camera_libuvc_nativeobject_UvcContext_nativeCreateUvcDevice()
11-19 15:09:46.126   985  1229 V UvcDevice: construct(pointer=0x7813df8b00|null)
11-19 15:09:46.126   985  1229 D Uvc     : [jni_device.cpp:108] Java_org_firstinspires_ftc_robotcore_internal_camera_libuvc_nativeobject_UvcDevice_nativeGetLibUsbDevice()...
11-19 15:09:46.126   985  1229 D Uvc     : [jni_device.cpp:108] ...Java_org_firstinspires_ftc_robotcore_internal_camera_libuvc_nativeobject_UvcDevice_nativeGetLibUsbDevice()
11-19 15:09:46.126   985  1229 V LibUsbDevice: construct(pointer=0x7814de89c0)
11-19 15:09:46.127   985  1229 V UvcApiCameraCharacteristicsBuilder: construct(0x0e764ae8)

Again, there are a lot of messages that should not concern the average user. One of them is spurious UVC compatibility messages. It’s important to understand that the USB bus is used for a lot of things - many internal devices hang off the internal USB hubs, most notably the Wi-Fi adapter in the Control Hub (it “shares” the USB 2.0 hub with devices plugged into the USB 2.0 USB-A port). The Control Hub doesn’t know or care what devices are “internal” devices and what devices are “external” devices on any of the USB hubs, all the Control Hub software knows is that there are a bunch of devices hanging off each of the USB hubs. So the enumeration driver software for UVC walks the USB tree and queries each one to see if they’re UVC compatible. Let’s take this snippet for example:

11-19 13:16:11.582  7110  7469 D UvcContext: usb device is *not* UVC compatible, /dev/bus/usb/003/013
11-19 13:16:11.582  7110  7469 D UvcContext: usb device is *not* UVC compatible, /dev/bus/usb/003/003
11-19 13:16:11.582  7110  7469 D UvcContext: found webcam: usbPath=/dev/bus/usb/001/002 vid=0x46D pid=0x8E5 serial=53F51E8F product=HD Pro Webcam C920

Notice the “path” of the USB devices that are found that are not UVC compatible - /dev/bus/usb/003/003, /dev/bus/usb/003/013. Then we get to finding your C920 webcam that is UVC compatible, and it’s at path /dev/bus/usb/001/002. Just understand that each device is evaluated independently. I’m not seeing any UVC compatibility problems detected for your camera here at all (unless, of course, you have 2 cameras plugged in, and the C920 isn’t the only camera you think should be UVC compatible).

Aha, I did not immediately notice this problem:

11-19 15:10:35.806   985  1212 E ControlHubApChannelManager: Timeout while getting current channel from AP service
11-19 15:10:45.473   985  1229 D LinearOpModeHelper: User runOpModeMethod exited
11-19 15:10:45.474   985  1229 V RobotCore: thread: ...terminating 'LinearOpMode main'
11-19 15:10:45.475   985  1184 I FtcEventLoop: auto-stopping OpMode 'Argo Auto Drive'

Here (and remember I just searched for RobotCore: and looked several lines before and after the message to find this) we can see that the Control Hub Ap Channel Manager began having problems communicating with the Access Point (AP), and it looks like 10 seconds later the LinearOpModeHelper decided it was time to terminate your OpMode. If the Control Hub cannot communicate with vital components of the Control Hub for long enough time, it will stop your programs as a failsafe. There could be multiple reasons - starving the CPU because you’re executing an operation that is starving the thread scheduler (like infinite loops), you’re executing some operation that is starving the USB channel (like performing 4k camera streaming that is consuming the available bandwidth on the USB bus), the Control Hub is browning out (low voltage) and so the Wi-Fi adapter is not receiving adequate power, or something else, it’s impossible to tell from here.

When you get a fatal error that causes an OpMode to be terminated, information specific to the crash can be found in a “match log” - the Robot Controller log file will tell you what log file to look in for the match-specific information. In this case, it’s here:

11-19 15:10:46.210   985  1184 I RobotCore: ******************** STOP - OPMODE /storage/emulated/0/FIRST/matchlogs/Match-0-Argo_Auto_Drive.txt ********************

This match log may provide you with more user-centric information about what happened. Or maybe it won’t, it’s kind of hit-or-miss sometimes depending on the error - some errors are easier to detect than others for sure!

I hope this helps explain a few things, and gives you ammo to look for other “smoking guns”.

-Danny

Thank you Danny for your help… Appreciate it

A post was split to a new topic: TensorFlow Crash on VuforiaFrameGenerator.run

A post was split to a new topic: Control Hub Crashing and continuing last command

A post was split to a new topic: Autonomous Crash