How to interpret Robot Controller Log

[Tim.Vargo]

SW-Mentor here. We are experiencing sudden and (apparently) random loss of communications, maybe between our Driver Station and Rev Hubs, but not yet known for sure -- the robot just simply stops during OpMode execution, or will not start up at all. The robot sometimes corrects itself after a 3 second dead period, but other times requires a power off/on to correct. We use one CHub and one ExpHub.

We have grabbed the Robot Controller Log file, but cannot figure out how to interpret the logs. The first column looks like dates, but they are not dates that make any sense, as today's date is not present, and the blocks of dates that are present jump around in ways that do not correspond to dates that we were running the robot. I have searched but cannot find a guide on how to properly interpret this log. Does such a guide exist?

[4634 Programmer]

Yes, those are dates, but because the Control Hub does not have a real time clock powered by a watch battery, the Control Hub will boot up with completely incorrect date/time. The date/time is sent to the Control Hub from the Driver Station, but the Driver Station has to have the correct date/time for that to work

There is not an official guide on how to interpret the logs, but there are plenty of folks like myself both here and on the FTC discord who are adept at reading them. Also, REV will be happy to help you out if you email the logs to them.

[Tim.Vargo]

I am attaching a Robot Controller Log to see if anyone here can tell us why our robot sometimes just stops during TeleOp. I believe that this particular log was obtained immediately after such an event occurred. The kids said that the Driver Station screen turned grey and network reported as disconnected, but then recovered on its own after about 3 seconds.

[NoahAndrews]

Tim, it looks like you cut off the beginning of the log file, including the part where the Op Mode actually dies. The log begins after the process of stopping the Op Mode is already underway.

[NoahAndrews]

Also, as 4634 alluded to, you should have your students fix the date and time on the driver station phone.

[Tim.Vargo]

I tried to attach the complete log, but it was too big (nearly 3MB) for this forum. Error message said it had to be less than 19.5KB, so I trimmed it to 19KB from the end. Please try this link:
https://drive.google.com/file/d/1y-S...ew?usp=sharing

[NoahAndrews]

Hey Tim,

Every time your TeleOp program stops, it is because the Driver Station app specifically told it to. You can get the log from your Driver Station phone, and see if that has anything helpful (you'll probably need to put the phone in USB file transfer mode instead of charging mode from a notification).

[Tim.Vargo]

Thank you for helping. I will have access to the robot and phone tomorrow. What is the name of the log you are suggesting that I get from the DS?

[Tim.Vargo]

The problem is happening very frequently now. I had the kids correctly set the date/time on DS, then restarted the CHub, so all log timestamps should be in sync now. The problem occurred again today (10-Apr) at about 14:45 local time. I am linking below both the RobotController and DriverStation Logs. We do have a scrimmage tomorrow so were worried our problem wont be solved in time.

robotControllerLog_LostComm_20210410_1445
https://drive.google.com/file/d/1GYL...ew?usp=sharing

driverStationLog_LostComm_20210410_1445
https://drive.google.com/file/d/1-fs...ew?usp=sharing

[4634 Programmer]

The problem is happening very frequently now. I had the kids correctly set the date/time on DS, then restarted the CHub, so all log timestamps should be in sync now. The problem occurred again today (10-Apr) at about 14:45 local time. I am linking below both the RobotController and DriverStation Logs. We do have a scrimmage tomorrow so were worried our problem wont be solved in time.

robotControllerLog_LostComm_20210410_1445
https://drive.google.com/file/d/1GYL...ew?usp=sharing

driverStationLog_LostComm_20210410_1445
https://drive.google.com/file/d/1-fs...ew?usp=sharing

I've trimmed your logs to isolate what we're looking at and removed some of the "noise" logging from the MediaCodec on the Driver Station. Here is a link to the trimmed logs: DS and RC

We see that at 14:44:30.874 the Driver Station sends over the CMD_RUN_OP_MODE command. The Control Hub reports receiving the command at 14:44:30.873. So, the Control Hub clock is likely running ever so slightly behind the DS clock.

The Control Hub appears to finish Vuforia and UVC driver initialization at 14:44:33.381
Then, after seeming running fine for many seconds, at 14:45:56.780, the Control Hub begins spamming USB UVC driver errors:

04-10 14:45:56.780 991 1174 D UvcStream: [stream.cpp:613] bad packet: error bit set
04-10 14:45:56.976 991 1174 D UvcStream: [stream.cpp:613] bad packet: error bit set
04-10 14:45:56.980 991 1174 D UvcStream: [stream.cpp:613] bad packet: error bit set
04-10 14:45:57.048 991 1174 D UvcStream: [stream.cpp:613] bad packet: error bit set
04-10 14:45:57.072 991 1174 D UvcStream: [stream.cpp:613] bad packet: error bit set

These errors continue until 14:45:57.338 at which point the webcam appears to drop off the USB bus entirely:

04-10 14:45:57.338 991 1174 D libusb : [1618087530.499657] [00000496] libusb: debug [_originate_err] [linux_usbfs.c:3357] originating err: -4(LIBUSB_ERROR_NO_DEVICE)
04-10 14:45:57.338 991 1174 D Uvc : [device.cpp:1829] transfer: not processing/resubmitting, status=5(LIBUSB_TRANSFER_NO_DEVICE)
04-10 14:45:57.543 991 1073 D CameraManager: ---------------------------------------------- ACTION_USB_DEVICE_DETACHED
04-10 14:45:57.544 991 991 V FtDeviceManager: ACTION_USB_DEVICE_DETACHED: /dev/bus/usb/003/004
04-10 14:45:57.563 991 1073 D CameraManager: ---------------------------------------------- ACTION_USB_DEVICE_DETACHED
04-10 14:45:57.564 991 2030 V RobotCore: event loop: device has shutdown abnormally: ABNORMAL
04-10 14:45:57.565 991 2030 V EventLoopManager: event loop: detaching device DC11B3D0

Very shortly thereafter at 14:45:57.816, the Control Hub loses the link with the Driver Station:

04-10 14:45:57.816 991 991 I RobotControllerAccessPointAssistant: Wifi state change:, wifiApState: 10
04-10 14:45:57.828 991 1177 V Robocol : sending CMD_PLAY_SOUND(44269), attempt: 1
04-10 14:45:57.988 991 1177 V Robocol : Giving up on command CMD_PLAY_SOUND(44269) after 2 attempts
04-10 14:45:58.349 991 991 I RobotControllerAccessPointAssistant: Wifi state change:, wifiApState: 11
04-10 14:45:58.350 991 991 I EventLoopManager: onNetworkConnectionEvent: DISCONNECTED
04-10 14:45:58.375 991 991 I RobotControllerAccessPointAssistant: Wifi state change:, wifiApState: 12
04-10 14:45:58.618 991 991 I RobotControllerAccessPointAssistant: Wifi state change:, wifiApState: 13
04-10 14:45:58.618 991 991 I EventLoopManager: onNetworkConnectionEvent: CONNECTION_INFO_AVAILABLE
04-10 14:45:58.619 991 991 I Robocol : Received network connection event
04-10 14:45:58.622 991 991 I RobotControllerAccessPointAssistant: Wifi AP is enabled
04-10 14:45:58.622 991 991 I NetworkConnectionHandler: Handling new network connection infomation, connected: true setup needed: false
04-10 14:45:58.623 991 991 I RobotControllerAccessPointAssistant: Wifi AP is enabled
04-10 14:46:00.629 991 1177 V UpdateUI: Network: active, disconnected

Meanwhile, the Driver Station reports the link loss a couple seconds later at 14:45:59.278

04-10 14:45:59.278 21095 21201 E RobotCore: { -4 59.272} java.lang.Throwable: Peer disconnected
...
04-10 14:45:59.315 21095 21201 V DriverStation: { -4 59.310} robot controller disconnected
04-10 14:45:59.315 21095 21201 V DriverStation: { -4 59.310} Assuming client disconnected
04-10 14:45:59.316 21095 21201 V DriverStation: { -4 59.310} writing pref name=pref_rc_connected value=false
04-10 14:45:59.316 21095 21201 V DriverStation: { -4 59.311} ui:uiRobotControllerIsDisconnected
04-10 14:45:59.317 21095 21201 V NetworkConnectionHandler: { -4 59.312} Peer connection lost
04-10 14:45:59.325 21095 21095 V NetDiscover_prefremds: { -4 59.320} onSharedPreferenceChanged(name=pref_rc_connected, value=false)
04-10 14:45:59.325 21095 21095 V DriverStation: { -4 59.320} onSharedPreferenceChanged() pref=pref_rc_connected
04-10 14:45:59.326 21095 21095 I DriverStation: { -4 59.321} Hide match logging UI
04-10 14:46:02.204 21095 21095 V RobotCore: { -4 2.198} Wifi state change:, state: [type: WIFI[], state: DISCONNECTED/DISCONNECTED, reason: (unspecified), extra: <unknown ssid>, failover: false, available: true, roaming: false, metered: false], wifiInfo: SSID: <unknown ssid>, BSSID: <none>, MAC: 02:00:00:00:00:00, Supplicant state: COMPLETED, RSSI: -127, Link speed: -1Mbps, Frequency: -1MHz, Net ID: -1, Metered hint: false, score: 0
04-10 14:46:02.204 21095 21095 V DriverStationAccessPointAssistant: { -4 2.199} Handling wifi disconnect
04-10 14:46:02.204 21095 21095 I RobotCore: { -4 2.199} Received networkConnectionEvent: DISCONNECTED

The Control Hub then E-STOPs the OpMode as the result of link loss, and the following begins to be spammed in the Control Hub log for the next 40 seconds:

04-10 14:46:22.477 991 991 I NetworkConnectionHandler: Handling new network connection infomation, connected: true setup needed: false
04-10 14:46:22.479 991 991 I RobotControllerAccessPointAssistant: Wifi AP is enabled
04-10 14:46:22.721 991 991 I RobotControllerAccessPointAssistant: Wifi state change:, wifiApState: 10
04-10 14:46:23.233 991 991 I RobotControllerAccessPointAssistant: Wifi state change:, wifiApState: 11
04-10 14:46:23.233 991 991 I EventLoopManager: onNetworkConnectionEvent: DISCONNECTED
04-10 14:46:23.262 991 991 I RobotControllerAccessPointAssistant: Wifi state change:, wifiApState: 12
04-10 14:46:23.515 991 991 I RobotControllerAccessPointAssistant: Wifi state change:, wifiApState: 13
04-10 14:46:23.515 991 991 I EventLoopManager: onNetworkConnectionEvent: CONNECTION_INFO_AVAILABLE
04-10 14:46:23.515 991 991 I Robocol : Received network connection event

Quite a while after reporting link loss, at 14:46:47.389 the following appears in the Control Hub log:

04-10 14:46:47.389 991 1073 D CameraManager: ---------------------------------------------- ACTION_USB_DEVICE_ATTACHED
04-10 14:46:47.390 991 991 V FtDeviceManager: ACTION_USB_DEVICE_ATTACHED: /dev/bus/usb/004/003
04-10 14:46:47.390 991 991 V FtDeviceManager: addOrUpdateUsbDevice(vid=0x0bda pid=0xc820)

If we look up the VID/PID mentioned, it appears this is the Reltek WiFi radio popping up on the USB bus. I am not sure why we did not get a log message for it previously disappearing, but it stands to reason that it we get a log event for it popping up it must have left the bus at some point previously and maybe the SDK just doesn't log that for some reason.

Shortly after the radio pops up on the USB bus, so does your webcam (VID and PID indicate a Logitech camera)

04-10 14:46:49.017 991 1073 D CameraManager: ---------------------------------------------- ACTION_USB_DEVICE_ATTACHED
04-10 14:46:49.019 991 991 V FtDeviceManager: ACTION_USB_DEVICE_ATTACHED: /dev/bus/usb/004/004
04-10 14:46:49.020 991 991 V FtDeviceManager: addOrUpdateUsbDevice(vid=0x046d pid=0x0825)
04-10 14:46:49.021 991 991 V RCActivity: onPause()
04-10 14:46:49.023 991 991 V RCActivity: ACTION_USB_DEVICE_ATTACHED: /dev/bus/usb/004/004

---

Ok, so what actually was going on here?

Based on analysis of your logs, my best guess is that your Control Hub suffered an ESD strike, causing both the radio and webcam to drop off the USB bus. If the radio drops then so does your connection to the Driver Station.

[Tim.Vargo]

4634 Programmer,
Wow, what an incredibly details analysis, thank you so much. I really do appreciate the low level of details that you provided, because I would eventually like to become adept at interrupting these logs myself. I plan to reference your post again in the future to learn this skill.

I too was suspecting ESD as a possible reason for these crashes. We have pushed our scrimmage matches out until this Saturday, so we have time now to implement some ESD mitigation.

[NoahAndrews]

Tim, if you aren't using the latest version of the Control Hub OS (1.1.2), you should update (ideally using the REV Hardware Client). It has some improvements to how the access point behaves after ESD events like you might be experiencing.

There's an additional log file on the Control Hub called WifiLog.txt. If you post that, it can help validate 4634's analysis.