Teleop Crashes Randomly

[PriyaSoneji]

During our teleop mode, we have noticed that op mode crashes randomly. It was working before and without any code changes we started experiencing intermittent crashing.
Android Version 7.1.1
Driver Station Version 6.0
Robot Controller Version 6.0
Control Hub OS Version 1.1.1
Control Hub Hardware Client Version 1.0.0
Expansion Hub Version 1.8.2

Here is the error we see in the log when this happens:
12-09 18:44:16.547 987 1155 V Robocol : sending CMD_NOTIFY_RUN_OP_MODE(5594), attempt: 0
12-09 18:45:01.410 987 1230 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=110 ref#=0
12-09 18:45:01.511 987 1230 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=110 ref#=0
12-09 18:45:01.559 987 1230 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=110 ref#=0
12-09 18:45:01.560 987 1230 E RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorEncoderPositionCommand mod=3 msg#=110
12-09 18:45:01.561 987 1230 E RobotCore: Marking module #3 as unresponsive until we receive some data back
12-09 18:45:01.561 987 1230 W RobotCore: Expansion Hub Left 3 is currently unresponsive.
12-09 18:45:01.563 987 1150 D RobotCore: system telemetry: key=$System$Warning$ msg="Expansion Hub Left 3 not currently responding to commands"
12-09 18:45:01.567 987 1224 V LynxModule: REV Hub #3 has reconnected
12-09 18:45:01.568 987 1224 E LynxModule: unable to find originating command for packetid=0x9009 msg#=41 ref#=111
12-09 18:45:01.570 987 1228 D RobotCore: system telemetry: key=$System$Warning$ msg="Expansion Hub Left 3 temporarily stopped responding to commands while an Op Mode was running"
12-09 18:45:01.690 987 1158 V SoundInfo: construct(0x04178359)
12-09 18:45:01.733 987 1157 I MediaCodec: callingProcessName:com.qualcomm.ftcrobotcontroller
12-09 18:45:01.737 987 1236 I ACodec : onAllocateComponent:6703 mSoftCodecPref:0 componentName:
12-09 18:45:01.738 987 1236 I ACodec : onAllocateComponent:6734 mSoftCodecPref:0 componentName:OMX.google.raw.decoder
12-09 18:45:01.788 987 1084 D SoundPlayer: onLoadComplete(samp=3|ms=2509, samp=3)=0
12-09 18:45:01.790 987 1158 W AudioTrack: AUDIO_OUTPUT_FLAG_FAST denied by client; transfer 4, track 48000 Hz, output 44100 Hz
12-09 18:45:01.796 987 1158 D SoundPlayer: playing volume=0.000000 samp=3|ms=2509
12-09 18:45:01.826 987 1155 V Robocol : sending CMD_PLAY_SOUND(7222), attempt: 0
12-09 18:45:04.081 987 1150 V Robocol : received command: CMD_INIT_OP_MODE(17154) $Stop$Robot$
12-09 18:45:04.092 987 1149 I RobotCore: ******************** STOP - OPMODE /storage/emulated/0/FIRST/matchlogs/Match-0-Ultimate.txt ********************
12-09 18:45:04.100 987 1240 I RobotCore: saving match logcat to /storage/emulated/0/FIRST/matchlogs/Match-0-Ultimate.txt
12-09 18:45:04.101 987 1240 I RobotCore: logging command line: exec logcat -d -T '12-9 18:44:15.000' -f /storage/emulated/0/FIRST/matchlogs/Match-0-Ultimate.txt -n4 -v threadtime UsbRequestJNI:S UsbRequest:S art:W ThreadPool:W System:W ExtendedExtractor:W OMXClient:W MediaPlayer:W dalvikvm:W *:V
12-09 18:45:04.101 987 1230 E LynxMotor: unexpected exception thrown during lynx communication
12-09 18:45:04.103 987 1230 E LynxMotor: java.lang.InterruptedException
12-09 18:45:04.105 987 1230 E LynxMotor: at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1036)
12-09 18:45:04.106 987 1230 E LynxMotor: at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1327)
12-09 18:45:04.108 987 1230 E LynxMotor: at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:249)
12-09 18:45:04.109 987 1230 E LynxMotor: at com.qualcomm.hardware.lynx.commands.LynxRespondable.awaitAndRetransmit(LynxRespondable.java:385)
12-09 18:45:04.110 987 1230 E LynxMotor: at com.qualcomm.hardware.lynx.commands.LynxRespondable.awaitAckResponseOrNack(LynxRespondable.java:400)
12-09 18:45:04.111 987 1230 E LynxMotor: at com.qualcomm.hardware.lynx.commands.LynxRespondable.sendReceive(LynxRespondable.java:259)
12-09 18:45:04.112 987 1230 E LynxMotor: at com.qualcomm.hardware.lynx.LynxDcMotorController.internalGetPublicMotorMode(LynxDcMotorController.java:427)
12-09 18:45:04.113 987 1230 E LynxMotor: at com.qualcomm.hardware.lynx.LynxDcMotorController.getMotorMode(LynxDcMotorController.java:405)
12-09 18:45:04.114 987 1230 E LynxMotor: at com.qualcomm.robotcore.hardware.DcMotorImpl.getMode(DcMotorImpl.java:331)
12-09 18:45:04.115 987 1230 E LynxMotor: at com.qualcomm.robotcore.hardware.DcMotorImpl.setPower(DcMotorImpl.java:196)
12-09 18:45:04.116 987 1230 E LynxMotor: at org.firstinspires.ftc.teamcode.bots.YellowBot.move(YellowBot.java:189)
12-09 18:45:04.117 987 1230 E LynxMotor: at org.firstinspires.ftc.teamcode.OpModes.UltimateMode.runOpMode(UltimateMode.java:99)
12-09 18:45:04.118 987 1230 E LynxMotor: at com.qualcomm.robotcore.eventloop.opmode.LinearOpMode$LinearOpModeHelper$1.run(LinearOpMode.java:271)
12-09 18:45:04.119 987 1230 E LynxMotor: at com.qualcomm.robotcore.util.ThreadPool.logThreadLifeCycle(ThreadPool.java:737)
12-09 18:45:04.121 987 1230 E LynxMotor: at com.qualcomm.robotcore.eventloop.opmode.LinearOpMode$LinearOpModeHelper.run(LinearOpMode.java:266)
12-09 18:45:04.122 987 1230 E LynxMotor: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
12-09 18:45:04.123 987 1230 E LynxMotor: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
12-09 18:45:04.124 987 1230 E LynxMotor: at com.qualcomm.robotcore.util.ThreadPool$ThreadFactoryImpl$1.run(ThreadPool.java:793)
12-09 18:45:04.124 987 1230 E LynxMotor: at java.lang.Thread.run(Thread.java:761)
12-09 18:45:04.125 987 1230 E LynxMotor: unexpected exception thrown during lynx communication
12-09 18:45:04.127 987 1230 E LynxMotor: java.lang.InterruptedException
12-09 18:45:04.129 987 1230 E LynxMotor: at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1218)
12-09 18:45:04.130 987 1230 E LynxMotor: at java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:312)
12-09 18:45:04.131 987 1230 E LynxMotor: at com.qualcomm.hardware.lynx.MessageKeyedLock.acquire(MessageKeyedLock.java:168)
12-09 18:45:04.133 987 1230 E LynxMotor: at com.qualcomm.hardware.lynx.LynxUsbDeviceImpl.acquireNetworkTransmissionLock(LynxUsbDeviceImpl.java:809)
12-09 18:45:04.133 987 1230 E LynxMotor: at com.qualcomm.hardware.lynx.LynxUsbDeviceDelegate.acquireNetworkTransmissionLock(LynxUsbDeviceDelegate.java:192)
12-09 18:45:04.134 987 1230 E LynxMotor: at com.qualcomm.hardware.lynx.LynxModule.acquireNetworkTransmissionLock(LynxModule.java:1740)
12-09 18:45:04.136 987 1230 E LynxMotor: at com.qualcomm.hardware.lynx.commands.LynxMessage.acquireNetworkLock(LynxMessage.java:130)
12-09 18:45:04.137 987 1230 E LynxMotor: at com.qualcomm.hardware.lynx.commands.LynxRespondable.sendReceive(LynxRespondable.java:255)
12-09 18:45:04.138 987 1230 E LynxMotor: at com.qualcomm.hardware.lynx.LynxDcMotorController.internalGetPublicMotorMode(LynxDcMotorController.java:427)
12-09 18:45:04.139 987 1230 E LynxMotor: at com.qualcomm.hardware.lynx.LynxDcMotorController.getMotorMode(LynxDcMotorController.java:405)
12-09 18:45:04.140 987 1230 E LynxMotor: at com.qualcomm.robotcore.hardware.DcMotorImpl.getMode(DcMotorImpl.java:331)
12-09 18:45:04.141 987 1230 E LynxMotor: at com.qualcomm.robotcore.hardware.DcMotorImpl.setPower(DcMotorImpl.java:196)
12-09 18:45:04.141 987 1230 E LynxMotor: at org.firstinspires.ftc.teamcode.bots.UltimateBot.stopintake(UltimateBot.java:161)
12-09 18:45:04.143 987 1230 E LynxMotor: at org.firstinspires.ftc.teamcode.OpModes.UltimateMode.runOpMode(UltimateMode.java:144)
12-09 18:45:04.144 987 1230 E LynxMotor: at com.qualcomm.robotcore.eventloop.opmode.LinearOpMode$LinearOpModeHelper$1.run(LinearOpMode.java:271)
12-09 18:45:04.145 987 1230 E LynxMotor: at com.qualcomm.robotcore.util.ThreadPool.logThreadLifeCycle(ThreadPool.java:737)
12-09 18:45:04.145 987 1230 E LynxMotor: at com.qualcomm.robotcore.eventloop.opmode.LinearOpMode$LinearOpModeHelper.run(LinearOpMode.java:266)
12-09 18:45:04.146 987 1230 E LynxMotor: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
12-09 18:45:04.148 987 1230 E LynxMotor: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)

[JIceberg]

Can you explain what you mean by "crashing"? Is the app activity ending or is there an error thrown on the Driver Station?

[PriyaSoneji]

The app activity ends in the middle of the run and the the network appears as disconnected on the Driver Station.
In order to restablish the connection, the robot has to be physically restarted.

[Windwoes]

The logs you provided, while they show temporary communication errors with your RS485 slave hub, do not show an activity crash.

Can you please reproduce the activity crash, restart the phone (to ensure the log is synced to disk) and then upload the entire log file as an attachment?

[PriyaSoneji]

Match-0-Ultimate.txt
This is the full match log.

[Windwoes]

Hmm, once again there is no indication of an activity crash in the logs.
These exceptions are perfectly normal to see at the end of an OpMode:

E LynxMotor: unexpected exception thrown during lynx communication
E LynxMotor: java.lang.InterruptedException

[JIceberg]

I cannot recognize what exactly is causing the app activity to crash either. Are you sure that is the full log?

[cmacfarl]

@PriyaSoneji are you using a Motorola E5?

[PriyaSoneji]

We are using a Moto G Play as the driver station and we are using a control hub on the robot. Without changing anything, issue stopped popping up. Couldn't find the cause of the it.

[NoahBres]

@cmacfarl That issue wasn't actually related. My apologies.

[NoahBres]

Regarding this issue, I also get intermittent crashes during teleop with the 6.1 SDK. I am not sure if it's prevalent in auto opmodes because I don't run auto opmodes long enough (I am not really familiar with SDK internals but I'm assuming the opmode annotation shouldn't really affect this anyways? Just stating it for information's sake)
There is nothing in the logs to indicate a crash.

However, the issue does not seem to occur in OpenRC stock?

Is there anything I can do to collect more information? Logcat doesn't show anything of concern.

[Windwoes]

Is there anything I can do to collect more information? Logcat doesn't show anything of concern.

Can you dump the non-filtered logcat after reproducing the issue with adb logcat > log.txt (or similar)?

[NoahBres]

I think I figured out my random intermittent crashing. We have AT&T Prepaid Moto E5's and because we have not activated them, an annoying "Activate SIM etc. etc." activity will appear from time to time. That activity kills the app. There seems to be a delay between when the app is killed and when the activity actually appears so I never noticed the correlation until now.

Once again, my particular issue is unrelated to this one :P

Edit: I'm not 100% convinced that the AT&T prepaid popup was actually the cause of the previous crashing. I don't actually recall it occurring as often before. I will assume that the cause of the issue is said popup until able to reproduce it later.

[AlecHub]

I think I figured out my random intermittent crashing. We have AT&T Prepaid Moto E5's and because we have not activated them, an annoying "Activate SIM etc. etc." activity will appear from time to time. That activity kills the app...

Did you try it without the SIM card installed in the phone?

[JIceberg]

Edit: I'm not 100% convinced that the AT&T prepaid popup was actually the cause of the previous crashing. I don't actually recall it occurring as often before. I will assume that the cause of the issue is said popup until able to reproduce it later.

So this does cause an app kill but might not be the reason for the previous issue?

[NoahBres]

Did you try it without the SIM card installed in the phone?

Windwoes suggested this earlier and it did work great! We normally take out the SIM prior to using it on a bot but apparently this set still had the SIM in and I did not realize :P

So this does cause an app kill but might not be the reason for the previous issue?

I don't think it actually kills the app. It kills Dashboard but the opmode seems to run fine in the background?

[NoahBres]

Anyways, I captured one of the random app "crashes".
(I'm not actually sure if this instance was a crash or just the opmode dying because I didn't have to relaunch the app)

log-d.txt

You can see the LinearOpMode terminating at 17:53:13.158 in the middle of driving. I did not initiate any opmode stop. I am not knowledgeable enough to notice anything wrong prior to that.

Edit:
Actually, the opmode termination seems to start at 17:53:12.595? The Dashboard socket closes before that.
At around 17:53:08.620, it prints "setting display to doze." Does the app kill the opmode because the screen turns off?