Announcement

Collapse
No announcement yet.

In a WSR semi match, robot went nuts in auto, couldn't recover

Collapse
X
  • Filter
  • Time
  • Show
Clear All
new posts

  • In a WSR semi match, robot went nuts in auto, couldn't recover

    In the last match of WSR semi, our robot apparently lost control in autonomous, and couldn't re-initialize. This happened right after the robot went off the balancing stone at 3-11 10:20:10.027. The weird thing was that the software seemed trying to recover and some sensors and motors were working, at least it was reading values and logged, 4 seconds after the initial disconnect detected. However, servos and IMU were not working anymore, and software couldn't initialize TeleOp program. After the game, we power cycled and everything was running fine.

    My thought was that this could be caused by a flaky USB connection or ESD when the robot came off the balancing stone. Another fact was that our robot was on the balancing stone waiting for the game to get started for about 9 minutes because FTA was helping our opposing alliance partner's robot to get connected.Could be completely unrelated to this incident, but just something we noticed.

    We also found the following in driverControl log once, but nothing else seemed wrong.

    "03-11 10:20:25.673 6843 6878 E DriverStation: {-14359 11.313} System telemetry warning: REV Robotics USB Expansion Hub Portal [DQ16V4CE] detached"

    Does anyone have some insights on this?

    Code:
    03-11 10:11:37.029  6731  6781 I FtcEventLoop: ======= INIT FINISH =======
    03-11 10:11:37.029  6731  6781 V RobotCore: EventLoopManager state is RUNNING
    03-11 10:11:37.029  6731  6781 V RobotCore: Robot Status: running, starting robot
    03-11 10:11:37.029  6731  6781 V RobotCore: Robot Status: running
    03-11 10:11:37.030  6731  6781 V ThreadPool: container(0x0579bad0: executorEventLoop) added id=539 TID=0 count=1
    03-11 10:11:37.031  6731  6781 V RobotCore: thread: ...terminating 'RobotSetupRunnable.run()'
    03-11 10:11:37.033  6731  6810 V RobotCore: thread: 'opmode loop()' starting...
    03-11 10:11:37.049  6731  6789 E Robocol : command processing took 0.902 s: command=CMD_INIT_OP_MODE
    03-11 10:11:37.056  6731  6799 D MediaPlayer: setSubtitleAnchor in MediaPlayer
    03-11 10:11:37.056  6731  6731 D MediaPlayer: setSubtitleAnchor in MediaPlayer
    03-11 10:11:37.063  6731  6795 V Robocol : sending CMD_NOTIFY_ROBOT_STATE(39), attempt: 0
    03-11 10:11:37.063  6731  6795 V Robocol : sending CMD_NOTIFY_ACTIVE_CONFIGURATION(44), attempt: 0
    03-11 10:11:37.072  6731  6797 D ExtendedUtils: extended extractor not needed, return default
    03-11 10:11:37.075  6731  6814 I OMXClient: Using client-side OMX mux.
    03-11 10:11:37.079  6731  6814 E OMXMaster: A component of name 'OMX.qcom.audio.decoder.aac' already exists, ignoring this one.
    03-11 10:11:37.093  6731  6799 W AudioTrack: AUDIO_OUTPUT_FLAG_FAST denied by client; transfer 4, track 8000 Hz, output 48000 Hz
    03-11 10:11:37.103  6731  6795 V Robocol : sending CMD_NOTIFY_USER_DEVICE_LIST(48), attempt: 0
    03-11 10:11:37.104  6731  6795 V Robocol : sending CMD_NOTIFY_OP_MODE_LIST(49), attempt: 0
    03-11 10:11:37.541  6731  6810 V ThreadPool: container(0x0443e26d: OpModeStuckCodeMonitor) added id=543 TID=0 count=1
    03-11 10:11:37.542  6731  6810 I RobotCore: Attempting to switch to op mode $Stop$Robot$
    03-11 10:11:37.623  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(59), attempt: 0
    03-11 10:11:37.803  6731  6810 I RobotCore: robot battery read duration: n=6, mean=3.935ms sd=1.244ms
    03-11 10:11:44.869  6731  6790 V Robocol : received command: CMD_INIT_OP_MODE(10124) $Stop$Robot$
    03-11 10:11:44.880  6731  6810 I RobotCore: Attempting to switch to op mode $Stop$Robot$
    03-11 10:11:44.943  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(164), attempt: 0
    03-11 10:11:48.071  6731  6790 V Robocol : received command: CMD_INIT_OP_MODE(10168) Auto RED #2
    03-11 10:11:48.081  6731  6810 I RobotCore: Attempting to switch to op mode Auto RED #2
    03-11 10:11:48.707  6731  6810 V ThreadPool: container(0x0807b3fc: LinearOpMode) added id=544 TID=0 count=1
    03-11 10:11:48.713  6731  6823 V RobotCore: thread: 'LinearOpMode main' starting...
    03-11 10:11:48.743  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(220), attempt: 0
    03-11 10:11:48.805  6731  6823 I TechNova: TileRunnerRobot: Init Drive Motors |  Drive Motors are initialized ...
    03-11 10:11:48.805  6731  6823 I TileRunnerRobot: 0 | init ...
    03-11 10:11:48.909  6731  6823 V RobotCore: addr=false data=true arb=false clock=false
    03-11 10:11:49.875  6731  6823 W AdaFruitIMU: re-issuing IMU mode: system status=IDLE expected=RUNNING_FUSION
    03-11 10:11:50.047  6731  6823 I TechNova: TileRunnerRobot: Init Imu | 1242 | imu initialized ...
    03-11 10:11:50.048  6731  6823 I TechNova: TileRunnerRobot: Init Range Sesnor |  Range Sensor x1 and x2 are initialized ...
    03-11 10:11:50.176  6731  6823 I TechNova: TileRunnerRobot: Init Servos |  Servos are initialized ...
    03-11 10:11:50.592  6731  6823 I System.out: Native library libVuforia.so loaded
    03-11 10:11:50.606  6731  6823 I AR      : Vuforia SDK version 6.0.117
    03-11 10:11:50.647  6731  6823 I CameraManagerGlobal: Connecting to camera service
    03-11 10:11:51.592  6731  6823 I AR      : ObjectTracker: Successfully created dataset
    03-11 10:11:51.592  6731  6823 V Vuforia : loading data set 'RelicVuMark'...
    03-11 10:11:52.032  6731  6823 V Vuforia : ... done loading data set 'RelicVuMark'
    03-11 10:11:52.113  6731  6823 I JewelPusher: Color in Init (R,G, B):33, 22, 20
    03-11 10:11:52.136  6731  6823 I TechNova: TileRunnerRobot: IMU Heading: | -0.0
    03-11 10:11:52.136  6731  6823 I VuMarkVision: VuMark | UNKNOWN visible
    03-11 10:11:56.831  6731  6790 E Robocol : exception SocketTimeoutException(null): no packet received [libcore.io.IoBridge.maybeThrowAfterRecvfrom(IoBridge.java:594)]
    03-11 10:12:03.294  6731  6790 V Robocol : received command: CMD_INIT_OP_MODE(10348) $Stop$Robot$
    03-11 10:12:03.304  6731  6810 V ThreadPool: waiting for service user linear op mode
    03-11 10:12:03.305  6731  6823 I TechNova: TileRunnerRobot: Robot: | Robot starting 15216.5
    03-11 10:12:03.306  6731  6823 V RobotCore: thread: ...terminating 'LinearOpMode main'
    03-11 10:12:03.306  6731  6810 V ThreadPool: awaitTermination returned, isTerminated=true
    03-11 10:12:03.306  6731  6823 V ThreadPool: container(0x0807b3fc: LinearOpMode) removed id=544 TID=6823 count=1
    03-11 10:12:03.306  6731  6810 V ThreadPool: executive service user linear op mode(0x0807b3fc) is terminated
    03-11 10:12:03.722  6731  6810 I RobotCore: Attempting to switch to op mode $Stop$Robot$
    03-11 10:12:03.783  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(414), attempt: 0
    03-11 10:12:04.023  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(414), attempt: 1
    03-11 10:12:04.263  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(414), attempt: 2
    03-11 10:12:04.503  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(414), attempt: 3
    03-11 10:12:04.743  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(414), attempt: 4
    03-11 10:12:04.767  6731  6810 I RobotCore: Attempting to switch to op mode Tile Runner (New) TeleOps
    03-11 10:12:04.983  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(414), attempt: 5
    03-11 10:12:05.223  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(414), attempt: 6
    03-11 10:12:05.386  6731  6810 V ThreadPool: container(0x0a7ae130: LinearOpMode) added id=558 TID=0 count=1
    03-11 10:12:05.388  6731  6937 V RobotCore: thread: 'LinearOpMode main' starting...
    03-11 10:12:05.423  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(422), attempt: 0
    03-11 10:12:05.463  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(414), attempt: 7
    03-11 10:12:05.466  6731  6937 I TechNova: TileRunnerRobot: Init Drive Motors |  Drive Motors are initialized ...
    03-11 10:12:05.597  6731  6937 I TechNova: TileRunnerRobot: Init Servos |  Servos are initialized ...
    03-11 10:12:05.624  6731  6795 V Robocol : issuing peerDisconnected(): lastRecvPacket=2.011 s
    03-11 10:12:05.624  6731  6795 V RobotCore: Network: active, disconnected
    03-11 10:12:05.625  6731  6795 I RobotCore: Lost connection while running op mode: Tile Runner (New) TeleOps
    03-11 10:12:05.670  6731  6797 D ExtendedUtils: extended extractor not needed, return default
    03-11 10:12:05.672  6731  6941 I OMXClient: Using client-side OMX mux.
    03-11 10:12:05.686  6731  6941 E OMXMaster: A component of name 'OMX.qcom.audio.decoder.aac' already exists, ignoring this one.
    03-11 10:12:05.710  6731  6799 W AudioTrack: AUDIO_OUTPUT_FLAG_FAST denied by client; transfer 4, track 44100 Hz, output 48000 Hz
    03-11 10:12:05.798  6731  6788 V ThreadPool: container(0x0f30b951: default threadpool) removed id=521 TID=6788 count=2
    03-11 10:12:06.128  6731  6810 V ThreadPool: waiting for service user linear op mode
    03-11 10:12:06.131  6731  6937 V RobotCore: thread: ...terminating 'LinearOpMode main'
    03-11 10:12:06.131  6731  6810 V ThreadPool: awaitTermination returned, isTerminated=true
    03-11 10:12:06.131  6731  6937 V ThreadPool: container(0x0a7ae130: LinearOpMode) removed id=558 TID=6937 count=1
    03-11 10:12:06.131  6731  6810 V ThreadPool: executive service user linear op mode(0x0a7ae130) is terminated
    03-11 10:12:06.132  6731  6810 I RobotCore: Attempting to switch to op mode $Stop$Robot$
    03-11 10:12:06.932  6731  6790 V Robocol : resetting peerDisconnected()
    03-11 10:12:06.943  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(414), attempt: 8
    03-11 10:12:06.944  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(422), attempt: 1
    03-11 10:12:06.945  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(426), attempt: 0
    03-11 10:12:06.976  6731  6790 V NetDiscover_prefremrc: sendAllPreferences()
    03-11 10:12:06.976  6731  6790 V NetDiscover_prefremrc: sending RC pref name=pref_wifip2p_remote_channel_change_works value=true
    03-11 10:12:06.977  6731  6790 V NetDiscover_prefremrc: sending RC pref name=pref_device_name value=12611-RC
    03-11 10:12:06.977  6731  6790 V NetDiscover_prefremrc: sending RC pref name=pref_has_independent_phone_battery value=true
    03-11 10:12:06.977  6731  6790 V NetDiscover_prefremrc: sending RC pref name=pref_app_theme value=teal
    03-11 10:12:06.977  6731  6790 V NetDiscover_prefremrc: sending RC pref name=pref_sound_on_off value=false
    03-11 10:12:06.978  6731  6790 V RobotCore: Network: active, connected
    03-11 10:12:06.979  6731  6799 W AudioTrack: AUDIO_OUTPUT_FLAG_FAST denied by client; transfer 4, track 44100 Hz, output 48000 Hz
    03-11 10:12:06.983  6731  6795 V Robocol : sending CMD_NOTIFY_USER_DEVICE_LIST(428), attempt: 0
    03-11 10:12:06.985  6731  6795 V Robocol : sending CMD_ROBOT_CONTROLLER_PREFERENCE(429), attempt: 0
    03-11 10:12:06.985  6731  6795 V Robocol : sending CMD_ROBOT_CONTROLLER_PREFERENCE(430), attempt: 0
    03-11 10:12:06.985  6731  6795 V Robocol : sending CMD_ROBOT_CONTROLLER_PREFERENCE(431), attempt: 0
    03-11 10:12:06.986  6731  6795 V Robocol : sending CMD_ROBOT_CONTROLLER_PREFERENCE(432), attempt: 0
    03-11 10:12:06.986  6731  6795 V Robocol : sending CMD_ROBOT_CONTROLLER_PREFERENCE(433), attempt: 0
    03-11 10:12:06.988  6731  6790 V Robocol : received command: CMD_REQUEST_UI_STATE(10010)
    03-11 10:12:07.023  6731  6795 V Robocol : sending CMD_NOTIFY_ACTIVE_CONFIGURATION(439), attempt: 0
    03-11 10:12:07.032  6731  6781 V ThreadPool: container(0x0f30b951: default threadpool) removed id=516 TID=6781 count=1
    03-11 10:12:07.063  6731  6795 V Robocol : sending CMD_NOTIFY_USER_DEVICE_LIST(441), attempt: 0
    03-11 10:12:07.065  6731  6795 V Robocol : sending CMD_NOTIFY_OP_MODE_LIST(442), attempt: 0
    03-11 10:12:07.183  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(414), attempt: 9
    03-11 10:12:07.184  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(422), attempt: 2
    03-11 10:12:07.185  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(426), attempt: 1
    03-11 10:12:07.265  6731  6790 V Robocol : received command: CMD_RUN_OP_MODE(10031) $Stop$Robot$
    03-11 10:12:07.305  6731  6795 V Robocol : sending CMD_NOTIFY_RUN_OP_MODE(461), attempt: 0
    03-11 10:12:07.310  6731  6790 V Robocol : received command: CMD_RUN_OP_MODE(10034) $Stop$Robot$
    03-11 10:12:07.344  6731  6795 V Robocol : sending CMD_NOTIFY_RUN_OP_MODE(465), attempt: 0
    03-11 10:12:08.823  6731  6790 V Robocol : received command: CMD_INIT_OP_MODE(10060) $Stop$Robot$
    03-11 10:12:08.836  6731  6810 I RobotCore: Attempting to switch to op mode $Stop$Robot$
    03-11 10:12:08.903  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(493), attempt: 0
    03-11 10:12:08.945  6731  6790 V Robocol : received command: CMD_RUN_OP_MODE(10066) $Stop$Robot$
    03-11 10:12:08.984  6731  6795 V Robocol : sending CMD_NOTIFY_RUN_OP_MODE(500), attempt: 0
    03-11 10:12:23.503  6731  6790 V Robocol : received command: CMD_INIT_OP_MODE(10251) Auto RED #2
    03-11 10:12:23.521  6731  6810 I RobotCore: Attempting to switch to op mode Auto RED #2
    03-11 10:12:24.159  6731  6810 V ThreadPool: container(0x0c19532e: LinearOpMode) added id=562 TID=0 count=1
    03-11 10:12:24.164  6731  6946 V RobotCore: thread: 'LinearOpMode main' starting...
    03-11 10:12:24.183  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(706), attempt: 0
    03-11 10:12:24.247  6731  6946 I TechNova: TileRunnerRobot: Init Drive Motors |  Drive Motors are initialized ...
    03-11 10:12:24.247  6731  6946 I TileRunnerRobot: 0 | init ...
    03-11 10:12:24.349  6731  6946 V RobotCore: addr=false data=true arb=false clock=false
    03-11 10:12:24.349  6731  6946 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
    03-11 10:12:24.349  6731  6946 E LynxI2cDeviceSynch: placeholder: readStatusQuery
    03-11 10:12:24.423  6731  6946 V RobotCore: addr=false data=true arb=false clock=false
    03-11 10:12:24.423  6731  6946 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
    03-11 10:12:24.493  6731  6946 V RobotCore: addr=false data=true arb=false clock=false
    03-11 10:12:24.494  6731  6946 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
    03-11 10:12:24.566  6731  6946 V RobotCore: addr=false data=true arb=false clock=false
    03-11 10:12:24.566  6731  6946 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
    03-11 10:12:24.637  6731  6946 V RobotCore: addr=false data=true arb=false clock=false
    03-11 10:12:24.637  6731  6946 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
    03-11 10:12:25.097  6731  6946 W AdaFruitIMU: re-issuing IMU mode: system status=IDLE expected=RUNNING_FUSION
    03-11 10:12:25.268  6731  6946 I TechNova: TileRunnerRobot: Init Imu | 1021 | imu initialized ...
    03-11 10:12:25.269  6731  6946 I TechNova: TileRunnerRobot: Init Range Sesnor |  Range Sensor x1 and x2 are initialized ...
    03-11 10:12:25.401  6731  6946 I TechNova: TileRunnerRobot: Init Servos |  Servos are initialized ...
    03-11 10:12:25.741  6731  6946 I AR      : Vuforia SDK version 6.0.117
    03-11 10:12:26.508  6731  6946 I AR      : ObjectTracker: Successfully created dataset
    03-11 10:12:26.508  6731  6946 V Vuforia : loading data set 'RelicVuMark'...
    03-11 10:12:26.790  6731  6946 V Vuforia : ... done loading data set 'RelicVuMark'
    03-11 10:12:26.860  6731  6946 I JewelPusher: Color in Init (R,G, B):39, 24, 23
    03-11 10:12:26.881  6731  6946 I TechNova: TileRunnerRobot: IMU Heading: | -0.2
    03-11 10:12:26.881  6731  6946 I VuMarkVision: VuMark | UNKNOWN visible
    03-11 10:13:31.161  6731  6946 V RobotCore: addr=false data=true arb=false clock=false
    03-11 10:13:31.161  6731  6946 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
    03-11 10:13:31.161  6731  6946 E LynxI2cDeviceSynch: placeholder: readStatusQuery
    03-11 10:13:31.162  6731  6810 D RobotCore: system telemetry: key=$System$Warning$ msg="problem with "x1Range""
    03-11 10:13:31.193  6731  6799 D MediaPlayer: setSubtitleAnchor in MediaPlayer
    03-11 10:13:31.219  6731  6731 E MediaPlayer: invoke failed: wrong state 8
    03-11 10:13:31.219  6731  6731 W MediaPlayer: mediaplayer went away with unhandled events
    03-11 10:13:31.252  6731  6797 D ExtendedUtils: extended extractor not needed, return default
    03-11 10:13:31.258  6731  7051 I OMXClient: Using client-side OMX mux.
    03-11 10:13:31.299  6731  7051 E OMXMaster: A component of name 'OMX.qcom.audio.decoder.aac' already exists, ignoring this one.
    03-11 10:13:31.343  6731  6810 D RobotCore: system telemetry: key=$System$None$ msg=""
    03-11 10:13:31.392  6731  6799 W AudioTrack: AUDIO_OUTPUT_FLAG_FAST denied by client; transfer 4, track 44100 Hz, output 48000 Hz
    03-11 10:14:39.006  6731  6810 I RobotCore: robot battery read duration: n=10, mean=7.293ms sd=6.407ms
    03-11 10:16:35.821  6731  6946 E LynxI2cDeviceSynch: exception thrown during lynx communication
    03-11 10:16:35.824  6731  6946 E LynxI2cDeviceSynch: com.qualcomm.hardware.lynx.LynxNackException: (DQ16V4CE #2) LynxI2cReadSingleByteCommand: nack received: I2C_OPERATION_IN_PROGRESS:41
    03-11 10:16:35.826  6731  6946 E LynxI2cDeviceSynch:     at com.qualcomm.hardware.lynx.commands.LynxRespondable.throwIfNack(LynxRespondable.java:324)
    03-11 10:16:35.827  6731  6946 E LynxI2cDeviceSynch:     at com.qualcomm.hardware.lynx.commands.LynxRespondable.send(LynxRespondable.java:239)
    03-11 10:16:35.827  6731  6946 E LynxI2cDeviceSynch:     at com.qualcomm.hardware.lynx.LynxI2cDeviceSynchV1$1.get(LynxI2cDeviceSynchV1.java:76)
    03-11 10:16:35.828  6731  6946 E LynxI2cDeviceSynch:     at com.qualcomm.hardware.lynx.LynxI2cDeviceSynchV1$1.get(LynxI2cDeviceSynchV1.java:64)
    03-11 10:16:35.839  6731  6946 E LynxI2cDeviceSynch:     at java.lang.Thread.run(Thread.java:818)
    03-11 10:16:35.839  6731  6946 E LynxI2cDeviceSynch: placeholder: readTimestamped
    03-11 10:16:35.842  6731  6810 D RobotCore: system telemetry: key=$System$Warning$ msg="problem with "x1Range""
    03-11 10:16:36.002  6731  6807 V RobotCore: nack rec'd mod=2 msg#=221 ref#=0 reason=PACKET_TYPE_ID_UNKNOWN:255
    03-11 10:16:36.003  6731  6946 E LynxI2cDeviceSynch: exception thrown during lynx communication
    03-11 10:16:36.004  6731  6946 E LynxI2cDeviceSynch: com.qualcomm.hardware.lynx.LynxNackException: (DQ16V4CE #2) LynxI2cWriteSingleByteCommand: nack received: PACKET_TYPE_ID_UNKNOWN:255
    03-11 10:16:36.007  6731  6946 E LynxI2cDeviceSynch:     at com.qualcomm.hardware.lynx.commands.LynxRespondable.throwIfNack(LynxRespondable.java:324)
    03-11 10:16:36.007  6731  6946 E LynxI2cDeviceSynch:     at com.qualcomm.hardware.lynx.commands.LynxRespondable.send(LynxRespondable.java:239)
    03-11 10:16:36.008  6731  6946 E LynxI2cDeviceSynch:     at com.qualcomm.hardware.lynx.LynxI2cDeviceSynch.sendI2cWriteTx(LynxI2cDeviceSynch.java:371)
    03-11 10:16:36.041  6731  6810 D RobotCore: system telemetry: key=$System$None$ msg=""
    03-11 10:17:40.375  6731  6810 I RobotCore: robot battery read duration: n=10, mean=4.471ms sd=1.498ms
    03-11 10:20:06.265  6731  6790 V Robocol : received command: CMD_RUN_OP_MODE(16074) Auto RED #2
    03-11 10:20:06.303  6731  6795 V Robocol : sending CMD_NOTIFY_RUN_OP_MODE(6927), attempt: 0
    03-11 10:20:06.470  6731  6946 I TechNova: TileRunnerRobot: Robot: | Robot starting 462948.1
    03-11 10:20:06.572  6731  6946 I RelicRecoveryAutoTileRunnerRed2: RED | State:                    0 [START] |  Start |  105.9 | 462950 | IMU: -0.2 | (x1,x2): 256.0, 2.8 | Glyph count:    0 | UNKNOWN | Battery: 12.96
    03-11 10:20:06.678  6731  6946 I RelicRecoveryAutoTileRunnerRed2: RED | State:                    0 [START] |    End |  206.9 | 463051 | IMU: -0.2 | (x1,x2): 256.0, 2.8 | Glyph count:    0 | UNKNOWN | Battery: 12.96
    03-11 10:20:06.690  6731  6946 I VuMarkVision: VuMark | RIGHT visible
    03-11 10:20:06.804  6731  6946 I RelicRecoveryAutoTileRunnerRed2: RED | State:               1 [PUSH_JEWEL] |  Start |  337.8 |    25 | IMU: -0.2 | (x1,x2): 36.0, 2.8 | Glyph count:    0 | RIGHT | Battery: 12.97
    03-11 10:20:06.804  6731  6946 I JewelPusher: Deploying jewel pusher arms ...
    03-11 10:20:08.075  6731  6946 I TechNova:JewelPusher: Jewel Color: (29|55) 33554689
    03-11 10:20:08.200  6731  6946 I TechNova: JewelPusher: JewelColor:BLUE
    03-11 10:20:09.224  6731  6946 I JewelPusher: Retracting jewel pusher arms ...
    03-11 10:20:09.852  6731  6946 I RelicRecoveryAutoTileRunnerRed2: RED | State:               1 [PUSH_JEWEL] |    End | 3381.7 |  3069 | IMU: -0.1 | (x1,x2): 36.0, 2.8 | Glyph count:    0 | RIGHT | Battery: 12.88
    03-11 10:20:10.025  6731  6946 I RelicRecoveryAutoTileRunnerRed2: RED | State:          2 [BACKWARD_3_FEET] |  Start | 3554.2 |    68 | IMU: -0.1 | (x1,x2): 36.0, 2.8 | Glyph count:    0 | RIGHT | Battery: 12.96
    03-11 10:20:10.027  6731  6946 I TechNova: RelicRecoveryAutoTileRunnerRed2: Drive backward: | 28.00, 0.25, 5.00
    03-11 10:20:11.260  6731  6792 E BulkPacketInWorker: DQ16V4CE: bulkTransfer() error: -1
    03-11 10:20:11.291  6731  6731 V FtDeviceManager: ACTION_USB_DEVICE_DETACHED: /dev/bus/usb/001/002
    03-11 10:20:11.291  6731  6731 V FtDevice: vv********************DQ16V4CE closing********************vv 0x0a689f11
    03-11 10:20:11.291  6731  6731 V FtDevice: DQ16V4CE stopping thread readBufferManager
    03-11 10:20:11.292  6731  6793 V FtDevice: DQ16V4CE thread readBufferManager is stopped
    03-11 10:20:11.293  6731  6731 V FtDevice: DQ16V4CE stopping thread bulkPacketInWorker
    03-11 10:20:11.293  6731  6792 V FtDevice: DQ16V4CE thread bulkPacketInWorker is stopped
    03-11 10:20:11.296  6731  6731 V MonitoredUsbDeviceConnection: closing UsbDeviceConnection(DQ16V4CE)
    03-11 10:20:11.296  6731  6731 D UsbDeviceConnectionJNI: close
    03-11 10:20:11.296  6731  6807 V LynxUsb : device closed in incoming datagram loop
    03-11 10:20:11.296  6731  6731 V FtDevice: ^^********************DQ16V4CE closed ********************^^
    03-11 10:20:11.297  6731  6807 V RobotUsbDeviceFtdi: closing DQ16V4CE
    03-11 10:20:11.297  6731  6807 V RobotCore: thread: ...terminating 'lynx incoming datagrams'
    03-11 10:20:11.297  6731  6810 D RobotCore: system telemetry: key=$System$Warning$ msg="REV Robotics USB Expansion Hub Portal [DQ16V4CE] detached"
    03-11 10:20:11.297  6731  6794 V ThreadPool: container(0x030c0338: WatchdogMonitor) removed id=527 TID=6794 count=1
    03-11 10:20:11.297  6731  6946 I TechNova: TileRunnerRobot: EncodersC |     1167    1185    0    0
    03-11 10:20:11.297  6731  6810 V RobotCore: event loop: device has shutdown abnormally: ABNORMAL
    03-11 10:20:11.298  6731  6810 V EventLoopManager: event loop: detaching device DQ16V4CE
    03-11 10:20:11.298  6731  6810 I FtcEventLoop: vv===== MODULE DETACH RECOVERY: disarm REV Robotics USB Expansion Hub Portal [DQ16V4CE]=====vv
    03-11 10:20:11.298  6731  6946 I TechNova: TileRunnerRobot: EncodersT |     0    0    0    0
    03-11 10:20:11.298  6731  6810 V LynxUsb : disarmDevice() serial=DQ16V4CE...
    03-11 10:20:11.298  6731  6810 V LynxUsb : shutting down incoming datagrams
    03-11 10:20:11.298  6731  6810 V ThreadPool: waiting for service Lynx incoming datagram poller
    03-11 10:20:11.299  6731  6807 V ThreadPool: container(0x07d71f49: lynx dg poller) removed id=536 TID=6807 count=1
    03-11 10:20:11.300  6731  6810 V ThreadPool: awaitTermination returned, isTerminated=true
    03-11 10:20:11.300  6731  6810 V ThreadPool: executive service Lynx incoming datagram poller(0x07d71f49) is terminated
    03-11 10:20:11.300  6731  6810 V RobotUsbDeviceFtdi: closing DQ16V4CE
    03-11 10:20:11.300  6731  6810 V LynxUsb : ...done disarmDevice()
    03-11 10:20:11.301  6731  6810 I FtcEventLoop: ======= MODULE DETACH RECOVERY: pretend REV Robotics USB Expansion Hub Portal [DQ16V4CE]=======
    03-11 10:20:11.306  6731  6810 V LynxUsb : doPretend() serial=DQ16V4CE
    03-11 10:20:11.554  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxIsMotorAtTargetCommand mod=2 msg#=0
    03-11 10:20:11.554  6731  6946 V RobotCore: nack rec'd mod=2 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:11.555  6731  6946 W LynxMotor: LynxIsMotorAtTargetCommand was abandoned waiting for response
    03-11 10:20:11.806  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxIsMotorAtTargetCommand mod=2 msg#=0
    03-11 10:20:11.806  6731  6946 V RobotCore: nack rec'd mod=2 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:11.806  6731  6946 W LynxMotor: LynxIsMotorAtTargetCommand was abandoned waiting for response
    03-11 10:20:11.984  6731  6731 V RCActivity: onPause()
    03-11 10:20:11.984  6731  6731 V RCActivity: ACTION_USB_DEVICE_ATTACHED: /dev/bus/usb/001/003
    03-11 10:20:11.984  6731  6731 V FtDeviceManager: openByUsbDevice(vid=0x0403 pid=0x6015)
    03-11 10:20:11.984  6731  6731 V FtDeviceManager: device not found: adding it on the fly
    03-11 10:20:11.985  6731  6731 V FtDeviceManager: addOrUpdateUsbDevice(vid=0x0403 pid=0x6015)
    03-11 10:20:11.991  6731  6731 V ThreadPool: container(0x03b2008e: WatchdogMonitor) added id=590 TID=0 count=1
    03-11 10:20:11.999  6731  6731 V FtDevice: initialize(vid=0x0403 pid=0x6015 bcdDevice=0x1000)
    03-11 10:20:12.000  6731  6731 V MonitoredUsbDeviceConnection: closing UsbDeviceConnection(DQ16V4CE)
    03-11 10:20:12.000  6731  6731 D UsbDeviceConnectionJNI: close
    03-11 10:20:12.000  6731  6731 V MonitoredUsbDeviceConnection: closing UsbDeviceConnection(DQ16V4CE)
    03-11 10:20:12.000  6731  6731 D UsbDeviceConnectionJNI: close
    03-11 10:20:12.000  6731  7189 V ThreadPool: container(0x03b2008e: WatchdogMonitor) removed id=590 TID=7189 count=1
    03-11 10:20:12.003  6731  6731 V FtDevice: vv********************DQ16V4CE opening********************vv 0x019cd445
    03-11 10:20:12.004  6731  6731 V FtDevice: ^^********************DQ16V4CE opened ********************^^
    03-11 10:20:12.004  6731  6731 V FtDevice: vv********************DQ16V4CE closing********************vv 0x019cd445
    03-11 10:20:12.004  6731  6731 V FtDevice: DQ16V4CE stopping thread readBufferManager
    03-11 10:20:12.004  6731  7191 V FtDevice: DQ16V4CE thread readBufferManager is stopped
    03-11 10:20:12.005  6731  6731 V FtDevice: DQ16V4CE stopping thread bulkPacketInWorker
    03-11 10:20:12.005  6731  7190 V FtDevice: DQ16V4CE thread bulkPacketInWorker is stopped
    03-11 10:20:12.005  6731  6731 V MonitoredUsbDeviceConnection: closing UsbDeviceConnection(DQ16V4CE)
    03-11 10:20:12.005  6731  6731 D UsbDeviceConnectionJNI: close
    03-11 10:20:12.005  6731  6731 V FtDevice: ^^********************DQ16V4CE closed ********************^^
    03-11 10:20:12.057  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxIsMotorAtTargetCommand mod=3 msg#=0
    03-11 10:20:12.057  6731  6946 V RobotCore: nack rec'd mod=3 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:12.057  6731  6946 W LynxMotor: LynxIsMotorAtTargetCommand was abandoned waiting for response
    03-11 10:20:12.308  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxIsMotorAtTargetCommand mod=3 msg#=0
    03-11 10:20:12.308  6731  6946 V RobotCore: nack rec'd mod=3 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:12.308  6731  6946 W LynxMotor: LynxIsMotorAtTargetCommand was abandoned waiting for response
    03-11 10:20:12.438  6731  6731 V RCActivity: onResume()
    03-11 10:20:12.439  6731  6731 V FtDeviceManager: ACTION_USB_DEVICE_ATTACHED: /dev/bus/usb/001/003
    03-11 10:20:12.439  6731  6731 V FtDeviceManager: addOrUpdateUsbDevice(vid=0x0403 pid=0x6015)
    03-11 10:20:12.440  6731  6731 I Choreographer: Skipped 42 frames!  The application may be doing too much work on its main thread.
    03-11 10:20:12.560  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=0
    03-11 10:20:12.560  6731  6946 V RobotCore: nack rec'd mod=3 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:12.561  6731  6946 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:12.812  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=0
    03-11 10:20:12.812  6731  6946 V RobotCore: nack rec'd mod=3 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:12.813  6731  6946 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:13.063  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for ack: cmd=LynxSetMotorConstantPowerCommand mod=3 msg#=0
    03-11 10:20:13.064  6731  6946 V RobotCore: nack rec'd mod=3 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_ACK:257
    03-11 10:20:13.064  6731  6946 W LynxMotor: LynxSetMotorConstantPowerCommand was abandoned waiting for ack
    03-11 10:20:13.315  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=0
    03-11 10:20:13.317  6731  6946 V RobotCore: nack rec'd mod=3 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:13.323  6731  6946 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:13.574  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=0
    03-11 10:20:13.574  6731  6946 V RobotCore: nack rec'd mod=3 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:13.575  6731  6946 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:13.825  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for ack: cmd=LynxSetMotorConstantPowerCommand mod=3 msg#=0
    03-11 10:20:13.826  6731  6946 V RobotCore: nack rec'd mod=3 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_ACK:257
    03-11 10:20:13.826  6731  6946 W LynxMotor: LynxSetMotorConstantPowerCommand was abandoned waiting for ack
    03-11 10:20:14.077  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=0
    03-11 10:20:14.077  6731  6946 V RobotCore: nack rec'd mod=3 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:14.078  6731  6946 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:14.328  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for ack: cmd=LynxSetMotorConstantPowerCommand mod=3 msg#=0
    03-11 10:20:14.328  6731  6946 V RobotCore: nack rec'd mod=3 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_ACK:257
    03-11 10:20:14.329  6731  6946 W LynxMotor: LynxSetMotorConstantPowerCommand was abandoned waiting for ack
    03-11 10:20:14.579  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for ack: cmd=LynxResetMotorEncoderCommand mod=3 msg#=0
    03-11 10:20:14.579  6731  6946 V RobotCore: nack rec'd mod=3 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_ACK:257
    03-11 10:20:14.580  6731  6946 W LynxMotor: LynxResetMotorEncoderCommand was abandoned waiting for ack
    03-11 10:20:14.830  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=0
    03-11 10:20:14.831  6731  6946 V RobotCore: nack rec'd mod=3 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:14.831  6731  6946 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:15.082  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for ack: cmd=LynxSetMotorConstantPowerCommand mod=3 msg#=0
    03-11 10:20:15.082  6731  6946 V RobotCore: nack rec'd mod=3 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_ACK:257
    03-11 10:20:15.083  6731  6946 W LynxMotor: LynxSetMotorConstantPowerCommand was abandoned waiting for ack
    03-11 10:20:15.333  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for ack: cmd=LynxResetMotorEncoderCommand mod=3 msg#=0
    03-11 10:20:15.333  6731  6946 V RobotCore: nack rec'd mod=3 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_ACK:257
    03-11 10:20:15.334  6731  6946 W LynxMotor: LynxResetMotorEncoderCommand was abandoned waiting for ack
    03-11 10:20:15.334  6731  6810 I FtcEventLoop: ^^===== MODULE DETACH RECOVERY: complete REV Robotics USB Expansion Hub Portal [DQ16V4CE]=====^^
    03-11 10:20:15.334  6731  6810 I FtcEventLoop: vv===== MODULE ATTACH: disarm REV Robotics USB Expansion Hub Portal [DQ16V4CE]=====vv
    03-11 10:20:15.335  6731  6810 V LynxUsb : disarmDevice() serial=DQ16V4CE...
    03-11 10:20:15.335  6731  6810 V LynxUsb : ...done disarmDevice()
    03-11 10:20:15.335  6731  6810 I FtcEventLoop: ======= MODULE ATTACH: arm or pretend REV Robotics USB Expansion Hub Portal [DQ16V4CE]=======
    03-11 10:20:15.336  6731  6810 V LynxUsb : clearing extant global warning: "REV Robotics USB Expansion Hub Portal [DQ16V4CE] detached"
    03-11 10:20:15.338  6731  6810 V FtDeviceManager: createDeviceInfoList(): 1 USB devices
    03-11 10:20:15.342  6731  6810 V FtDevice: vv********************DQ16V4CE opening********************vv 0x019cd445
    03-11 10:20:15.343  6731  6810 V FtDevice: ^^********************DQ16V4CE opened ********************^^
    03-11 10:20:15.343  6731  6810 V FtDevice: resetting DQ16V4CE
    03-11 10:20:15.343  6731  6810 V ThreadPool: container(0x0be5a93e: WatchdogMonitor) added id=603 TID=0 count=1
    03-11 10:20:15.349  6731  6810 V LynxUsb : armDevice() serial=DQ16V4CE...
    03-11 10:20:15.350  6731  6810 V ThreadPool: container(0x0219ccec: lynx dg poller) added id=604 TID=0 count=1
    03-11 10:20:15.351  6731  6810 V LynxModule: pingAndQueryKnownInterfaces mod=2
    03-11 10:20:15.353  6731  7274 V RobotCore: thread: 'lynx incoming datagrams' starting...
    03-11 10:20:15.354  6731  7274 V LynxUsb : synchronization gained: serial=DQ16V4CE
    03-11 10:20:15.362  6731  6810 V LynxModule: queryInterface(DEKA)=49 commands
    03-11 10:20:15.368  6731  6810 V LynxModule: mod#=2 intf=DEKA: expected 53 commands; found 49
    03-11 10:20:15.371  6731  6810 V LynxModule: sendLEDPatternSteps(): #steps=6
    03-11 10:20:15.374  6731  6808 V LynxModule: received status: LynxGetModuleStatusResponse(status=0x02 alerts=0x00: Reset)
    03-11 10:20:15.381  6731  6810 V LynxModule: pingAndQueryKnownInterfaces mod=3
    03-11 10:20:15.390  6731  6790 D RobotCore: system telemetry: key=$System$None$ msg=""
    03-11 10:20:15.392  6731  6810 V LynxModule: queryInterface(DEKA)=49 commands
    03-11 10:20:15.397  6731  6810 V LynxModule: mod#=3 intf=DEKA: expected 53 commands; found 49
    03-11 10:20:15.404  6731  6810 V LynxModule: sendLEDPatternSteps(): #steps=8
    03-11 10:20:15.408  6731  6809 V LynxModule: received status: LynxGetModuleStatusResponse(status=0x02 alerts=0x00: Reset)
    03-11 10:20:15.418  6731  6810 V LynxUsb : ...done armDevice()
    03-11 10:20:15.589  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for ack: cmd=LynxI2cWriteSingleByteCommand mod=2 msg#=0
    03-11 10:20:15.589  6731  6946 V RobotCore: nack rec'd mod=2 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_ACK:257
    03-11 10:20:15.590  6731  6946 W LynxI2cDeviceSynch: LynxI2cWriteSingleByteCommand was abandoned waiting for ack
    03-11 10:20:15.590  6731  6946 E LynxI2cDeviceSynch: placeholder: readTimestamped
    03-11 10:20:15.626  6731  6790 D RobotCore: system telemetry: key=$System$Warning$ msg="problem with "imu""
    03-11 10:20:15.875  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for ack: cmd=LynxI2cWriteSingleByteCommand mod=3 msg#=0
    03-11 10:20:15.875  6731  6946 V RobotCore: nack rec'd mod=3 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_ACK:257
    03-11 10:20:15.876  6731  6946 W LynxI2cDeviceSynch: LynxI2cWriteSingleByteCommand was abandoned waiting for ack
    03-11 10:20:15.876  6731  6946 E LynxI2cDeviceSynch: placeholder: readTimestamped
    03-11 10:20:15.876  6731  6810 I FtcEventLoop: ^^===== MODULE ATTACH: complete REV Robotics USB Expansion Hub Portal [DQ16V4CE]=====^^
    03-11 10:20:15.915  6731  6946 I RelicRecoveryAutoTileRunnerRed2: RED | State:          2 [BACKWARD_3_FEET] |    End | 8971.9 |  5485 | IMU: -0.0 | (x1,x2): 37.0, 3.1 | Glyph count:    0 | RIGHT | Battery: 13.06
    03-11 10:20:16.044  6731  6810 D RobotCore: system telemetry: key=$System$None$ msg=""
    03-11 10:20:16.116  6731  6946 I RelicRecoveryAutoTileRunnerRed2: RED | State:          3 [TURN_LEFT_TO_90] |  Start | 9655.2 |   106 | IMU: -0.0 | (x1,x2): 37.0, 3.1 | Glyph count:    0 | RIGHT | Battery: 13.03
    03-11 10:20:21.147  6731  6946 I TechNova: RelicRecoveryAutoTileRunnerRed2:  -- Angle Reached -- : | -0.0
    03-11 10:20:21.754  6731  6946 I RelicRecoveryAutoTileRunnerRed2: RED | State:          3 [TURN_LEFT_TO_90] |    End | 15289.8 |  5740 | IMU: -0.0 | (x1,x2): 23.0, 256.0 | Glyph count:    0 | RIGHT | Battery: 12.95
    03-11 10:20:21.931  6731  6946 I RelicRecoveryAutoTileRunnerRed2: RED | State:          4 [BACKWARD_1_FEET] |  Start | 15457.3 |    68 | IMU: -0.0 | (x1,x2): 256.0, 3.5 | Glyph count:    0 | RIGHT | Battery: 12.98
    03-11 10:20:26.981  6731  6946 I TechNova: RelicRecoveryAutoTileRunnerRed2:  -- Angle Reached -- : | -0.0
    03-11 10:20:26.983  6731  6946 I TechNova: RelicRecoveryAutoTileRunnerRed2: Drive backward: | 6.00, 0.25, 5.00
    03-11 10:20:26.983  6731  6946 I TechNova: TileRunnerRobot: Encoder: | 50.93 | 305
    03-11 10:20:27.218  6731  6946 I TechNova: TileRunnerRobot: Encoder Remain |     282.0    328.0    471.7
    03-11 10:20:27.239  6731  6946 I TechNova: TileRunnerRobot: EncodersC |     27    41    29    33
    03-11 10:20:27.257  6731  6946 I TechNova: TileRunnerRobot: EncodersT |     304    305    305    304
    03-11 10:20:27.372  6731  6946 I TechNova: TileRunnerRobot: Encoder Remain |     194.0    244.0    328.0
    03-11 10:20:27.389  6731  6946 I TechNova: TileRunnerRobot: EncodersC |     129    145    134    143
    03-11 10:20:27.404  6731  6946 I TechNova: TileRunnerRobot: EncodersT |     304    305    305    304
    03-11 10:20:27.519  6731  6946 I TechNova: TileRunnerRobot: Encoder Remain |     56.0    177.3    244.0
    03-11 10:20:27.533  6731  6946 I TechNova: TileRunnerRobot: EncodersC |     271    279    273    281
    03-11 10:20:27.554  6731  6946 I TechNova: TileRunnerRobot: EncodersT |     304    305    305    304
    03-11 10:20:27.799  6731  6946 I RelicRecoveryAutoTileRunnerRed2: RED | State:          4 [BACKWARD_1_FEET] |    End | 21327.0 |  5938 | IMU: -0.0 | (x1,x2): 87.0, 75.6 | Glyph count:    0 | RIGHT | Battery: 12.94
    03-11 10:20:27.923  6731  6946 I RelicRecoveryAutoTileRunnerRed2: RED | State:          5 [TURN_RIGHT_TO_0] |  Start | 21453.7 |    20 | IMU: -0.0 | (x1,x2): 90.0, 3.5 | Glyph count:    0 | RIGHT | Battery: 12.94
    03-11 10:20:32.940  6731  6946 I TechNova: RelicRecoveryAutoTileRunnerRed2:  -- Angle Reached -- : | -0.0
    03-11 10:20:33.562  6731  6946 I RelicRecoveryAutoTileRunnerRed2: RED | State:          5 [TURN_RIGHT_TO_0] |    End | 27081.8 |  5648 | IMU: -0.0 | (x1,x2): 256.0, 3.5 | Glyph count:    0 | RIGHT | Battery: 12.95
    03-11 10:20:33.729  6731  6946 I RelicRecoveryAutoTileRunnerRed2: RED | State:        6 [BACKWARD_7_INCHES] |  Start | 27261.9 |    65 | IMU: -0.0 | (x1,x2): 256.0, 3.5 | Glyph count:    0 | RIGHT | Battery: 12.95
    03-11 10:20:33.741  6731  7274 V RobotCore: nack rec'd mod=2 msg#=109 ref#=0 reason=SERVO_NOT_CONFIG_BEFORE_ENABLED:30
    03-11 10:20:33.741  6731  6946 E LynxServoController: exception thrown during lynx communication
    03-11 10:20:33.742  6731  6946 E LynxServoController: com.qualcomm.hardware.lynx.LynxNackException: (DQ16V4CE #2) LynxSetServoEnableCommand: nack received: SERVO_NOT_CONFIG_BEFORE_ENABLED:30
    03-11 10:20:33.743  6731  6946 E LynxServoController:     at com.qualcomm.hardware.lynx.commands.LynxRespondable.throwIfNack(LynxRespondable.java:324)
    03-11 10:20:33.751  6731  6946 E LynxServoController:     at java.lang.Thread.run(Thread.java:818)
    03-11 10:20:33.752  6731  6946 I TechNova: RelicRecoveryAutoTileRunnerRed2: Drive backward: | 2.50, 0.25, 5.00
    03-11 10:20:33.752  6731  6946 I TechNova: TileRunnerRobot: Encoder: | 50.93 | 127
    03-11 10:20:33.988  6731  6946 I TechNova: TileRunnerRobot: Encoder Remain |     104.0    118.0    177.3
    03-11 10:20:34.008  6731  6946 I TechNova: TileRunnerRobot: EncodersC |     28    34    34    30
    03-11 10:20:34.030  6731  6946 I TechNova: TileRunnerRobot: EncodersT |     126    127    127    126
    03-11 10:20:34.166  6731  6946 I TechNova: TileRunnerRobot: Encoder Remain |     31.0    63.7    118.0
    03-11 10:20:34.186  6731  6946 I TechNova: TileRunnerRobot: EncodersC |     108    114    110    107
    03-11 10:20:34.210  6731  6946 I TechNova: TileRunnerRobot: EncodersT |     126    127    127    126
    03-11 10:20:34.434  6731  6946 I RelicRecoveryAutoTileRunnerRed2: RED | State:        6 [BACKWARD_7_INCHES] |    End | 27971.6 |   778 | IMU: -0.0 | (x1,x2): 50.0, 3.1 | Glyph count:    0 | RIGHT | Battery: 12.91
    03-11 10:20:34.564  6731  6946 I RelicRecoveryAutoTileRunnerRed2: RED | State:  7 [PLACE_GLYPH_INTO_CRYPTO] |  Start | 28090.0 |    21 | IMU: -0.0 | (x1,x2): 256.0, 3.1 | Glyph count:    0 | RIGHT | Battery: 12.94
    03-11 10:20:34.564  6731  6946 I TechNova: RelicRecoveryAutoTileRunnerRed2:  --- Align robot to the cryptobox ---
    03-11 10:20:34.564  6731  6946 I TechNova: RelicRecoveryAutoTileRunnerRed2:  --- Get the distance sensor in place ---
    03-11 10:20:34.653  6731  6946 I TechNova: RelicRecoveryAutoTileRunnerRed2: Final Distance from the column (in): 3.1
    03-11 10:20:34.658  6731  7274 V RobotCore: nack rec'd mod=2 msg#=190 ref#=0 reason=SERVO_NOT_CONFIG_BEFORE_ENABLED:30
    03-11 10:20:34.660  6731  6946 E LynxServoController: exception thrown during lynx communication
    03-11 10:20:34.660  6731  6946 E LynxServoController: com.qualcomm.hardware.lynx.LynxNackException: (DQ16V4CE #2) LynxSetServoEnableCommand: nack received: SERVO_NOT_CONFIG_BEFORE_ENABLED:30
    03-11 10:20:34.661  6731  6946 E LynxServoController:     at com.qualcomm.hardware.lynx.commands.LynxRespondable.throwIfNack(LynxRespondable.java:324)
    03-11 10:20:34.674  6731  6946 E LynxServoController:     at java.lang.Thread.run(Thread.java:818)
    03-11 10:20:34.676  6731  6946 I TechNova: RelicRecoveryAutoTileRunnerRed2:  --- Flip Glyph Tray ---
    03-11 10:20:34.684  6731  7274 V RobotCore: nack rec'd mod=3 msg#=117 ref#=0 reason=SERVO_NOT_CONFIG_BEFORE_ENABLED:30
    03-11 10:20:34.685  6731  6946 E LynxServoController: exception thrown during lynx communication
    03-11 10:20:34.686  6731  6946 E LynxServoController: com.qualcomm.hardware.lynx.LynxNackException: (DQ16V4CE #3) LynxSetServoEnableCommand: nack received: SERVO_NOT_CONFIG_BEFORE_ENABLED:30
    03-11 10:20:34.687  6731  6946 E LynxServoController:     at com.qualcomm.hardware.lynx.commands.LynxRespondable.throwIfNack(LynxRespondable.java:324)
    03-11 10:20:34.696  6731  6946 E LynxServoController:     at java.lang.Thread.run(Thread.java:818)
    03-11 10:20:35.000  6731  6946 I TechNova: RelicRecoveryAutoTileRunnerRed2:  --- More backward to let glyph fall on the floor ---
    03-11 10:20:35.001  6731  6946 I TechNova: RelicRecoveryAutoTileRunnerRed2: Drive forward: | 2.50, 0.25
    03-11 10:20:35.001  6731  6946 I TechNova: TileRunnerRobot: Encoder: | 50.93 | 127
    03-11 10:20:35.325  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=142 ref#=0
    03-11 10:20:35.427  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=142 ref#=0
    03-11 10:20:35.474  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=142 ref#=0
    03-11 10:20:35.476  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorEncoderPositionCommand mod=3 msg#=142
    03-11 10:20:35.477  6731  6946 V RobotCore: nack rec'd mod=3 msg#=142 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:35.478  6731  6946 W LynxMotor: LynxGetMotorEncoderPositionCommand was abandoned waiting for response
    03-11 10:20:35.581  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1014 msg#=143 ref#=0
    03-11 10:20:35.683  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1014 msg#=143 ref#=0
    03-11 10:20:35.730  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1014 msg#=143 ref#=0
    03-11 10:20:35.733  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorTargetPositionCommand mod=3 msg#=143
    03-11 10:20:35.733  6731  6946 V RobotCore: nack rec'd mod=3 msg#=143 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:35.734  6731  6946 W LynxMotor: LynxGetMotorTargetPositionCommand was abandoned waiting for response
    03-11 10:20:35.836  6731  6946 V LynxModule: retransmitting: mod=2 cmd=0x1009 msg#=215 ref#=0
    03-11 10:20:35.839  6731  7274 V LynxUsb : synchronization lost: serial=DQ16V4CE
    03-11 10:20:35.938  6731  6946 V LynxModule: retransmitting: mod=2 cmd=0x1009 msg#=215 ref#=0
    03-11 10:20:35.942  6731  7274 V LynxUsb : synchronization gained: serial=DQ16V4CE
    03-11 10:20:36.045  6731  6946 V LynxModule: retransmitting: mod=2 cmd=0x1009 msg#=216 ref#=0
    03-11 10:20:36.151  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=144 ref#=0
    03-11 10:20:36.255  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=144 ref#=0
    03-11 10:20:36.301  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=144 ref#=0
    03-11 10:20:36.303  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=144
    03-11 10:20:36.303  6731  6946 V RobotCore: nack rec'd mod=3 msg#=144 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:36.304  6731  6946 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:36.408  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=145 ref#=0
    03-11 10:20:36.510  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=145 ref#=0
    03-11 10:20:36.557  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=145 ref#=0
    03-11 10:20:36.559  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=145
    03-11 10:20:36.559  6731  6946 V RobotCore: nack rec'd mod=3 msg#=145 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:36.559  6731  6946 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:36.560  6731  6946 I TechNova: TileRunnerRobot: Encoder Remain |     0.0    45.0    63.7
    03-11 10:20:36.590  6731  6790 V Robocol : received command: CMD_INIT_OP_MODE(16355) $Stop$Robot$
    03-11 10:20:36.662  6731  6946 V LynxModule: retransmitting: mod=2 cmd=0x1016 msg#=217 ref#=0
    03-11 10:20:36.767  6731  6946 V LynxModule: retransmitting: mod=2 cmd=0x1016 msg#=218 ref#=0
    03-11 10:20:36.875  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=146 ref#=0
    03-11 10:20:36.978  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=146 ref#=0
    03-11 10:20:37.024  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=146 ref#=0
    03-11 10:20:37.026  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorEncoderPositionCommand mod=3 msg#=146
    03-11 10:20:37.026  6731  6946 V RobotCore: nack rec'd mod=3 msg#=146 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:37.027  6731  6946 W LynxMotor: LynxGetMotorEncoderPositionCommand was abandoned waiting for response
    03-11 10:20:37.129  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=147 ref#=0
    03-11 10:20:37.231  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=147 ref#=0
    03-11 10:20:37.279  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=147 ref#=0
    03-11 10:20:37.284  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorEncoderPositionCommand mod=3 msg#=147
    03-11 10:20:37.285  6731  6946 V RobotCore: nack rec'd mod=3 msg#=147 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:37.286  6731  6946 W LynxMotor: LynxGetMotorEncoderPositionCommand was abandoned waiting for response
    03-11 10:20:37.287  6731  6946 I TechNova: TileRunnerRobot: EncodersC |     0    0    0    0
    03-11 10:20:37.389  6731  6946 V LynxModule: retransmitting: mod=2 cmd=0x1014 msg#=219 ref#=0
    03-11 10:20:37.495  6731  6946 V LynxModule: retransmitting: mod=2 cmd=0x1014 msg#=220 ref#=0
    03-11 10:20:37.602  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1014 msg#=148 ref#=0
    03-11 10:20:37.704  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1014 msg#=148 ref#=0
    03-11 10:20:37.751  6731  6946 V LynxModule: retransmitting: mod=3 cmd=0x1014 msg#=148 ref#=0
    03-11 10:20:37.753  6731  6946 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorTargetPositionCommand mod=3 msg#=148
    03-11 10:20:37.753  6731  6946 V RobotCore: nack rec'd mod=3 msg#=148 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:37.754  6731  6946 W LynxMotor: LynxGetMotorTargetPositionCommand was abandoned waiting for response
    03-11 10:20:37.856  6731  6789 V LynxModule: retransmitting: mod=3 cmd=0x1007 msg#=149 ref#=0
    03-11 10:20:37.959  6731  6789 V LynxModule: retransmitting: mod=3 cmd=0x1007 msg#=149 ref#=0
    03-11 10:20:38.006  6731  6789 V LynxModule: retransmitting: mod=3 cmd=0x1007 msg#=149 ref#=0
    03-11 10:20:38.008  6731  6789 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetADCCommand mod=3 msg#=149
    03-11 10:20:38.008  6731  6789 V RobotCore: nack rec'd mod=3 msg#=149 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:38.009  6731  6789 W LynxVoltageSensor: LynxGetADCCommand was abandoned waiting for response
    03-11 10:20:38.110  6731  6789 V LynxModule: retransmitting: mod=2 cmd=0x1007 msg#=221 ref#=0
    03-11 10:20:38.113  6731  6789 E Robocol : command processing took 1.523 s: command=CMD_INIT_OP_MODE
    03-11 10:20:38.114  6731  6810 V ThreadPool: waiting for service user linear op mode
    03-11 10:20:38.115  6731  6946 I TechNova: TileRunnerRobot: EncodersT |     0    0    0    0
    03-11 10:20:38.122  6731  6946 I TechNova: RelicRecoveryAutoTileRunnerRed2: Drive forward: | 6.00, 0.25
    03-11 10:20:38.123  6731  6946 I TechNova: TileRunnerRobot: Encoder: | 50.93 | 305
    03-11 10:20:38.129  6731  6946 I TechNova: RelicRecoveryAutoTileRunnerRed2: Drive forward: | 12.00, 0.35
    03-11 10:20:38.130  6731  6946 I TechNova: TileRunnerRobot: Encoder: | 50.93 | 611
    03-11 10:20:38.137  6731  6946 I TechNova: RelicRecoveryAutoTileRunnerRed2:  -- Angle Reached -- : | 0.0
    03-11 10:20:38.138  6731  6946 E LynxI2cDeviceSynch: placeholder: readTimestamped
    03-11 10:20:38.138  6731  6946 E LynxI2cDeviceSynch: placeholder: readTimestamped
    03-11 10:20:38.139  6731  6946 E LynxI2cDeviceSynch: placeholder: readTimestamped
    03-11 10:20:38.140  6731  6946 I RelicRecoveryAutoTileRunnerRed2: RED | State:  7 [PLACE_GLYPH_INTO_CRYPTO] |    End | 31771.8 |  3703 | IMU: -0.0 | (x1,x2): 0.0, 0.0 | Glyph count:    0 | RIGHT | Battery: 0.00
    03-11 10:20:38.142  6731  6946 V RobotCore: thread: ...terminating 'LinearOpMode main'
    03-11 10:20:38.142  6731  6946 V ThreadPool: container(0x0c19532e: LinearOpMode) removed id=562 TID=6946 count=1
    03-11 10:20:38.142  6731  6810 V ThreadPool: awaitTermination returned, isTerminated=true
    03-11 10:20:38.142  6731  6810 V ThreadPool: executive service user linear op mode(0x0c19532e) is terminated
    03-11 10:20:38.562  6731  6810 I RobotCore: Attempting to switch to op mode $Stop$Robot$
    03-11 10:20:38.665  6731  6810 V LynxModule: retransmitting: mod=2 cmd=0x1009 msg#=222 ref#=0
    03-11 10:20:38.771  6731  6810 V LynxModule: retransmitting: mod=2 cmd=0x1009 msg#=223 ref#=0
    03-11 10:20:38.876  6731  6810 V LynxModule: retransmitting: mod=2 cmd=0x1010 msg#=224 ref#=0
    03-11 10:20:38.981  6731  6810 V LynxModule: retransmitting: mod=2 cmd=0x1009 msg#=225 ref#=0
    03-11 10:20:39.086  6731  6810 V LynxModule: retransmitting: mod=2 cmd=0x1010 msg#=226 ref#=0
    03-11 10:20:39.191  6731  6810 V LynxModule: retransmitting: mod=2 cmd=0x1009 msg#=227 ref#=0
    03-11 10:20:39.296  6731  6810 V LynxModule: retransmitting: mod=2 cmd=0x1010 msg#=228 ref#=0
    03-11 10:20:39.402  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=151 ref#=0
    03-11 10:20:39.504  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=151 ref#=0
    03-11 10:20:39.552  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=151 ref#=0
    03-11 10:20:39.554  6731  6810 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=151
    03-11 10:20:39.554  6731  6810 V RobotCore: nack rec'd mod=3 msg#=151 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:39.555  6731  6810 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:39.658  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1010 msg#=152 ref#=0
    03-11 10:20:39.760  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1010 msg#=152 ref#=0
    03-11 10:20:39.807  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1010 msg#=152 ref#=0
    03-11 10:20:39.809  6731  6810 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorConstantPowerCommand mod=3 msg#=152
    03-11 10:20:39.809  6731  6810 V RobotCore: nack rec'd mod=3 msg#=152 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:39.810  6731  6810 W LynxMotor: LynxGetMotorConstantPowerCommand was abandoned waiting for response
    03-11 10:20:39.912  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=153 ref#=0
    03-11 10:20:40.015  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=153 ref#=0
    03-11 10:20:40.061  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=153 ref#=0
    03-11 10:20:40.063  6731  6810 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=153
    03-11 10:20:40.063  6731  6810 V RobotCore: nack rec'd mod=3 msg#=153 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:40.064  6731  6810 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:40.166  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=154 ref#=0
    03-11 10:20:40.268  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=154 ref#=0
    03-11 10:20:40.316  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=154 ref#=0
    03-11 10:20:40.318  6731  6810 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=154
    03-11 10:20:40.318  6731  6810 V RobotCore: nack rec'd mod=3 msg#=154 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:40.319  6731  6810 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:40.421  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1010 msg#=155 ref#=0
    03-11 10:20:40.523  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1010 msg#=155 ref#=0
    03-11 10:20:40.571  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1010 msg#=155 ref#=0
    03-11 10:20:40.572  6731  6810 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorConstantPowerCommand mod=3 msg#=155
    03-11 10:20:40.572  6731  6810 V RobotCore: nack rec'd mod=3 msg#=155 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:40.573  6731  6810 W LynxMotor: LynxGetMotorConstantPowerCommand was abandoned waiting for response
    03-11 10:20:40.675  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=156 ref#=0
    03-11 10:20:40.777  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=156 ref#=0
    03-11 10:20:40.825  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=156 ref#=0
    03-11 10:20:40.827  6731  6810 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=156
    03-11 10:20:40.827  6731  6810 V RobotCore: nack rec'd mod=3 msg#=156 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:40.828  6731  6810 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:40.931  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=157 ref#=0
    03-11 10:20:41.033  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=157 ref#=0
    03-11 10:20:41.081  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=157 ref#=0
    03-11 10:20:41.083  6731  6810 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=157
    03-11 10:20:41.083  6731  6810 V RobotCore: nack rec'd mod=3 msg#=157 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:41.084  6731  6810 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:41.186  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1010 msg#=158 ref#=0
    03-11 10:20:41.288  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1010 msg#=158 ref#=0
    03-11 10:20:41.336  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1010 msg#=158 ref#=0
    03-11 10:20:41.338  6731  6810 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorConstantPowerCommand mod=3 msg#=158
    03-11 10:20:41.338  6731  6810 V RobotCore: nack rec'd mod=3 msg#=158 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:41.339  6731  6810 W LynxMotor: LynxGetMotorConstantPowerCommand was abandoned waiting for response
    03-11 10:20:41.441  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=159 ref#=0
    03-11 10:20:41.515  6731  6790 V Robocol : received command: CMD_INIT_OP_MODE(16405) $Stop$Robot$
    03-11 10:20:41.543  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=159 ref#=0
    03-11 10:20:41.591  6731  6810 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=159 ref#=0
    03-11 10:20:41.593  6731  6810 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=159
    03-11 10:20:41.593  6731  6810 V RobotCore: nack rec'd mod=3 msg#=159 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:41.594  6731  6810 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:41.602  6731  6808 V LynxModule: received status: LynxGetModuleStatusResponse(status=0x02 alerts=0x00: Reset)
    03-11 10:20:41.623  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(7281), attempt: 0
    03-11 10:20:41.631  6731  6810 I RobotCore: robot battery read duration: n=10, mean=16.994ms sd=31.054ms
    03-11 10:20:41.633  6731  6810 I RobotCore: Attempting to switch to op mode Tile Runner (New) TeleOps
    03-11 10:20:41.638  6731  6809 V LynxModule: received status: LynxGetModuleStatusResponse(status=0x06 alerts=0x00: Reset|FailSafe)
    03-11 10:20:41.667  6731  6790 V Robocol : received command: CMD_RUN_OP_MODE(16409) $Stop$Robot$
    03-11 10:20:42.258  6731  6810 V ThreadPool: container(0x0b0f1b4a: LinearOpMode) added id=605 TID=0 count=1
    03-11 10:20:42.262  6731  7292 V RobotCore: thread: 'LinearOpMode main' starting...
    03-11 10:20:42.263  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(7294), attempt: 0
    03-11 10:20:42.279  6731  6810 V ThreadPool: waiting for service user linear op mode
    03-11 10:20:42.282  6731  6789 E Robocol : command processing took 0.763 s: command=CMD_INIT_OP_MODE
    03-11 10:20:42.285  6731  7292 I TechNova: TileRunnerRobot: Init Drive Motors |  Drive Motors are initialized ...
    03-11 10:20:42.290  6731  7292 I TechNova: TileRunnerRobot: Init Servos |  Servos are initialized ...
    03-11 10:20:42.294  6731  7292 V RobotCore: thread: ...terminating 'LinearOpMode main'
    03-11 10:20:42.294  6731  6810 V ThreadPool: awaitTermination returned, isTerminated=true
    03-11 10:20:42.295  6731  7292 V ThreadPool: container(0x0b0f1b4a: LinearOpMode) removed id=605 TID=7292 count=1
    03-11 10:20:42.295  6731  6810 V ThreadPool: executive service user linear op mode(0x0b0f1b4a) is terminated
    03-11 10:20:42.295  6731  6810 I RobotCore: Attempting to switch to op mode $Stop$Robot$
    03-11 10:20:42.343  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(7302), attempt: 0
    03-11 10:20:42.383  6731  6795 V Robocol : sending CMD_NOTIFY_RUN_OP_MODE(7305), attempt: 0
    03-11 10:20:42.390  6731  6790 V Robocol : received command: CMD_RUN_OP_MODE(16424) $Stop$Robot$
    03-11 10:20:42.424  6731  6795 V Robocol : sending CMD_NOTIFY_RUN_OP_MODE(7311), attempt: 0
    03-11 10:20:43.266  6731  6790 V Robocol : received command: CMD_INIT_OP_MODE(16443) Tile Runner (New) TeleOps
    03-11 10:20:43.281  6731  6810 I RobotCore: Attempting to switch to op mode Tile Runner (New) TeleOps
    03-11 10:20:43.927  6731  6810 V ThreadPool: container(0x0c4ccbd8: LinearOpMode) added id=606 TID=0 count=1
    03-11 10:20:43.933  6731  7293 V RobotCore: thread: 'LinearOpMode main' starting...
    03-11 10:20:43.943  6731  6795 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(7337), attempt: 0
    03-11 10:20:44.016  6731  7293 I TechNova: TileRunnerRobot: Init Drive Motors |  Drive Motors are initialized ...
    03-11 10:20:44.154  6731  7293 I TechNova: TileRunnerRobot: Init Servos |  Servos are initialized ...
    03-11 10:20:45.103  6731  6790 V Robocol : received command: CMD_RUN_OP_MODE(16463) Tile Runner (New) TeleOps
    03-11 10:20:45.144  6731  6795 V Robocol : sending CMD_NOTIFY_RUN_OP_MODE(7352), attempt: 0
    03-11 10:20:45.507  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=132 ref#=0
    03-11 10:20:45.608  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=132 ref#=0
    03-11 10:20:45.658  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=132 ref#=0
    03-11 10:20:45.661  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorEncoderPositionCommand mod=3 msg#=132
    03-11 10:20:45.661  6731  7293 V RobotCore: nack rec'd mod=3 msg#=132 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:45.662  6731  7293 W LynxMotor: LynxGetMotorEncoderPositionCommand was abandoned waiting for response
    03-11 10:20:45.766  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=133 ref#=0
    03-11 10:20:45.868  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=133 ref#=0
    03-11 10:20:45.916  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=133 ref#=0
    03-11 10:20:45.918  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorEncoderPositionCommand mod=3 msg#=133
    03-11 10:20:45.918  6731  7293 V RobotCore: nack rec'd mod=3 msg#=133 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:45.919  6731  7293 W LynxMotor: LynxGetMotorEncoderPositionCommand was abandoned waiting for response
    03-11 10:20:46.023  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=134 ref#=0
    03-11 10:20:46.125  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=134 ref#=0
    03-11 10:20:46.173  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=134 ref#=0
    03-11 10:20:46.175  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorEncoderPositionCommand mod=3 msg#=134
    03-11 10:20:46.175  6731  7293 V RobotCore: nack rec'd mod=3 msg#=134 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:46.175  6731  7293 W LynxMotor: LynxGetMotorEncoderPositionCommand was abandoned waiting for response
    03-11 10:20:46.278  6731  7293 V LynxModule: retransmitting: mod=2 cmd=0x1016 msg#=26 ref#=0
    03-11 10:20:46.281  6731  7274 V LynxUsb : synchronization lost: serial=DQ16V4CE
    03-11 10:20:46.380  6731  7293 V LynxModule: retransmitting: mod=2 cmd=0x1016 msg#=26 ref#=0
    03-11 10:20:46.384  6731  7274 V LynxUsb : synchronization gained: serial=DQ16V4CE
    03-11 10:20:46.486  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=135 ref#=0
    03-11 10:20:46.588  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=135 ref#=0
    03-11 10:20:46.635  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=135 ref#=0
    03-11 10:20:46.637  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorEncoderPositionCommand mod=3 msg#=135
    03-11 10:20:46.637  6731  7293 V RobotCore: nack rec'd mod=3 msg#=135 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:46.637  6731  7293 W LynxMotor: LynxGetMotorEncoderPositionCommand was abandoned waiting for response
    03-11 10:20:46.739  6731  7293 V LynxModule: retransmitting: mod=2 cmd=0x1016 msg#=27 ref#=0
    03-11 10:20:46.844  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=136 ref#=0
    03-11 10:20:46.946  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=136 ref#=0
    03-11 10:20:46.994  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=136 ref#=0
    03-11 10:20:46.996  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorEncoderPositionCommand mod=3 msg#=136
    03-11 10:20:46.996  6731  7293 V RobotCore: nack rec'd mod=3 msg#=136 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:46.996  6731  7293 W LynxMotor: LynxGetMotorEncoderPositionCommand was abandoned waiting for response
    03-11 10:20:47.099  6731  7293 V LynxModule: retransmitting: mod=2 cmd=0x1009 msg#=28 ref#=0
    03-11 10:20:47.205  6731  7293 V LynxModule: retransmitting: mod=2 cmd=0x100f msg#=29 ref#=0
    03-11 10:20:47.310  6731  7293 V LynxModule: retransmitting: mod=2 cmd=0x100a msg#=30 ref#=0
    03-11 10:20:47.416  6731  7293 V LynxModule: retransmitting: mod=2 cmd=0x1009 msg#=31 ref#=0
    03-11 10:20:47.521  6731  7293 V LynxModule: retransmitting: mod=2 cmd=0x100f msg#=32 ref#=0
    03-11 10:20:47.626  6731  7293 V LynxModule: retransmitting: mod=2 cmd=0x100a msg#=33 ref#=0
    03-11 10:20:47.731  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=137 ref#=0
    03-11 10:20:47.833  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=137 ref#=0
    03-11 10:20:47.881  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=137 ref#=0
    03-11 10:20:47.883  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=137
    03-11 10:20:47.883  6731  7293 V RobotCore: nack rec'd mod=3 msg#=137 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:47.884  6731  7293 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:47.986  6731  6808 V LynxModule: retransmitting: mod=2 cmd=0x7f03 msg#=34 ref#=0
    03-11 10:20:47.990  6731  6808 V LynxModule: received status: LynxGetModuleStatusResponse(status=0x02 alerts=0x00: Reset)
    03-11 10:20:48.092  6731  6808 V LynxModule: retransmitting: mod=2 cmd=0x7f03 msg#=35 ref#=0
    03-11 10:20:48.197  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=138 ref#=0
    03-11 10:20:48.299  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=138 ref#=0
    03-11 10:20:48.346  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=138 ref#=0
    03-11 10:20:48.348  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=138
    03-11 10:20:48.348  6731  7293 V RobotCore: nack rec'd mod=3 msg#=138 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:48.349  6731  7293 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:48.451  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x100f msg#=139 ref#=0
    03-11 10:20:48.554  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x100f msg#=139 ref#=0
    03-11 10:20:48.601  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x100f msg#=139 ref#=0
    03-11 10:20:48.604  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for ack: cmd=LynxSetMotorConstantPowerCommand mod=3 msg#=139
    03-11 10:20:48.605  6731  7293 V RobotCore: nack rec'd mod=3 msg#=139 ref#=0 reason=ABANDONED_WAITING_FOR_ACK:257
    03-11 10:20:48.606  6731  7293 W LynxMotor: LynxSetMotorConstantPowerCommand was abandoned waiting for ack
    03-11 10:20:48.709  6731  7293 V LynxModule: retransmitting: mod=2 cmd=0x1009 msg#=36 ref#=0
    03-11 10:20:48.815  6731  7293 V LynxModule: retransmitting: mod=2 cmd=0x100f msg#=37 ref#=0
    03-11 10:20:48.919  6731  7293 V LynxModule: retransmitting: mod=2 cmd=0x100a msg#=38 ref#=0
    03-11 10:20:49.025  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=140 ref#=0
    03-11 10:20:49.127  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=140 ref#=0
    03-11 10:20:49.173  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=140 ref#=0
    03-11 10:20:49.175  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=140
    03-11 10:20:49.175  6731  7293 V RobotCore: nack rec'd mod=3 msg#=140 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:49.176  6731  7293 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:49.278  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=141 ref#=0
    03-11 10:20:49.380  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=141 ref#=0
    03-11 10:20:49.427  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=141 ref#=0
    03-11 10:20:49.429  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=141
    03-11 10:20:49.429  6731  7293 V RobotCore: nack rec'd mod=3 msg#=141 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:49.430  6731  7293 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:49.532  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x100f msg#=142 ref#=0
    03-11 10:20:49.634  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x100f msg#=142 ref#=0
    03-11 10:20:49.681  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x100f msg#=142 ref#=0
    03-11 10:20:49.683  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for ack: cmd=LynxSetMotorConstantPowerCommand mod=3 msg#=142
    03-11 10:20:49.683  6731  7293 V RobotCore: nack rec'd mod=3 msg#=142 ref#=0 reason=ABANDONED_WAITING_FOR_ACK:257
    03-11 10:20:49.684  6731  7293 W LynxMotor: LynxSetMotorConstantPowerCommand was abandoned waiting for ack
    03-11 10:20:49.786  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=143 ref#=0
    03-11 10:20:49.888  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=143 ref#=0
    03-11 10:20:49.936  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=143 ref#=0
    03-11 10:20:49.938  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorEncoderPositionCommand mod=3 msg#=143
    03-11 10:20:49.938  6731  7293 V RobotCore: nack rec'd mod=3 msg#=143 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:49.939  6731  7293 W LynxMotor: LynxGetMotorEncoderPositionCommand was abandoned waiting for response
    03-11 10:20:50.042  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1022 msg#=144 ref#=0
    03-11 10:20:50.144  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1022 msg#=144 ref#=0
    03-11 10:20:50.192  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1022 msg#=144 ref#=0
    03-11 10:20:50.194  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetServoPulseWidthCommand mod=3 msg#=144
    03-11 10:20:50.194  6731  7293 V RobotCore: nack rec'd mod=3 msg#=144 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:50.195  6731  7293 W LynxServoController: LynxGetServoPulseWidthCommand was abandoned waiting for response
    03-11 10:20:50.297  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=145 ref#=0
    03-11 10:20:50.399  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=145 ref#=0
    03-11 10:20:50.446  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=145 ref#=0
    03-11 10:20:50.448  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorEncoderPositionCommand mod=3 msg#=145
    03-11 10:20:50.448  6731  7293 V RobotCore: nack rec'd mod=3 msg#=145 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:50.449  6731  7293 W LynxMotor: LynxGetMotorEncoderPositionCommand was abandoned waiting for response
    03-11 10:20:50.552  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1007 msg#=146 ref#=0
    03-11 10:20:50.649  6731  6790 V EventLoopManager: synthetic gamepad received: id=-2 user=TWO atRest=true
    03-11 10:20:50.654  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1007 msg#=146 ref#=0
    03-11 10:20:50.669  6731  6790 V EventLoopManager: synthetic gamepad received: id=-2 user=ONE atRest=true
    03-11 10:20:50.701  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1007 msg#=146 ref#=0
    03-11 10:20:50.703  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetADCCommand mod=3 msg#=146
    03-11 10:20:50.703  6731  7293 V RobotCore: nack rec'd mod=3 msg#=146 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:50.704  6731  7293 W LynxVoltageSensor: LynxGetADCCommand was abandoned waiting for response
    03-11 10:20:50.806  6731  7293 V LynxModule: retransmitting: mod=2 cmd=0x1007 msg#=39 ref#=0
    03-11 10:20:50.918  6731  7293 V LynxModule: retransmitting: mod=2 cmd=0x1009 msg#=40 ref#=0
    03-11 10:20:51.023  6731  7293 V LynxModule: retransmitting: mod=2 cmd=0x100f msg#=41 ref#=0
    03-11 10:20:51.128  6731  7293 V LynxModule: retransmitting: mod=2 cmd=0x100a msg#=42 ref#=0
    03-11 10:20:51.233  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1022 msg#=147 ref#=0
    03-11 10:20:51.337  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1022 msg#=147 ref#=0
    03-11 10:20:51.383  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1022 msg#=147 ref#=0
    03-11 10:20:51.385  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetServoPulseWidthCommand mod=3 msg#=147
    03-11 10:20:51.385  6731  7293 V RobotCore: nack rec'd mod=3 msg#=147 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:51.385  6731  7293 W LynxServoController: LynxGetServoPulseWidthCommand was abandoned waiting for response
    03-11 10:20:51.486  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=148 ref#=0
    03-11 10:20:51.590  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=148 ref#=0
    03-11 10:20:51.636  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=148 ref#=0
    03-11 10:20:51.638  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=148
    03-11 10:20:51.638  6731  7293 V RobotCore: nack rec'd mod=3 msg#=148 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:51.638  6731  7293 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:51.740  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1008 msg#=149 ref#=0
    03-11 10:20:51.843  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1008 msg#=149 ref#=0
    03-11 10:20:51.890  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1008 msg#=149 ref#=0
    03-11 10:20:51.891  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for ack: cmd=LynxSetMotorChannelModeCommand mod=3 msg#=149
    03-11 10:20:51.891  6731  7293 V RobotCore: nack rec'd mod=3 msg#=149 ref#=0 reason=ABANDONED_WAITING_FOR_ACK:257
    03-11 10:20:51.892  6731  7293 W LynxMotor: LynxSetMotorChannelModeCommand was abandoned waiting for ack
    03-11 10:20:51.994  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=150 ref#=0
    03-11 10:20:52.096  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=150 ref#=0
    03-11 10:20:52.144  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=150 ref#=0
    03-11 10:20:52.146  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=150
    03-11 10:20:52.146  6731  7293 V RobotCore: nack rec'd mod=3 msg#=150 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:52.147  6731  7293 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:52.249  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1008 msg#=151 ref#=0
    03-11 10:20:52.351  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1008 msg#=151 ref#=0
    03-11 10:20:52.398  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1008 msg#=151 ref#=0
    03-11 10:20:52.400  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for ack: cmd=LynxSetMotorChannelModeCommand mod=3 msg#=151
    03-11 10:20:52.400  6731  7293 V RobotCore: nack rec'd mod=3 msg#=151 ref#=0 reason=ABANDONED_WAITING_FOR_ACK:257
    03-11 10:20:52.401  6731  7293 W LynxMotor: LynxSetMotorChannelModeCommand was abandoned waiting for ack
    03-11 10:20:52.503  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=152 ref#=0
    03-11 10:20:52.605  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=152 ref#=0
    03-11 10:20:52.653  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=152 ref#=0
    03-11 10:20:52.655  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=152
    03-11 10:20:52.655  6731  7293 V RobotCore: nack rec'd mod=3 msg#=152 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:52.656  6731  7293 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:52.758  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=153 ref#=0
    03-11 10:20:52.860  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=153 ref#=0
    03-11 10:20:52.908  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=153 ref#=0
    03-11 10:20:52.910  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=153
    03-11 10:20:52.910  6731  7293 V RobotCore: nack rec'd mod=3 msg#=153 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:52.911  6731  7293 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:53.013  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x100f msg#=154 ref#=0
    03-11 10:20:53.115  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x100f msg#=154 ref#=0
    03-11 10:20:53.163  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x100f msg#=154 ref#=0
    03-11 10:20:53.165  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for ack: cmd=LynxSetMotorConstantPowerCommand mod=3 msg#=154
    03-11 10:20:53.165  6731  7293 V RobotCore: nack rec'd mod=3 msg#=154 ref#=0 reason=ABANDONED_WAITING_FOR_ACK:257
    03-11 10:20:53.165  6731  7293 W LynxMotor: LynxSetMotorConstantPowerCommand was abandoned waiting for ack
    03-11 10:20:53.266  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=155 ref#=0
    03-11 10:20:53.369  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=155 ref#=0
    03-11 10:20:53.416  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=155 ref#=0
    03-11 10:20:53.418  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=155
    03-11 10:20:53.418  6731  7293 V RobotCore: nack rec'd mod=3 msg#=155 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:53.419  6731  7293 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:53.521  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=156 ref#=0
    03-11 10:20:53.623  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=156 ref#=0
    03-11 10:20:53.671  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x1009 msg#=156 ref#=0
    03-11 10:20:53.672  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=3 msg#=156
    03-11 10:20:53.673  6731  7293 V RobotCore: nack rec'd mod=3 msg#=156 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:53.673  6731  7293 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:53.774  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x100f msg#=157 ref#=0
    03-11 10:20:53.876  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x100f msg#=157 ref#=0
    03-11 10:20:53.924  6731  7293 V LynxModule: retransmitting: mod=3 cmd=0x100f msg#=157 ref#=0
    03-11 10:20:53.925  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for ack: cmd=LynxSetMotorConstantPowerCommand mod=3 msg#=157
    03-11 10:20:53.925  6731  7293 V RobotCore: nack rec'd mod=3 msg#=157 ref#=0 reason=ABANDONED_WAITING_FOR_ACK:257
    03-11 10:20:53.926  6731  7293 W LynxMotor: LynxSetMotorConstantPowerCommand was abandoned waiting for ack
    03-11 10:20:53.987  6731  6809 V LynxModule: received status: LynxGetModuleStatusResponse(status=0x02 alerts=0x00: Reset)
    03-11 10:20:54.380  6731  7274 V RobotCore: nack rec'd mod=3 msg#=235 ref#=0 reason=SERVO_NOT_CONFIG_BEFORE_ENABLED:30
    03-11 10:20:54.381  6731  7293 E LynxServoController: exception thrown during lynx communication
    03-11 10:20:54.382  6731  7293 E LynxServoController: com.qualcomm.hardware.lynx.LynxNackException: (DQ16V4CE #3) LynxSetServoEnableCommand: nack received: SERVO_NOT_CONFIG_BEFORE_ENABLED:30
    03-11 10:20:54.396  6731  7293 E LynxServoController:     at java.lang.Thread.run(Thread.java:818)
    03-11 10:20:54.670  6731  7271 E BulkPacketInWorker: DQ16V4CE: bulkTransfer() error: -1
    03-11 10:20:54.677  6731  6731 V FtDeviceManager: ACTION_USB_DEVICE_DETACHED: /dev/bus/usb/001/003
    03-11 10:20:54.677  6731  6731 V FtDevice: vv********************DQ16V4CE closing********************vv 0x019cd445
    03-11 10:20:54.677  6731  6731 V FtDevice: DQ16V4CE stopping thread readBufferManager
    03-11 10:20:54.677  6731  7272 V FtDevice: DQ16V4CE thread readBufferManager is stopped
    03-11 10:20:54.678  6731  6731 V FtDevice: DQ16V4CE stopping thread bulkPacketInWorker
    03-11 10:20:54.678  6731  7271 V FtDevice: DQ16V4CE thread bulkPacketInWorker is stopped
    03-11 10:20:54.678  6731  7274 V LynxUsb : device closed in incoming datagram loop
    03-11 10:20:54.678  6731  6731 V MonitoredUsbDeviceConnection: closing UsbDeviceConnection(DQ16V4CE)
    03-11 10:20:54.678  6731  6731 D UsbDeviceConnectionJNI: close
    03-11 10:20:54.679  6731  6731 V FtDevice: ^^********************DQ16V4CE closed ********************^^
    03-11 10:20:54.679  6731  7273 V ThreadPool: container(0x0be5a93e: WatchdogMonitor) removed id=603 TID=7273 count=1
    03-11 10:20:54.679  6731  7274 V RobotUsbDeviceFtdi: closing DQ16V4CE
    03-11 10:20:54.679  6731  7274 V RobotCore: thread: ...terminating 'lynx incoming datagrams'
    03-11 10:20:54.680  6731  6810 D RobotCore: system telemetry: key=$System$Warning$ msg="REV Robotics USB Expansion Hub Portal [DQ16V4CE] detached"
    03-11 10:20:54.680  6731  6810 V RobotCore: event loop: device has shutdown abnormally: ABNORMAL
    03-11 10:20:54.680  6731  6810 V EventLoopManager: event loop: detaching device DQ16V4CE
    03-11 10:20:54.680  6731  6810 I FtcEventLoop: vv===== MODULE DETACH RECOVERY: disarm REV Robotics USB Expansion Hub Portal [DQ16V4CE]=====vv
    03-11 10:20:54.681  6731  6810 V LynxUsb : disarmDevice() serial=DQ16V4CE...
    03-11 10:20:54.677  7274  7274 W com.qualcomm.ftcrobotcontroller: type=1400 audit(0.0:5080): avc: denied { search } for uid=10133 comm=6C796E7820696E636F6D696E672064 name="usb" dev="tmpfs" ino=8248 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:usb_device:s0 tclass=dir permissive=0
    03-11 10:20:54.681  6731  6810 V LynxUsb : shutting down incoming datagrams
    03-11 10:20:54.681  6731  6810 V ThreadPool: waiting for service Lynx incoming datagram poller
    03-11 10:20:54.682  6731  6810 V ThreadPool: awaitTermination returned, isTerminated=true
    03-11 10:20:54.682  6731  7274 V ThreadPool: container(0x0219ccec: lynx dg poller) removed id=604 TID=7274 count=1
    03-11 10:20:54.682  6731  6810 V ThreadPool: executive service Lynx incoming datagram poller(0x0219ccec) is terminated
    03-11 10:20:54.682  6731  6810 V RobotUsbDeviceFtdi: closing DQ16V4CE
    03-11 10:20:54.682  6731  6810 V LynxUsb : ...done disarmDevice()
    03-11 10:20:54.684  6731  6810 I FtcEventLoop: ======= MODULE DETACH RECOVERY: pretend REV Robotics USB Expansion Hub Portal [DQ16V4CE]=======
    03-11 10:20:54.934  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorEncoderPositionCommand mod=2 msg#=0
    03-11 10:20:54.934  6731  7293 V RobotCore: nack rec'd mod=2 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:54.935  6731  7293 W LynxMotor: LynxGetMotorEncoderPositionCommand was abandoned waiting for response
    03-11 10:20:55.099  6731  6731 V RCActivity: onPause()
    03-11 10:20:55.100  6731  6731 V RCActivity: ACTION_USB_DEVICE_ATTACHED: /dev/bus/usb/001/004
    03-11 10:20:55.100  6731  6731 V FtDeviceManager: openByUsbDevice(vid=0x0403 pid=0x6015)
    03-11 10:20:55.100  6731  6731 V FtDeviceManager: device not found: adding it on the fly
    03-11 10:20:55.100  6731  6731 V FtDeviceManager: addOrUpdateUsbDevice(vid=0x0403 pid=0x6015)
    03-11 10:20:55.106  6731  6731 V ThreadPool: container(0x00aba216: WatchdogMonitor) added id=607 TID=0 count=1
    03-11 10:20:55.114  6731  6731 V FtDevice: initialize(vid=0x0403 pid=0x6015 bcdDevice=0x1000)
    03-11 10:20:55.115  6731  6731 V MonitoredUsbDeviceConnection: closing UsbDeviceConnection(DQ16V4CE)
    03-11 10:20:55.115  6731  6731 D UsbDeviceConnectionJNI: close
    03-11 10:20:55.115  6731  6731 V MonitoredUsbDeviceConnection: closing UsbDeviceConnection(DQ16V4CE)
    03-11 10:20:55.115  6731  6731 D UsbDeviceConnectionJNI: close
    03-11 10:20:55.115  6731  7295 V ThreadPool: container(0x00aba216: WatchdogMonitor) removed id=607 TID=7295 count=1
    03-11 10:20:55.118  6731  6731 V FtDevice: vv********************DQ16V4CE opening********************vv 0x0023e96d
    03-11 10:20:55.119  6731  6731 V FtDevice: ^^********************DQ16V4CE opened ********************^^
    03-11 10:20:55.119  6731  6731 V FtDevice: vv********************DQ16V4CE closing********************vv 0x0023e96d
    03-11 10:20:55.119  6731  6731 V FtDevice: DQ16V4CE stopping thread readBufferManager
    03-11 10:20:55.119  6731  7297 V FtDevice: DQ16V4CE thread readBufferManager is stopped
    03-11 10:20:55.120  6731  6731 V FtDevice: DQ16V4CE stopping thread bulkPacketInWorker
    03-11 10:20:55.121  6731  7296 V FtDevice: DQ16V4CE thread bulkPacketInWorker is stopped
    03-11 10:20:55.121  6731  6731 V MonitoredUsbDeviceConnection: closing UsbDeviceConnection(DQ16V4CE)
    03-11 10:20:55.121  6731  6731 D UsbDeviceConnectionJNI: close
    03-11 10:20:55.121  6731  6731 V FtDevice: ^^********************DQ16V4CE closed ********************^^
    03-11 10:20:55.121  6731  6731 V RCActivity: onResume()
    03-11 10:20:55.122  6731  6731 V FtDeviceManager: ACTION_USB_DEVICE_ATTACHED: /dev/bus/usb/001/004
    03-11 10:20:55.122  6731  6731 V FtDeviceManager: addOrUpdateUsbDevice(vid=0x0403 pid=0x6015)
    03-11 10:20:55.186  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorEncoderPositionCommand mod=3 msg#=0
    03-11 10:20:55.186  6731  7293 V RobotCore: nack rec'd mod=3 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:55.186  6731  7293 W LynxMotor: LynxGetMotorEncoderPositionCommand was abandoned waiting for response
    03-11 10:20:55.186  6731  6810 V LynxUsb : doPretend() serial=DQ16V4CE
    03-11 10:20:55.436  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorEncoderPositionCommand mod=2 msg#=0
    03-11 10:20:55.436  6731  7293 V RobotCore: nack rec'd mod=2 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:55.437  6731  7293 W LynxMotor: LynxGetMotorEncoderPositionCommand was abandoned waiting for response
    03-11 10:20:55.687  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorEncoderPositionCommand mod=3 msg#=0
    03-11 10:20:55.687  6731  7293 V RobotCore: nack rec'd mod=3 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:55.688  6731  7293 W LynxMotor: LynxGetMotorEncoderPositionCommand was abandoned waiting for response
    03-11 10:20:55.688  6731  6810 I FtcEventLoop: ^^===== MODULE DETACH RECOVERY: complete REV Robotics USB Expansion Hub Portal [DQ16V4CE]=====^^
    03-11 10:20:55.688  6731  6810 I FtcEventLoop: vv===== MODULE ATTACH: disarm REV Robotics USB Expansion Hub Portal [DQ16V4CE]=====vv
    03-11 10:20:55.688  6731  6810 V LynxUsb : disarmDevice() serial=DQ16V4CE...
    03-11 10:20:55.689  6731  6810 V LynxUsb : ...done disarmDevice()
    03-11 10:20:55.689  6731  7293 E RobotCore: lynx xmit lock: #### releasing ownerless message keyed lock: ignored: LynxGetMotorChannelModeCommand
    03-11 10:20:55.689  6731  6810 I FtcEventLoop: ======= MODULE ATTACH: arm or pretend REV Robotics USB Expansion Hub Portal [DQ16V4CE]=======
    03-11 10:20:55.689  6731  6810 V LynxUsb : clearing extant global warning: "REV Robotics USB Expansion Hub Portal [DQ16V4CE] detached"
    03-11 10:20:55.691  6731  6810 V FtDeviceManager: createDeviceInfoList(): 1 USB devices
    03-11 10:20:55.696  6731  6810 V FtDevice: vv********************DQ16V4CE opening********************vv 0x0023e96d
    03-11 10:20:55.697  6731  6810 V FtDevice: ^^********************DQ16V4CE opened ********************^^
    03-11 10:20:55.697  6731  6810 V FtDevice: resetting DQ16V4CE
    03-11 10:20:55.697  6731  6810 V ThreadPool: container(0x07b7c9a2: WatchdogMonitor) added id=612 TID=0 count=1
    03-11 10:20:55.702  6731  6810 V LynxUsb : armDevice() serial=DQ16V4CE...
    03-11 10:20:55.702  6731  6810 V ThreadPool: container(0x0a0d3df0: lynx dg poller) added id=613 TID=0 count=1
    03-11 10:20:55.703  6731  6810 V LynxModule: pingAndQueryKnownInterfaces mod=2
    03-11 10:20:55.703  6731  7301 V RobotCore: thread: 'lynx incoming datagrams' starting...
    03-11 10:20:55.705  6731  7301 V LynxUsb : synchronization gained: serial=DQ16V4CE
    03-11 10:20:55.708  6731  6810 V LynxModule: queryInterface(DEKA)=49 commands
    03-11 10:20:55.712  6731  6810 V LynxModule: mod#=2 intf=DEKA: expected 53 commands; found 49
    03-11 10:20:55.715  6731  6810 V LynxModule: sendLEDPatternSteps(): #steps=6
    03-11 10:20:55.717  6731  6790 D RobotCore: system telemetry: key=$System$None$ msg=""
    03-11 10:20:55.721  6731  6810 V LynxModule: pingAndQueryKnownInterfaces mod=3
    03-11 10:20:55.732  6731  6810 V LynxModule: queryInterface(DEKA)=49 commands
    03-11 10:20:55.735  6731  6808 V LynxModule: received status: LynxGetModuleStatusResponse(status=0x02 alerts=0x00: Reset)
    03-11 10:20:55.738  6731  6810 V LynxModule: mod#=3 intf=DEKA: expected 53 commands; found 49
    03-11 10:20:55.741  6731  6810 V LynxModule: sendLEDPatternSteps(): #steps=8
    03-11 10:20:55.750  6731  6810 V LynxUsb : ...done armDevice()
    03-11 10:20:55.773  6731  6809 V LynxModule: received status: LynxGetModuleStatusResponse(status=0x02 alerts=0x00: Reset)
    03-11 10:20:55.940  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorEncoderPositionCommand mod=3 msg#=0
    03-11 10:20:55.940  6731  7293 V RobotCore: nack rec'd mod=3 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:55.941  6731  7293 W LynxMotor: LynxGetMotorEncoderPositionCommand was abandoned waiting for response
    03-11 10:20:55.941  6731  6810 I FtcEventLoop: ^^===== MODULE ATTACH: complete REV Robotics USB Expansion Hub Portal [DQ16V4CE]=====^^
    03-11 10:20:55.986  6731  7301 V RobotCore: nack rec'd mod=3 msg#=58 ref#=0 reason=SERVO_NOT_CONFIG_BEFORE_ENABLED:30
    03-11 10:20:55.987  6731  7293 E LynxServoController: exception thrown during lynx communication
    03-11 10:20:55.987  6731  7293 E LynxServoController: com.qualcomm.hardware.lynx.LynxNackException: (DQ16V4CE #3) LynxSetServoEnableCommand: nack received: SERVO_NOT_CONFIG_BEFORE_ENABLED:30
    03-11 10:20:55.988  6731  7293 E LynxServoController:     at com.qualcomm.hardware.lynx.commands.LynxRespondable.throwIfNack(LynxRespondable.java:324)
    03-11 10:20:55.994  6731  7293 E LynxServoController:     at java.lang.Thread.run(Thread.java:818)
    03-11 10:20:56.477  6731  7298 E BulkPacketInWorker: DQ16V4CE: bulkTransfer() error: -1
    03-11 10:20:56.483  6731  6731 V FtDeviceManager: ACTION_USB_DEVICE_DETACHED: /dev/bus/usb/001/004
    03-11 10:20:56.483  6731  6731 V FtDevice: vv********************DQ16V4CE closing********************vv 0x0023e96d
    03-11 10:20:56.483  6731  6731 V FtDevice: DQ16V4CE stopping thread readBufferManager
    03-11 10:20:56.483  6731  7299 V FtDevice: DQ16V4CE thread readBufferManager is stopped
    03-11 10:20:56.483  6731  6731 V FtDevice: DQ16V4CE stopping thread bulkPacketInWorker
    03-11 10:20:56.484  6731  7298 V FtDevice: DQ16V4CE thread bulkPacketInWorker is stopped
    03-11 10:20:56.484  6731  7301 V LynxUsb : device closed in incoming datagram loop
    03-11 10:20:56.483  7301  7301 W com.qualcomm.ftcrobotcontroller: type=1400 audit(0.0:5081): avc: denied { search } for uid=10133 comm=6C796E7820696E636F6D696E672064 name="usb" dev="tmpfs" ino=8248 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:usb_device:s0 tclass=dir permissive=0
    03-11 10:20:56.484  6731  6731 V MonitoredUsbDeviceConnection: closing UsbDeviceConnection(DQ16V4CE)
    03-11 10:20:56.484  6731  6810 V RobotCore: event loop: device has shutdown abnormally: ABNORMAL
    03-11 10:20:56.484  6731  6731 D UsbDeviceConnectionJNI: close
    03-11 10:20:56.484  6731  6810 V EventLoopManager: event loop: detaching device DQ16V4CE
    03-11 10:20:56.484  6731  6810 I FtcEventLoop: vv===== MODULE DETACH RECOVERY: disarm REV Robotics USB Expansion Hub Portal [DQ16V4CE]=====vv
    03-11 10:20:56.484  6731  6731 V FtDevice: ^^********************DQ16V4CE closed ********************^^
    03-11 10:20:56.485  6731  7300 V ThreadPool: container(0x07b7c9a2: WatchdogMonitor) removed id=612 TID=7300 count=1
    03-11 10:20:56.485  6731  7301 V RobotUsbDeviceFtdi: closing DQ16V4CE
    03-11 10:20:56.485  6731  7301 V RobotCore: thread: ...terminating 'lynx incoming datagrams'
    03-11 10:20:56.486  6731  6810 V LynxUsb : disarmDevice() serial=DQ16V4CE...
    03-11 10:20:56.486  6731  6810 V LynxUsb : shutting down incoming datagrams
    03-11 10:20:56.486  6731  6810 V ThreadPool: waiting for service Lynx incoming datagram poller
    03-11 10:20:56.486  6731  7301 V ThreadPool: container(0x0a0d3df0: lynx dg poller) removed id=613 TID=7301 count=1
    03-11 10:20:56.487  6731  6810 V ThreadPool: awaitTermination returned, isTerminated=true
    03-11 10:20:56.487  6731  6810 V ThreadPool: executive service Lynx incoming datagram poller(0x0a0d3df0) is terminated
    03-11 10:20:56.487  6731  6810 V RobotUsbDeviceFtdi: closing DQ16V4CE
    03-11 10:20:56.487  6731  6810 V LynxUsb : ...done disarmDevice()
    03-11 10:20:56.487  6731  6810 I FtcEventLoop: ======= MODULE DETACH RECOVERY: pretend REV Robotics USB Expansion Hub Portal [DQ16V4CE]=======
    03-11 10:20:56.487  6731  6810 V LynxUsb : doPretend() serial=DQ16V4CE
    03-11 10:20:56.523  6731  6790 D RobotCore: system telemetry: key=$System$Warning$ msg="REV Robotics USB Expansion Hub Portal [DQ16V4CE] detached"
    03-11 10:20:56.738  6731  7293 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=2 msg#=0
    03-11 10:20:56.738  6731  7293 V RobotCore: nack rec'd mod=2 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
    03-11 10:20:56.739  6731  7293 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
    03-11 10:20:56.739  6731  6810 I FtcEventLoop: ^^===== MODULE DETACH RECOVERY: complete REV Robotics USB Expansion Hub Portal [DQ16V4CE]=====^^
    03-11 10:21:01.464  6731  6790 V Robocol : received command: CMD_RESTART_ROBOT(17151)
    03-11 10:21:01.466  6731  6789 D FtcEventLoopHandler: restarting robot...
    03-11 10:21:01.467  6731  6789 V ThreadPool: container(0x0f30b951: default threadpool) added id=614 TID=0 count=1
    03-11 10:21:01.474  6731  6731 V Robocol : EventLoopManager.shutdown()
    03-11 10:21:01.474  6731  6731 V ThreadPool: waiting for service EventLoop
    03-11 10:21:01.475  6731  6810 V RobotCore: EventLoopRunnable interrupted
    03-11 10:21:01.475  6731  6810 V RobotCore: EventLoopManager state is STOPPED
    03-11 10:21:01.475  6731  6810 V RobotCore: Robot Status: stopped
    03-11 10:21:01.475  6731  6810 I FtcEventLoop: ======= TEARDOWN =======
    03-11 10:21:01.475  6731  6810 V ThreadPool: waiting for service user linear op mode
    03-11 10:21:01.476  6731  6810 V LynxMotor: disengage mod#=2
    03-11 10:21:01.476  6731  6810 V LynxMotor: disengage mod#=3
    03-11 10:21:01.476  6731  7293 V RobotCore: thread: ...terminating 'LinearOpMode main'
    03-11 10:21:01.476  6731  7293 V ThreadPool: container(0x0c4ccbd8: LinearOpMode) removed id=606 TID=7293 count=1
    03-11 10:21:01.476  6731  6818 V ThreadPool: container(0x0443e26d: OpModeStuckCodeMonitor) removed id=543 TID=6818 count=1
    03-11 10:21:01.477  6731  6810 V LynxServoController: disengage mod#=3
    03-11 10:21:01.477  6731  6810 V LynxServoController: disengage mod#=2
    03-11 10:21:01.477  6731  6810 V LynxUsb : 0x021bd56f on 0x0dfeae95: releasing delegate to [DQ16V4CE]
    03-11 10:21:01.477  6731  6810 V LynxUsb : 0x0dfeae95: releaseRef [DQ16V4CE]=0
    03-11 10:21:01.477  6731  6810 V LynxUsb : doClose([DQ16V4CE])...
    03-11 10:21:01.477  6731  6810 V LynxModule: close()
    03-11 10:21:01.477  6731  6810 V ThreadPool: waiting for service lynx module executor
    03-11 10:21:01.477  6731  6810 V LynxModule: close()
    03-11 10:21:01.478  6731  6808 V ThreadPool: container(0x0bba598b: lynx module executor) removed id=537 TID=6808 count=1
    03-11 10:21:01.478  6731  6810 V ThreadPool: waiting for service lynx module executor
    03-11 10:21:01.478  6731  6810 V LynxUsb : disarmDevice() serial=DQ16V4CE...
    03-11 10:21:01.478  6731  6809 V ThreadPool: container(0x0d1e6e81: lynx module executor) removed id=538 TID=6809 count=1
    03-11 10:21:01.478  6731  6810 V LynxUsb : ...doClose([DQ16V4CE])
    03-11 10:21:01.478  6731  6810 I FtcEventLoop: ======= TEARDOWN COMPLETE =======
    03-11 10:21:01.478  6731  6810 V RobotCore: thread: ...terminating 'opmode loop()'
    03-11 10:21:01.479  6731  6731 V ThreadPool: awaitTermination returned, isTerminated=true
    03-11 10:21:01.479  6731  6731 V ThreadPool: executive service EventLoop(0x0579bad0) is terminated
    03-11 10:21:01.479  6731  6731 V RobotCore: EventLoopManager state is STOPPED
    03-11 10:21:01.480  6731  6810 V ThreadPool: container(0x0579bad0: executorEventLoop) removed id=539 TID=6810 count=1
    03-11 10:21:01.483  6731  7302 V RobotCore: thread: 'RobotSetupRunnable.run()' starting...
    03-11 10:21:01.483  6731  7302 V FTCService: Processing robot setup
    03-11 10:21:01.483  6731  7302 V RobotCore: Robot Status: stopped, scanning for USB devices
    03-11 10:21:01.504  6731  6795 V Robocol : sending CMD_SHOW_TOAST(8030), attempt: 0
    03-11 10:21:01.504  6731  6795 V Robocol : sending CMD_NOTIFY_ROBOT_STATE(8031), attempt: 0
    03-11 10:21:01.504  6731  6795 V Robocol : sending CMD_NOTIFY_ROBOT_STATE(8033), attempt: 0
    03-11 10:21:01.505  6731  6795 V Robocol : sending CMD_SHOW_TOAST(8034), attempt: 0
    03-11 10:21:01.547  6731  6790 D RobotCore: system telemetry: key=$System$None$ msg=""
    03-11 10:21:01.578  6731  6777 V RenderScript: 0xba0e7d00 Launching thread(s), CPUs 4
    03-11 10:21:06.484  6731  7302 V RobotCore: Robot Status: stopped, waiting for Wifi to enable
    03-11 10:21:06.484  6731  7302 V RobotCore: Robot Status: stopped, waiting for Wifi Direct to enable
    03-11 10:21:06.485  6731  7302 V RobotCore: Robot Status: stopped, waiting for network to become active
    03-11 10:21:06.485  6731  7302 V RobotCore: Robot Status: stopped, starting robot
    03-11 10:21:06.485  6731  7302 V Robocol : EventLoopManager.start()
    03-11 10:21:06.485  6731  7302 V Robocol : Spoofing a Network Connection event...
    03-11 10:21:06.485  6731  7302 V ThreadPool: executive service EventLoop(0x0579bad0) is terminated
    03-11 10:21:06.485  6731  7302 V RobotCore: EventLoopManager state is STOPPED
    03-11 10:21:06.486  6731  7302 V Robocol : eventLoop=FtcEventLoop
    03-11 10:21:06.486  6731  7302 V RobotCore: EventLoopManager state is INIT
    03-11 10:21:06.486  6731  7302 V RobotCore: Robot Status: initializing, starting robot
    03-11 10:21:06.486  6731  7302 I FtcEventLoop: ======= INIT START =======
    03-11 10:21:06.492  6731  7302 V OpmodeRegistration: registered {DefaultOpMode} as {$Stop$Robot$}
    03-11 10:21:06.494  6731  7302 V FileBasedLock: locked /storage/emulated/0/FIRST/blocks/projectslock/lock.dat
    03-11 10:21:06.494  6731  7302 V ThreadPool: container(0x0f30b951: default threadpool) added id=615 TID=0 count=2
    03-11 10:21:06.495  6731  7302 V FileBasedLock: unlocking /storage/emulated/0/FIRST/blocks/projectslock/lock.dat
    03-11 10:21:06.500  6731  7302 V OpmodeRegistration: registered {SensorTest} as {Sensor Test}
    03-11 10:21:06.501  6731  7302 V OpmodeRegistration: registered {RelicRecoveryAutoTileRunnerBlue3} as {Auto BLUE #1 More Glyphs}
    03-11 10:21:06.502  6731  7302 V OpmodeRegistration: registered {RelicRecoveryAutoTileRunnerRed3} as {Auto RED #1 More Glyphs}
    03-11 10:21:06.502  6731  7302 V OpmodeRegistration: registered {RelicRecoveryAutoTileRunnerRed1} as {Auto RED #1}
    03-11 10:21:06.503  6731  6795 V Robocol : sending CMD_NOTIFY_ROBOT_STATE(8086), attempt: 0
    03-11 10:21:06.503  6731  7302 V OpmodeRegistration: registered {RelicRecoveryAutoTileRunnerBlue2} as {Auto BLUE #2}
    03-11 10:21:06.503  6731  6795 V Robocol : sending CMD_NOTIFY_ROBOT_STATE(8087), attempt: 0
    03-11 10:21:06.504  6731  7302 V OpmodeRegistration: registered {RelicRecoveryAutoTileRunnerBlue1} as {Auto BLUE #1}
    03-11 10:21:06.505  6731  7302 V OpmodeRegistration: registered {RelicRecoveryAutoTileRunnerRed2} as {Auto RED #2}
    03-11 10:21:06.505  6731  7302 V OpmodeRegistration: registered {RelicRecoveryAutoTileRunnerBlue4} as {Auto BLUE #1 Dump Glyphs}
    03-11 10:21:06.506  6731  7302 V OpmodeRegistration: registered {RelicRecoveryTileRunnerTeleOpsLinear} as {Tile Runner (New) TeleOps}
    03-11 10:21:06.506  6731  7302 V OpmodeRegistration: registered {RelicRecoveryAutoTileRunnerRed4} as {Auto RED #1 Dump Glyphs}
    03-11 10:21:06.508  6731  6731 D WifiDirect: cannot create group, does group already exist?
    03-11 10:21:06.539  6731  7302 V HardwareFactory: createHardwareMap()
    03-11 10:21:06.539  6731  7302 V WifiDirectInviteMonitor: clearUILynxModule()
    03-11 10:21:06.539  6731  7302 V ReadXMLFileHandler: handleLynxModule() mod#=2...
    03-11 10:21:06.539  6731  7302 V ConfigurationUtility: buildEmptyLynxModule() mod#=2...
    03-11 10:21:06.540  6731  7302 V ConfigurationUtility: ...buildEmptyLynxModule() mod#=2
    03-11 10:21:06.540  6731  7302 V ReadXMLFileHandler: ...handleLynxModule() mod#=2
    03-11 10:21:06.540  6731  7302 V ReadXMLFileHandler: handleLynxModule() mod#=3...
    03-11 10:21:06.540  6731  7302 V ConfigurationUtility: buildEmptyLynxModule() mod#=3...
    03-11 10:21:06.540  6731  7302 V ConfigurationUtility: ...buildEmptyLynxModule() mod#=3
    03-11 10:21:06.541  6731  7302 V ReadXMLFileHandler: ...handleLynxModule() mod#=3
    03-11 10:21:06.541  6731  7302 V RobotCore: Creating REV Robotics USB Expansion Hub Portal [DQ16V4CE]
    03-11 10:21:06.541  6731  7302 V LynxUsb : creating new [DQ16V4CE]: 0x08a29fb4
    03-11 10:21:06.542  6731  7302 V FtDeviceManager: createDeviceInfoList(): 0 USB devices
    03-11 10:21:06.542  6731  7302 W System.err: unable to find lynx USB device with serial number DQ16V4CE
    03-11 10:21:06.542  6731  7302 E LynxUsb : exception RobotCoreException(unable to find lynx USB device with serial number DQ16V4CE): exception arming DQ16V4CE [com.qualcomm.hardware.lynx.LynxUsbUtil.logMessageAndThrow(LynxUsbUtil.java:108)]
    03-11 10:21:06.543  6731  7302 V LynxUsb : doPretend() serial=DQ16V4CE
    03-11 10:21:06.543  6731  7302 V LynxUsb : 0x031f07dd on 0x08a29fb4: new delegate to [DQ16V4CE]
    03-11 10:21:06.543  6731  7302 V RobotCore: Creating Lynx Module - mod=2 parent=true
    03-11 10:21:06.543  6731  7302 V RobotCore: Creating Lynx Module - mod=3 parent=false
    03-11 10:21:06.543  6731  6795 V Robocol : sending CMD_NOTIFY_ACTIVE_CONFIGURATION(8088), attempt: 0
    03-11 10:21:06.543  6731  7302 V LynxUsb : addConfiguredModule() module#=2
    03-11 10:21:06.543  6731  7302 V LynxModule: pingAndQueryKnownInterfaces mod=2
    03-11 10:21:06.543  6731  7302 V LynxModule: queryInterface(DEKA)=0 commands
    03-11 10:21:06.543  6731  6795 V Robocol : sending CMD_NOTIFY_USER_DEVICE_LIST(8090), attempt: 0
    03-11 10:21:06.543  6731  7302 V LynxModule: mod#=2 intf=DEKA: expected 53 commands; found 0
    03-11 10:21:06.544  6731  7302 V LynxModule: sendLEDPatternSteps(): #steps=6
    03-11 10:21:06.544  6731  7302 V LynxUsb : addConfiguredModule() module#=3
    03-11 10:21:06.544  6731  7302 V LynxModule: pingAndQueryKnownInterfaces mod=3
    03-11 10:21:06.544  6731  7302 V LynxModule: queryInterface(DEKA)=0 commands
    03-11 10:21:06.544  6731  7302 V LynxModule: mod#=3 intf=DEKA: expected 53 commands; found 0
    03-11 10:21:06.544  6731  6795 V Robocol : sending CMD_NOTIFY_OP_MODE_LIST(8091), attempt: 0
    03-11 10:21:06.544  6731  7302 V LynxModule: sendLEDPatternSteps(): #steps=8
    03-11 10:21:06.545  6731  7302 V LynxMotor: initializeHardware() mod#=2
    03-11 10:21:06.545  6731  7302 V RobotCore: DcMotorImpl(type=RevRoboticsHDHexMotor)
    03-11 10:21:06.546  6731  7302 V RobotCore: DcMotorImpl(type=RevRoboticsHDHexMotor)
    03-11 10:21:06.546  6731  7302 V RobotCore: DcMotorImpl(type=RevRoboticsCoreHexMotor)
    03-11 10:21:06.546  6731  7302 V RobotCore: DcMotorImpl(type=NeveRest20Gearmotor)
    03-11 10:21:06.546  6731  7302 V LynxServoController: initializeHardware() mod#=2
    03-11 10:21:06.546  6731  7302 V LynxVoltageSensor: initializeHardware() mod#=2
    03-11 10:21:06.547  6731  7302 V LynxAnalogInputController: initializeHardware() mod#=2
    03-11 10:21:06.547  6731  7302 V LynxDigitalChannelController: initializeHardware() mod#=2
    03-11 10:21:06.547  6731  6790 D RobotCore: system telemetry: key=$System$Warning$ msg="unable to open REV Robotics USB Expansion Hub Portal [DQ16V4CE]"
    03-11 10:21:06.547  6731  7302 V RobotCore: Creating Lynx Color/Range Sensor - mod=2 bus=1
    03-11 10:21:06.547  6731  7302 I RobotCore: LynxFirmwareVersionManager: LynxI2cDeviceSynchV1
    03-11 10:21:06.547  6731  7302 V LynxI2cDeviceSynch: initializeHardware() mod#=2
    03-11 10:21:06.547  6731  7302 V LynxI2cDeviceSynch: engaging mod#=2
    03-11 10:21:06.547  6731  7302 V RobotCore: Creating user sensor MR Range Sensor - on Lynx module=2 bus=3
    03-11 10:21:06.548  6731  7302 V RobotCore: Creating I2cDeviceSynch (Lynx) - mod=2 bus=3
    03-11 10:21:06.548  6731  7302 I RobotCore: LynxFirmwareVersionManager: LynxI2cDeviceSynchV1
    03-11 10:21:06.548  6731  7302 V LynxI2cDeviceSynch: initializeHardware() mod#=2
    03-11 10:21:06.548  6731  7302 V RobotCore: Creating user sensor Adafruit IMU - on Lynx module=2 bus=0
    03-11 10:21:06.548  6731  7302 V RobotCore: Creating I2cDeviceSynch (Lynx) - mod=2 bus=0
    03-11 10:21:06.548  6731  7302 I RobotCore: LynxFirmwareVersionManager: LynxI2cDeviceSynchV1
    03-11 10:21:06.548  6731  7302 V LynxI2cDeviceSynch: initializeHardware() mod#=2
    03-11 10:21:06.548  6731  7302 V LynxMotor: initializeHardware() mod#=3
    03-11 10:21:06.550  6731  7302 V RobotCore: DcMotorImpl(type=RevRoboticsHDHexMotor)
    03-11 10:21:06.550  6731  7302 V RobotCore: DcMotorImpl(type=RevRoboticsHDHexMotor)
    03-11 10:21:06.550  6731  7302 V RobotCore: DcMotorImpl(type=RevRoboticsCoreHexMotor)
    03-11 10:21:06.550  6731  7302 V RobotCore: DcMotorImpl(type=NeveRest40Gearmotor)
    03-11 10:21:06.550  6731  7302 V LynxServoController: initializeHardware() mod#=3
    03-11 10:21:06.551  6731  7302 V LynxVoltageSensor: initializeHardware() mod#=3
    03-11 10:21:06.552  6731  7302 V LynxAnalogInputController: initializeHardware() mod#=3
    03-11 10:21:06.552  6731  7302 V LynxDigitalChannelController: initializeHardware() mod#=3
    03-11 10:21:06.552  6731  7302 V RobotCore: Creating user sensor MR Range Sensor - on Lynx module=3 bus=1
    03-11 10:21:06.552  6731  7302 V RobotCore: Creating I2cDeviceSynch (Lynx) - mod=3 bus=1
    03-11 10:21:06.552  6731  7302 I RobotCore: LynxFirmwareVersionManager: LynxI2cDeviceSynchV1
    03-11 10:21:06.552  6731  7302 V LynxI2cDeviceSynch: initializeHardware() mod#=3
    03-11 10:21:06.553  6731  7302 I RobotCore: ========= Device Information ===================================================

  • #2
    Robots bumping into things, hitting obstacles, or getting off the balance stone can cause a disconnect. Even a tiny fraction of a disconnect with any of the electronics can cause it. I've been an FTA for last 2 years, and have seen it many times. Restarting the robots solves 80% of the disconnect problems I've seen (if not more). The wiring needs to be solidly connected, with zip ties or etc. Many times, robots crashing into a wall or each other have caused some great robots to disconnect.

    Replacing some bad or old USB wires is also needed occasionally. Also, those joysticks sometimes will die after a lot of use, good to have a back-up on hand if they're getting old. The robot's overall wiring can make a big difference in connection reliability.

    Comment


    • #3
      And just a note, I have a robot dedicated to demoes/outreach that we've taken to MakerFaire and another event to let kids play with on the balance stone for many hours at a time. I was surprised how well the robot handled. The battery level affects autonomous more than TeleOp, so it ran and ran. The kids had it going up and down on the balance stone, hitting blocks around, etc, it did not disconnect. The wiring on that robot is all tied down and secured, so are the rest of the electronics and phone. Any problems we ever had with the robots disconnecting were fixed when we got new USB wires from Walmart (and updated the apps).

      Comment

      Working...
      X