Expansion Hubs unresponsive after ESD event until opmode is stopped #702

Windwoes · 2019-03-07T16:23:33Z

I'm doing some ESD testing with our robot and just ran into an extremely strange issue. After driving around the field and zapping the lander, the Expansion Hubs became unresponsive to the gamepads and the robot began stalling out against the playing field wall. However, no comms errors showed up in the log, and upon pressing the stop button, the robot immediately stopped. What the heck?

Here's the log in case there's anything of interest that I missed, but I don't see anything:

03-07 11:03:24.433  2008  2565 V Robocol : received command: CMD_RUN_OP_MODE(10420) A - Practice TeleOp
03-07 11:03:24.446  2008  2602 V Robocol : sending CMD_NOTIFY_RUN_OP_MODE(570), attempt: 0
03-07 11:03:24.577  2008  2572 V RobotCore: nack rec'd mod=3 msg#=193 ref#=0 reason=MOTOR_NOT_CONFIG_BEFORE_ENABLED:50
03-07 11:03:24.579  2008  2657 E LynxMotor: exception thrown during lynx communication
03-07 11:03:24.581  2008  2657 E LynxMotor: com.qualcomm.hardware.lynx.LynxNackException: (DQ2ASZXG #3) LynxSetMotorChannelEnableCommand: nack received: MOTOR_NOT_CONFIG_BEFORE_ENABLED:50
03-07 11:03:24.588  2008  2657 E LynxMotor: 	at com.qualcomm.hardware.lynx.commands.LynxRespondable.throwIfNack(LynxRespondable.java:325)
03-07 11:03:24.589  2008  2657 E LynxMotor: 	at com.qualcomm.hardware.lynx.commands.LynxRespondable.send(LynxRespondable.java:239)
03-07 11:03:24.591  2008  2657 E LynxMotor: 	at com.qualcomm.hardware.lynx.LynxDcMotorController.internalSetMotorEnable(LynxDcMotorController.java:221)
03-07 11:03:24.592  2008  2657 E LynxMotor: 	at com.qualcomm.hardware.lynx.LynxDcMotorController.internalSetMotorPower(LynxDcMotorController.java:543)
03-07 11:03:24.595  2008  2657 E LynxMotor: 	at com.qualcomm.hardware.lynx.LynxDcMotorController.setMotorMode(LynxDcMotorController.java:373)
03-07 11:03:24.596  2008  2657 E LynxMotor: 	at com.qualcomm.robotcore.hardware.DcMotorImpl.internalSetMode(DcMotorImpl.java:322)
03-07 11:03:24.597  2008  2657 E LynxMotor: 	at com.qualcomm.robotcore.hardware.DcMotorImpl.setMode(DcMotorImpl.java:318)
03-07 11:03:24.598  2008  2657 E LynxMotor: 	at net.frogbots.roverruckus.hardware.components.DebrisAssembly.init(DebrisAssembly.java:35)
03-07 11:03:24.599  2008  2657 E LynxMotor: 	at net.frogbots.roverruckus.hardware.Robot.init(Robot.java:39)
03-07 11:03:24.601  2008  2657 E LynxMotor: 	at net.frogbots.roverruckus.meta.opmode.FrogOpModeImpl.runOpMode(FrogOpModeImpl.java:68)
03-07 11:03:24.601  2008  2657 E LynxMotor: 	at com.qualcomm.robotcore.eventloop.opmode.LinearOpMode$LinearOpModeHelper$1.run(LinearOpMode.java:305)
03-07 11:03:24.602  2008  2657 E LynxMotor: 	at com.qualcomm.robotcore.util.ThreadPool.logThreadLifeCycle(ThreadPool.java:737)
03-07 11:03:24.602  2008  2657 E LynxMotor: 	at com.qualcomm.robotcore.eventloop.opmode.LinearOpMode$LinearOpModeHelper.run(LinearOpMode.java:300)
03-07 11:03:24.603  2008  2657 E LynxMotor: 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
03-07 11:03:24.603  2008  2657 E LynxMotor: 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
03-07 11:03:24.604  2008  2657 E LynxMotor: 	at com.qualcomm.robotcore.util.ThreadPool$ThreadFactoryImpl$1.run(ThreadPool.java:793)
03-07 11:03:24.604  2008  2657 E LynxMotor: 	at java.lang.Thread.run(Thread.java:761)
03-07 11:03:24.753  2008  2657 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:03:24.754  2008  2657 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:03:24.754  2008  2657 E LynxI2cDeviceSynch: placeholder: readStatusQuery
03-07 11:03:24.821  2008  2657 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:03:24.821  2008  2657 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:03:24.888  2008  2657 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:03:24.888  2008  2657 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:03:24.955  2008  2657 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:03:24.955  2008  2657 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:03:25.022  2008  2657 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:03:25.023  2008  2657 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:03:25.091  2008  2657 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:03:25.092  2008  2657 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:03:25.160  2008  2657 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:03:25.160  2008  2657 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:03:25.228  2008  2657 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:03:25.228  2008  2657 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:04:00.916  2008  2565 V Robocol : received command: CMD_INIT_OP_MODE(11619) $Stop$Robot$

Also, in a previous test, the gamepad disconnected from the driver station at the exact moment of the ESD event on the robot. Coincidence? Somehow I think not. Unfortunately I do not have the logs for that encounter because they were overwritten by the log from another test.

Both Expansion Hubs are running firmware 1.8.2

The text was updated successfully, but these errors were encountered:

NoahAndrews · 2019-03-07T16:36:21Z

I literally was just looking at possibly this very thing. Are you using run to position mode?

Windwoes · 2019-03-07T16:37:19Z

I was able to catch the gamepad disconnecting from the driver station during the ESD event in the act in a log!

Notice this line in the log:

03-07 11:33:09.723  3469  3576 V EventLoopManager: synthetic gamepad received: id=-2 user=ONE atRest=true

Here's the full log:

03-07 11:31:16.205  3469  3576 V Robocol : received command: CMD_INIT_OP_MODE(10803) A - Practice TeleOp
03-07 11:31:16.234  3469  3575 I RobotCore: ******************** START - OPMODE A - Practice TeleOp ********************
03-07 11:31:16.235  3469  3595 I RobotCore: Attempting to switch to op mode A - Practice TeleOp
03-07 11:31:16.314  3469  3595 W LynxPwmOutputController: LynxSetPWMEnableCommand not implemented by lynx hw; ignoring
03-07 11:31:16.318  3469  3595 W LynxPwmOutputController: LynxSetPWMConfigurationCommand not implemented by lynx hw; ignoring
03-07 11:31:16.321  3469  3595 W LynxPwmOutputController: LynxSetPWMEnableCommand not implemented by lynx hw; ignoring
03-07 11:31:16.324  3469  3595 W LynxPwmOutputController: LynxSetPWMConfigurationCommand not implemented by lynx hw; ignoring
03-07 11:31:16.328  3469  3595 W LynxPwmOutputController: LynxSetPWMEnableCommand not implemented by lynx hw; ignoring
03-07 11:31:16.331  3469  3595 W LynxPwmOutputController: LynxSetPWMConfigurationCommand not implemented by lynx hw; ignoring
03-07 11:31:16.334  3469  3595 W LynxPwmOutputController: LynxSetPWMEnableCommand not implemented by lynx hw; ignoring
03-07 11:31:16.338  3469  3595 W LynxPwmOutputController: LynxSetPWMConfigurationCommand not implemented by lynx hw; ignoring
03-07 11:31:16.544  3469  3595 D STMicroVL53L0X: : Checking to see if it's really a VL53L0X sensor...
03-07 11:31:16.554  3469  3595 D STMicroVL53L0X: : Reg 0xC0 = ee (should be 0xEE)
03-07 11:31:16.562  3469  3595 D STMicroVL53L0X: : Reg 0xC1 = aa (should be 0xAA)
03-07 11:31:16.571  3469  3595 D STMicroVL53L0X: : Reg 0xC2 = 10 (should be 0x10)
03-07 11:31:16.580  3469  3595 D STMicroVL53L0X: : Reg 0x51 = 0 (should be 0x0099)
03-07 11:31:16.590  3469  3595 D STMicroVL53L0X: : Reg 0x61 = 0 (should be 0x0000)
03-07 11:31:16.670  3469  3595 D STMicroVL53L0X: : initial sig rate lim (MCPS) 0.000000
03-07 11:31:16.685  3469  3595 D STMicroVL53L0X: : adjusted sig rate lim (MCPS) 0.250000
03-07 11:31:17.369  3469  3595 W LynxPwmOutputController: LynxSetPWMEnableCommand not implemented by lynx hw; ignoring
03-07 11:31:17.379  3469  3595 W LynxPwmOutputController: LynxSetPWMConfigurationCommand not implemented by lynx hw; ignoring
03-07 11:31:17.383  3469  3595 W LynxPwmOutputController: LynxSetPWMEnableCommand not implemented by lynx hw; ignoring
03-07 11:31:17.387  3469  3595 W LynxPwmOutputController: LynxSetPWMConfigurationCommand not implemented by lynx hw; ignoring
03-07 11:31:17.392  3469  3595 W LynxPwmOutputController: LynxSetPWMEnableCommand not implemented by lynx hw; ignoring
03-07 11:31:17.398  3469  3595 W LynxPwmOutputController: LynxSetPWMConfigurationCommand not implemented by lynx hw; ignoring
03-07 11:31:17.402  3469  3595 W LynxPwmOutputController: LynxSetPWMEnableCommand not implemented by lynx hw; ignoring
03-07 11:31:17.407  3469  3595 W LynxPwmOutputController: LynxSetPWMConfigurationCommand not implemented by lynx hw; ignoring
03-07 11:31:17.428  3469  3739 V RobotCore: thread: 'LinearOpMode main' starting...
03-07 11:31:17.430  3469  3629 V Robocol : sending CMD_NOTIFY_INIT_OP_MODE(949), attempt: 0
03-07 11:31:19.682  3469  3576 V Robocol : received command: CMD_RUN_OP_MODE(10887) A - Practice TeleOp
03-07 11:31:19.710  3469  3629 V Robocol : sending CMD_NOTIFY_RUN_OP_MODE(1020), attempt: 0
03-07 11:31:19.806  3469  3588 V RobotCore: nack rec'd mod=3 msg#=102 ref#=0 reason=MOTOR_NOT_CONFIG_BEFORE_ENABLED:50
03-07 11:31:19.806  3469  3739 E LynxMotor: exception thrown during lynx communication
03-07 11:31:19.808  3469  3739 E LynxMotor: com.qualcomm.hardware.lynx.LynxNackException: (DQ2ASZXG #3) LynxSetMotorChannelEnableCommand: nack received: MOTOR_NOT_CONFIG_BEFORE_ENABLED:50
03-07 11:31:19.810  3469  3739 E LynxMotor: 	at com.qualcomm.hardware.lynx.commands.LynxRespondable.throwIfNack(LynxRespondable.java:325)
03-07 11:31:19.810  3469  3739 E LynxMotor: 	at com.qualcomm.hardware.lynx.commands.LynxRespondable.send(LynxRespondable.java:239)
03-07 11:31:19.812  3469  3739 E LynxMotor: 	at com.qualcomm.hardware.lynx.LynxDcMotorController.internalSetMotorEnable(LynxDcMotorController.java:221)
03-07 11:31:19.813  3469  3739 E LynxMotor: 	at com.qualcomm.hardware.lynx.LynxDcMotorController.internalSetMotorPower(LynxDcMotorController.java:543)
03-07 11:31:19.814  3469  3739 E LynxMotor: 	at com.qualcomm.hardware.lynx.LynxDcMotorController.setMotorMode(LynxDcMotorController.java:373)
03-07 11:31:19.816  3469  3739 E LynxMotor: 	at com.qualcomm.robotcore.hardware.DcMotorImpl.internalSetMode(DcMotorImpl.java:322)
03-07 11:31:19.817  3469  3739 E LynxMotor: 	at com.qualcomm.robotcore.hardware.DcMotorImpl.setMode(DcMotorImpl.java:318)
03-07 11:31:19.818  3469  3739 E LynxMotor: 	at net.frogbots.roverruckus.hardware.components.DebrisAssembly.init(DebrisAssembly.java:35)
03-07 11:31:19.818  3469  3739 E LynxMotor: 	at net.frogbots.roverruckus.hardware.Robot.init(Robot.java:39)
03-07 11:31:19.818  3469  3739 E LynxMotor: 	at net.frogbots.roverruckus.meta.opmode.FrogOpModeImpl.runOpMode(FrogOpModeImpl.java:68)
03-07 11:31:19.819  3469  3739 E LynxMotor: 	at com.qualcomm.robotcore.eventloop.opmode.LinearOpMode$LinearOpModeHelper$1.run(LinearOpMode.java:305)
03-07 11:31:19.819  3469  3739 E LynxMotor: 	at com.qualcomm.robotcore.util.ThreadPool.logThreadLifeCycle(ThreadPool.java:737)
03-07 11:31:19.819  3469  3739 E LynxMotor: 	at com.qualcomm.robotcore.eventloop.opmode.LinearOpMode$LinearOpModeHelper.run(LinearOpMode.java:300)
03-07 11:31:19.820  3469  3739 E LynxMotor: 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
03-07 11:31:19.820  3469  3739 E LynxMotor: 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
03-07 11:31:19.821  3469  3739 E LynxMotor: 	at com.qualcomm.robotcore.util.ThreadPool$ThreadFactoryImpl$1.run(ThreadPool.java:793)
03-07 11:31:19.821  3469  3739 E LynxMotor: 	at java.lang.Thread.run(Thread.java:761)
03-07 11:31:19.955  3469  3739 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:31:19.955  3469  3739 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:31:19.955  3469  3739 E LynxI2cDeviceSynch: placeholder: readStatusQuery
03-07 11:31:20.022  3469  3739 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:31:20.023  3469  3739 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:31:20.090  3469  3739 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:31:20.090  3469  3739 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:31:20.159  3469  3739 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:31:20.159  3469  3739 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:31:20.226  3469  3739 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:31:20.226  3469  3739 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:31:20.292  3469  3739 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:31:20.292  3469  3739 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:31:20.359  3469  3739 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:31:20.359  3469  3739 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:31:20.430  3469  3739 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:31:20.430  3469  3739 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:31:21.148  3469  3739 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:31:21.149  3469  3739 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:31:21.149  3469  3739 E LynxI2cDeviceSynch: placeholder: readStatusQuery
03-07 11:31:21.227  3469  3739 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:31:21.228  3469  3739 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:31:21.307  3469  3739 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:31:21.307  3469  3739 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:31:21.386  3469  3739 V RobotCore: addr=false data=true arb=false clock=false
03-07 11:31:21.386  3469  3739 E LynxI2cDeviceSynch: readStatusQuery: cbExpected=1 cbRead=0
03-07 11:31:49.720  3469  3585 E BulkPacketInWorker: DQ2ASZXG: bulkTransfer() error: -1
03-07 11:31:49.823  3469  3739 V LynxModule: retransmitting: mod=3 cmd=0x1016 msg#=249 ref#=0 
03-07 11:31:49.890  3469  3469 V FtDeviceManager: ACTION_USB_DEVICE_DETACHED: /dev/bus/usb/001/004
03-07 11:31:49.890  3469  3509 D CameraManager: ---------------------------------------------- ACTION_USB_DEVICE_DETACHED
03-07 11:31:49.890  3469  3469 V FtDevice: vv********************DQ2ASZXG closing********************vv 0x052e3605
03-07 11:31:49.891  3469  3469 V FtDevice: DQ2ASZXG stopping thread readBufferManager
03-07 11:31:49.891  3469  3586 V FtDevice: DQ2ASZXG thread readBufferManager is stopped
03-07 11:31:49.892  3469  3469 V FtDevice: DQ2ASZXG stopping thread bulkPacketInWorker
03-07 11:31:49.896  3469  3585 V FtDevice: DQ2ASZXG thread bulkPacketInWorker is stopped
03-07 11:31:49.888  3588  3588 W com.qualcomm.ftcrobotcontroller: type=1400 audit(0.0:38): avc: denied { search } for comm=6C796E7820696E636F6D696E672064 name="usb" dev="tmpfs" ino=21676 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:usb_device:s0 tclass=dir permissive=0
03-07 11:31:49.896  3469  3588 V LynxUsb : device closed in incoming datagram loop
03-07 11:31:49.896  3469  3588 V RobotUsbDeviceFtdi: closing DQ2ASZXG
03-07 11:31:49.897  3469  3469 V MonitoredUsbDeviceConnection: closing UsbDeviceConnection(DQ2ASZXG)
03-07 11:31:49.897  3469  3469 D UsbDeviceConnectionJNI: close
03-07 11:31:49.897  3469  3469 V FtDevice: ^^********************DQ2ASZXG closed ********************^^
03-07 11:31:49.897  3469  3588 V RobotCore: thread: ...terminating 'lynx incoming datagrams'
03-07 11:31:49.905  3469  3595 D RobotCore: system telemetry: key=$System$Warning$ msg="REV Robotics USB Expansion Hub Portal [DQ2ASZXG] detached"
03-07 11:31:49.908  3469  3595 V RobotCore: event loop: device has shutdown abnormally: ABNORMAL
03-07 11:31:49.909  3469  3595 V EventLoopManager: event loop: detaching device DQ2ASZXG
03-07 11:31:49.909  3469  3595 I FtcEventLoop: vv===== MODULE DETACH RECOVERY: disarm REV Robotics USB Expansion Hub Portal [DQ2ASZXG]=====vv
03-07 11:31:49.910  3469  3595 V LynxUsb : disarmDevice() serial=DQ2ASZXG...
03-07 11:31:49.911  3469  3595 V LynxUsb : shutting down incoming datagrams
03-07 11:31:49.912  3469  3595 V RobotUsbDeviceFtdi: closing DQ2ASZXG
03-07 11:31:49.912  3469  3595 V LynxUsb : ...done disarmDevice()
03-07 11:31:49.915  3469  3595 I FtcEventLoop: ======= MODULE DETACH RECOVERY: pretend REV Robotics USB Expansion Hub Portal [DQ2ASZXG]=======
03-07 11:31:49.916  3469  3595 V LynxUsb : doPretend() serial=DQ2ASZXG
03-07 11:31:49.975  3469  3593 V SoundInfo: construct(0x030b6fc7)
03-07 11:31:50.045  3469  3509 D SoundPlayer: onLoadComplete(samp=3|ms=1044, samp=3)=0
03-07 11:31:50.046  3469  3593 W AudioTrack: AUDIO_OUTPUT_FLAG_FAST denied by client; transfer 4, track 44100 Hz, output 48000 Hz
03-07 11:31:50.049  3469  3593 D SoundPlayer: playing volume=1.000000 samp=3|ms=1044
03-07 11:31:50.070  3469  3629 V Robocol : sending CMD_PLAY_SOUND(2009), attempt: 0
03-07 11:31:50.166  3469  3739 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=2 msg#=0
03-07 11:31:50.167  3469  3739 V RobotCore: nack rec'd mod=2 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
03-07 11:31:50.167  3469  3739 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
03-07 11:31:50.168  3469  3595 W art     : Long monitor contention with owner LinearOpMode main (3739) at com.qualcomm.robotcore.hardware.DcMotor$RunMode com.qualcomm.hardware.lynx.LynxDcMotorController.getMotorMode(int)(LynxDcMotorController.java:-1) waiters=0 in void com.qualcomm.hardware.lynx.LynxController.onModuleStateChange(com.qualcomm.robotcore.hardware.usb.RobotArmingStateNotifier, com.qualcomm.robotcore.hardware.usb.RobotArmingStateNotifier$ARMINGSTATE) for 251ms
03-07 11:31:50.185  3469  3509 D CameraManager: ---------------------------------------------- ACTION_USB_DEVICE_ATTACHED
03-07 11:31:50.185  3469  3469 V FtDeviceManager: ACTION_USB_DEVICE_ATTACHED: /dev/bus/usb/001/005
03-07 11:31:50.185  3469  3469 V FtDeviceManager: addOrUpdateUsbDevice(vid=0x0403 pid=0x6015)
03-07 11:31:50.195  3469  3469 V FtDevice: initialize(vid=0x0403 pid=0x6015 bcdDevice=0x1000)
03-07 11:31:50.195  3469  3469 V MonitoredUsbDeviceConnection: closing UsbDeviceConnection(DQ2ASZXG)
03-07 11:31:50.195  3469  3469 D UsbDeviceConnectionJNI: close
03-07 11:31:50.195  3469  3469 V MonitoredUsbDeviceConnection: closing UsbDeviceConnection(DQ2ASZXG)
03-07 11:31:50.195  3469  3469 D UsbDeviceConnectionJNI: close
03-07 11:31:50.196  3469  3469 V RCActivity: onPause()
03-07 11:31:50.196  3469  3469 V RCActivity: ACTION_USB_DEVICE_ATTACHED: /dev/bus/usb/001/005
03-07 11:31:50.197  3469  3469 V RCActivity: onResume()
03-07 11:31:50.418  3469  3739 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=2 msg#=0
03-07 11:31:50.419  3469  3739 V RobotCore: nack rec'd mod=2 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
03-07 11:31:50.421  3469  3739 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
03-07 11:31:50.671  3469  3739 V RobotCore: timeout: abandoning waiting 250ms for ack: cmd=LynxSetMotorConstantPowerCommand mod=2 msg#=0
03-07 11:31:50.671  3469  3739 V RobotCore: nack rec'd mod=2 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_ACK:257
03-07 11:31:50.672  3469  3739 W LynxMotor: LynxSetMotorConstantPowerCommand was abandoned waiting for ack
03-07 11:31:50.672  3469  3595 W art     : Long monitor contention with owner LinearOpMode main (3739) at void com.qualcomm.hardware.lynx.LynxDcMotorController.setMotorPower(int, double)(LynxDcMotorController.java:-1) waiters=0 in void com.qualcomm.hardware.lynx.LynxController.onModuleStateChange(com.qualcomm.robotcore.hardware.usb.RobotArmingStateNotifier, com.qualcomm.robotcore.hardware.usb.RobotArmingStateNotifier$ARMINGSTATE) for 505ms
03-07 11:31:50.673  3469  3595 I FtcEventLoop: ^^===== MODULE DETACH RECOVERY: complete REV Robotics USB Expansion Hub Portal [DQ2ASZXG]=====^^
03-07 11:31:50.673  3469  3595 I FtcEventLoop: vv===== MODULE ATTACH: disarm REV Robotics USB Expansion Hub Portal [DQ2ASZXG]=====vv
03-07 11:31:50.674  3469  3595 V LynxUsb : disarmDevice() serial=DQ2ASZXG...
03-07 11:31:50.674  3469  3595 V LynxUsb : ...done disarmDevice()
03-07 11:31:50.675  3469  3595 I FtcEventLoop: ======= MODULE ATTACH: arm or pretend REV Robotics USB Expansion Hub Portal [DQ2ASZXG]=======
03-07 11:31:50.675  3469  3595 V LynxUsb : clearing extant global warning: "REV Robotics USB Expansion Hub Portal [DQ2ASZXG] detached"
03-07 11:31:50.680  3469  3595 V FtDeviceManager: createDeviceInfoList(): 1 USB devices
03-07 11:31:50.682  3469  3576 D RobotCore: system telemetry: key=$System$None$ msg=""
03-07 11:31:50.683  3469  3595 V FtDevice: vv********************DQ2ASZXG opening********************vv 0x0f3f7619
03-07 11:31:50.683  3469  3595 V FtDevice: ^^********************DQ2ASZXG opened ********************^^
03-07 11:31:50.684  3469  3595 V FtDevice: resetting DQ2ASZXG
03-07 11:31:50.688  3469  3595 V LynxUsb : armDevice() serial=DQ2ASZXG...
03-07 11:31:50.689  3469  3595 V LynxModule: pingAndQueryKnownInterfaces mod=2
03-07 11:31:50.691  3469  3913 V RobotCore: thread: 'lynx incoming datagrams' starting...
03-07 11:31:50.691  3469  3913 V LynxUsb : synchronization gained: serial=DQ2ASZXG
03-07 11:31:50.695  3469  3595 V LynxModule: mod#=2 queryInterface(DEKA)=54 commands starting at 4096
03-07 11:31:50.709  3469  3595 V LynxModule: sendLEDPatternSteps(): #steps=6
03-07 11:31:50.715  3469  3595 V LynxModule: pingAndQueryKnownInterfaces mod=3
03-07 11:31:50.723  3469  3595 V LynxModule: mod#=3 queryInterface(DEKA)=54 commands starting at 4096
03-07 11:31:50.738  3469  3595 V LynxModule: sendLEDPatternSteps(): #steps=8
03-07 11:31:50.746  3469  3595 V LynxUsb : ...done armDevice()
03-07 11:31:50.926  3469  3739 V RobotCore: timeout: abandoning waiting 250ms for response: cmd=LynxGetMotorChannelModeCommand mod=2 msg#=0
03-07 11:31:50.928  3469  3739 V RobotCore: nack rec'd mod=2 msg#=0 ref#=0 reason=ABANDONED_WAITING_FOR_RESPONSE:256
03-07 11:31:50.932  3469  3739 W LynxMotor: LynxGetMotorChannelModeCommand was abandoned waiting for response
03-07 11:31:50.933  3469  3595 W art     : Long monitor contention with owner LinearOpMode main (3739) at com.qualcomm.robotcore.hardware.DcMotor$RunMode com.qualcomm.hardware.lynx.LynxDcMotorController.getMotorMode(int)(LynxDcMotorController.java:-1) waiters=0 in void com.qualcomm.hardware.lynx.LynxController.onModuleStateChange(com.qualcomm.robotcore.hardware.usb.RobotArmingStateNotifier, com.qualcomm.robotcore.hardware.usb.RobotArmingStateNotifier$ARMINGSTATE) for 186ms
03-07 11:31:50.937  3469  3595 I FtcEventLoop: ^^===== MODULE ATTACH: complete REV Robotics USB Expansion Hub Portal [DQ2ASZXG]=====^^
03-07 11:33:09.723  3469  3576 V EventLoopManager: synthetic gamepad received: id=-2 user=ONE atRest=true 
03-07 11:33:14.044  3469  3576 V Robocol : received command: CMD_INIT_OP_MODE(14368) $Stop$Robot$
03-07 11:33:14.061  3469  3575 I RobotCore: ******************** STOP - OPMODE /storage/emulated/0/FIRST/matchlogs/Match-18-A_-_Practice_TeleOp.txt ********************

Windwoes · 2019-03-07T16:40:55Z

@NoahAndrews

I literally was just looking at possibly this very thing. Are you using run to position mode?

Yes I am, for more than one motor actually.

NoahAndrews · 2019-03-07T16:43:18Z

Make sure you always assign a position to the motor before putting it in run to position mode. Do you still see the issue when fixing that?

Windwoes · 2019-03-07T16:48:07Z

Make sure you always assign a position to the motor before putting it in run to position mode. Do you still see the issue when fixing that?

This issue is pretty hard to reproduce, it might take me a while to determine the answer to that...

Windwoes · 2019-03-07T16:53:59Z

Also, here's the DS's log of the gamepad disconnect during the ESD event. (Not sure if it shows anything the RC log doesn't)

03-07 11:31:15.109 17059 17175 V Robocol : { 4606 19.714} received command: CMD_NOTIFY_RUN_OP_MODE(1020) A - Practice TeleOp
03-07 11:31:15.109 17059 17174 V DriverStation: { 4606 19.715} Robot Controller starting op mode: A - Practice TeleOp
03-07 11:31:15.110 17059 17174 V DriverStation: { 4606 19.715} ui:uiWaitingForStopEvent
03-07 11:31:19.114 17059 17087 V NetDiscover_wifiDirectAgent_bcast: { 4604 23.718} peers found: count=1
03-07 11:31:19.114 17059 17087 V NetDiscover_wifiDirectAgent_bcast: { 4604 23.718}     peer: 8e:3a:e3:71:77:7c 4634-RC
03-07 11:31:19.130 17059 17059 D WifiDirect: { 4605 23.735} broadcast: peers changed
03-07 11:31:19.147 17059 17059 V WifiDirect: { 4605 23.752} peers found: 1
03-07 11:31:19.147 17059 17059 V WifiDirect: { 4605 23.752}     peer: 8e:3a:e3:71:77:7c 4634-RC
03-07 11:31:19.148 17059 17059 I RobotCore: { 4605 23.752} Received networkConnectionEvent: PEERS_AVAILABLE
03-07 11:31:45.302 17059 17175 E DriverStation: { 4605 49.907} System telemetry warning: REV Robotics USB Expansion Hub Portal [DQ2ASZXG] detached
03-07 11:31:45.467 17059 17175 V Robocol : { 4604 50.071} received command: CMD_PLAY_SOUND(2009) {"hashString":"1e48ddeaa00488b1e532f1de418fdb6f","loopControl":0,"msPresentationTime":1551976310045,"rate":1.0,"volume":1.0,"waitForNonLoopingSoundsToFinish":true}
03-07 11:31:45.468 17059 17174 W AudioTrack: AUDIO_OUTPUT_FLAG_FAST denied by client; transfer 4, track 44100 Hz, output 48000 Hz
03-07 11:31:45.473 17059 17174 D SoundPlayer: { 4604 50.077} playing volume=1.000000 samp=8|ms=1044
03-07 11:33:05.080 17059 17059 V DriverStation: { 4605  9.685} Input device (id = 21) removed.
03-07 11:33:05.116 17059 17180 V GamepadManager: { 4605  9.721} transmitting synthetic gamepad user=ONE
03-07 11:33:05.398 17059 17059 V DriverStation: { 4609 10.007} New input device (id = 22) detected.
03-07 11:33:09.367 17059 17059 V StateMachine: { 4610 13.977} State with no transitions: WifiState
03-07 11:33:09.410 17059 17059 V StateMachine: { 4609 14.019} State with no transitions: WifiState
03-07 11:33:09.436 17059 17180 V Robocol : { 4609 14.045} sending CMD_INIT_OP_MODE(14368), attempt: 0
03-07 11:33:09.631 17059 17175 V Robocol : { 4605 14.236} received command: CMD_NOTIFY_INIT_OP_MODE(4618) $Stop$Robot$
03-07 11:33:09.632 17059 17174 V DriverStation: { 4605 14.237} Robot Controller initializing op mode: $Stop$Robot$
03-07 11:33:09.632 17059 17174 V DriverStation: { 4605 14.237} ui:uiWaitingForInitEvent
03-07 11:33:09.633 17059 17174 V StateMachine: { 4605 14.238} State with no transitions: WifiState
03-07 11:33:09.636 17059 17180 V Robocol : { 4605 14.241} sending CMD_RUN_OP_MODE(14374), attempt: 0
03-07 11:33:09.667 17059 17175 V Robocol : { 4606 14.273} received command: CMD_NOTIFY_RUN_OP_MODE(4624) $Stop$Robot$
03-07 11:33:09.668 17059 17174 V DriverStation: { 4606 14.274} Robot Controller starting op mode: $Stop$Robot$

NoahAndrews · 2019-03-07T23:05:07Z

It doesn't sound like the MOTOR_NOT_CONFIG_BEFORE_ENABLED nacks are relevant to this bug, so nevermind what I said earlier.

Windwoes mentioned this issue Mar 7, 2019

Gamepads sometimes disconnect from DS following ESD event #703

Open

Windwoes mentioned this issue Nov 15, 2019

Probable bug with app lifecycle / USB intents / ESD FIRST-Tech-Challenge/SkyStone#133

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Expansion Hubs unresponsive after ESD event until opmode is stopped #702

Expansion Hubs unresponsive after ESD event until opmode is stopped #702

Windwoes commented Mar 7, 2019 •

edited

Loading

NoahAndrews commented Mar 7, 2019

Windwoes commented Mar 7, 2019 •

edited

Loading

Windwoes commented Mar 7, 2019 •

edited

Loading

NoahAndrews commented Mar 7, 2019 •

edited

Loading

Windwoes commented Mar 7, 2019

Windwoes commented Mar 7, 2019

NoahAndrews commented Mar 7, 2019

Expansion Hubs unresponsive after ESD event until opmode is stopped #702

Expansion Hubs unresponsive after ESD event until opmode is stopped #702

Comments

Windwoes commented Mar 7, 2019 • edited Loading

NoahAndrews commented Mar 7, 2019

Windwoes commented Mar 7, 2019 • edited Loading

Windwoes commented Mar 7, 2019 • edited Loading

NoahAndrews commented Mar 7, 2019 • edited Loading

Windwoes commented Mar 7, 2019

Windwoes commented Mar 7, 2019

NoahAndrews commented Mar 7, 2019

Windwoes commented Mar 7, 2019 •

edited

Loading

Windwoes commented Mar 7, 2019 •

edited

Loading

Windwoes commented Mar 7, 2019 •

edited

Loading

NoahAndrews commented Mar 7, 2019 •

edited

Loading