[Nut-upsuser] Problems with handing USB unplug-plug with bcmxcp_usb

[Rich Wrenn]

I have been investigating a problem where bcmxcp_usb fails to recover from a USB cable unplug-plug sequence.  So far, I have been trying to characterize the conditions which cause the failure.  Before I start trying to debug this, I thought I would ask if this is a known problem and if someone has a solution.

The configuration is a Westmere platform running Debian 6 with a 2.6.39 kernel with NUT 2.6.4 with a Powerware 5115 UPS connected via USB 1.1.  We have many systems that are identically configured and all have this problem.

The reaction of bcmxcp_usb seems to depend on how long the USB cable is unplugged.
If the cable is unplugged for only 5 seconds, then communication to the UPS recovers but there are periodic RECONNECT USB DEVICE messages in the syslog.
If the cable is unplugged for more than 25 seconds, then bcmxcp_usb exits (sometimes) and my software restarts it and then communication to the UPS recovers.
However, in many cases bcmxcp_usb neither recovers communication to the UPS nor exits.  These are easy to reproduce, particularly if the USB cable unplug-plug sequence is repeated more than once.   In these cases, there is often nothing in the syslog from bcmxcp_usb, however the driver does not respond to a PING.   In these cases I can kill the bcmxcp_usb process and restart it and then communication to the UPS recovers.

In all cases, I notice that when the USB cable is plugged back in the kernel assigns it a new USB device number.  I suspect that this might have something to do with the failures.

I believe that these failures are new behavior.  These systems have been in production for over 3 years and the USB cable unplug-plug sequence has worked in the past.  However, many things have changed recently so I am not willing to say that this is new bcmxcp_usb behavior (it could be new kernel driver behavior or new libusb behavior).

Thanks,
Rich

The following is an example syslog that shows the reaction to a 5-second cable pull.
2012-09-06T06:50:56.616960+00:00 (none) kernel: [ 1157.122391] usb 4-2: USB disconnect, device number 3
2012-09-06T06:50:56.818756+00:00 (none) bcmxcp_usb[4678]: Communications with UPS lost: Error executing command
2012-09-06T06:50:56.818766+00:00 (none) bcmxcp_usb[4678]: Short read from UPS
2012-09-06T06:50:58.819548+00:00 (none) bcmxcp_usb[4678]: Communications with UPS lost: Error executing command
2012-09-06T06:50:58.819556+00:00 (none) bcmxcp_usb[4678]: Short read from UPS
2012-09-06T06:51:00.821146+00:00 (none) bcmxcp_usb[4678]: Communications with UPS lost: Error executing command
2012-09-06T06:51:00.821154+00:00 (none) bcmxcp_usb[4678]: Short read from UPS
2012-09-06T06:51:02.821666+00:00 (none) bcmxcp_usb[4678]: Communications with UPS lost: Error executing command
2012-09-06T06:51:02.821673+00:00 (none) bcmxcp_usb[4678]: Short read from UPS
2012-09-06T06:51:03.554410+00:00 (none) kernel: [ 1164.058615] usb 4-2: new low speed USB device number 4 using uhci_hcd
2012-09-06T06:51:04.822084+00:00 (none) bcmxcp_usb[4678]: Communications with UPS lost: Error executing command
2012-09-06T06:51:04.822091+00:00 (none) bcmxcp_usb[4678]: Short read from UPS
2012-09-06T06:51:06.822307+00:00 (none) bcmxcp_usb[4678]: Communications with UPS lost: Error executing command
2012-09-06T06:51:06.822315+00:00 (none) bcmxcp_usb[4678]: Short read from UPS
2012-09-06T06:51:08.822796+00:00 (none) bcmxcp_usb[4678]: Communications with UPS lost: Error executing command
2012-09-06T06:51:08.822804+00:00 (none) bcmxcp_usb[4678]: Short read from UPS
2012-09-06T06:51:10.823378+00:00 (none) bcmxcp_usb[4678]: Warning: excessive comm failures, limiting error reporting
2012-09-06T06:51:10.823385+00:00 (none) bcmxcp_usb[4678]: Communications with UPS lost: Error executing command
2012-09-06T06:51:10.823389+00:00 (none) bcmxcp_usb[4678]: Short read from UPS
2012-09-06T06:51:12.824128+00:00 (none) bcmxcp_usb[4678]: RECONNECT USB DEVICE
2012-09-06T06:51:12.826415+00:00 (none) bcmxcp_usb[4678]: Short read from UPS
2012-09-06T06:52:47.267635+00:00 (none) bcmxcp_usb[4678]: RECONNECT USB DEVICE
2012-09-06T06:53:21.491630+00:00 (none) bcmxcp_usb[4678]: RECONNECT USB DEVICE
2012-09-06T06:55:33.923723+00:00 (none) bcmxcp_usb[4678]: RECONNECT USB DEVICE
2012-09-06T06:56:47.331749+00:00 (none) bcmxcp_usb[4678]: RECONNECT USB DEVICE
2012-09-06T06:57:19.923746+00:00 (none) bcmxcp_usb[4678]: RECONNECT USB DEVICE
2012-09-06T07:01:09.603900+00:00 (none) bcmxcp_usb[4678]: RECONNECT USB DEVICE
2012-09-06T07:02:43.427937+00:00 (none) bcmxcp_usb[4678]: RECONNECT USB DEVICE

The following is an example syslog that shows the reaction to a 25-second cable pull.
2012-09-06T07:45:15.584954+00:00 (none) kernel: [ 4416.204455] usb 4-2: USB disconnect, device number 4
2012-09-06T07:45:15.952872+00:00 (none) bcmxcp_usb[5083]: Communications with UPS lost: Error executing command
2012-09-06T07:45:15.952879+00:00 (none) bcmxcp_usb[5083]: Short read from UPS
2012-09-06T07:45:17.954857+00:00 (none) bcmxcp_usb[5083]: Communications with UPS lost: Error executing command
2012-09-06T07:45:17.954865+00:00 (none) bcmxcp_usb[5083]: Short read from UPS
2012-09-06T07:45:19.956861+00:00 (none) bcmxcp_usb[5083]: Communications with UPS lost: Error executing command
2012-09-06T07:45:19.956869+00:00 (none) bcmxcp_usb[5083]: Short read from UPS
2012-09-06T07:45:21.957451+00:00 (none) bcmxcp_usb[5083]: Communications with UPS lost: Error executing command
2012-09-06T07:45:21.957459+00:00 (none) bcmxcp_usb[5083]: Short read from UPS
2012-09-06T07:45:23.958350+00:00 (none) bcmxcp_usb[5083]: Communications with UPS lost: Error executing command
2012-09-06T07:45:23.958357+00:00 (none) bcmxcp_usb[5083]: Short read from UPS
2012-09-06T07:45:25.958454+00:00 (none) bcmxcp_usb[5083]: Communications with UPS lost: Error executing command
2012-09-06T07:45:25.958461+00:00 (none) bcmxcp_usb[5083]: Short read from UPS
2012-09-06T07:45:27.959023+00:00 (none) bcmxcp_usb[5083]: Communications with UPS lost: Error executing command
2012-09-06T07:45:27.959030+00:00 (none) bcmxcp_usb[5083]: Short read from UPS
2012-09-06T07:45:29.959933+00:00 (none) bcmxcp_usb[5083]: Communications with UPS lost: Error executing command
2012-09-06T07:45:29.959940+00:00 (none) bcmxcp_usb[5083]: Short read from UPS
2012-09-06T07:45:31.961017+00:00 (none) bcmxcp_usb[5083]: Communications with UPS lost: Error executing command
2012-09-06T07:45:31.961024+00:00 (none) bcmxcp_usb[5083]: Short read from UPS
2012-09-06T07:45:33.963028+00:00 (none) bcmxcp_usb[5083]: Warning: excessive comm failures, limiting error reporting
2012-09-06T07:45:33.963037+00:00 (none) bcmxcp_usb[5083]: Communications with UPS lost: Error executing command
2012-09-06T07:45:33.963041+00:00 (none) bcmxcp_usb[5083]: Short read from UPS
2012-09-06T07:45:35.964370+00:00 (none) bcmxcp_usb[5083]: RECONNECT USB DEVICE
2012-09-06T07:45:35.964378+00:00 (none) bcmxcp_usb[5083]: Fatal error: unusable configuration
2012-09-06T07:45:35.964382+00:00 (none) bcmxcp_usb[5083]: CLOSING
2012-09-06T07:45:42.882509+00:00 (none) kernel: [ 4443.501394] usb 4-2: new low speed USB device number 5 using uhci_hcd
2012-09-06T07:47:00.885780+00:00 (none) JHELPER[4682]: upsdrvctl start
2012-09-06T07:47:04.422380+00:00 (none) bcmxcp_usb[5127]: Startup successful
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.alioth.debian.org/pipermail/nut-upsuser/attachments/20120906/6310a961/attachment-0001.html>