Re: Gnome Pilot Causing USB Drive problems (version 2.0.10)]

[Sam Williams <sam-williams insightbb com>]

On Sun, 2004-09-05 at 22:59, JP Rosevear wrote:
> On Wed, 2004-09-01 at 21:52 -0500, Sam Williams wrote:
> > I'm running Fedora Core 2, but I've been having this problem at least
> > since Fedora Core 1. First, of all I have a Sony Clie that takes an act
> > of God to hotsync using gpilotd. I've found that I can general
> > accomplish the task if I stop gpilotd, start the hotsync from the clie,
> > then restart gpilotd. May take a couple of times to get it to sync...
> > 
> > However two days ago I discovered that gpilotd is causing problems with
> > my usb drives. I can easy mount and use any usbdrive that is 128 Mbytes
> > or less with gpilotd running. If gpilotd is running and I try to mount a
> > 256 Mbyte usbdrive the story is different. It tries multiple times to
> > mount and the ultimately times out with an error. In the rare occasion
> > that it will mount the device is mounted read only. 
> > 
> > If I stop or pause gpilotd and then try to use a 256 Mbyte usbdrive it
> > will work as flawlessly as the 128 Mbyte one. Now for the record this
> > behavior is 100% reproducible and has been demonstrated with both a
> > SanDisk Minicruiser and a Lexar Jumpdrive, both are 256 Mbytes in size.
> > 
> > There is a serious problem with gpilotd that would allow this
> > interaction to occur. First, the daemon doesn't allow easy or flawless
> > hotsyncing for my Clie and now I find that it gets in the way of normal
> > usbdrive operation....
> > 
> > Please look into this and see where the problem might exist.
> 
> Gnome Pilot does not interact directly with USB in the kernel, it simply
> accesses a serial to usb device bridge provided by the visor module, the
> existence of which it detects by polling /proc/bus/usb/devices and
> matching pilot vendor/product ids.  I'm not clear why you think this
> behaviour is the fault of gnome-pilot (unless the usb drives are
> stupidly reporting a matching product/vendor id to some pilot device).

Actually its very simple. I thought my initial documentation explained
it, but I'll try to be a little more succinct. If I try to mount a
usbdrive of 128 Mbytes or less, I can mount and use it regardless of
what other things are running on my system. If I try and mount a
usbbrive of 256Mbytes while I have gpilotd running I get tons of
messages suggesting a control timeout on ep0in. It might eventually
mount, but if it does the device is read only and can not be used. 

If I kill or pause gpilotd then I can mount and use all usbdrives
without issue. Why do I think gpilotd is the problem? If it runs things
don't work, if it isn't running everything works.

Using usbview or lsusb I get reports from the various devices that are
consistent with the type, size, and characteristics of the device. I get
these results regardless if gpilotd is running or not. I see Lexar or
SANdisk, depending on which one is attached to the system. Further, I've
had this problem for at least a year, but only recently  was I able to
make the connection with gpilotd. I have included a listing of the
output I see in /var/log/messages as I try mounting and unmounting a 256
Mbyte Lexar usbdrive..... I have also included some stop and start
messages using logger to provide a little perspective on behavior...

************************************************* [ /var/log/messages ]

Sep  6 10:12:28 zurg samurai: Starting the test of USB MEMORY DRIVES---
NO GPILOTD
Sep  6 10:12:39 zurg kernel: usb 1-1: new high speed USB device using
address 3
Sep  6 10:12:40 zurg kernel: Initializing USB Mass Storage driver...
Sep  6 10:12:40 zurg kernel: scsi0 : SCSI emulation for USB Mass Storage
devices
Sep  6 10:12:40 zurg kernel:   Vendor: Generic   Model: STORAGE
DEVICE    Rev: 1.25
Sep  6 10:12:40 zurg kernel:   Type:  
Direct-Access                      ANSI SCSI revision: 02
Sep  6 10:12:40 zurg kernel: Attached scsi generic sg0 at scsi0, channel
0, id 0, lun 0,  type 0
Sep  6 10:12:40 zurg kernel: usbcore: registered new driver usb-storage
Sep  6 10:12:40 zurg kernel: USB Mass Storage support registered.
Sep  6 10:12:40 zurg kernel: SCSI device sda: 512000 512-byte hdwr
sectors (262 MB)
Sep  6 10:12:40 zurg kernel: sda: Write Protect is off
Sep  6 10:12:40 zurg kernel: sda: assuming drive cache: write through
Sep  6 10:12:41 zurg kernel:  sda: sda1
Sep  6 10:12:41 zurg kernel: Attached scsi removable disk sda at scsi0,
channel 0, id 0, lun 0
Sep  6 10:12:41 zurg kernel: updfstab: Using deprecated /dev/sg
mechanism instead of SG_IO on the actual device
Sep  6 10:12:41 zurg scsi.agent[10530]: disk at
/devices/pci0000:00/0000:00:03.2/usb1/1-1/1-1:1.0/host0/0:0:0:0
Sep  6 10:12:43 zurg udev[10597]: creating device node '/udev/sg0'
Sep  6 10:12:43 zurg udev[10598]: creating device node '/udev/sda'
Sep  6 10:12:43 zurg udev[10599]: creating device node '/udev/sda1'
Sep  6 10:13:55 zurg samurai: Successful mounting of Lexar 256Mbyte
stick -- NO GPILOTD
Sep  6 10:14:31 zurg samurai: Unmounting Lexar 256 Mbyte Stick
Sep  6 10:15:15 zurg udev[10635]: removing device node '/udev/sg0'
Sep  6 10:15:15 zurg udev[10653]: removing device node '/udev/sda1'
Sep  6 10:15:16 zurg udev[10664]: removing device node '/udev/sda'
Sep  6 10:15:16 zurg kernel: usb 1-1: USB disconnect, address 3
Sep  6 10:15:31 zurg samurai: Starting the test of USB MEMORY DRIVES---
WITH GPILOTD
Sep  6 10:15:38 zurg kernel: usb 1-1: new high speed USB device using
address 4
Sep  6 10:15:38 zurg kernel: scsi1 : SCSI emulation for USB Mass Storage
devices
Sep  6 10:15:38 zurg kernel:   Vendor: Generic   Model: STORAGE
DEVICE    Rev: 1.25
Sep  6 10:15:38 zurg kernel:   Type:  
Direct-Access                      ANSI SCSI revision: 02
Sep  6 10:15:39 zurg kernel: SCSI device sda: 512000 512-byte hdwr
sectors (262 MB)
Sep  6 10:15:39 zurg kernel: sda: Write Protect is off
Sep  6 10:15:39 zurg kernel: sda: assuming drive cache: write through
Sep  6 10:15:39 zurg kernel:  sda: sda1
Sep  6 10:15:39 zurg kernel: Attached scsi removable disk sda at scsi1,
channel 0, id 0, lun 0
Sep  6 10:15:39 zurg kernel: Attached scsi generic sg0 at scsi1, channel
0, id 0, lun 0,  type 0
Sep  6 10:15:39 zurg kernel: updfstab: Using deprecated /dev/sg
mechanism instead of SG_IO on the actual device
Sep  6 10:15:39 zurg scsi.agent[10749]: disk at
/devices/pci0000:00/0000:00:03.2/usb1/1-1/1-1:1.0/host1/1:0:0:0
Sep  6 10:15:41 zurg udev[10817]: creating device node '/udev/sda'
Sep  6 10:15:41 zurg udev[10818]: creating device node '/udev/sda1'
Sep  6 10:15:41 zurg udev[10828]: creating device node '/udev/sg0'
Sep  6 10:17:10 zurg kernel: usb 1-1: control timeout on ep0in
Sep  6 10:17:45 zurg last message repeated 7 times
Sep  6 10:18:50 zurg last message repeated 13 times
Sep  6 10:19:05 zurg last message repeated 3 times
Sep  6 10:19:05 zurg udev[10906]: removing device node '/udev/sg0'
Sep  6 10:19:05 zurg kernel: scsi: Device offlined - not ready after
error recovery: host 1 channel 0 id 0 lun 0
Sep  6 10:19:05 zurg kernel: SCSI error : <1 0 0 0> return code =
0x50000
Sep  6 10:19:05 zurg kernel: end_request: I/O error, dev sda, sector 32
Sep  6 10:19:05 zurg kernel: usb 1-1: USB disconnect, address 4
Sep  6 10:19:05 zurg kernel: FAT: unable to read boot sector
Sep  6 10:19:05 zurg udev[10924]: removing device node '/udev/sda1'
Sep  6 10:19:05 zurg udev[10935]: removing device node '/udev/sda'
Sep  6 10:19:06 zurg kernel: usb 1-1: new high speed USB device using
address 5
Sep  6 10:19:06 zurg kernel: scsi2 : SCSI emulation for USB Mass Storage
devices
Sep  6 10:19:06 zurg kernel:   Vendor: Generic   Model: STORAGE
DEVICE    Rev: 1.25
Sep  6 10:19:06 zurg kernel:   Type:  
Direct-Access                      ANSI SCSI revision: 02
Sep  6 10:19:07 zurg kernel: SCSI device sda: 512000 512-byte hdwr
sectors (262 MB)
Sep  6 10:19:07 zurg kernel: sda: Write Protect is off
Sep  6 10:19:07 zurg kernel: sda: assuming drive cache: write through
Sep  6 10:19:07 zurg kernel:  sda: sda1
Sep  6 10:19:07 zurg kernel: Attached scsi removable disk sda at scsi2,
channel 0, id 0, lun 0
Sep  6 10:19:07 zurg kernel: Attached scsi generic sg0 at scsi2, channel
0, id 0, lun 0,  type 0
Sep  6 10:19:08 zurg scsi.agent[11020]: disk at
/devices/pci0000:00/0000:00:03.2/usb1/1-1/1-1:1.0/host2/2:0:0:0
Sep  6 10:19:08 zurg udev[11086]: creating device node '/udev/sda'
Sep  6 10:19:08 zurg udev[11087]: creating device node '/udev/sda1'
Sep  6 10:19:08 zurg udev[11089]: creating device node '/udev/sg0'
Sep  6 10:20:14 zurg samurai: End of Unsuccessful mount --- WITH GPILOTD
Sep  6 10:20:23 zurg udev[11125]: removing device node '/udev/sg0'
Sep  6 10:20:23 zurg udev[11143]: removing device node '/udev/sda1'
Sep  6 10:20:23 zurg kernel: usb 1-1: USB disconnect, address 5
Sep  6 10:20:23 zurg udev[11189]: removing device node '/udev/sda'
Sep  6 10:20:50 zurg samurai: Pausing GPILOTD and trying previous test
again
Sep  6 10:21:03 zurg kernel: usb 1-1: new high speed USB device using
address 6
Sep  6 10:21:03 zurg kernel: scsi3 : SCSI emulation for USB Mass Storage
devices
Sep  6 10:21:03 zurg kernel:   Vendor: Generic   Model: STORAGE
DEVICE    Rev: 1.25
Sep  6 10:21:03 zurg kernel:   Type:  
Direct-Access                      ANSI SCSI revision: 02
Sep  6 10:21:04 zurg kernel: SCSI device sda: 512000 512-byte hdwr
sectors (262 MB)
Sep  6 10:21:04 zurg kernel: sda: Write Protect is off
Sep  6 10:21:04 zurg kernel: sda: assuming drive cache: write through
Sep  6 10:21:04 zurg kernel:  sda: sda1
Sep  6 10:21:04 zurg kernel: Attached scsi removable disk sda at scsi3,
channel 0, id 0, lun 0
Sep  6 10:21:04 zurg kernel: Attached scsi generic sg0 at scsi3, channel
0, id 0, lun 0,  type 0
Sep  6 10:21:04 zurg scsi.agent[11246]: disk at
/devices/pci0000:00/0000:00:03.2/usb1/1-1/1-1:1.0/host3/3:0:0:0
Sep  6 10:21:05 zurg udev[11307]: creating device node '/udev/sda'
Sep  6 10:21:05 zurg udev[11308]: creating device node '/udev/sda1'
Sep  6 10:21:05 zurg udev[11310]: creating device node '/udev/sg0'
Sep  6 10:22:00 zurg samurai: Successful Mounting with GPILOTD paused
Sep  6 10:22:22 zurg samurai: Successful unMounting of usbdrive with
GPILOTD paused
Sep  6 10:22:25 zurg udev[11337]: removing device node '/udev/sg0'
Sep  6 10:22:25 zurg udev[11355]: removing device node '/udev/sda1'
Sep  6 10:22:25 zurg udev[11366]: removing device node '/udev/sda'
Sep  6 10:22:25 zurg kernel: usb 1-1: USB disconnect, address 6
****************************************** [ End of /var/log/messages ]

On top of all this I find gpilotd extremely intermittent with hotsyncing
my Clie. Most of the time it won't work, unless I do strange things with
stopping and restarting the daemon while attempting a hotsync. Having
said that however, it worked fine with my old pilot that used a serial
cable for hotsync.

Now on top of all this coolness pilot-xfer works perfectly for
hotsyncing and backup of the clie. I'm just very disappointed because I
really didn't think that wanting a palm device to synchronize though
evolution should be that big of an issue.

Thanks for your reply
-- 
Sam Williams                                             samurai acm org
+----------------------------------------------------------------------+
+"It is easy to be blinded to the essential uselessness of computers   +
+ by the sense of accomplishment you get from getting them to work at  +
+ all."                                                                +
+                                                     - Douglas Adams  +
+----------------------------------------------------------------------+