Custom OpMode Registration Concurrency Issues

[tom-ricci]

Last spring I built a custom OpMode registrar and it's been working well until recently. Now, the built-in annotated OpMode manager throws a ConcurrencyModificationException every time the app boots, causing the robot to do an emergency restart and essentially bootloop. I can't pinpoint exactly when it stopped working nor the exact reason why, but it seems like it has to do with the SDK update to 8.0.0 because rolling-back code isn't helping and the 8.0.0 changelog contains this (it doesn't seem like it's the direct cause of my issue but given that there has been changes to registration this season it's probably related):

• Moves OpModeManagerImpl to the com.qualcomm.robotcore.eventloop.opmode package.
  • This breaks third party libraries EasyOpenCV (version 1.5.1 and earlier) and FTC Dashboard (version 0.4.4 and earlier).

Does anyone have other guesses as to what the problem is/how these two libs fixed it? (I'm not sure about EasyOpenCV, but FTC Dashboard does have an OpMode so they're probably using a custom registrar too). I can't seem to find any useful info about this on google, the discord, fourms, etc.

Here's the relevant logs (I have about 13k lines of this so if you need more just ask 😅):

09-23 18:57:15.462  7298  7380 W EventLoopManager: Caught exception during looper init: java.util.ConcurrentModificationException
09-23 18:57:15.463  7298  7408 W art     : Long monitor contention with owner RobotSetupRunnable.run() (7380) at java.lang.Object java.util.ArrayList$Itr.next()(ArrayList.java:830) waiters=0 in org.firstinspires.ftc.robotcore.internal.network.CallbackResult com.qualcomm.robotcore.eventloop.EventLoopManager.commandEvent(com.qualcomm.robotcore.robocol.Command) for 10.267s
09-23 18:57:15.464  7298  7380 E EventLoopManager: java.util.ConcurrentModificationException
09-23 18:57:15.465  7298  7380 E EventLoopManager: 	at java.util.HashMap$HashIterator.nextEntry(HashMap.java:851)
09-23 18:57:15.466  7298  7408 V FtcEventLoopHandler: sendTelemetry() with null EventLoopManager; ignored
09-23 18:57:15.466  7298  7380 E EventLoopManager: 	at java.util.HashMap$KeyIterator.next(HashMap.java:885)
09-23 18:57:15.468  7298  7380 E EventLoopManager: 	at org.firstinspires.ftc.robotcore.internal.opmode.AnnotatedOpModeClassFilter.callOpModeRegistrarMethods(AnnotatedOpModeClassFilter.java:507)
09-23 18:57:15.469  7298  7380 E EventLoopManager: 	at org.firstinspires.ftc.robotcore.internal.opmode.AnnotatedOpModeClassFilter.registerAllClasses(AnnotatedOpModeClassFilter.java:120)
09-23 18:57:15.469  7298  7380 E EventLoopManager: 	at org.firstinspires.ftc.robotcore.internal.opmode.RegisteredOpModes$3.run(RegisteredOpModes.java:199)
09-23 18:57:15.471  7298  7408 E Robocol : command processing took 10276 ms: command=CMD_REQUEST_ACTIVE_CONFIG
09-23 18:57:15.471  7298  7380 E EventLoopManager: 	at org.firstinspires.ftc.robotcore.internal.opmode.RegisteredOpModes.lockOpModesWhile(RegisteredOpModes.java:320)
09-23 18:57:15.472  7298  7380 E EventLoopManager: 	at org.firstinspires.ftc.robotcore.internal.opmode.RegisteredOpModes.registerAllOpModes(RegisteredOpModes.java:183)
09-23 18:57:15.473  7298  7380 E EventLoopManager: 	at com.qualcomm.ftccommon.FtcEventLoop.init(FtcEventLoop.java:194)
09-23 18:57:15.473  7298  7408 V FtcEventLoopHandler: sendTelemetry() with null EventLoopManager; ignored
09-23 18:57:15.474  7298  7380 E EventLoopManager: 	at com.qualcomm.robotcore.eventloop.EventLoopManager.startEventLoop(EventLoopManager.java:563)
09-23 18:57:15.474  7298  7380 E EventLoopManager: 	at com.qualcomm.robotcore.eventloop.EventLoopManager.setEventLoop(EventLoopManager.java:537)
09-23 18:57:15.475  7298  7380 E EventLoopManager: 	at com.qualcomm.robotcore.eventloop.EventLoopManager.start(EventLoopManager.java:479)
09-23 18:57:15.476  7298  7380 E EventLoopManager: 	at com.qualcomm.robotcore.robot.Robot.start(Robot.java:59)
09-23 18:57:15.478  7298  7380 E EventLoopManager: 	at com.qualcomm.ftccommon.FtcRobotControllerService$RobotSetupRunnable.startRobot(FtcRobotControllerService.java:281)
09-23 18:57:15.478  7298  7380 E EventLoopManager: 	at com.qualcomm.ftccommon.FtcRobotControllerService$RobotSetupRunnable$1.run(FtcRobotControllerService.java:300)
09-23 18:57:15.479  7298  7380 E EventLoopManager: 	at com.qualcomm.robotcore.util.ThreadPool.logThreadLifeCycle(ThreadPool.java:737)
09-23 18:57:15.480  7298  7380 E EventLoopManager: 	at com.qualcomm.ftccommon.FtcRobotControllerService$RobotSetupRunnable.run(FtcRobotControllerService.java:291)
09-23 18:57:15.481  7298  7380 E EventLoopManager: 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:428)
09-23 18:57:15.482  7298  7380 E EventLoopManager: 	at java.util.concurrent.FutureTask.run(FutureTask.java:237)
09-23 18:57:15.483  7298  7380 E EventLoopManager: 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
09-23 18:57:15.484  7298  7380 E EventLoopManager: 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
09-23 18:57:15.485  7298  7380 E EventLoopManager: 	at com.qualcomm.robotcore.util.ThreadPool$ThreadFactoryImpl$1.run(ThreadPool.java:793)
09-23 18:57:15.486  7298  7380 E EventLoopManager: 	at java.lang.Thread.run(Thread.java:761)
09-23 18:57:15.486  7298  7380 V RobotCore: EventLoopManager state is EMERGENCY_STOP
09-23 18:57:15.487  7298  7380 V RobotCore: Robot Status: EMERGENCY STOP, starting robot
09-23 18:57:15.491  7298  7380 V RobotCore: Robot Status: EMERGENCY STOP, unable to start robot
09-23 18:57:15.494  7298  7380 D FTCService: Detecting Wi-Fi reset
09-23 18:57:15.495  7298  7380 D RobotControllerAccessPointAssistant: detectWifiReset button=false
09-23 18:57:15.497  7298  7380 V RobotCore: thread: ...terminating 'RobotSetupRunnable.run()'
09-23 18:57:15.510  7298  7410 V Robocol : sending CMD_NOTIFY_ACTIVE_CONFIGURATION(144), attempt: 0
09-23 18:57:15.512  7298  7410 V Robocol : sending CMD_NOTIFY_ROBOT_STATE(146), attempt: 0
09-23 18:57:15.513  7298  7410 V Robocol : sending CMD_SHOW_TOAST(147), attempt: 0
09-23 18:57:15.526  7298  7408 V FtcEventLoopHandler: sendTelemetry() with null EventLoopManager; ignored
09-23 18:57:15.550  7298  7410 V Robocol : sending CMD_NOTIFY_USER_DEVICE_LIST(148), attempt: 0
09-23 18:57:15.552  7298  7407 D RobotCore: system telemetry: key=$System$Error$ msg="unable to create robot: Robot failed to start: null"

The registrar itself: https://github.com/XaverianTeamRobotics/FtcRobotController/blob/dev/thomas/TeamCode/src/main/java/org/firstinspires/ftc/teamcode/utils/registration/OperationModeRegistrar.java

Sorry if this is a problem with my code that I missed and not the SDK! I figured it would be worth asking here just in case.

[lizlooney]

Thanks for the issue report.

The problem occurs because some code in SDK iterates through a set of methods that have the OpModeRegistrar annotation, calling each one. When it calls your method, your method calls ClassManagerFactory.processAllClasses(), which causes the SDK code to re-populate the set of OpModeRegistrar methods. I will try to fix this in the SDK by iterating on a copy of the set.

In the meantime, you should remove the call to ClassManagerFactory.processAllClasses() from your registerOperationModes method.

[tom-ricci]

Ah, thanks!

[NoahAndrews]

Instead of calling processAllClasses(), you need to move your registerFilter() call to right above the processAllClasses() call in the main activity:

FtcRobotController/FtcRobotController/src/main/java/org/firstinspires/ftc/robotcontroller/internal/FtcRobotControllerActivity.java

Line 356 in 2390680

ClassManagerFactory.processAllClasses();

[tom-ricci]

Alr, we'll try that out for now--if it's possible to get an SDK update to support this before the end of this season (this is my last year and I don't want to leave the rest of my team with this issue lol) that would still be great though since we wouldn't have to worry about keeping our changes in /internal/ every time we pull from upstream. Thanks again!

Actually maybe we won't have to modify any internal stuff. Not really sure, I'm thinking this through as I'm typing this reply out.

[tom-ricci]

Got it working with Noah's suggestion XaverianTeamRobotics@7719bde. Thanks again!

[NoahAndrews]

That's good to hear. Just so you know, further analysis revealed that the problem was that processAllClasses() should not be called multiple times. Version 8.1 will make it so that calling processAllClasses() a second time does nothing but print a warning.

I'd also discourage you from documenting that the FtcRobotControllerActivity file shouldn't be updated from upstream. Keeping that file updated and in sync with the rest of the app is very important. Instead, perhaps you could document that something like the following steps should be performed when updating the SDK:

1. When merging in the new SDK commits, accept the upstream version of the FtcRobotControllerActivity if there are any conflicts.
2. Copy the code snippet you wrote immediately above the call to ClassManagerFactory.processAllClasses().

We did file an internal issue for allowing class filters to be registered without modifying the Activity, but it's a low priority.