Ok. It looks to me like I hadn't got usbfs_snoop working for that last extract from the syslog. So, I built this script to set everything up: I rebooted the computer and ran the script, after sunset with the inverter connected. I then let the sun come up, stopped the wiresharks and saved their captured files. copied /var/log/messages and stripped out the noise with: sed '1,/Jan 16/d' messages |sed '1,/0\.000000/d' |egrep -v "NetworkManager|dhclient">filteredSyslog this leaves me with the following files in the current directory: -rw-------. 1 root root 16572 Jan 15 15:12 bus1PlugInPviForgotToRunUsbSnoop -rw-------. 1 root root 701780 Jan 17 07:50 bus1UsbPluggedInOverSunup -rw-------. 1 root root 4278 Jan 15 15:08 bus2PlugInPviForgotToRunUsbSnoop -rw-------. 1 root root 282 Jan 16 21:12 bus2UsbPluggedInOverSunup -rw-------. 1 root root 8495 Jan 15 15:13 bus3PlugInPviForgotToRunUsbSnoop -rw-------. 1 root root 13083260 Jan 17 07:50 bus3UsbPluggedInOverSunup -rw-------. 1 root root 1614 Jan 15 15:08 bus4PlugInPviForgotToRunUsbSnoop -rw-------. 1 root root 460 Jan 16 21:12 bus4UsbPluggedInOverSunup -rw-------. 1 root root 282 Jan 15 15:08 bus5PlugInPviForgotToRunUsbSnoop -rw-------. 1 root root 816 Jan 16 21:12 bus5UsbPluggedInOverSunup -rw-r--r--. 1 root root 628207 Jan 21 15:37 filteredSyslog -rw-------. 1 root root 2924156 Jan 17 21:02 messages Which, I think is the output that's needed. I think that the inverter must be plugged into bus3. So I'm dropping bus3UsbPluggedInOverSunup and filteredSyslog into my public folder again. (http://dl.dropbox.com/u/10589123/filteredSyslog and http://dl.dropbox.com/u/10589123/bus3UsbPluggedInOverSunup When I look through filteredSyslog, I cannot see what other program's driving the device. How can I find what's happening as /dev/ttyUSB0 appears. Should I be running lsof or similar to get a view on what's waiting for the usb device to come up? I'm guessing that whatever it is is waiting on some file to appear/change or on a socket, but I don't know how to validate that, nor how to identify the program. Tim On 15 Jan 2012, at 14:47, Tim Coote wrote: > Hi Alan > I'm going to have another go at this before the sun goes down, if I can. the run that I did yesterday stopped the damned inverter from working. If it had worked, then the wireshark trace should have been the same as the previous working wireshark trace. As this is a different box, I've got to get it in a consistent condition first. > > I thought that I'd enabled usb_snoop before grabbing that log. > > I'll get a stable test bed automated, so that I can be clear that it's done what I think it has and then come back with the readings. > > Tim > On 14 Jan 2012, at 17:07, Alan Stern wrote: > >> On Sat, 14 Jan 2012, Tim Coote wrote: >> >>> On 13 Jan 2012, at 15:34, Alan Stern wrote: >>> [snip] >>>> >>>> It may be something like usb_modeswitch, or a program invoked by a udev >>>> rule. Or it could be a modem manager. >>>> >>>> Something that might help is to enable the usbfs_snoop module parameter >>>> for usbcore before plugging in the device: >>>> >>>> echo 1 >/sys/module/usbcore/parameters/usbfs_snoop >>>> >>>> That will add a bunch of output to the system log, including the names >>>> of programs that directly access USB devices. >>> Here's what I got: >>> Jan 14 10:50:49 pluto kernel: [ 4622.452049] usb 3-2: new full speed USB device number 2 using uhci_hcd >>> Jan 14 10:50:49 pluto kernel: [ 4622.684080] usb 3-2: New USB device found, idVendor=0451, idProduct=3410 >>> Jan 14 10:50:49 pluto kernel: [ 4622.684089] usb 3-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3 >>> Jan 14 10:50:49 pluto kernel: [ 4622.684097] usb 3-2: Product: TUSB3410 Boot Device >>> Jan 14 10:50:49 pluto kernel: [ 4622.684102] usb 3-2: Manufacturer: Texas Instruments >>> Jan 14 10:50:49 pluto kernel: [ 4622.684108] usb 3-2: SerialNumber: TUSB3410 >>> Jan 14 10:50:50 pluto kernel: [ 4623.150995] USB Serial support registered for TI USB 3410 1 port adapter >>> Jan 14 10:50:50 pluto kernel: [ 4623.151213] USB Serial support registered for TI USB 5052 2 port adapter >>> Jan 14 10:50:50 pluto kernel: [ 4623.151255] ti_usb_3410_5052 3-2:1.0: TI USB 3410 1 port adapter converter detected >>> Jan 14 10:50:51 pluto kernel: [ 4623.788052] usb 3-2: reset full speed USB device number 2 using uhci_hcd >>> Jan 14 10:50:51 pluto kernel: [ 4623.918079] usb 3-2: device firmware changed >>> Jan 14 10:50:51 pluto kernel: [ 4623.918117] usb 3-2: USB disconnect, device number 2 >>> Jan 14 10:50:51 pluto kernel: [ 4623.918144] ti_usb_3410_5052: probe of 3-2:1.0 failed with error -5 >>> Jan 14 10:50:51 pluto kernel: [ 4623.919413] usbcore: registered new interface driver ti_usb_3410_5052 >>> Jan 14 10:50:51 pluto kernel: [ 4623.919420] ti_usb_3410_5052: v0.10:TI USB 3410/5052 Serial Driver >>> Jan 14 10:50:51 pluto kernel: [ 4624.023049] usb 3-2: new full speed USB device number 3 using uhci_hcd >>> Jan 14 10:50:51 pluto kernel: [ 4624.232076] usb 3-2: New USB device found, idVendor=0451, idProduct=3410 >>> Jan 14 10:50:51 pluto kernel: [ 4624.232086] usb 3-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3 >>> Jan 14 10:50:51 pluto kernel: [ 4624.232094] usb 3-2: Product: TUSB3410 Boot Device >>> Jan 14 10:50:51 pluto kernel: [ 4624.232100] usb 3-2: Manufacturer: Texas Instruments >>> Jan 14 10:50:51 pluto kernel: [ 4624.232106] usb 3-2: SerialNumber: TUSB3410 >>> Jan 14 10:50:51 pluto kernel: [ 4624.235195] ti_usb_3410_5052 3-2:1.0: TI USB 3410 1 port adapter converter detected >>> Jan 14 10:50:51 pluto kernel: [ 4624.235223] ti_usb_3410_5052: probe of 3-2:1.0 failed with error -5 >>> Jan 14 10:50:51 pluto kernel: [ 4624.239194] ti_usb_3410_5052 3-2:2.0: TI USB 3410 1 port adapter converter detected >>> Jan 14 10:50:51 pluto kernel: [ 4624.239743] usb 3-2: TI USB 3410 1 port adapter converter now attached to ttyUSB0 >> >> That's all perfectly normal. Do you have a wireshark or usbmon trace >> for this test? >> [snip] >> >>> If I >>> understand your description of the initiation process, that driver is >>> being installed as a result of some other program that I've yet to >>> track down. >> >> That program is udev. The driver is installed normally, just as any >> other driver is installed when needed. >> >>> And dbus is a likely starting point for running the >>> program, possibly related to tcp_lp (whatever that is, and I note >>> that it's not dependant on the other driver). I think that >>> ti_usb_3410_5052 does try to load firmware. >> >> Yes, it does. And it switches to config 2. But as far as I can tell, >> it doesn't send anything else to the device (like those requests for >> string descriptor 0xee) until the ttyUSB device is opened. >> >> dbus isn't your problem. Some other program must be trying to >> communicate with the device. Did you enable the usbfs_snoop parameter >> before collecting the log above? >> >> Alan Stern >> > -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
