Gamepads sometimes disconnect from DS following ESD event

[Windwoes]

This has got to be the weirdest bug I have ever seen, but I have been able to reproduce it nearly 10 times so I'm very confident in my analysis.

Sometimes, right after an ESD event, the gamepad will inexplicably disconnect from the driver station. All that is required to reproduce it is to drive the robot around the field to build up static charge, and then drive it so that it touches an object at a lower potential (or a grounded object); thus creating an ESD event. I have been able to reproduce this with 1) ESD from the field wall 2) ESD from the lander leg 3) ESD from a wheel of the robot touching the metal base of a floor lamp. I actually managed to catch that last one on video. Please ignore the warning message on the driver station; I had a webcam disconnected during this test.

Logs from the DS and RC of this encounter can be found on my other issue that I opened today. (At first I thought that previous issue and this were related and thus posted the logs there; but I now believe they are separate and apart issues)

[Windwoes]

Update: this bug bit me in a real match in Detroit (Ochoa Q-115)...

Not only do I have a commented log from both the driver station and the robot controller, but here's a timestamp to the livestream a few seconds before the event for full context.

[Windwoes]

One notable difference between the behavior I saw in Detroit and that I saw in testing is that in Detroit, not only did the gamepads disconnect, but the OpMode also stopped - in my previous testing, the gamepads disconnected but the OpMode continued to run...

[AustinShalit]

OpModes stopping when a gamepad disconnects is probably a good thing.

[Windwoes]

@AustinShalit whether it is a good thing or not, it is not the normal behavior. Besides, the question here is why are the gamepads disconnecting from the DS....

[gearsincorg]

OpModes stopping when a gamepad disconnects is probably a good thing.

Unless you are running in autonomous, in which case it's an unnecessary disaster.
The current behavior is/should be that gamepad buttons/joysticks revert back to their "safe" (off) values.

[Windwoes]

@gearsincorg as I mentioned to you in Detroit, it seems that this issue was triggered by onPause() being called when it shouldn't have (see line 106 in DS log). If you look in FtcDriverStationActivity, you will find this:

    protected void onPause()
    {
        super.onPause();
        RobotLog.vv(TAG, "onPause()");
        analytics.unregister();
        gamepadManager.clearGamepadAssignments();
        mInputManager.unregisterInputDeviceListener(this);
        initDefaultOpMode();
    }

Notice that the gamepads are dropped and the default OpMode (StopRobot) is started.

[gearsincorg]

OK, I've processed the two log files from issue #702 and created a combined log with corrected timestamps.
From this I can see what came first, the chicken or the egg, and it's pretty interesting.

Sequence of events
Note: to sync the two phone clocks we can look at the Opmode run commands command response times below and determine the time dif between the DS and RC

DS ## 03-07 11:33:09.636 17059 17180 V Robocol : { 4605 14.241} sending CMD_RUN_OP_MODE(14374), attempt: 0
RC -- 03-07 11:33:12.944  3469  3576 V Robocol : received command: CMD_INIT_OP_MODE(14368) $Stop$Robot$
DS ## 03-07 11:33:09.667 17059 17175 V Robocol : { 4606 14.273} received command: CMD_NOTIFY_RUN_OP_MODE(4624) $Stop$Robot$

This indicates that the RC clock is ahead of the DS clock by approx. 3.3 sec (+/- 0.015 sec)
So, the time-synched event sequence is:

DS ## 03-07 11:31:15.109 17059 17175 V Robocol : { 4606 19.714} received command: CMD_NOTIFY_RUN_OP_MODE(1020) A - Practice TeleOp
DS ## 03-07 11:31:15.109 17059 17174 V DriverStation: { 4606 19.715} Robot Controller starting op mode: A - Practice TeleOp
RC -- 03-07 11:31:16.382  3469  3576 V Robocol : received command: CMD_RUN_OP_MODE(10887) A - Practice TeleOp
RC -- 03-07 11:31:16.410  3469  3629 V Robocol : sending CMD_NOTIFY_RUN_OP_MODE(1020), attempt: 0
. . .
. . .
DS ## 03-07 11:31:45.473 17059 17174 D SoundPlayer: { 4604 50.077} playing volume=1.000000 samp=8|ms=1044
RC -- 03-07 11:31:47.637  3469  3595 I FtcEventLoop: ^^===== MODULE ATTACH: complete REV Robotics USB..  Hub Portal [DQ2ASZXG]=====^^
   -- ESD EVENT OCCURS
DS ## 03-07 11:33:05.080 17059 17059 V DriverStation: { 4605  9.685} Input device (id = 21) removed.
DS ## 03-07 11:33:05.116 17059 17180 V GamepadManager: { 4605  9.721} transmitting synthetic gamepad user=ONE
RC -- 03-07 11:33:05.323  3469  3576 V EventLoopManager: synthetic gamepad received: id=-2 user=ONE atRest=true
DS ## 03-07 11:33:05.398 17059 17059 V DriverStation: { 4609 10.007} New input device (id = 22) detected.

DS ## 03-07 11:33:09.367 17059 17059 V StateMachine: { 4610 13.977} State with no transitions: WifiState
DS ## 03-07 11:33:09.410 17059 17059 V StateMachine: { 4609 14.019} State with no transitions: WifiState
DS ## 03-07 11:33:09.636 17059 17180 V Robocol : { 4605 14.241} sending CMD_RUN_OP_MODE(14374), attempt: 0
RC -- 03-07 11:33:09.644  3469  3576 V Robocol : received command: CMD_INIT_OP_MODE(14368) $Stop$Robot$
DS ## 03-07 11:33:09.667 17059 17175 V Robocol : { 4606 14.273} received command: CMD_NOTIFY_RUN_OP_MODE(4624) $Stop$Robot$
DS ## 03-07 11:33:09.668 17059 17174 V DriverStation: { 4606 14.274} Robot Controller starting op mode: $Stop$Robot$

From this I think we can conclude:

1. The first record of any event relating to the ESD and/or game controller was on the Driver Station when the Input device was removed. So there is no log of any trigger from the Robot Controller
2. The Gamepad reappears 310 mSec after the initial disconnect
3. The DS sends the $Stop$Robot command 4.3 seconds AFTER the gamepad is reconnected.
   The only significant event before this is the WiFi state change, which appears to initiate the $Stop$Robot action. Still no smoking gun from RC.

Based on this, my conclusion would have to be that the DS phone/gamepad connection was disrupted by the ESD event, but not through the robot, but rather this points to the disruption being transmitted via a EM pulse (ie: radio interference) that is somehow seen at the Gamepad interface, and/or is locking up the WiFi, and confusing the WiFi state machine..

Anyone else see a trigger I'm missing?

[Windwoes]

@gearsincorg Interesting analysis, a few points of my own:

1. It seems like you looked at the logs from my previous testing which show slightly different symptoms than what I saw in Detoit
2. The stop robot 4.3 seconds after the event was from me manually pressing stop.
3. In order to test if EMI/ESD to the DS USB connection was the cause, I walked around the field to build up charge and zapped a grounded object within 2 inches of the DS USB connection about 5 times and nothing odd happened so I'm inclined to believe that is not the cause.
4. We should also merge the logs from Q115 in Detroit and see what they show since the symptoms were slightly different

Edit for clarity: in testing the OpMode did not stop by itself, I stopped it manually. In Q115, the OpMode stopped by itself.

[gearsincorg]

We should also merge the logs from Q115 in Detroit and see what they show since the symptoms were slightly different

@FROGbots-4634 Since you have the originals can you do that? Double check my time synching as well.

[Windwoes]

@gearsincorg

Since you have the originals can you do that? Double check my time synching as well.

I can try, though I'm not entirely sure how you determined the time difference? Did you assume the command arrived at the RC at exactly the time it was sent from the DS?

Also, what exactly does this message mean?

StateMachine: { -114 7.297} State with no transitions: WifiState

[gearsincorg]

Re: WiFiState change. Yes, I also noticed that.

To determine time difference I found an RC log line that must occur between two close DS log lines, and split the 30mS time difference.

DS ## 03-07 11:33:09.636 17059 17180 V Robocol : { 4605 14.241} sending CMD_RUN_OP_MODE(14374), attempt: 0
RC -- 03-07 11:33:12.944  3469  3576 V Robocol : received command: CMD_INIT_OP_MODE(14368) $Stop$Robot$
DS ## 03-07 11:33:09.667 17059 17175 V Robocol : { 4606 14.273} received command: CMD_NOTIFY_RUN_OP_MODE(4624) $Stop$Robot$

RC 12.944 - DS 9.65 = 3.3 sec (approx)

[Windwoes]

Ok I think I understand. One other thing I suppose I could do to test whether EMI is really at play would be to back up say 12FT from the field while driving around and see if I can still reproduce.

[gearsincorg]

@cmacfarl @rgatkinson @tomeng70

What can cause this DS log message:

V StateMachine: { 4610 13.977} State with no transitions: WifiState

It's happening around the time of the ESD/Gamepad disconnection. Is this expected under any situations, or is it indicative of a problem?

[gearsincorg]

Ok I think I understand. One other thing I suppose I could do to test whether EMI is really at play would be to back up say 12FT from the field while driving around and see if I can still reproduce.

Yes, that would definitely help to determine if the Gamepad is seeing the EMI, but it would not prevent the WiFi from being effected.