Loss of usb device connection while running an OpMode

[btipton]

We've had some issues with having to try multiple times to get our usb devices to all scan, but usually we're able to start the OpModes. The problem we're having now is that while the robot is running, we'll lose our connection to one of the motor controllers. Our first thought was that we were somehow momentarily losing contact with the cable connected to the phone, but after half a day of experimenting, we're sure that's not it. We've tried running the robot while someone held the robot controller in their way with the cable firmly attached, and we'll still lose a connection. It has happened when the robot was climbing and getting bounced around, but also when it's sitting still or driving on a smooth floor. The one constant has been that the same usb serial number shows up as the lost device. The logs show an FTDI null pointer exception, but I'm not sure if that's the cause of the error, or just a side effect of the lost usb connection.

Has anyone else experienced this, and if so, did it turn out to be a bad usb device? We've ordered some spare motor controllers that we can swap out, but I'm worried that if that doesn't fix it we're going to be in real trouble.

[Tom Eng]

We've had some issues with having to try multiple times to get our usb devices to all scan, but usually we're able to start the OpModes. The problem we're having now is that while the robot is running, we'll lose our connection to one of the motor controllers. Our first thought was that we were somehow momentarily losing contact with the cable connected to the phone, but after half a day of experimenting, we're sure that's not it. We've tried running the robot while someone held the robot controller in their way with the cable firmly attached, and we'll still lose a connection. It has happened when the robot was climbing and getting bounced around, but also when it's sitting still or driving on a smooth floor. The one constant has been that the same usb serial number shows up as the lost device. The logs show an FTDI null pointer exception, but I'm not sure if that's the cause of the error, or just a side effect of the lost usb connection.

Has anyone else experienced this, and if so, did it turn out to be a bad usb device? We've ordered some spare motor controllers that we can swap out, but I'm worried that if that doesn't fix it we're going to be in real trouble.

btipton,

Do you know how to find the logcat file on your robot controller?

If you are using Windows, if you connect your Android device to the Windows PC using a USB cable, and if you configure your ZTE Speed phone to act as a media device, you should be able to use the Window File Browser to go to the android device's main folder and look for a file called "com.qualcomm.ftcrobotcontroller.logcat". Can you copy this file to your PC and tell us what error messages you might be getting?

Tom

[btipton]

Tom,

Thanks for helping with this. Below is what I think is a representative sample of the errors - please let me know if you need more of the log:

10-04 18:02:17.334 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:17.334 W/RobotCore( 2139): [55 aa 00 40 1e] -> [00 00 00 00 00]
10-04 18:02:17.344 W/RobotCore( 2139): could not write to device AL00VCD1: comm timeout
10-04 18:02:17.474 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:17.474 W/RobotCore( 2139): [55 aa 80 40 1e] -> [00 00 00 00 00]
10-04 18:02:17.474 W/RobotCore( 2139): could not read from device AL00VCD1: comm timeout
10-04 18:02:17.614 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:17.614 W/RobotCore( 2139): [55 aa 00 40 1e] -> [00 00 00 00 00]
10-04 18:02:17.624 W/RobotCore( 2139): could not write to device AL00VCD1: comm timeout
10-04 18:02:17.774 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:17.774 W/RobotCore( 2139): [55 aa 80 40 1e] -> [00 00 00 00 00]
10-04 18:02:17.784 W/RobotCore( 2139): could not read from device AL00VCD1: comm timeout
10-04 18:02:17.934 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:17.934 W/RobotCore( 2139): [55 aa 00 40 1e] -> [00 00 00 00 00]
10-04 18:02:17.944 W/RobotCore( 2139): could not write to device AL00VCD1: comm timeout
10-04 18:02:18.084 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:18.084 W/RobotCore( 2139): [55 aa 80 40 1e] -> [00 00 00 00 00]
10-04 18:02:18.094 W/RobotCore( 2139): could not read from device AL00VCD1: comm timeout
10-04 18:02:18.244 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:18.244 W/RobotCore( 2139): [55 aa 00 40 1e] -> [00 00 00 00 00]
10-04 18:02:18.254 W/RobotCore( 2139): could not write to device AL00VCD1: comm timeout
10-04 18:02:18.384 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:18.384 W/RobotCore( 2139): [55 aa 80 40 1e] -> [00 00 00 00 00]
10-04 18:02:18.394 W/RobotCore( 2139): could not read from device AL00VCD1: comm timeout
10-04 18:02:18.424 W/RobotCore( 2139): Unable to send RobocolDatagram: java.net.SocketException: Socket is closed
10-04 18:02:18.434 W/RobotCore( 2139): RobocolDatagram - type:NONE, addr:null, size:0
10-04 18:02:18.434 I/RobotCore( 2139): Battery Checker, Level Remaining: 58.0
10-04 18:02:18.564 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:18.564 W/RobotCore( 2139): [55 aa 00 40 1e] -> [00 00 00 00 00]
10-04 18:02:18.574 W/RobotCore( 2139): could not write to device AL00VCD1: comm timeout
10-04 18:02:18.714 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:18.714 W/RobotCore( 2139): [55 aa 80 40 1e] -> [00 00 00 00 00]
10-04 18:02:18.724 W/RobotCore( 2139): could not read from device AL00VCD1: comm timeout
10-04 18:02:18.904 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:18.904 W/RobotCore( 2139): [55 aa 00 40 1e] -> [00 00 00 00 00]
10-04 18:02:18.914 W/RobotCore( 2139): could not write to device AL00VCD1: comm timeout
10-04 18:02:19.094 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:19.094 W/RobotCore( 2139): [55 aa 80 40 1e] -> [00 00 00 00 00]
10-04 18:02:19.104 W/RobotCore( 2139): could not read from device AL00VCD1: comm timeout
10-04 18:02:19.244 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:19.244 W/RobotCore( 2139): [55 aa 00 40 1e] -> [00 00 00 00 00]
10-04 18:02:19.254 W/RobotCore( 2139): could not write to device AL00VCD1: comm timeout
10-04 18:02:19.424 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:19.424 W/RobotCore( 2139): [55 aa 80 40 1e] -> [00 00 00 00 00]
10-04 18:02:19.434 W/RobotCore( 2139): could not read from device AL00VCD1: comm timeout
10-04 18:02:19.544 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:19.544 W/RobotCore( 2139): [55 aa 00 40 1e] -> [00 00 00 00 00]
10-04 18:02:19.564 W/RobotCore( 2139): could not write to device AL00VCD1: comm timeout
10-04 18:02:19.694 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:19.694 W/RobotCore( 2139): [55 aa 80 40 1e] -> [00 00 00 00 00]
10-04 18:02:19.704 W/RobotCore( 2139): could not read from device AL00VCD1: comm timeout
10-04 18:02:19.904 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:19.904 W/RobotCore( 2139): [55 aa 00 40 1e] -> [00 00 00 00 00]
10-04 18:02:19.914 W/RobotCore( 2139): could not write to device AL00VCD1: comm timeout
10-04 18:02:20.044 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:20.054 W/RobotCore( 2139): [55 aa 80 40 1e] -> [00 00 00 00 00]
10-04 18:02:20.054 W/RobotCore( 2139): could not read from device AL00VCD1: comm timeout
10-04 18:02:20.224 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:20.224 W/RobotCore( 2139): [55 aa 00 40 1e] -> [00 00 00 00 00]
10-04 18:02:20.234 W/RobotCore( 2139): could not write to device AL00VCD1: comm timeout
10-04 18:02:20.344 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:20.344 W/RobotCore( 2139): [55 aa 80 40 1e] -> [00 00 00 00 00]
10-04 18:02:20.354 W/RobotCore( 2139): could not read from device AL00VCD1: comm timeout
10-04 18:02:20.564 W/RobotCore( 2139): header sync bytes are incorrect
10-04 18:02:20.564 W/RobotCore( 2139): [55 aa 00 40 1e] -> [00 00 00 00 00]
10-04 18:02:20.564 W/RobotCore( 2139): could not write to device AL00VCD1: comm timeout
10-04 18:02:20.564 W/RobotCore( 2139): Too many sequential USB errors on device
10-04 18:02:20.564 V/RobotCore( 2139): stopped read/write loop for device AL00VCD1
10-04 18:02:20.664 W/RobotCore( 2139): sync device block requested, but device is shut down - AL00VCD1
10-04 18:02:20.664 V/RobotCore( 2139): RobotCoreException in EventLoopManager: cannot block, device is shut down
10-04 18:02:20.664 V/RobotCore( 2139): EventLoopManager state is EMERGENCY_STOP
10-04 18:02:20.664 I/FIRST ( 2139): Robot Status: EMERGENCY STOP
10-04 18:02:20.664 I/FIRST ( 2139): ======= TEARDOWN =======
10-04 18:02:20.664 I/FIRST ( 2139): Stopping DC Motor Controller LeftController
10-04 18:02:20.664 V/RobotCore( 2139): Shutting down device AL00VCDK
10-04 18:02:20.674 V/RobotCore( 2139): stopped read/write loop for device AL00VCDK
10-04 18:02:20.674 D/ProcessRequestThread: 2139): Device has been closed.
10-04 18:02:20.674 W/System.err( 2139): java.lang.InterruptedException
10-04 18:02:20.674 W/System.err( 2139): at java.util.concurrent.locks.AbstractQueuedSynchroni zer.doAcquireSharedInterruptibly(AbstractQueuedSyn chronizer.java:975)
10-04 18:02:20.674 W/System.err( 2139): at java.util.concurrent.locks.AbstractQueuedSynchroni zer.acquireSharedInterruptibly(AbstractQueuedSynch ronizer.java:1281)
10-04 18:02:20.674 W/System.err( 2139): at java.util.concurrent.Semaphore.acquire(Semaphore.j ava:283)
10-04 18:02:20.674 W/System.err( 2139): at com.ftdi.j2xx.o.c(SourceFile:2294)
10-04 18:02:20.674 W/System.err( 2139): at com.ftdi.j2xx.p.run(SourceFile:2764)
10-04 18:02:20.674 W/System.err( 2139): at java.lang.Thread.run(Thread.java:841)
10-04 18:02:20.684 D/UsbDeviceConnectionJNI( 2139): close
10-04 18:02:20.684 I/FIRST ( 2139): Stopping DC Motor Controller RightController
10-04 18:02:20.684 V/RobotCore( 2139): Shutting down device AL00VCD1
10-04 18:02:20.684 D/BulkIn: 2139): Stop BulkIn thread
10-04 18:02:20.684 W/System.err( 2139): java.lang.NullPointerException
10-04 18:02:20.684 W/System.err( 2139): at com.ftdi.j2xx.o.f(SourceFile:2672)
10-04 18:02:20.684 W/System.err( 2139): at com.ftdi.j2xx.a.run(SourceFile:2879)
10-04 18:02:20.684 W/System.err( 2139): at java.lang.Thread.run(Thread.java:841)
10-04 18:02:20.784 W/RobotCore( 2139): sync device block requested, but device is shut down - AL00VCD1
10-04 18:02:20.784 D/ProcessRequestThread: 2139): Device has been closed.
10-04 18:02:20.784 D/UsbDeviceConnectionJNI( 2139): close
10-04 18:02:20.784 W/System.err( 2139): java.lang.InterruptedException
10-04 18:02:20.784 W/System.err( 2139): at java.util.concurrent.locks.AbstractQueuedSynchroni zer.doAcquireSharedInterruptibly(AbstractQueuedSyn chronizer.java:975)
10-04 18:02:20.784 W/System.err( 2139): at java.util.concurrent.locks.AbstractQueuedSynchroni zer.acquireSharedInterruptibly(AbstractQueuedSynch ronizer.java:1281)
10-04 18:02:20.784 W/System.err( 2139): at java.util.concurrent.Semaphore.acquire(Semaphore.j ava:283)
10-04 18:02:20.784 W/System.err( 2139): at com.ftdi.j2xx.o.c(SourceFile:2294)
10-04 18:02:20.784 I/FIRST ( 2139): ======= TEARDOWN COMPLETE =======
10-04 18:02:20.784 V/RobotCore( 2139): EventLoopRunnable has exited
10-04 18:02:20.784 W/System.err( 2139): at com.ftdi.j2xx.p.run(SourceFile:2764)
10-04 18:02:20.784 W/System.err( 2139): at java.lang.Thread.run(Thread.java:841)
10-04 18:02:20.784 D/BulkIn: 2139): Stop BulkIn thread
10-04 18:02:20.784 W/System.err( 2139): java.lang.NullPointerException
10-04 18:02:20.784 W/System.err( 2139): at com.ftdi.j2xx.o.f(SourceFile:2672)
10-04 18:02:20.784 W/System.err( 2139): at com.ftdi.j2xx.a.run(SourceFile:2879)
10-04 18:02:20.784 W/System.err( 2139): at java.lang.Thread.run(Thread.java:841)
10-04 18:02:21.224 I/RobotCore( 2139): Battery Checker, Level Remaining: 58.0
10-04 18:02:28.954 I/FIRST ( 2139): Stopping FTC Controller Service
10-04 18:02:28.954 V/RobotCore( 2139): There are 0 Wifi Direct Assistant Clients (-)
10-04 18:02:28.954 V/RobotCore( 2139): Disabling Wifi Direct Assistant
10-04 18:02:28.964 D/RobotCore( 2139): RobocolDatagramSocket receive error: java.net.SocketException: Socket closed
10-04 18:02:28.964 D/RobotCore( 2139): RobocolDatagramSocket is closed
10-04 18:02:29.164 V/RobotCore( 2139): EventLoopManager state is STOPPED
10-04 18:02:29.164 I/FIRST ( 2139): Robot Status: stopped
10-04 18:02:29.164 I/FIRST ( 2139): ======= TEARDOWN =======
10-04 18:02:29.164 I/FIRST ( 2139): Stopping DC Motor Controller LeftController
10-04 18:02:29.164 V/RobotCore( 2139): Shutting down device AL00VCDK
10-04 18:02:29.274 W/RobotCore( 2139): sync device block requested, but device is shut down - AL00VCDK
10-04 18:02:29.274 I/FIRST ( 2139): Stopping DC Motor Controller RightController
10-04 18:02:29.274 V/RobotCore( 2139): Shutting down device AL00VCD1
10-04 18:02:29.374 W/RobotCore( 2139): sync device block requested, but device is shut down - AL00VCD1
10-04 18:02:29.374 I/FIRST ( 2139): ======= TEARDOWN COMPLETE =======
10-04 18:02:29.374 D/RobotCore( 2139): RobocolDatagramSocket is closed
10-04 18:02:29.374 I/FIRST ( 2139): Robot Status: null
10-04 18:02:29.374 W/RobotCore( 2139): Unable to send RobocolDatagram: java.net.SocketException: Socket is closed
10-04 18:02:29.384 W/RobotCore( 2139): RobocolDatagram - type:NONE, addr:null, size:0
10-04 18:02:29.384 I/RobotCore( 2139): Battery Checker, Level Remaining: 58.0
10-04 18:02:29.944 V/RobotCore( 2139): closing logcat file /storage/emulated/0/com.qualcomm.ftcrobotcontroller
10-04 18:02:29.974 D/dalvikvm( 2139): GC_FOR_ALLOC freed 2491K, 53% free 5279K/11092K, paused 33ms, total 35ms
10-04 18:02:30.164 V/RobotCore( 2139): Killing PID 3467

[btipton]

Trying replacement hardware

It doesn't look like anyone else is experiencing the same type of problem, so the most likely explanation is some sort of hardware problem with the motor controller. We've ordered some extras, and hopefully I'll be able to swap one out and see an improvement. I'll post here the results in case anyone else has similar problems.

[Tom Eng]

btipton,

One thing that we have seen is loose USB cables causing this kind of issue.

Here are some things we sugest:

Make sure your USB Modules are securely mounted. In some testing and demos, some teams simply placed the USB modules on their bot and didn't fasten them to the frame. We suspect that if the module is not secured, it could vibrate/get jolted, possibly causing a loss of communication with the Android device.

Make sure your USB cables are strain relieved properly (i.e., secured so they won't rattle loose or get jolted loose, with a little slack so you can disconnect them if you need to work on your module).

Also, power on the robot and modules BEFORE you connect the USB cable to the phone. There is a slight start up period for the modules that can cause issues.

If you've done these things and are still having issues, please contact the manufacturer (Modern Robotics) and they can troubleshoot the device with you. If it's defective, they can replace it, but please make sure you do not modify your module (for example by cutting off the connectors and replacing with a different connector) before you attempt to have it replaced.

Good luck and let us know if you are able to resolve this issue.

Tom

[FTC0417]

Also, power on the robot and modules BEFORE you connect the USB cable to the phone. There is a slight start up period for the modules that can cause issues.

While I understand what is being said here, to me this seems like a burdensome requirement for a power up sequence in competition. Teams wouldn't typically want to power their bots before they get to the field (would they even be allowed to?) but would definitely want to do all the connecting and reconnecting possible while in the pits. It's probably kind of a big deal. I don't personally think it's reasonable to have the "best-practice" have one need to plug in the USB after having powered the bot.

Isn't this startup period of the modules something that can be worked around in the software?

[btipton]

Problem solved! (probably?)

btipton,

Good luck and let us know if you are able to resolve this issue.

Tom

The new motor controller worked today for about 4 hours without any issues, whereas before we would be lucky to go more than a minute or so without throwing an error. We're going to put the old (suspected bad) controller back in and test once more to make sure it really is the cause, but I'm 90% sure it was just a bad motor controller.

[Roborams]

We started having the same problem last week. We have ordered a new motor controller? Did you get a chance to test further?

[btipton]

Yes, we haven't had any more disconnect issues while driving since replacing the motor controller. We're going to contact Modern Robotics this week about replacing the unit that seemed to be causing the problem.

[mhaeberli]

blipton,
We are seeing exactly the same problem. While we haven't confirmed down to the logcat level on all three, with all three of our PDMs. With each of our two motor controllers. In fact, logcat traces show the original failure attributed, on different occasions, to disconnects from different motor controllers.
Thanks,
Martin Haeberli
Mentor, Team 7593 TigerBots

[Roborams]

Sudden Loss of Communication

It looks like others have experienced this problem as well.

We purchased a new motor controller, but that didn't solve the problem for us. It appears to be the USB connection in our case.

[btipton]

We just had the same problem with the second motor controller we got when we originally purchased out set. Couldn't drive more than a couple of minutes without an error, then replaced the controller, and no problems so far.

[hexafraction]

We just had the same problem with the second motor controller we got when we originally purchased out set. Couldn't drive more than a couple of minutes without an error, then replaced the controller, and no problems so far.

We're getting the same issue with our Legacy module. However, in our case it appears to be messing with the phone's USB chip as we need to disconnect the cable at the PHONE side (presumably to release the USB OTG sense pin and reset the USB chip). Happened at the same time when our PDM stopped providing USB. Opened it up and there was a large GASH through one of the ICs, straight to the leadframe. The PDM was never opened before then by us.

[Tom Eng]

We're getting the same issue with our Legacy module. However, in our case it appears to be messing with the phone's USB chip as we need to disconnect the cable at the PHONE side (presumably to release the USB OTG sense pin and reset the USB chip). Happened at the same time when our PDM stopped providing USB. Opened it up and there was a large GASH through one of the ICs, straight to the leadframe. The PDM was never opened before then by us.

hexafraction - could you post a pic of the gash? Have you contacted Modern Robotics?

[hexafraction]

hexafraction - could you post a pic of the gash? Have you contacted Modern Robotics?

Tom, I will post an image when I get a chance. I'm currently unable to physically access our robotics stuff until Tuesday due to timing and other factors. I'll contact MR then, since I need to get the part and serial numbers for the components we're having troubles with. My current hunch is catastrophic overcurrent or manufacturing error, but I would defer to your expertise once I can get the pics posted.