Re: udev fails to add/remove devices

[Kay Sievers <kay.sievers@vrfy.org>]

On Fri, Mar 26, 2004 at 06:08:55PM +0100, Oliver Paschke wrote:
> Hi,
> 
> I have a problem with my current udev/hotplug configuration (023/2004_03_11) since i rebuilt my system (lfs-5.1_pre1, glibc-3.3 against 2.4.25 headers). Udev worked perfectly before (lfs-3.1).
> 
> When I assign /sbin/udev as hotplugging-agent device-adding/-removal works the way it should, but when /proc/sys/kernel/hotplug points to /sbin/hotplug udev queues the events while hotplugging still works fine. Compiling udev with or without klibc doesn't make a difference.

All events are queued by udevd. /sbin/hotplug calls udevsend to
send a message to udevd, which calls the real udev after a possibly
reordering of the sequence numbers.

What says your syslog after doing this as root. I've pasted in, what I
get with a working setup. You can follow the udevsend->udevd->udev->udevd call:

manual send without sequence number:

  ACTION­d DEVPATH=/test /sbin/udevsend test

  Mar 26 18:31:21 pim udevsend[2619]: main: daemon started
  Mar 26 18:31:21 pim udevd[2621]: udev_run: => exec seq -1 [2622] working at '/test'
  Mar 26 18:31:21 pim udevd[2621]: exec_queue_manager: moved seq -1 to running list
  Mar 26 18:31:21 pim udev[2622]: get_dirs: sysfs_path='/sys'
  Mar 26 18:31:21 pim udev[2622]: parse_config_file: reading '/etc/udev/udev.conf' as config file
  Mar 26 18:31:21 pim udev[2622]: main: version 023
  Mar 26 18:31:21 pim udev[2622]: udev_hotplug: looking at '/test'
  Mar 26 18:31:21 pim udev[2622]: udev_hotplug: not a block or class device
  Mar 26 18:31:21 pim udevd[2621]: udev_done: <= exec seq -1 came back
  

manual send with sequence number:

  SEQNUM\x1000000 ACTION­d DEVPATH=/test /sbin/udevsend test

  Mar 26 18:34:03 pim udevsend[2623]: main: version 023
  Mar 26 18:34:03 pim udevsend[2623]: main: subsystem = 'test'
  Mar 26 18:34:03 pim udevsend[2623]: main: DEVPATH = '/test'
  Mar 26 18:34:03 pim udevsend[2623]: main: ACTION = 'add'
  Mar 26 18:34:03 pim udevsend[2623]: main: SEQNUM = '1000000'
  Mar 26 18:34:03 pim udevd[2621]: msg_queue_insert: queued message seq 1000000
  Mar 26 18:34:03 pim udevd[2621]: msg_queue_manager: msg queue manager, next expected is 0
  Mar 26 18:34:03 pim udevd[2621]: msg_dump_queue: sequence 1000000 in queue
  Mar 26 18:34:03 pim udevd[2621]: msg_queue_manager: next event expires in 5 seconds
  Mar 26 18:34:08 pim udevd[2621]: msg_queue_manager: msg queue manager, next expected is 0
  Mar 26 18:34:08 pim udev[2624]: get_dirs: sysfs_path='/sys'
  Mar 26 18:34:08 pim udev[2624]: parse_config_file: reading '/etc/udev/udev.conf' as config file
  Mar 26 18:34:08 pim udev[2624]: main: version 023
  Mar 26 18:34:08 pim udev[2624]: udev_hotplug: looking at '/test'
  Mar 26 18:34:08 pim udevd[2621]: udev_run: => exec seq 1000000 [2624] working at '/test'
  Mar 26 18:34:08 pim udevd[2621]: exec_queue_manager: moved seq 1000000 to running list
  Mar 26 18:34:08 pim udevd[2621]: msg_move_exec: moved seq 1000000 to exec, next expected is 1000001
  Mar 26 18:34:08 pim udev[2624]: udev_hotplug: not a block or class device
  Mar 26 18:34:08 pim udevd[2621]: udev_done: <= exec seq 1000000 came back


> Any help would be appreciated,
> thanks
> 
> 
> Syslog debug-messages of a 'modprobe nvidia' call as example:
> (nvidia module with sysfs patch - alsa behaves the same way..)
> 
> /sbin/hotplug:
> Mar 26 16:53:08 pandora udevsend[1429]: main: version 023
> Mar 26 16:53:08 pandora udevsend[1429]: main: subsystem = 'nvidia'
> Mar 26 16:53:08 pandora udevsend[1429]: main: DEVPATH = '/class/nvidia/nvidiactl'
> Mar 26 16:53:08 pandora udevsend[1429]: main: ACTION = 'add'
> Mar 26 16:53:08 pandora udevsend[1429]: main: SEQNUM = '192'
> Mar 26 16:53:08 pandora udevd[226]: msg_queue_insert: queued message seq 192
> Mar 26 16:53:08 pandora udevd[226]: msg_queue_manager: msg queue manager, next expected is 0
> Mar 26 16:53:08 pandora udevd[226]: msg_dump_queue: sequence 116 in queue
> ...
> Mar 26 16:53:08 pandora udevd[226]: msg_dump_queue: sequence 192 in queue
> Mar 26 16:53:08 pandora udevd[226]: msg_queue_manager: next event expires in 2907 seconds
> Mar 26 16:53:08 pandora udevsend[1435]: main: version 023
> Mar 26 16:53:08 pandora udevsend[1435]: main: subsystem = 'nvidia'
> Mar 26 16:53:08 pandora udevsend[1435]: main: DEVPATH = '/class/nvidia/nvidia0'
> Mar 26 16:53:08 pandora udevsend[1435]: main: ACTION = 'add'
> Mar 26 16:53:08 pandora udevsend[1435]: main: SEQNUM = '193'
> Mar 26 16:53:08 pandora udevd[226]: msg_queue_insert: queued message seq 193
> Mar 26 16:53:08 pandora udevd[226]: msg_queue_manager: msg queue manager, next expected is 0
> Mar 26 16:53:08 pandora udevd[226]: msg_dump_queue: sequence 116 in queue
> ...
> Mar 26 16:53:08 pandora udevd[226]: msg_dump_queue: sequence 193 in queue
> Mar 26 16:53:08 pandora udevd[226]: msg_queue_manager: next event expires in 2907 seconds

Huh, what's this 2907 seconds? Sounds a bit too much :)


> /sbin/udev:
> Mar 26 16:50:59 pandora udev[1412]: get_dirs: sysfs_path='/sys'
> Mar 26 16:50:59 pandora udev[1412]: parse_config_file: reading '/etc/udev/udev.conf' as config file
> Mar 26 16:50:59 pandora udev[1412]: main: version 023
> Mar 26 16:50:59 pandora udev[1412]: udev_hotplug: looking at '/class/nvidia/nvidiactl'
> ...
> Mar 26 16:50:59 pandora udev[1413]: sleep_for_file: looking for '/sys/class/nvidia/nvidia0/dev'
> Mar 26 16:51:00 pandora udev[1412]: sleep_for_file: looking for '/sys/class/nvidia/nvidiactl/dev'
> Mar 26 16:51:00 pandora udev[1412]: get_class_dev: looking at '/sys/class/nvidia/nvidiactl'
> Mar 26 16:51:00 pandora udev[1412]: get_class_dev: class_dev->name='nvidiactl'
> Mar 26 16:51:00 pandora udev[1412]: get_major_minor: dev='195:255 '
> Mar 26 16:51:00 pandora udev[1412]: get_major_minor: found major\x195, minor%5
> Mar 26 16:51:00 pandora udev[1413]: sleep_for_file: looking for '/sys/class/nvidia/nvidia0/dev'
> Mar 26 16:51:00 pandora udev[1413]: get_class_dev: looking at '/sys/class/nvidia/nvidia0'
> Mar 26 16:51:00 pandora udev[1413]: get_class_dev: class_dev->name='nvidia0'
> Mar 26 16:51:00 pandora udev[1413]: get_major_minor: dev='195:0 '
> Mar 26 16:51:00 pandora udev[1413]: get_major_minor: found major\x195, minor=0
> Mar 26 16:51:00 pandora udev[1413]: sysfs_path_is_link: stat() failed 
> Mar 26 16:51:00 pandora last message repeated 7 times
> Mar 26 16:51:00 pandora udev[1413]: sysfs_open_device_path: Could not get device 0000:01:00.0's driver 
> Mar 26 16:51:00 pandora udev[1413]: get_sysfs_device: device 0000:01:00.0 is registered with bus 'pci'
> Mar 26 16:51:00 pandora udev[1413]: namedev_name_device: sysfs_device->path='/sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0'
> Mar 26 16:51:00 pandora udev[1413]: namedev_name_device: sysfs_device->bus_id='0000:01:00.0'
> Mar 26 16:51:00 pandora udev[1413]: namedev_name_device: sysfs_device->bus='pci'
> Mar 26 16:51:00 pandora udev[1413]: wait_for_device_to_initialize: looking for file 'vendor' on bus 'pci'
> Mar 26 16:51:00 pandora udev[1413]: namedev_name_device: class_dev->name = 'nvidia0'
> Mar 26 16:51:00 pandora udev[1413]: namedev_name_device: udev->kernel_name = 'nvidia0'
> Mar 26 16:51:00 pandora udev[1413]: namedev_name_device: kernel_number='0'
> Mar 26 16:51:00 pandora udev[1413]: namedev_name_device: name, 'nvidia0' is going to have owner='root', group='video', mode = 0660
> Mar 26 16:51:00 pandora udev[1413]: udev_add_device: udevdb_add_dev failed, but we are going to try to create the node anyway. But remove might not work properly for this device.
> Mar 26 16:51:00 pandora udev[1413]: udev_add_device: name='nvidia0'
> Mar 26 16:51:00 pandora udev[1413]: creating device node '/dev/nvidia0'
> Mar 26 16:51:00 pandora udev[1413]: make_node: chmod(/dev/nvidia0, 020660)
> Mar 26 16:51:00 pandora udev[1413]: make_node: chown(/dev/nvidia0, 0, 12)
> ...
> Mar 26 16:51:00 pandora udev[1412]: sysfs_path_is_link: stat() failed 
> Mar 26 16:51:00 pandora last message repeated 8 times
> Mar 26 16:51:00 pandora udev[1412]: get_sysfs_device: timed out waiting for device symlink, continuing on anyway...
> Mar 26 16:51:00 pandora udev[1412]: namedev_name_device: class_dev->name = 'nvidiactl'
> Mar 26 16:51:00 pandora udev[1412]: namedev_name_device: udev->kernel_name = 'nvidiactl'
> Mar 26 16:51:00 pandora udev[1412]: namedev_name_device: kernel_number=''
> Mar 26 16:51:00 pandora udev[1412]: namedev_name_device: name, 'nvidiactl' is going to have owner='root', group='video', mode = 0660
> Mar 26 16:51:00 pandora udev[1412]: udev_add_device: udevdb_add_dev failed, but we are going to try to create the node anyway. But remove might not work properly for this device.

Are you sure, that you have removed to old db after upgrading?
Normally 'make install' should do this.

> Mar 26 16:51:00 pandora udev[1412]: udev_add_device: name='nvidiactl'
> Mar 26 16:51:00 pandora udev[1412]: creating device node '/dev/nvidiactl'
> Mar 26 16:51:00 pandora udev[1412]: make_node: chmod(/dev/nvidiactl, 020660)
> Mar 26 16:51:00 pandora udev[1412]: make_node: chown(/dev/nvidiactl, 0, 12)

thanks,
Kay


-------------------------------------------------------
This SF.Net email is sponsored by: IBM Linux Tutorials
Free Linux tutorial presented by Daniel Robbins, President and CEO of
GenToo technologies. Learn everything from fundamentals to system
administration.http://ads.osdn.com/?ad_id\x1470&alloc_id638&op=click
_______________________________________________
Linux-hotplug-devel mailing list  http://linux-hotplug.sourceforge.net
Linux-hotplug-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/linux-hotplug-devel