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