/var/log/messages is populated with this warning message, from hald removing device : May 25 18:07:27 localhost hald[2309]: 18:07:27.602 [W] device.c:4480: Error removing device Reproducible: Always
Confirmed. [ebuild R ] sys-apps/hal-0.5.11 USE="crypt (-acpi) (-apm) -debug (-dell) -disk-partition -doc (-laptop) (-selinux)" 0 kB They usually come in quintuples: May 25 18:13:59 elmer hald[13732]: 18:13:59.938 [I] osspec.c:241: SEQNUM=1300, A CTION=add, SUBSYSTEM=uids, DEVPATH=/sys/kernel/uids/250, DEVNAME=, IFINDEX=0 May 25 18:13:59 elmer hald[13732]: 18:13:59.938 [I] device.c:4406: add_dev: subs ys=uids sysfs_path=/sys/kernel/uids/250 dev= parent_dev=0x00000000 May 25 18:14:00 elmer hald[13732]: 18:14:00.206 [I] osspec.c:241: SEQNUM=1301, A CTION=remove, SUBSYSTEM=uids, DEVPATH=/sys/kernel/uids/250, DEVNAME=, IFINDEX=0 May 25 18:14:00 elmer hald[13732]: 18:14:00.206 [I] device.c:4476: remove_dev: s ubsys=uids sysfs_path=/sys/kernel/uids/250 May 25 18:14:00 elmer hald[13732]: 18:14:00.206 [W] device.c:4480: Error removin g device [...] May 25 18:34:08 elmer hald[13732]: 18:34:08.658 [I] osspec.c:241: SEQNUM=1302, A CTION=add, SUBSYSTEM=uids, DEVPATH=/sys/kernel/uids/250, DEVNAME=, IFINDEX=0 May 25 18:34:08 elmer hald[13732]: 18:34:08.658 [I] device.c:4406: add_dev: subs ys=uids sysfs_path=/sys/kernel/uids/250 dev= parent_dev=0x00000000 May 25 18:34:13 elmer hald[13732]: 18:34:13.114 [I] osspec.c:241: SEQNUM=1303, A CTION=remove, SUBSYSTEM=uids, DEVPATH=/sys/kernel/uids/250, DEVNAME=, IFINDEX=0 May 25 18:34:13 elmer hald[13732]: 18:34:13.114 [I] device.c:4476: remove_dev: s ubsys=uids sysfs_path=/sys/kernel/uids/250 May 25 18:34:13 elmer hald[13732]: 18:34:13.114 [W] device.c:4480: Error removin g device Sun May 25 19:08:30 CEST 2008 Portage 2.1.5.2 (default-linux/hppa/2007.0, gcc-4.1.2, glibc-2.7-r2, 2.6.25-gentoo-r2-JeR parisc) ================================================================= System uname: 2.6.25-gentoo-r2-JeR parisc PA8700 (PCX-W2) Timestamp of tree: Sun, 25 May 2008 16:21:01 +0000 distcc 2.18.3 hppa2.0-unknown-linux-gnu (protocols 1 and 2) (default port 3632) [disabled] ccache version 2.4 [disabled] app-shells/bash: 3.2_p33 dev-lang/python: 2.4.4-r13, 2.5.2-r4 dev-python/pycrypto: 2.0.1-r6 dev-util/ccache: 2.4-r7 sys-apps/baselayout: 2.0.0 sys-apps/openrc: 0.2.4-r1 sys-apps/sandbox: 1.2.18.1-r2 sys-devel/autoconf: 2.13, 2.61-r1 sys-devel/automake: 1.4_p6, 1.5, 1.6.3, 1.7.9-r1, 1.8.5-r3, 1.9.6-r2, 1.10.1 sys-devel/binutils: 2.18-r1 sys-devel/gcc-config: 1.4.0-r4 sys-devel/libtool: 1.5.26 virtual/os-headers: 2.6.23-r3 ACCEPT_KEYWORDS="hppa" CBUILD="hppa2.0-unknown-linux-gnu" CFLAGS="-O2 -pipe -mschedule=8000 -march=2.0 -g -ggdb -Wall" CHOST="hppa2.0-unknown-linux-gnu" CONFIG_PROTECT="/etc /usr/kde/3.5/env /usr/kde/3.5/share/config /usr/kde/3.5/shutdown /usr/share/X11/xkb /usr/share/config /var/bind /var/spool/torque /var/www/localhost/htdocs/wordpress/wp-config.php" CONFIG_PROTECT_MASK="/etc/env.d /etc/fonts/fonts.conf /etc/gconf /etc/gentoo-release /etc/php/apache2-php5/ext-active/ /etc/php/cgi-php5/ext-active/ /etc/php/cli-php5/ext-active/ /etc/revdep-rebuild /etc/terminfo /etc/texmf/web2c /etc/udev/rules.d" CXXFLAGS="-O2 -pipe -mschedule=8000 -march=2.0 -g -ggdb -Wall" DISTDIR="/keeps/gentoo/distfiles" FEATURES="autoaddcvs buildpkg cvs distlocks fixpackages notitles parallel-fetch sandbox sfperms splitdebug strict unmerge-orphans userfetch" GENTOO_MIRRORS="http://ftp.snt.utwente.nl/pub/os/linux/gentoo http://mirror.muntinternet.net/pub/gentoo/ http://gentoo.tiscali.nl/" LC_ALL="en_US.UTF-8" LDFLAGS="" LINGUAS="en nl he" MAKEOPTS="-j4" PKGDIR="/keeps/gentoo/packages/elmer" PORTAGE_RSYNC_OPTS="--recursive --links --safe-links --perms --times --compress --force --whole-file --delete --stats --timeout=180 --exclude=/distfiles --exclude=/local --exclude=/packages" PORTAGE_TMPDIR="/mnt/alt/portage-tmp" PORTDIR="/keeps/gentoo/portage" PORTDIR_OVERLAY="/keeps/gentoo/local" SYNC="rsync://rsync.europe.gentoo.org/gentoo-portage" USE="7zip X Xaw3d a52 aac aalib accessibility ads alsa amr amrnb amrwb ao aoss apache2 ares arts asf async asyncns audiofile audit automount avfs bash-completion berkdb bidi bittorrent bl bluetooth bzip2 c++ cairo caps catalogs cblas cdb cddb cdparanoia cdr chardet cjk cli cpudetection cracklib crypt cups curl custom-cflags dbtool dbus device-mapper dga dia directfb djbfft domainkeys dts dv dvd dvdr dvdread dxr3 edl elf emacs enca encode esd examples exif expat fam fame fastbuild fastcgi fbcon ffmpeg filter flac fontconfig foomaticdb fortran ftp gadu galago gd gdbm geoip ggi gif gimp gimpprint glep glib glut gmp gnome gnutls gphoto2 gpm gs gsl gtk gtk2 gtkhtml hal hesiod hppa ical icecast iconv idea idn imagemagick imlib immqt-bc inquisitio ipv6 isdnlog jack javascript jingle jpeg jpeg2k kde kerberos lapack lcms ldap leim libcaca libnotify libsamplerate libwww live logrotate logwatch lua lzo mad matroska memcache metis mhash midi mikmod mmap mng modplug motif mozbranding mp3 mpi mplayer mssql mudflap musepack mysql nas ncurses netpbm network-cron nfconntrack nfs nls nntp nptl nptlonly nsplugin offensive ogg openexr opengl openmp oss ots overlays pam pango pbs pch pcre pdf pdo-external perl php pic plotutils plugins png portage portaudio postgres povray ppds pppd pulseaudio python pyzord qdbm qt3 qt3support quotas raw readline recode reflection rpc rrdtool rtc ruby samba sasl scanner scim sdl seamonkey server session sid slang slp sms sndfile snmp soundex speex spell spl sqlite ssl startup-notification suhosin supernodal svg swat sysfs syslog talkfilters tcl tcpd test tga theora threads thunar-vfs tidy tiff timidity tk tools truetype twolame udev unicode unzip urandom usb userlocales utempter utf v4l v4l2 vanim vcd vidix vim-syntax vorbis wavpack webdav webinstall winbind wlan wma wmf xanim xattr xchattext xcomposite xface xml xml2 xmpi xorg xpm xrandr xscreensaver xsettings xulrunner xv xvid xvmc zip zip-external zlib" ALSA_CARDS="ad1889 usb-audio" ALSA_PCM_PLUGINS="adpcm alaw asym copy dmix dshare dsnoop empty extplug file hooks iec958 ioplug ladspa lfloat linear meter mulaw multi null plug rate route share shm softvol" APACHE2_MODULES="actions alias auth_basic auth_digest authn_anon authn_dbd authn_dbm authn_default authn_file authz_dbm authz_default authz_groupfile authz_host authz_owner authz_user autoindex cache dav dav_fs dav_lock dbd deflate dir disk_cache env expires ext_filter file_cache filter headers ident imagemap include info log_config logio mem_cache mime mime_magic negotiation proxy proxy_ajp proxy_balancer proxy_connect proxy_http rewrite setenvif so speling status unique_id userdir usertrack vhost_alias" ELIBC="glibc" INPUT_DEVICES="keyboard mouse evdev joystick" KERNEL="linux" LCD_DEVICES="bayrad cfontz cfontz633 glk hd44780 lb216 lcdm001 mtxorb ncurses text" LINGUAS="en nl he" USERLAND="GNU" VIDEO_CARDS="stifb fbdev matrox" Unset: CPPFLAGS, CTARGET, EMERGE_DEFAULT_OPTS, INSTALL_MASK, LANG, PORTAGE_COMPRESS, PORTAGE_COMPRESS_FLAGS, PORTAGE_RSYNC_EXTRA_OPTS
i had this error too. I realised the /kernel/uid/{foo} just happened to match a user ID in /etc/passwd, and that these errors turned up whenever i ran paludis ( which happened to be running *as* that user ID ) # su -s /bin/rbash paludisbuild rbash: /dev/null/.bashrc: Not a directory su[30947]: Successful su for paludisbuild by root su[30947]: + pts/3 root:paludisbuild su[30947]: pam_unix(su:session): session opened for user paludisbuild by (uid=0) hald[11220]: 10:53:33.790 [I] osspec.c:241: SEQNUM=8280, ACTION=add, SUBSYSTEM=uids, DEVPATH=/sys/kernel/uids/132, DEVNAME=, IFINDEX=0 hald[11220]: 10:53:33.791 [I] device.c:4406: add_dev: subsys=uids sysfs_path=/sys/kernel/uids/132 dev= parent_dev=0x00000000 # exit su[30947]: pam_unix(su:session): session closed for user paludisbuild hald[11220]: 10:54:46.338 [I] osspec.c:241: SEQNUM=8281, ACTION=remove, SUBSYSTEM=uids, DEVPATH=/sys/kernel/uids/132, DEVNAME=, IFINDEX=0 hald[11220]: 10:54:46.338 [I] device.c:4476: remove_dev: subsys=uids sysfs_path=/sys/kernel/uids/132 hald[11220]: 10:54:46.338 [W] device.c:4480: Error removing device After further testing, I discovered this happened *everytime* I 'su'd to a user that wasn't already logged in somewhere. Further digging delegated this cause to UDEV. udevadm monitor udevmonitor will print the received events for: UDEV the event which udev sends out after rule processing UEVENT the kernel uevent UEVENT[1214694054.153910] add /kernel/uids/132 (uids) UDEV [1214694054.157167] add /kernel/uids/132 (uids) UDEV [1214694056.479146] remove /kernel/uids/132 (uids) based on what does turn up in those folders, I imagine this to be a CFS + GroupSechduling connected issue. http://lwn.net/Articles/254559/
Ideally this should be reported upstream, as HAL seems to be responding to uevents that it can not actually handle. (In other words, this bug can not be specific to Gentoo) Should this still be an issue for you on 0.5.11-r7, could you please file a (new) bug and assign it to me directly. I will then help track it down.
I'm having the exact same excessive logging from hald on both of my machines at home (amd64 and x86). Also seems to be taking a pretty good amount of resources to operate as well. Clip from my log: Oct 23 16:57:21 davinci hald[5619]: 16:57:21.582 [D] hotplug.c:453: events queued = 0, events in progress = 0 Oct 23 16:57:21 davinci hald[5619]: 16:57:21.582 [D] hotplug.c:458: Hotplug-queue empty now ... no hotplug events in progress Oct 23 16:57:21 davinci hald[5619]: 16:57:21.586 [I] osspec.c:247: SEQNUM=5263, ACTION=remove, SUBSYSTEM=usb, DEVPATH=/sys/devices/pci0000:00/0000:00:0b.0/usb2/2-2/2-2.4, DEVNAME=/dev/bus/usb/002/110, IFINDEX=0 Oct 23 16:57:21 davinci hald[5619]: 16:57:21.586 [I] hotplug.c:435: checking event /sys/devices/pci0000:00/0000:00:0b.0/usb2/2-2/2-2.4 Oct 23 16:57:21 davinci hald[5619]: 16:57:21.586 [I] hotplug.c:121: /sys/devices/pci0000:00/0000:00:0b.0/usb2/2-2/2-2.4 is a device (store) Oct 23 16:57:21 davinci hald[5619]: 16:57:21.586 [I] device.c:4795: remove_dev: subsys=usb sysfs_path=/sys/devices/pci0000:00/0000:00:0b.0/usb2/2-2/2-2.4 Oct 23 16:57:21 davinci hald[5619]: 16:57:21.586 [I] device.c:4587: Remove callouts completed udi=/org/freedesktop/Hal/devices/usb_device_45e_db_noserial Oct 23 16:57:21 davinci hald[5619]: 16:57:21.586 [D] device_store.c:519: removing 0x684260 from (linux.sysfs_path,/sys/devices/pci0000:00/0000:00:0b.0/usb2/2-2/2-2.4) Oct 23 16:57:21 davinci hald[5619]: 16:57:21.586 [I] hald.c:143: Removed device from GDL; udi=/org/freedesktop/Hal/devices/usb_device_45e_db_noserial Oct 23 16:57:21 davinci hald[5619]: 16:57:21.586 [D] hotplug.c:453: events queued = 0, events in progress = 0 Oct 23 16:57:21 davinci hald[5619]: 16:57:21.586 [D] hotplug.c:458: Hotplug-queue empty now ... no hotplug events in progress Oct 23 16:57:21 davinci hald[5619]: 16:57:21.586 [I] osspec.c:247: SEQNUM=5267, ACTION=remove, SUBSYSTEM=usb, DEVPATH=/sys/devices/pci0000:00/0000:00:0b.0/usb2/2-2, DEVNAME=/dev/bus/usb/002/108, IFINDEX=0 Oct 23 16:57:21 davinci hald[5619]: 16:57:21.586 [I] hotplug.c:435: checking event /sys/devices/pci0000:00/0000:00:0b.0/usb2/2-2 Oct 23 16:57:21 davinci hald[5619]: 16:57:21.586 [I] hotplug.c:121: /sys/devices/pci0000:00/0000:00:0b.0/usb2/2-2 is a device (store) Oct 23 16:57:21 davinci hald[5619]: 16:57:21.586 [I] device.c:4795: remove_dev: subsys=usb sysfs_path=/sys/devices/pci0000:00/0000:00:0b.0/usb2/2-2 Oct 23 16:57:21 davinci hald[5619]: 16:57:21.586 [I] device.c:4587: Remove callouts completed udi=/org/freedesktop/Hal/devices/usb_device_451_2046_noserial Oct 23 16:57:21 davinci hald[5619]: 16:57:21.586 [D] device_store.c:519: removing 0x6882c0 from (linux.sysfs_path,/sys/devices/pci0000:00/0000:00:0b.0/usb2/2-2) Oct 23 16:57:21 davinci hald[5619]: 16:57:21.586 [I] hald.c:143: Removed device from GDL; udi=/org/freedesktop/Hal/devices/usb_device_451_2046_noserial Oct 23 16:57:21 davinci hald[5619]: 16:57:21.590 [D] hotplug.c:453: events queued = 0, events in progress = 0 Oct 23 16:57:21 davinci hald[5619]: 16:57:21.590 [D] hotplug.c:458: Hotplug-queue empty now ... no hotplug events in progress Oct 23 16:57:36 davinci sshd[1336]: warning: /etc/hosts.deny, line 1351: host name/address mismatch: 67.40.108.105 != plato.onevisionbeyond.com Oct 23 16:57:36 davinci hald[5619]: 16:57:36.342 [I] osspec.c:247: SEQNUM=5268, ACTION=add, SUBSYSTEM=uids, DEVPATH=/sys/kernel/uids/22, DEVNAME=, IFINDEX=0 Oct 23 16:57:36 davinci hald[5619]: 16:57:36.342 [I] hotplug.c:435: checking event /sys/kernel/uids/22 Oct 23 16:57:36 davinci hald[5619]: 16:57:36.342 [I] device.c:4725: add_dev: subsys=uids sysfs_path=/sys/kernel/uids/22 dev= parent_dev=0x00000000 Oct 23 16:57:36 davinci hald[5619]: 16:57:36.342 [D] hotplug.c:453: events queued = 0, events in progress = 0 Oct 23 16:57:36 davinci hald[5619]: 16:57:36.342 [D] hotplug.c:458: Hotplug-queue empty now ... no hotplug events in progress Oct 23 16:57:39 davinci hald[5619]: 16:57:39.310 [I] osspec.c:247: SEQNUM=5269, ACTION=add, SUBSYSTEM=class, DEVPATH=/sys/class/usb, DEVNAME=, IFINDEX=0 Oct 23 16:57:39 davinci hald[5619]: 16:57:39.310 [I] hotplug.c:435: checking event /sys/class/usb Oct 23 16:57:39 davinci hald[5619]: 16:57:39.310 [I] device.c:4725: add_dev: subsys=class sysfs_path=/sys/class/usb dev= parent_dev=0x00000000 Oct 23 16:57:39 davinci hald[5619]: 16:57:39.310 [D] hotplug.c:453: events queued = 0, events in progress = 0 Oct 23 16:57:39 davinci hald[5619]: 16:57:39.310 [D] hotplug.c:458: Hotplug-queue empty now ... no hotplug events in progress Oct 23 16:57:39 davinci hald[5619]: 16:57:39.734 [I] osspec.c:247: SEQNUM=5270, ACTION=add, SUBSYSTEM=usb, DEVPATH=/sys/class/usb/lp0, DEVNAME=/dev/usb/lp0, IFINDEX=0 Oct 23 16:57:39 davinci hald[5619]: 16:57:39.734 [I] hotplug.c:435: checking event /sys/class/usb/lp0 Oct 23 16:57:39 davinci hald[5619]: 16:57:39.734 [I] hotplug.c:145: /sys/class/usb/lp0 is a device (subsystem) Oct 23 16:57:39 davinci hald[5619]: 16:57:39.734 [I] osspec.c:980: hal_util_find_known_parent: '/sys/class/usb/lp0'->'/sys/devices/pci0000:00/0000:00:0b.0/usb2/2-1/2-1:1.0' Oct 23 16:57:39 davinci hald[5619]: 16:57:39.734 [I] device.c:4725: add_dev: subsys=usb sysfs_path=/sys/class/usb/lp0 dev=/dev/usb/lp0 parent_dev=0x00686920 Oct 23 16:57:39 davinci hald[5619]: 16:57:39.734 [D] hotplug.c:453: events queued = 0, events in progress = 1 Oct 23 16:57:41 davinci hald[5619]: 16:57:41.062 [D] hald_dbus.c:1652: udi=/org/freedesktop/Hal/devices/temp/562, key=info.vendor Oct 23 16:57:41 davinci hald[5619]: 16:57:41.062 [D] hald_dbus.c:1652: udi=/org/freedesktop/Hal/devices/temp/562, key=printer.vendor Oct 23 16:57:41 davinci hald[5619]: 16:57:41.062 [D] hald_dbus.c:1652: udi=/org/freedesktop/Hal/devices/temp/562, key=info.product Oct 23 16:57:41 davinci hald[5619]: 16:57:41.066 [D] hald_dbus.c:1652: udi=/org/freedesktop/Hal/devices/temp/562, key=printer.product Oct 23 16:57:41 davinci hald[5619]: 16:57:41.066 [D] hald_dbus.c:1652: udi=/org/freedesktop/Hal/devices/temp/562, key=printer.serial Oct 23 16:57:41 davinci hald-probe-printer: [1347]: 16:57:41.062 [D] probe-printer.c:105: device_id = MFG:Hewlett-Packard;MDL:OfficeJet G55;CMD:MLC,PCL,PML,SCL;CLASS:PRINTER;DESCRIPTION:Hewlett-Packard OfficeJet G Series;1284.3M:f7f,f7f;1284.4DL:4d,4e,1;SERN:SGA9C10LSVVL;VSTATUS:$HB0$NC0,ff,DN,IDLE,CUT,K0,C0,SM,NR,KP014,CP083;AiO:0;�1 Oct 23 16:57:41 davinci hald[5619]: 16:57:41.066 [D] hald_dbus.c:1652: udi=/org/freedesktop/Hal/devices/temp/562, key=printer.description Oct 23 16:57:41 davinci hald[5619]: 16:57:41.066 [I] device.c:4642: entering; exit_type=0, return_code=0 Oct 23 16:57:41 davinci hald[5619]: 16:57:41.070 [I] device.c:4573: Add callouts completed udi=/org/freedesktop/Hal/devices/usb_device_3f0_11_SGA9C10LSVVL_if0_printer_SGA9C10LSVVL Oct 23 16:57:41 davinci hald[5619]: 16:57:41.070 [D] device_store.c:516: adding 0x6b6f40 to (linux.sysfs_path,/sys/class/usb/lp0) Oct 23 16:57:41 davinci hald[5619]: 16:57:41.070 [I] hald.c:108: Added device to GDL; udi=/org/freedesktop/Hal/devices/usb_device_3f0_11_SGA9C10LSVVL_if0_printer_SGA9C10LSVVL Oct 23 16:57:41 davinci hald[5619]: 16:57:41.070 [D] hotplug.c:453: events queued = 0, events in progress = 0 Oct 23 16:57:41 davinci hald[5619]: 16:57:41.070 [D] hotplug.c:458: Hotplug-queue empty now ... no hotplug events in progress Oct 23 16:57:41 davinci sshd[1336]: Accepted keyboard-interactive/pam for root from 67.40.108.105 port 38313 ssh2 Oct 23 16:57:41 davinci hald[5619]: 16:57:41.842 [I] osspec.c:247: SEQNUM=5271, ACTION=remove, SUBSYSTEM=uids, DEVPATH=/sys/kernel/uids/22, DEVNAME=, IFINDEX=0 Oct 23 16:57:41 davinci hald[5619]: 16:57:41.842 [I] hotplug.c:435: checking event /sys/kernel/uids/22 Oct 23 16:57:41 davinci hald[5619]: 16:57:41.842 [I] device.c:4795: remove_dev: subsys=uids sysfs_path=/sys/kernel/uids/22 Oct 23 16:57:41 davinci hald[5619]: 16:57:41.842 [W] device.c:4799: Error removing device
FWIW I'm still seeing this with sys-apps/hal-0.5.12_rc1-r8 installed.
