Rich Wrenn
2012-Sep-06 13:49 UTC
[Nut-upsuser] Problems with handing USB unplug-plug with bcmxcp_usb
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>