Bug 131154

Created attachment 103194 [details]
Log of hald --daemon=no --verbose=yes

Created attachment 103195 [details]
Output of lshal

bah no need to make an attachment for the cat /proc/scsi/scsi its very
short. 
Attached devices:
Host: scsi0 Channel: 00 Id: 00 Lun: 00
  Vendor:          Model: Scanner 600A4    Rev: 1.23
  Type:   Scanner                          ANSI SCSI revision: 02
Host: scsi6 Channel: 00 Id: 00 Lun: 00
  Vendor: USB      Model: Flash Disk       Rev: 1.00
  Type:   Direct-Access                    ANSI SCSI revision: 02


The flash Disk is what is showing up as sda, but hal isnt creating a
mount point for it.... unless hal is started with the device plugged in.

-jef

Hi, thanks for the debug logs. 

I think I know what is wrong - udevinfo is failing and this confuses
hal; this is a bug in hal (should be a very easy fix though) to not
handle this error condition properly, but it is also a bug in udev.

Try killing hald, run udevstart, startup hald (with --daemon=no
--verbose=yes), wait for hald to say "device probing is complete" and
plugin your usbstick again. 

Please also try hotplugging all your devices; IIRC you mentioned on
the fedora-test mailing list that this was a problem.

Question: what version of udev are you running?

Thanks,
David

udev-030-7, which should be the latest available in the development
tree.  I'd love to blame udev...i really would.  How about we schedule
a day sometime in the next week, build a metal sculpture representing
udev and the spend some quality time beating the physical
manifestation of udev with baseball bats.. spiked baseball bats.

how long should i be waiting for hald to produce the text
"device probing is complete"?  hald started over 5 minutes ago and
that text message isnt in the log i started from the output.  So i
waited for 5 minutes no "device probing is complete" string and
plugged the stick in anyways defying your instructions out of a desire
to go to bed.  No change. 

I'll do the udevstart, hald, wait again and let it sit there till
morning logging the hald output. But if I didnt see that string in the
first 5 minutes I'm not particularly hopeful of seeing it in 4 hours
either on this dual athlon xp 1800+ box.


Do I need to unplug all my other usb devices like my scanner and my
printer to do this test?  I've been concentrating on my usb storage
devices so far becuase the printer and the scanner seem to be working
fine.


-jef

Hi, yeah it will take some time to get udev fully integrated; it's
nice to have a minimal /dev though.

The device probing complete should really happen within a few seconds.
Please send the logs you got until now, in particular they shouldn't
have any lines such as '19:10:26.587 [E] linux/common.c:687:
/usr/bin/udevinfo returned 256 for /block/hda/hda5'. Thanks.

Also trying to unplug your scanner might help. 

/me stares at '19:10:26.684 [I] linux/osspec.c:743: handling
/sys/class/scsi_host/host0 scsi_host'

Thanks,
David

Before unplugging the scanner please attach output of 'tree /sys'.

OK, I *think* that I fixed the problem, no promises, but... Please try
these RPMS

 http://freedesktop.org/~david/js-rpms/

I built them at home (I'm lazy on saturdays :-), so if they look good
I'll run them through the build system.

If it fails please post the hald output again. In either case please
post output of 'tree /sys' with your scanner plugged in.

thanks,
david

Created attachment 103202 [details]
hald verbose output from saturday

Almost there..... I'll attach a log of the hald session of my actions
0)start hald
1)usbstick is seen and fstab entry created!!!!!  /media/usbdisk
2)compact flash card reader is seen and fstab entry created when flash
card is inserted in the reader after the reader is plugged in.
/media/usbdisk1
3)nikon digital camera... /dev/sdc1 device created... hal doesnt
update the fstab or /media.
4)unmount the usbdisk and usbdisk1 volumes, gnome volume manager is
set to automount the hotpluggable storage devices
5)remove nikon camera from the system
6)remove compact flash card from reader, reader is still plugged im
  /media and fstab are updated
7)remove usbstick, /media and fstab are updated
8)put the camera back on to see if hal notices it....no luck there
9)stop hald 

this is with the scanner plugged in still.
I'll also attach the output of tree /sys in a second

Created attachment 103204 [details]
tree /sys

did a little more testing... im not getting consistent behavior out
doing the camera,flash reader, and usbstick in different orders
i get situations where the usbstick doesnt get a mount point.
I can't get the camera to ever have a mount point.

Hi, this looks good so far. I'm a bit troubled to see lines like this

10:40:38.285 [E] linux/common.c:687: /usr/bin/udevinfo returned 256
for /block/hda

Did you reboot since last udevstart? Seems so, try to run udevstart
and see if this comes up again. (udevstart should be run be the
initscripts but I think that is a bug in udev). 

If this makes it work we need to file a bug against udev (it may be
the same problem as described below though).

Another thing that troubles me is this; this is when we get the event

10:42:35.370 [I] linux/osspec.c:1381: Queing up seqnum=474,
sysfspath=/block/sdc, subsys=block

Then when we process it (we have to order the hotplug events to
process them in the right order)

10:42:37.353 [I] linux/osspec.c:1125: add, SEQNUM=474 subsystem=block
sysfs_path=/sys/block/sdc

we wait up to sixty seconds for udev to give us anything (will also
work if udev sent us something before either of these events), but
with no luck

10:43:37.359 [W] linux/class_device.c:399: Never got device file for
class device at /sys/block/sdc

I think what we are seeing is a symptom of this 

 http://freedesktop.org/pipermail/hal/2004-August/000851.html

that is probably caused by the hotplug scripts taking to long (e.g.
udevd ignores the hotplug event for /block/sdc because of timeouts)

If you can try to change the symlinks in /etc/hotplug.d/default as
described in the mail from Kay and test again it would be superb.

Btw, it's really great to get testing like this; I really appreciate it.

Interestingly enough, we do get the remove events (udev unfortunately
got a bug where it doesn't give us SEQNUM but Kay got patch)

10:46:59.216 [I] linux/osspec.c:1171: entering rem, Seqnum=-1 
subsystem=block devpath=/block/sdc devnode=/dev/sdc
10:46:59.216 [I] linux/osspec.c:1171: entering rem, Seqnum=-1 
subsystem=block devpath=/block/sdc/sdc1 devnode=/dev/sdc1

Does /var/log/messages contain messages about udev creating /dev/sdc
and /dev/sdc1 between 10:42 and 10:47?

Re: comment 15

Aug 28 10:42:37 goober udev[16537]: creating device node '/dev/sdc'
Aug 28 10:42:37 goober udev[16538]: creating device node '/dev/sdc1'
Aug 28 10:42:37 goober udev[16540]: creating device node '/dev/sg3'
Aug 28 10:46:59 goober kernel: usb 1-1.4: USB disconnect, address 17
Aug 28 10:46:59 goober udev[16621]: removing device node '/dev/sg3'
Aug 28 10:46:59 goober udev[16629]: removing device node '/dev/sdc'
Aug 28 10:46:59 goober udev[16627]: removing device node '/dev/sdc1'

i've been watching /var/log/messages like a hawk, i see the devices
get created and removed like I expect everytime.

Re Comment 14:
I just pulled the lasted rawhide updates... including a udev update...
im going to reboot and do the udevstart dance again with the new
kernel and udev and initscripts packages i just pulled down from rawhide.

/etc/rc.d/rc.sysinit  doesn't show any call to udevstart that i can
find. Does the initrd run udevstart? 

-jef

Hi, 

I think the initrd runs udevstart, yeah.

Hmm, strange indeed with hal not receiving the message; I'll look into
the hal.dev source but it's extremely simple (like one page of code).

For debugging, please try to download the hal.dev binary (i386) from 
http://freedesktop.org/~david/js-rpms/ and put it into /usr/libexec -
you might need to make it executable (I always forget). It contains a
lot more debug so I can figure out what is wrong.

I have to leave for tonight unfortunately, some commitments in rl, but
I'm back tomorrow morning (I'm at UTC+2, in Denmark).

Thanks

Holy crap! going to the 532 kernel was a HUGE mistake!
the introduction of ub into the kernel is giving me a flood of I/O
errors on any usb mass storage device.  Ugh.... thats going to suck a
lot, if I have to beat up on the kernel level stuff...before I can
beat up on udev...before I can beat up on hal...before I can beat up
on gamin and gnome-volume-manager.

So im back down to 526smp, and things are actually a little better.
with the new rawhide updates Im not getting /media/floppy and
/media/cdrw created for the first time at boot up. So thats positive
motion.

As for the usb hotplugging... it seems i need to run udevstart again
after boot up to get hal to co-operate... even though its being run in
initrd. I'll give you a new set of hald logging ouput in the two cases
 udevstart being run and not being run, this afternoon.

Still having issues with hal when the camera is connected. the camera
is never really seen correctly even by itself.. and if i have the
camera connect my usbstick doesnt get seen properly either..but the
flash card reader does still.  I'll run through all the scenarios and
summarize it step-by-step when i give you the new log this afternoon.

First thing I'm going to do is install that hal.dev binary and see.
Expect a couple of more comments and a couple of attachments later today.

-jef

test of usb mass storage hotplugging without manually running
udevstart.  Attached is the associated section of /var/log/messages
as well as the output of verbose hal.   
packages I'm using
kernel-smp-2.6.8-1.526
initscripts-7.73-1
udev-030-10
hal-0.2.97.cvs20040828-1

times denoted in EST starting at 2:38 PM:
2:38 bootup  with flash card reader plugged in with no card
2:40 hald --daemon=no --verbose=yes 2>/tmp/no-udevstart-hal.log
2:41 plug in flash card in reader 
        /media/usbdisk created  fstab updated
        gnome-volume-manager mounted the device
2:43 plugin usbdisk 
     /media/usbdisk1 created  fstab updated
     gnome-volume-manager mounted the device
2:45 unmount usbdisk1 via desktop icon
2:46 unplug usbdisk
       fstab and /media updated
2.47 unmount usbdisk via desktop icon
2:48   remove compact flash card from reader      
        fstab and /media updated
2:49 usbdisk plugged in  
        /media/usbdisk created and mounted on  desktop
2:50 cf card inserted into reader
       /media/usbdisk1 created and mounted on desktop
2:51 plugin nikon digital camera
       hal seems
2:53: remove camera
2:55 unmount usbdisk and usbdisk1
2:56 unplug usbdisk and remove cf card from reader
2:57 plugin in camera
2:57:30 cf card inserted  /media/usbdisk created
5:58  usbdisk plugged in.... hal is confused

noticing lots of errors in /var/log/messages associated with sdb
stopped the test to reboot

rebooted with flash card reader empty and usbstick plugged in
stopped haldaemon service
ran  udevstart
no usbdisk mountpoint
3:10 plugged in nikon camera
        usbdisk1 mountpoint created and automounted
3:14  unplug camera and usbstick
        flash carder reader still in place with no card
3:15 plugin usbdisk
        nothing
        unplug usbdisk
3:16 plug in camera
        nothing
3:17 insert flash card
        usbdisk created and mounted
        insert usbdisk
        nothing

rebooting again.... to start fresh

Created attachment 103211 [details]
Hald output from test session in comment 19

Created attachment 103212 [details]
/va/log/messages for session in comment 19

test of usb mass storage hotplugging with manual running
udevstart after boot up.

boot  flash card reader plugged in with no card inserted
3:25 udevstart
3:26 hald verbose /tmp/udevstart-hal.log
3:27 plugin camera
        /media/usbdisk mount point created and mounted on desktop
        /dev/sdb1 device used
3:28  insert cf card in reader
         /media/usbdisk1 created and mounted on desktop
         /dev/sda1 device used
3:29  plugin usbdisk
         /dev/sdc1 device used and is mountable
         no mountpoint created by hal 
3:33 usbdisk unplugged
3:34 umount unplug camera
       umount remove cf card from reader
       hal cleans up the mount points
3:35 plug in the usbdisk
       /dev/sdb1 used but no hal mount point
       unplug usbdisk
3:37 insert cf card
        /media/usbdisk mounted
        remove cf card hal mount point removed

stopping hald running udevstart again restarting hald
/tmp/udevstart-hal2.log

3:39 plugin in usbdisk
       /dev/sdb1 used and /media/usbdisk mountpoint created
3:41 insert cf card into reader
       /dev/sda1 used and /media/usbdisk1 created
3:42 plugin camera
        no mount point created no messages about /dev/sdc1 being used
        is this a udev bug?
3:44  remove all three devices
        sdb io errors now going to need to reboot most likely

Created attachment 103213 [details]
Hald output from test session in comment 22

Created attachment 103214 [details]
/va/log/messages for session in comment 22

Yah, Bugzilla is now back (been down most of the day for some reason).

A few things;

1. Thanks for the logs, very useful, this is great.

2. udevstart seems to be called on boot; at least hald doesn't
complain about missing device nodes and it creates mount points for
your optical and floppy drives.

3. The timestamps doesn't seem to match the bugzilla comments though,
did you attach the wrong logs or enter the wrong times in the comments?

4. Everything seems to work so far (there are no timeouts or warnings)
in HAL proper so I think we may have isolated the problems to
fstab-sync, e.g. entries not being created in /etc/fstab. Would you agree?

5. If you can reproduce a problem when a fstab entry isn't created or
removed, it is sufficient to post all the hald output up until that
point, /var/log/messages output from start of hald till that point,
the time it happened (and /dev-node name), what /etc/fstab looked like
at that point and a lshal output dump at that point in time.

I have a gut feeling these errors are caused by either problems with
the media or the driver (cf. the io errors) which causes the
filesystem probing code in hal to fail. Which may indeed be errors in
the hal filesystem probe code, who knows? But I need the logs
mentioned in 5. to verify that :-)

Much thanks,
Davie

re comment 25
3) I i just checked... attachments 103211  and 103212 concerning
comment 19  have the correct timeframe starting at about 14:40 /2 :40
PM. I did how ever leave out one attachment concerning some of the
testing in comment 22.  I will add the /tmp/udevstart-hal.log  from
3:36 PM as an attachment. The attachment 103213 [details] is
/tmp/udevstart-hal2.log from 3:39 PM. the /var/log/messages in
attchement 103214 covers the full timewindow for both hald starts. 

4) Shrug, since I'm still trying to devine a deeper knowledge of how
this all works I'll defer to your judgement and refrain from agreeing
just in case your wrong so I can point and laugh at you later.  But
from my completely novice reading of the /var/log/messages log, the
lack of an fstab-sync entry seems to be the only thing missing. 

The wierd thing is..i only seem to run into problems when i try to
have my camera and my usbstick in at the same time. If it were
problems with the media or driver interaction with a specific piece of
hardware i have, i would have expected it to fail when no other
storage devices are plugged in.  I'm going to steal my wife's usbstick
and do more testing without the camera.

-jef"starting to rememeber why he bought a cf carder reader in the
first place, so he never ever had to plugin his camera"spaleta

Created attachment 103223 [details]
hald output from first half of comment #22

Thanks, think I'm closing in on it; I'm staring at this line

15:35:12.361 [I] linux/osspec.c:992: dev_file=/dev/sdb1 is for
udi=/org/freedesktop/Hal/devices/temp/70

and wondering why the heck /org/freedesktop/Hal/devices/temp/70 never
got added to the global device list or at least cancelled - that is
without a doubt a bug!

Will investigate, got some ideas already; I may upload some new RPMS
tomorrow with a bit more debug output.

Btw, for some background about hal, fstab-sync, g-v-m etc. one
document is here: http://freedesktop.org/~david/hal-spec/hal-spec.html

Allrighty, I've been able to reproduce this (/dev/sdb1 not appearing
at 15:35:12.361). I was also able to fix it!

The eeeenteresting thing is that I could only trigger it when runnning
the packages specifically compiled for Fedora, e.g. optimized for
i686, pentium4 or whatever. Please give hal-0.2.97.cvs20040901-1 a
whirl and let me know how it works (you need a kernel with usb-storage
instead of ub).

Much thanks,
David

You can get i386 RPMS from http://people.redhat.com/davidz. I also put
up the g-v-m packages you need for bug #130866.

These packages will also appear in Rawhide. 

/dev/sdb1               /media/usbdisk          vfat   
noauto,user,exec,kudzu,noatime,sync 0 0
/dev/sda1               /media/usbdisk1         vfat   
noauto,user,exec,kudzu,noatime,sync 0 0
/dev/sdc1               /media/usbdisk2         vfat   
noauto,user,exec,kudzu,noatime,sync 0 0

flash card, usbstick AND camera all at the same time... if i weren't
too drunk to stand up...i'd dance a jig.

-jef

Yay, very nice! Thanks for all the traces, they were instrumental in
fixing this issue with hal; keep up it good work!

Best,
David