Bug 175892 - hal does not mount usb devices anymore
Summary: hal does not mount usb devices anymore
Keywords:
Status: CLOSED RAWHIDE
Alias: None
Product: Fedora
Classification: Fedora
Component: hal
Version: rawhide
Hardware: All
OS: Linux
medium
medium
Target Milestone: ---
Assignee: David Zeuthen
QA Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2005-12-15 23:31 UTC by Michal Jaegermann
Modified: 2013-03-06 03:44 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2006-10-03 20:19:39 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
gzipped trace from hald from plugging in a USB floppy device (4.28 KB, application/octet-stream)
2005-12-20 00:07 UTC, Michal Jaegermann
no flags Details
verbose log from hald (191.88 KB, text/plain)
2006-09-04 18:23 UTC, Michal Jaegermann
no flags Details
udevd debug log after an attempt to attach a file system on an USB drive (27.48 KB, text/plain)
2006-09-04 18:25 UTC, Michal Jaegermann
no flags Details
udev debug trace with another device (28.69 KB, text/plain)
2006-09-07 21:00 UTC, Michal Jaegermann
no flags Details

Description Michal Jaegermann 2005-12-15 23:31:55 UTC
Description of problem:

After the latest series of massive updates hal apparently ceased any
cooperation with hotplug (or whatever else is involved here). If I plug
in such devices like a USB floppy, or a USB memory stick, I can see those
devices showing up in system logs and 'lshal' output seems to show what
is expected.  A status of hald is also reported as "running".  But apparently
nothing ever runs 'fstab-sync' nor devices are ever mounted and/or
show up on a desktop and/or "Computer" browser.

The other, maybe related, observation is that 'hal-device-manager' takes now
a very long time to show up.  It does that, eventually, but it takes around
30 seconds to do that (measured by watch).

I did not look at hal related issues for quite a while so I do not really
know when this started to misbehave.

Version-Release number of selected component (if applicable):
hal-0.5.5.1-2.1

How reproducible:
always

Comment 1 John (J5) Palmieri 2005-12-15 23:44:07 UTC
hal-device-manager taking a long time to start up is a known issue in the
current d-bus python bindings.  There is no fix as of yet.  As for USB key
mounting mine works fine.  Did you reboot after the update?  Try updating
tomorrow morning and seeing if it is fixed.  Also check that se-linux isn't the
culprit by looking at your logs.

Comment 2 Michal Jaegermann 2005-12-15 23:58:23 UTC
> Did you reboot after the update?

Yes.  All of the above was after a fresh reboot with 2.6.14-1.1765_FC5
kernel. SELinux is not a culprit as it is not active.

> As for USB key mounting mine works fine.

Maybe then this is an issue of architecture?  I was doing that on x86_64
and hal used to work (at least in general).

I will see what will happen tomorrow.


Comment 3 Michal Jaegermann 2005-12-16 00:45:00 UTC
Maybe an underlying reason is that for every invocation of fstab-sync, does
not matter what options and arguments, I am seeing:

error: libhal_ctx_init_direct: (null): (null)

In particular I am seeing that when trying '--add' with UDI taken from lshal
output.

Comment 4 John (J5) Palmieri 2005-12-16 01:20:12 UTC
I also did it on an X86_64.

You can't run fstab-sync from outside a HAL callout because fstab-sync talks to
hal directly through a socket which Hal passes as part of the enviornment when
invoking fstab-sync.  It should most likely talk through the bus if it can't
connect on the private channel but we are getting rid of fstab-sync in the
future anyway.

I'm thinking I heard some rumbling about gnome-vfs2 doing some bad stuff that is
now fixed (in fact I think this morning) so that might be the problem in which
case you just need to update tomorrow.  I got the fix because we have local
repositories and the public repositories only get updated once a night.

Confirm that fstab-sync is functioning by looking in /etc/fstab for an entry
after you plug in your device (BTW it won't be there for a USB floppy unless you
have a disk in the drive).

Comment 5 Michal Jaegermann 2005-12-16 20:49:44 UTC
I updated at this moment the following packages:

Dec 16 12:32:32 Updated: gnome-vfs2.x86_64 2.13.3-1
Dec 16 12:32:34 Updated: gnome-vfs2.i386 2.13.3-1
Dec 16 12:32:35 Updated: gnome-vfs2-devel.x86_64 2.13.3-1
Dec 16 12:32:36 Updated: gnome-vfs2-smb.x86_64 2.13.3-1
Dec 16 12:32:37 Updated: gnome-volume-manager.x86_64 1.5.5-1

This does not show any real changes in the problem.

Hooking up a USB floppy shows in logs something like that:

usb-storage: device found at 5
usb-storage: waiting for device to settle before scanning
  Vendor: SONY      Model: USB-FDU           Rev: 5.01
  Type:   Direct-Access                      ANSI SCSI revision: 00
SCSI device sdd: 1440 512-byte hdwr sectors (1 MB)
sdd: Write Protect is on
sdd: Mode Sense: 00 46 1e 80
sdd: assuming drive cache: write through
SCSI device sdd: 1440 512-byte hdwr sectors (1 MB)
sdd: Write Protect is on
sdd: Mode Sense: 00 46 1e 80
sdd: assuming drive cache: write through
 sdd: unknown partition table
sd 7:0:0:0: Attached scsi removable disk sdd
usb-storage: device scan complete

but no changes on a desktop or in /etc/fstab.

If I will do 'service haldaemon restart' while USB floppy is physically
attached then this takes 23 seconds of a wall-clock time and relevant lines
in /etc/fstab change from

/dev/fd0                /media/floppy          auto ....

to

/dev/sdd                /media/floppy           auto ...
/dev/fd0                /media/floppy1          auto ...

(I used to have some user policy file to prevent such name flip-flops
but apparently some hal update destroyed it without traces).  With that
I can do, at least as root, 'mount /media/floppy' and that action not only
produces a new icon on a desktop but also pops out an annoying browser window.
Unplugging that device physically does unmount /media/floppy, and
a corresponding line goes away from /etc/fstab, but plugging it back does
not have any visible changes with a mount situation nor causes further updates
in /etc/fstab.

The same goes with

usb-storage: device found at 6
usb-storage: waiting for device to settle before scanning
  Vendor: SanDisk   Model: Cruzer Mini       Rev: 0.2 
  Type:   Direct-Access                      ANSI SCSI revision: 02
SCSI device sdd: 2001888 512-byte hdwr sectors (1025 MB)
sdd: Write Protect is off
sdd: Mode Sense: 03 00 00 00
sdd: assuming drive cache: write through
SCSI device sdd: 2001888 512-byte hdwr sectors (1025 MB)
sdd: Write Protect is off
sdd: Mode Sense: 03 00 00 00
sdd: assuming drive cache: write through
 sdd: sdd1
sd 9:0:0:0: Attached scsi removable disk sdd

regardless if it used on its own or together with a USB floppy, i.e.
that a corresponding "/media/usbdisk" line in /etc/fstab will be found
if I restarted haldaemon while that device was attached and so on ...

As for 'fstab-sync' manpage says "This program is usually never run directly
from a shell" but it does not follow from that it cannot be used that way.
Actually this was possible in the past; I did that while trying to resolve
some earlier hal problems.  If this is no longer true then that documentation
needs an update and '--usage' and '--help' options seem to be of a little
value.


Comment 6 Tom London 2005-12-17 18:41:09 UTC
I'm seeing the same issue: /dev/sda? entries created, /media/usbdisk dirs
created, but no mounts.

Manually mounting (e.g., 'mount /dev/sda2 /media/usbdisk') works, but no
automounting is happening.

Dec 17 09:55:24 localhost kernel: Initializing USB Mass Storage driver...
Dec 17 09:55:24 localhost kernel: scsi0 : SCSI emulation for USB Mass Storage
devices
Dec 17 09:55:24 localhost kernel: usbcore: registered new driver usb-storage
Dec 17 09:55:24 localhost kernel: USB Mass Storage support registered.
Dec 17 09:55:29 localhost kernel:   Vendor: TOSHIBA   Model: MK8026GAX        
Rev: 0811
Dec 17 09:55:29 localhost kernel:   Type:   Direct-Access                     
ANSI SCSI revision: 00
Dec 17 09:55:29 localhost kernel: SCSI device sda: 156301488 512-byte hdwr
sectors (80026 MB)
Dec 17 09:55:29 localhost kernel: sda: assuming drive cache: write through
Dec 17 09:55:29 localhost kernel: SCSI device sda: 156301488 512-byte hdwr
sectors (80026 MB)
Dec 17 09:55:29 localhost kernel: sda: assuming drive cache: write through
Dec 17 09:55:29 localhost kernel:  sda: sda1 sda2 sda3
Dec 17 09:55:29 localhost kernel: sd 0:0:0:0: Attached scsi disk sda
Dec 17 09:55:31 localhost fstab-sync[4354]: added mount point /media/usbdisk for
/dev/sda2
Dec 17 09:55:31 localhost fstab-sync[4357]: added mount point /media/usbdisk1
for /dev/sda1

But no mounts.....

Comment 7 Michal Jaegermann 2005-12-17 19:03:26 UTC
> ... localhost fstab-sync[4354]: added mount point ...

In a situation described in comment #6 you are still one important point
ahead of me; namely mount points are added.  I have to restart hald for
that and I still cannot figure out what is the difference.

Comment 8 Tom London 2005-12-17 19:20:24 UTC
I'm running on x86; perhaps....?

Checking /var/log/audit/audit.log yields only the following (not clear that this
is relevant):

----
type=PATH msg=audit(12/17/2005 11:18:30.455:368) : item=0 flags=follow
inode=2142265 dev=fd:00 mode=socket,666 ouid=root ogid=root rdev=00:00
type=SOCKETCALL msg=audit(12/17/2005 11:18:30.455:368) : nargs=3 a0=4
a1=bfa5e966 a2=6e
type=SOCKADDR msg=audit(12/17/2005 11:18:30.455:368) : saddr=local
/var/run/acpid.socket
type=SYSCALL msg=audit(12/17/2005 11:18:30.455:368) : arch=i386
syscall=socketcall(connect) success=no exit=-13(Permission denied) a0=3
a1=bfa5e930 a2=4 a3=8dec030 items=1 pid=2836 auid=unknown(4294967295) uid=root
gid=root euid=root suid=root fsuid=root egid=root sgid=root fsgid=root
comm=hald-addon-acpi exe=/usr/libexec/hald-addon-acpi
type=AVC msg=audit(12/17/2005 11:18:30.455:368) : avc:  denied  { write } for 
pid=2836 comm=hald-addon-acpi name=acpid.socket dev=dm-0 ino=2142265
scontext=system_u:system_r:hald_t:s0 tcontext=system_u:object_r:var_run_t:s0
tclass=sock_file


Comment 9 Michal Jaegermann 2005-12-20 00:07:43 UTC
Created attachment 122428 [details]
gzipped trace from hald from plugging in a USB floppy device

With rawhide updates current I tried to attach strace to a running hald and
plug in my USB floppy test device.  Results are attached but I am not sure
how to interpret these.

'netstat' shows that hald has a DGRAM socket @/var/run/hal/hotplug_socket2
and also listens on @/tmp/hald-local/dbus-PGMPwxAECL (with this one showing
ACC flags hence, I think, unconnected).

Comment 10 Nickolay V. Shmyrev 2006-09-03 18:30:33 UTC
Michal, please enable hald debug with --verbose=yes --syslog and search for the
messages in 

15:34:55.556 [E] util.c:516: Cannot open
'/sys/devices/pci0000:00/0000:00:03.2/usb1/1-5/1-5:1.0/host6/target6:0:0/6:0:0:0/model'
15:34:55.556 [E] util.c:516: Cannot open
'/sys/devices/pci0000:00/0000:00:03.2/usb1/1-5/1-5:1.0/host6/target6:0:0/6:0:0:0/vendor'
15:34:55.556 [E] util.c:324: Cannot open
'/sys/devices/pci0000:00/0000:00:03.2/usb1/1-5/1-5:1.0/host6/target6:0:0/6:0:0:0/type'

From your strace I see it's probably the same problem as in the bug 200047 and
hal bug https://bugs.freedesktop.org/show_bug.cgi?id=7756



Comment 11 Michal Jaegermann 2006-09-03 20:29:15 UTC
I indeed can find (with '--use-syslog' option) "Cannot open" messages
but they look slightly different:

13:32:41.538 [E] util.c:322: Cannot open
'/sys/devices/pci0000:00/0000:00:07.0/fw-host0/00e0180000575a14/00e0180000575a14-0/model_id'
13:33:11.029 [E] util.c:463: Cannot open
'/sys/devices/pci0000:00/0000:00:10.3/usb4/4-1/serial'
13:33:11.029 [E] util.c:463: Cannot open
'/sys/devices/pci0000:00/0000:00:10.3/usb4/4-1/serial'

But a situation did change somewhat in over eight months from a time
of the original report.  AFAICS removable media now are automatically
mounted, at least on my test machine,  but only on non-root accounts.
I do not have any particular problem with that but I have a gnawing
suspicion that this is by an accident and not by a design.

One reason for that feeling is that attempts to use hal via automount
often end up with unexpected and hard to reproduce side-effects.  For
example after login on _another_ account may open, not anticipated and
totally by themselves, multiple browse windows to a fixed file system;
or in a gnome-terminal window a key starts to autorepeat ad infinitum.
Nothing of that sort ever happens if you will leaven removable media
and hald alone.  Add to that a long overdue mythical "Policy Kit" and ...

Comment 12 Nickolay V. Shmyrev 2006-09-03 21:38:33 UTC
It's udev bug 201422 actually and it should be fixed in rawhide already. Please
mark it as a duplicate.

Heh, of course it's a bit buggy, but I suspect the discussion is out of topic
here. We can improve the situation at least by filing bug reports.

Comment 13 Michal Jaegermann 2006-09-03 22:53:02 UTC
> It's udev bug 201422 actually and it should be fixed in rawhide already.
> Please mark it as a duplicate.

Are you sure?  Bug 201422 was closed nearly two months ago and it appears
that I am still seeing a not entirely correct behaviour.  Or you are saying
that everything is how it is supposed to be?  How can I tell?

Comment 14 Nickolay V. Shmyrev 2006-09-04 04:16:49 UTC
Well, I am not sure so completely. Can you paste the logs then with verbose
messages of hald and also enabled debug of udev (run command udevcontrol
log_priority=debug)

Comment 15 Michal Jaegermann 2006-09-04 18:23:40 UTC
Created attachment 135507 [details]
verbose log from hald

> Can you paste the logs then with verbose messages of hald

Pasting would be slightly excessive. :-)  This log is closing to
200K in size.  Attached.

Just in case of some doubts.  This log comes from a try with a working
device and with a valid, mountable and "no problems" file system on it.

Comment 16 Michal Jaegermann 2006-09-04 18:25:39 UTC
Created attachment 135508 [details]
udevd debug log after an attempt to attach a file system on an USB drive

Comment 17 Nickolay V. Shmyrev 2006-09-07 05:41:42 UTC
From what I see from the logs when you are mounting USB, udev waits for events
because it has rule

ACTION=="add", SUBSYSTEM=="scsi", WAIT_FOR_SYSFS="ioerr_cnt"

The line is about it

udevd-event[2812]: wait_for_sysfs: wait for
'/sys/devices/pci0000:00/0000:00:10.3/usb4/4-1/4-1:1.0/host5/target5:0:0/5:0:0:0/ioerr_cnt'
for 20 mseconds

But when you are mounting serial, the rule doesn't work. So you need to
update the rule. Probably replacing SYBSYSTEM="scsi" to SUBSYSTEM="serial" or
something like that.

But for me it looks like a major flow in hal design - kernel creates devices
asynchornously while hald handle then like synchronouns devices. That's
ceratainly a hald bug


Comment 18 Michal Jaegermann 2006-09-07 21:00:07 UTC
Created attachment 135809 [details]
udev debug trace with another device

> But when you are mounting serial, the rule doesn't work.

Well, here is a trace while using SanDisk memory stick.  There
is nothing "serial" here AFAICS.  It looks to me from all of this
that a device is actually mounted and for some reasons immediately
removed without any action on my part.	I am not sure why.

As mentioned previously currently on non-root accounts a behaviour
is different (so, in that sense, this is is not a big deal).

Comment 19 David Zeuthen 2006-09-28 23:42:46 UTC
Is this still happening with latest Rawhide?

Comment 20 Michal Jaegermann 2006-09-28 23:48:37 UTC
> Is this still happening with latest Rawhide?

AFAICS this is fixed (and I even mentioned that elsewhere on bugzilla).
I do not know about others. Nickolay? Tom?

Comment 21 Tom London 2006-09-28 23:59:17 UTC
This 'Works for Me'.

Comment 22 David Zeuthen 2006-10-03 20:19:39 UTC
Works for two. Nickolay, please reopen if this doesn't work for you. Thanks.


Note You need to log in before you can comment on or make changes to this bug.