Re: Clie / USB Timing Problem

[Lars Weissflog <L rs-w de>]

Additional Info: 
I just noticed there are two more line in dmesg:
with usb-uhci.o loaded:

usb_control/bulk_msg: timeout
visor.c: visor_startup - error getting first unknown palm command
usb_control/bulk_msg: timeout
visor.c: visor_startup - error getting second unknown palm command


with alternative uhci.o loaded:
visor.c: visor_startup - error getting first unknown palm command
visor.c: visor_startup - error getting second unknown palm command


So, the visor.c lines are suspicious but do not depend on the usb-uhci /
uhci difference. Any hints?

Regs
Lars


On Tue, 2003-11-25 at 20:26, Lars Weissflog wrote:
> Hi all, 
> 
> before staring with the problem: This is long. Sorry, but I tried to
> include as much information as possible, i.e. all I have for now. It's
> about USB timing problems, dealing with the relevant modules and more
> related to the usb-subsystem than to pilot-link or gnome-pilot, but I
> assume those of you who developed the pilot-link stuff and all that know
> a lot about the USB-stuff as well and might derive from my explanations
> below that it is _not_ a problem of pilot-link as others on USB-Related
> lists might propose. So here I go:
> 
> Some of you might remember that I repeatedly reported about "timing
> issues" when trying to sync my Sony Clie SJ30 with evolution. Well, this
> is not evolution or gnome-pilot specific as I learned today. Here is
> what I have so far:
> 
> 1) pilot-link's version numbers give me headache, but that's not the
> core problem, Anyway:
> --
> [1850] moi carryme:~ $ pilot-xfer --version
>    .--.
>    | (c) Copyright 1996-2003, pilot-link team   |
>    |   Join the pilot-link lists to help out.   |
>    `--'
>    This is pilot-xfer, from pilot-link version 0.11.7
> 
>    Build target..: i686-pc-linux-gnu
>    Build date....: Feb  9 2003 17:26:03
> 
>    pilot-link 0.11.7 is covered under the GPL/LGPL
>    See the file COPYING under docs for more info.
> 
>    Please use -h for more detailed options.
> --
> This says it is version 0.11.7. This is the first thing I don't
> understand. The manpage says in its last line:
> 
> --
> (c) FSF 1996-2003      pilot-link - 0.11.8          pilot-xfer(1)
> Manual page pilot-xfer(1) line 222/252 (END)
> --
> So according to this it should be 0.11.8.
> 
> I installed it from Jamie's packages together with gnome-pilot,
> evolution and so on:
> --
> [1850] moi carryme:~ $ apt-cache policy pilot-link
> pilot-link:
>   Installed: 0.11.8-4jds1
>   Candidate: 0.11.8-4jds1
>   Version Table:
> *** 0.11.8-4jds1 0
>         500 http://ftp.acc.umu.se gnome2.2/ Packages
>         100 /var/lib/dpkg/status
>      0.9.5.0-8 0
>         500 http://ftp.de.debian.org stable/main Packages
> --
> 
> Okay, now you'll point me at the possibility that there are manually
> installed versions on my system. NO!:
> --
> [1849][root carryme:/]$ updatedb
> [1850][root carryme:/]$ locate pilot-xfer
> /usr/bin/pilot-xfer
> /usr/share/man/man1/pilot-xfer.1.gz
> [1850][root carryme:/]$
> 
> --
> So, there is definitely only _one_ pilot-xfer binary on my box, and that
> one claims to be 0.11.7 though Jamie's packages claim to be 0.11.8.
> STRANGE. But that is not the timing problem I was talking about. See
> below.
> 
> 2) Kernel: 2.4.20, build from stock kernel.org sources, several times,
> working flawlessly, having USB support as modules:
> --
> [1852][root carryme:/]$ lsmod
> Module                  Size  Used by    Not tainted
> [...unrelated...]
> visor                   8556   0 
> usbserial              16508   0  [visor]
> keybdev                 1728   0  (unused)
> mousedev                3768   1 
> hid                    18564   0  (unused)
> input                   3296   0  [keybdev mousedev hid]
> usb-uhci               21196   0  (unused)
> usbcore                61696   1  [visor usbserial hid usb-uhci]
> [...unrelated...]
> [1856][root carryme:/]$ 
> --
> 
> Okay, this is all stuff that more or less uses the USB subsystem, and
> here the problems start: I'm using usb-uhci since (a) someone once
> mentioned it is the standard driver and should be preferred against uhci
> (JE-alternative) and (b) vmware requires that one and won't work with
> the latter. 
> Now, when using usb-uhci I _sometimes_ can connect to my clie (be it in
> gnome-pilot running gpilotd or, after killing gpilotd, using
> pilot-xfer), apparently when I hit hotsync on the clie and then, a
> second or something later start pilot-xfer on the laptop. To make this
> clear: I _do_ know and understand that I have to hit hotsync first and
> afterwards start pilot-xfer. OK!? 
> Using the alternative uhci module, I get connected _every_ _single_
> _time_, no matter how long I wait between pressing hotsync and executing
> pilot-xfer.
> I have recently installed woody on my big machine and that one has a
> SIS-Chipset, using the usb-ohci module. On that machine I get connected
> every single time, too.
> 
> So, apparently the problem I was chasing from time to time over the last
> year or so arises from the usb-uhci code. There is something I noticed
> in the kernel log when connecting the clie, but you don't have to read
> the following output now, I'll come back to it a little later and point
> you at the strange lines. 
> With usb-uhci I get in /var/log/messages:
> --
> Nov 25 19:06:40 carryme kernel: hub.c: new USB device 00:07.2-2,
> assigned address 5
> Nov 25 19:06:40 carryme kernel: Manufacturer: Palm, Inc.
> Nov 25 19:06:40 carryme kernel: Product: Palm Handheld
> Nov 25 19:06:40 carryme kernel: usbserial.c: Handspring Visor / Palm 4.0
> / Clié 4.x converter detected
> Nov 25 19:06:40 carryme kernel: visor.c: Handspring Visor / Palm 4.0 /
> Clié 4.x: Number of ports: 2
> Nov 25 19:06:40 carryme kernel: visor.c: Handspring Visor / Palm 4.0 /
> Clié 4.x: port 1, is for Generic use and is bound to ttyUSB0
> Nov 25 19:06:40 carryme kernel: visor.c: Handspring Visor / Palm 4.0 /
> Clié 4.x: port 2, is for HotSync use and is bound to ttyUSB1
> Nov 25 19:06:40 carryme kernel: usb-uhci.c: interrupt, status 2, frame#
> 1137
> Nov 25 19:06:43 carryme kernel: usb_control/bulk_msg: timeout
> Nov 25 19:06:46 carryme kernel: usb_control/bulk_msg: timeout
> Nov 25 19:06:46 carryme kernel: usbserial.c: Handspring Visor / Palm 4.0
> / Clié 4.x converter now attached to ttyUSB0 (or usb/tts/0 for devfs)
> Nov 25 19:06:46 carryme kernel: usbserial.c: Handspring Visor / Palm 4.0
> / Clié 4.x converter now attached to ttyUSB1 (or usb/tts/1 for devfs)
> Nov 25 19:06:54 carryme kernel: usb-uhci.c: interrupt, status 2, frame#
> 838
> Nov 25 19:06:57 carryme kernel: usb_control/bulk_msg: timeout
> Nov 25 19:06:58 carryme kernel: usb.c: USB disconnect on device
> 00:07.2-2 address 5
> Nov 25 19:06:58 carryme kernel: usbserial.c: Handspring Visor / Palm 4.0
> / Clié 4.x converter now disconnected from ttyUSB0
> Nov 25 19:06:58 carryme kernel: usbserial.c: Handspring Visor / Palm 4.0
> / Clié 4.x converter now disconnected from ttyUSB1
> 
> --
> Starting pilot-xfer at any time during the appearance of these messages,
> it results in saying:
> 
> --
> [1852] moi carryme:~ $ pilot-xfer -p /dev/ttyUSB1 -l
> 
>    Listening to port: /dev/ttyUSB1
> 
>    Please press the HotSync button now... 
> --
> So, no connection possible 99% of my tries. in 01% of my tries it seems
> I have the right timing in my fingers to fire up pilot-xfer in the right
> moment. STRANGE. THIS IS MY PROBLEM.
> 
> Okay, next I try the alternative uhci module. First, I unload visor,
> usbserial and then usb-uhci in that order. Second, I modprobe uhci,
> usbserial, visor back into kernel again in that order. Finally, I press
> hotsync on the clie and get the following in var/log/messages:
> 
> --
> -- MARK --
> Nov 25 19:21:20 carryme kernel: hub.c: new USB device 00:07.2-2,
> assigned address 4
> Nov 25 19:21:20 carryme kernel: Manufacturer: Palm, Inc.
> Nov 25 19:21:20 carryme kernel: Product: Palm Handheld
> Nov 25 19:21:20 carryme kernel: usbserial.c: Handspring Visor / Palm 4.0
> / Clié 4.x converter detected
> Nov 25 19:21:20 carryme kernel: visor.c: Handspring Visor / Palm 4.0 /
> Clié 4.x: Number of ports: 2
> Nov 25 19:21:20 carryme kernel: visor.c: Handspring Visor / Palm 4.0 /
> Clié 4.x: port 1, is for Generic use and is bound to ttyUSB0
> Nov 25 19:21:20 carryme kernel: visor.c: Handspring Visor / Palm 4.0 /
> Clié 4.x: port 2, is for HotSync use and is bound to ttyUSB1
> Nov 25 19:21:20 carryme kernel: usbserial.c: Handspring Visor / Palm 4.0
> / Clié 4.x converter now attached to ttyUSB0 (or usb/tts/0 for devfs)
> Nov 25 19:21:20 carryme kernel: usbserial.c: Handspring Visor / Palm 4.0
> / Clié 4.x converter now attached to ttyUSB1 (or usb/tts/1 for devfs)
> Nov 25 19:21:30 carryme kernel: usb.c: USB disconnect on device
> 00:07.2-2 address 4
> Nov 25 19:21:30 carryme kernel: usbserial.c: Handspring Visor / Palm 4.0
> / Clié 4.x converter now disconnected from ttyUSB0
> Nov 25 19:21:30 carryme kernel: usbserial.c: Handspring Visor / Palm 4.0
> / Clié 4.x converter now disconnected from ttyUSB1
> --
> 
> With the uhci module, the pilot-xfer listing command runs no matter how
> long I wait before executing it after those lines saying "... attached
> to ttyUSB1..." appear in the log. 
> As mentioned above, here we return to the usb-uhci output. What makes me
> wonder are three additional lines found in /var/log/messages when using
> usb-uhci, they are:
> 
> --
> Nov 25 19:06:40 carryme kernel: usb-uhci.c: interrupt, status 2, frame#
> 1137
> Nov 25 19:06:43 carryme kernel: usb_control/bulk_msg: timeout
> Nov 25 19:06:46 carryme kernel: usb_control/bulk_msg: timeout
> --
> 
> These lines appear twice in that log (see above for the entire log in
> the usb-uhci case), just after visor.c has bound to USB1 and just after
> usbserial.c has bound to USB1. 
> 
> So, here I ask the USB-experts out there: What does that timeout message
> mean? Could it be a problem with a lousy USB-Chipset? lspci gives:
> --
> 00:07.2 USB Controller: Intel Corp. 82371AB PIIX4 USB (rev 01)
> --
> Which belongs to the 440ZX in this HP Omnibook XE3 (PIIIM-700):
> 
> --
> 00:00.0 Host bridge: Intel Corp. 440BX/ZX - 82443BX/ZX Host bridge (rev
> 03)
> 00:01.0 PCI bridge: Intel Corp. 440BX/ZX - 82443BX/ZX AGP bridge (rev
> 03)
> --
> 
> I found many posts via google dealing with those timeout messages, but
> nowhere was an answer that would lead to anything. Hope here someone has
> some tips what to try next.
> 
> Regards 
> Lars
-- 
LarsWeissflog
L rs-W dot DE