Bug 655693

Set udev in info or debug mode in /etc/udev/udev.conf, or boot with "udevinfo" or "udevdebug" on the kernel command line.

Can also be a modprobe error. To test this boot with "modprobedebug" on the kernel command line (takes a long time).

Created attachment 462127 [details]
dmesg3.log

With both modprobedebug and udev debug logs enabled, when i ran udevadm settle, it seg faulted.

[root@lcle176 ~]# udevadm settle
libudev: udev_list_entry_add: 'UDEV_LOG=7' added
libudev: udev_new: context 0xdde030 created
libudev: udev_new: log_priority=7
libudev: udev_new: config_file='/etc/udev/udev.conf'
libudev: udev_new: dev_path='/dev'
libudev: udev_new: sys_path='/sys'
custom logging function 0xdde030 registered
selinux=1
calling: settle
version 147
Segmentation fault (core dumped)


I have attached the coredump as well as the dmesg log and /var/log/messages.

I also have /var/log/messages from host boot, but the size of that file is more than 150MB and I dont think i can attach it here.  If you need those messages, please send the details of a ftp server to which i can upload it to.

Created attachment 462128 [details]
messages3

Created attachment 462130 [details]
udevadm_coredump.tar

Created attachment 462444 [details]
messages4

Created attachment 462445 [details]
dmesg4

I removed all the arrays LUNs and still udevadm settle takes 3 minutes.  

With modprobedebug and udev debug log enabled, I got some more logs from host reboot and attached them here as dmesg4 and messages4.

Please let me know if  you need anything else.

(In reply to comment #6)
> Created attachment 462130 [details]
> udevadm_coredump.tar

this coredump reveils a completly trashed stack with no valid information

(In reply to comment #4)
> With both modprobedebug and udev debug logs enabled, when i ran udevadm settle,
> it seg faulted.
> 
> [root@lcle176 ~]# udevadm settle
> libudev: udev_list_entry_add: 'UDEV_LOG=7' added
> libudev: udev_new: context 0xdde030 created
> libudev: udev_new: log_priority=7
> libudev: udev_new: config_file='/etc/udev/udev.conf'
> libudev: udev_new: dev_path='/dev'
> libudev: udev_new: sys_path='/sys'
> custom logging function 0xdde030 registered
> selinux=1
> calling: settle
> version 147
> Segmentation fault (core dumped)
> 
> 
> I have attached the coredump as well as the dmesg log and /var/log/messages.
> 
> I also have /var/log/messages from host boot, but the size of that file is more
> than 150MB and I dont think i can attach it here.  If you need those messages,
> please send the details of a ftp server to which i can upload it to.


can you strace "udevadm settle" ?

# strace -f udevadm settle

or better:

# strace -f -r -ttt udevadm settle

Here you go.  I have attached two log files that I got from running udevadm settle with strace and the options you have mentioned.

1. udevadm_settle_strace1.log -  Without udev debug enabled.

2. udevadm_settle_strace1.log -  With udev debug enabled and host started with modprobedebug.

Created attachment 462599 [details]
udevadm_settle_strace1.log

Created attachment 462600 [details]
udevadm_settle_strace2.log

thank you.. finally I could reproduce it!

ok, here is the fix for the "debug" "udevadm settle" segfault.

http://git.kernel.org/?p=linux/hotplug/udev.git;a=commitdiff;h=d5a01cb8b31bd0791d1617c56d4c669a02018bd7


now back to your original problem.

I made some rpms for you, which should fix the segfault:

http://people.redhat.com/harald/downloads/udev/udev-147-2.29.0.1.el6/

so we can debug your original problem.

Created attachment 462657 [details]
udevadm_settle_strace3.log

Please find the strace logs in udevadm_settle_strace3.log after I upgraded udev with the rpms you have provided.  udevadm doesnt segfault now with debug logs enabled.

ok, no need for strace anymore.
now you can just remove "modprobedebug" from the kernel command line. 
"udevdebug" on the kernel command line is enough.

Now I need the /var/log/messages from a debug enabled boot, please.

Created attachment 462732 [details]
messages6

Here you go... attached messages6

One thing that I did not mention before because I thought its not relevant, but it might be.  If I boot the host only with udevdebug, after the host comes up, network is not initialized.  eth0 does not come up.  Even if i try ifup eth0, it doesn't come up.  But if i boot with both udevdebug and modprobedebug, then network is properly initialized.

Also, you mentioned that you were able to reproduce the issue.  Did you mean you were able to repro udevadm settle taking 3 mins or the segfault in debug mode?

(In reply to comment #24)
> Also, you mentioned that you were able to reproduce the issue.  Did you mean
> you were able to repro udevadm settle taking 3 mins or the segfault in debug
> mode?

the segfault

ok, "messages6" is incomplete... a whole bunch is missing (because rsyslog is started so late). A console log would be more usefule, but there is another possibility:

Please boot with "udevlog udevdebug" and attach /dev/.udev/udev.log

Created attachment 462857 [details]
messages7

(In reply to comment #27)
> Created attachment 462857 [details]
> messages7

 /dev/.udev/udev.log please!

Created attachment 462861 [details]
udev.log7.tar.gz

the udev log was more than 30MB and hence when I tried to upload it, there was an error as attachments mor ethan 20MB are not allowed.

Hence I have created a compressed tar file, udev.log7.tar.gz. Please unzip with 'tar -xvzf'.

ok, /var/log/boot.log also please

(In reply to comment #31)
> ok, /var/log/boot.log also please

from this same boot

4:25:03 udevd starts
4:25:05 start_udev ends (udevadm settle)

2 seconds... that's ok!!!

1290677105.927512 [491] udev_list_entry_add: 'DEVPATH=/module/scsi_wait_scan' added

is 4:25:05, and is in rc.sysinit "modprobe scsi_wait_scan"

1290677130.492588 [491] udev_list_entry_add: 'DEVPATH=/devices/virtual/vc/vcs2' added

is 4:25:30 and marks the point when getty's spawn and provide a login to the virtual terminals 2-6

which is basically the end of the boot...


so where is the " udevadm settle takes 3 minutes to complete " ???

(In reply to comment #19)
> Created attachment 462657 [details]
> udevadm_settle_strace3.log

also this takes not long

     0.000062 exit_group(0)             = ?

(In reply to comment #34)
> (In reply to comment #19)
> > Created attachment 462657 [details] [details]
> > udevadm_settle_strace3.log
> 
> also this takes not long
> 
>      0.000062 exit_group(0)             = ?

oops "-r" rendered "-ttt" invalid... misinterpretation... 

   179.997660 --- SIGALRM (Alarm clock) @ 0 (0) ---

This seems to be the indicator...

ok, once more strace udevadm settle without the "-r" flag.

# time strace -f -ttt udevadm settle


Here is how the relevant parts look like on my system:
# time strace -f -ttt udevadm settle
....
1290685100.477515 alarm(180)            = 0
1290685100.477557 getuid()              = 0
1290685100.477597 socket(PF_FILE, SOCK_DGRAM, 0) = 4
1290685100.477645 rt_sigprocmask(SIG_BLOCK, [USR1 ALRM], [], 8) = 0
1290685100.477694 sendto(4, "udev-147\0\0\0\0\0\0\0\0\352\35\255\336\10\0\0\0\0\0\0\0\0\0\0\0"..., 280, 0, {sa_family=AF_FILE, path=@"/org/kernel/udev/udevd"}, 25) = 280
1290685100.477759 rt_sigsuspend([])     = ? ERESTARTNOHAND (To be restarted)
1290685100.477797 --- SIGUSR1 (User defined signal 1) @ 0 (0) ---
1290685100.477818 rt_sigreturn(0xa)     = -1 EINTR (Interrupted system call)
1290685100.477854 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
1290685100.477887 close(4)              = 0
1290685100.477929 open("/dev/.udev/queue.bin", O_RDONLY) = 4
1290685100.477976 fstat(4, {st_mode=S_IFREG|0644, st_size=8, ...}) = 0
1290685100.478028 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f197565f000
1290685100.478064 read(4, "\336\6\0\0\0\0\0\0", 4096) = 8
1290685100.478105 read(4, "", 4096)     = 0
1290685100.478139 open("/sys/kernel/uevent_seqnum", O_RDONLY) = 5
1290685100.478188 read(5, "1758\n", 32) = 5
1290685100.478225 close(5)              = 0
1290685100.478265 write(2, "seqnum=1758\n", 12seqnum=1758
) = 12
1290685100.478311 sendto(3, "<31>Nov 25 12:38:20 udevadm[2838"..., 47, MSG_NOSIGNAL, NULL, 0) = 47
1290685100.478371 write(2, "queue is empty\n", 15queue is empty
) = 15
1290685100.478417 sendto(3, "<31>Nov 25 12:38:20 udevadm[2838"..., 50, MSG_NOSIGNAL, NULL, 0) = 50
1290685100.478472 close(4)              = 0
1290685100.478505 munmap(0x7f197565f000, 4096) = 0
1290685100.478547 write(2, "context 0x1970030 released\n", 27context 0x1970030 released
) = 27
1290685100.478597 sendto(3, "<31>Nov 25 12:38:20 udevadm[2838"..., 62, MSG_NOSIGNAL, NULL, 0) = 62
1290685100.478653 close(3)              = 0
1290685100.478700 exit_group(0)         = ?

real	0m0.024s
user	0m0.012s
sys	0m0.015s

ok, after "udevadm settle" does

sendto(4, "udev-147\0\....

udevadm is waiting for a SIGUSR1 from the udevd daemon or a SIGALRM (180 seconds)

So it seems like your udevd is not sending SIGUSR1 to the "udevadm settle".

This poses two questions:

1. is udevd running at all?
# pidof udevd

2. what is udevd doing?
# strace -f -p <udevd lowest pid>

attachement 462657 looks like your system has not yet booted up completly.

/dev/sdb /dev/sdc /dev/sdd seem to take a long time to come up. Any reason?

ok, it's sdc, sdd and sde in attachment 462857 [details]

Nov 25 04:25:31 lcle176 path_id[2147]: device 0x6b4160 has devpath '/devices/pci0000:00/0000:00:03.0/0000:01:00.0/host2/port-2:3/end_device-2:3/target2:0:3/2:0:3:0/block/sdd'

Nov 25 04:25:31 lcle176 path_id[2149]: device 0x729160 has devpath '/devices/pci0000:00/0000:00:03.0/0000:01:00.0/host2/port-2:2/end_device-2:2/target2:0:2/2:0:2:0/block/sdc'


Nov 25 04:25:31 lcle176 path_id[2153]: device 0x20d6160 has devpath '/devices/pci0000:00/0000:00:1d.7/usb1/1-1/1-1.2/1-1.2:1.1/host6/target6:0:0/6:0:0:0/block/sde'

Are these devices added later on? Network maybe?

anyway.. nothing of this takes longer than 3 minutes... so, please look at comment 37

Created attachment 462895 [details]
boot.log8

Created attachment 462896 [details]
messages8

Created attachment 462897 [details]
udev.log8.tar.gz

Created attachment 462898 [details]
messages9

Created attachment 462899 [details]
udev.log9.tar.gz

Created attachment 462900 [details]
udevadm_settle_strace.log9

Created attachment 462901 [details]
udevd_pid_499_strace.log9

Created attachment 462902 [details]
udevd_pid_2171_strace.log9

Created attachment 462903 [details]
udevd_pid_2172_strace.log9

Sorry, i thought I had provided all the logs that you asked for.  Apparently there was some communication.  Anyways, I have collected a fresh set of logs and hopefully this covers everything you asked for.  Please note that i have booted the host with udevlog and udevdebug on the kernel command line.

After the host come up, these are the relevant logs:
messages8
boot.log8
udev.log8.tar.gz


Now the udevd processes are:

[root@lcle176 ~]# pidof udevd
2172 2171 499

strace of all these processes were started and then strace of udevadm settle was run.  After udevadm settle completed after 3 minutes, stopped the strace of all the udevd processes using Ctrl-C.  the relevant logs now are:

messages9
udev.log9.tar.gz
udevadm_settle_strace.log9
udevd_pid_499_strace.log9
udevd_pid_2171_strace.log9
udevd_pid_2171_strace.log9


Now regarding those harddisks, they are all internal hard disks.  Details below:

[root@lcle176 ~]# lspci
00:00.0 Host bridge: Intel Corporation 5000X Chipset Memory Controller Hub (rev 12)
00:02.0 PCI bridge: Intel Corporation 5000 Series Chipset PCI Express x4 Port 2 (rev 12)
00:03.0 PCI bridge: Intel Corporation 5000 Series Chipset PCI Express x4 Port 3 (rev 12)
00:04.0 PCI bridge: Intel Corporation 5000 Series Chipset PCI Express x8 Port 4-5 (rev 12)
00:05.0 PCI bridge: Intel Corporation 5000 Series Chipset PCI Express x4 Port 5 (rev 12)
00:06.0 PCI bridge: Intel Corporation 5000 Series Chipset PCI Express x8 Port 6-7 (rev 12)
00:07.0 PCI bridge: Intel Corporation 5000 Series Chipset PCI Express x4 Port 7 (rev 12)
00:10.0 Host bridge: Intel Corporation 5000 Series Chipset FSB Registers (rev 12)
00:10.1 Host bridge: Intel Corporation 5000 Series Chipset FSB Registers (rev 12)
00:10.2 Host bridge: Intel Corporation 5000 Series Chipset FSB Registers (rev 12)
00:11.0 Host bridge: Intel Corporation 5000 Series Chipset Reserved Registers (rev 12)
00:13.0 Host bridge: Intel Corporation 5000 Series Chipset Reserved Registers (rev 12)
00:15.0 Host bridge: Intel Corporation 5000 Series Chipset FBD Registers (rev 12)
00:16.0 Host bridge: Intel Corporation 5000 Series Chipset FBD Registers (rev 12)
00:1c.0 PCI bridge: Intel Corporation 631xESB/632xESB/3100 Chipset PCI Express Root Port 1 (rev 09)
00:1d.0 USB Controller: Intel Corporation 631xESB/632xESB/3100 Chipset UHCI USB Controller #1 (rev 09)
00:1d.1 USB Controller: Intel Corporation 631xESB/632xESB/3100 Chipset UHCI USB Controller #2 (rev 09)
00:1d.2 USB Controller: Intel Corporation 631xESB/632xESB/3100 Chipset UHCI USB Controller #3 (rev 09)
00:1d.3 USB Controller: Intel Corporation 631xESB/632xESB/3100 Chipset UHCI USB Controller #4 (rev 09)
00:1d.7 USB Controller: Intel Corporation 631xESB/632xESB/3100 Chipset EHCI USB2 Controller (rev 09)
00:1e.0 PCI bridge: Intel Corporation 82801 PCI Bridge (rev d9)
00:1f.0 ISA bridge: Intel Corporation 631xESB/632xESB/3100 Chipset LPC Interface Controller (rev 09)
00:1f.1 IDE interface: Intel Corporation 631xESB/632xESB IDE Controller (rev 09)
01:00.0 SCSI storage controller: LSI Logic / Symbios Logic SAS1068E PCI-Express Fusion-MPT SAS (rev 08)
02:00.0 PCI bridge: Broadcom EPB PCI-Express to PCI-X Bridge (rev c3)
03:00.0 Ethernet controller: Broadcom Corporation NetXtreme II BCM5708 Gigabit Ethernet (rev 12)
04:00.0 PCI bridge: Intel Corporation 6311ESB/6321ESB PCI Express Upstream Port (rev 01)
04:00.3 PCI bridge: Intel Corporation 6311ESB/6321ESB PCI Express to PCI-X Bridge (rev 01)
05:00.0 PCI bridge: Intel Corporation 6311ESB/6321ESB PCI Express Downstream Port E1 (rev 01)
05:01.0 PCI bridge: Intel Corporation 6311ESB/6321ESB PCI Express Downstream Port E2 (rev 01)
06:00.0 PCI bridge: Broadcom EPB PCI-Express to PCI-X Bridge (rev c3)
07:00.0 Ethernet controller: Broadcom Corporation NetXtreme II BCM5708 Gigabit Ethernet (rev 12)
08:00.0 Fibre Channel: Emulex Corporation Zephyr-X LightPulse Fibre Channel Host Adapter (rev 02)
08:00.1 Fibre Channel: Emulex Corporation Zephyr-X LightPulse Fibre Channel Host Adapter (rev 02)
0e:0d.0 VGA compatible controller: ATI Technologies Inc ES1000 (rev 02)
[root@lcle176 ~]#
[root@lcle176 ~]# cat /proc/scsi/scsi
Attached devices:
Host: scsi2 Channel: 00 Id: 00 Lun: 00
  Vendor: FUJITSU  Model: MBA3073RC        Rev: D305
  Type:   Direct-Access                    ANSI  SCSI revision: 05
Host: scsi2 Channel: 00 Id: 01 Lun: 00
  Vendor: FUJITSU  Model: MBA3073RC        Rev: D305
  Type:   Direct-Access                    ANSI  SCSI revision: 05
Host: scsi2 Channel: 00 Id: 02 Lun: 00
  Vendor: FUJITSU  Model: MBA3073RC        Rev: D305
  Type:   Direct-Access                    ANSI  SCSI revision: 05
Host: scsi2 Channel: 00 Id: 03 Lun: 00
  Vendor: FUJITSU  Model: MBA3073RC        Rev: D305
  Type:   Direct-Access                    ANSI  SCSI revision: 05
Host: scsi3 Channel: 00 Id: 00 Lun: 00
  Vendor: HL-DT-ST Model: DVD-ROM GDR8084N Rev: 1.01
  Type:   CD-ROM                           ANSI  SCSI revision: 05
Host: scsi5 Channel: 00 Id: 00 Lun: 00
  Vendor: Dell     Model: Virtual  CDROM   Rev: 123
  Type:   CD-ROM                           ANSI  SCSI revision: 00
Host: scsi6 Channel: 00 Id: 00 Lun: 00
  Vendor: Dell     Model: Virtual  Floppy  Rev: 123
  Type:   Direct-Access                    ANSI  SCSI revision: 00
[root@lcle176 ~]#
[root@lcle176 ~]#
[root@lcle176 ~]# cat /proc/partitions
major minor  #blocks  name

   8        0   71687325 sda
   8        1     297171 sda1
   8        2    4401810 sda2
   8        4          1 sda4
   8        5    9775521 sda5
   8        6    9775521 sda6
   8        7    9775521 sda7
   8        8    9775521 sda8
   8        9   27880776 sda9
   8       48   71687325 sdd
   8       49   71686144 sdd1
   8       32   71687325 sdc
   8       16   71687325 sdb
   8       17   12305758 sdb1
   8       18   12691350 sdb2
[root@lcle176 ~]#

In order to avoid confusion and for the sake of expediency, I would appreciate if you could please let me know in detail what you are looking for in your future requests.

Btw, really appreciate your quick responses to this ticket.

Thanks.

kill(2429, SIGUSR1)                     = -1 EACCES (Permission denied)

wow!

Is udevd running as a different user?
Any selinux restrictions about this?

[root@lcle176 ~]# ps -elf | grep udevd
5 S root       499     1  0  76  -4 -  2780 poll_s 08:40 ?        00:00:00 /sbin/udevd -d --debug
5 S root      2171   499  0  78  -2 -  3076 poll_s 08:40 ?        00:00:00 /sbin/udevd -d --debug
5 S root      2172   499  0  78  -2 -  3076 poll_s 08:40 ?        00:00:00 /sbin/udevd -d --debug
0 S root      3249  2836  0  80   0 - 25789 pipe_w 09:58 pts/1    00:00:00 grep udevd
[root@lcle176 ~]# cat /etc/selinux/config

# This file controls the state of SELinux on the system.
# SELINUX= can take one of these three values:
#     enforcing - SELinux security policy is enforced.
#     permissive - SELinux prints warnings instead of enforcing.
#     disabled - No SELinux policy is loaded.
SELINUX=enforcing
# SELINUXTYPE= can take one of these two values:
#     targeted - Targeted processes are protected,
#     mls - Multi Level Security protection.
SELINUXTYPE=targeted




Is udevd running as a different user?
No.  its running as root only.

Any selinux restrictions about this?
From the config file, it appears selinux is active.  Is there any other way to check this.  I remember using 'setup' command to disable selinux in the past, but on this host, when i run the setup command, I dont see options for selinux.

kill(2429, SIGUSR1)                     = -1 EACCES (Permission denied)
Is this the reason, you think udevadm settle takes 3 mins?

(In reply to comment #55)

> kill(2429, SIGUSR1)                     = -1 EACCES (Permission denied)
> Is this the reason, you think udevadm settle takes 3 mins?

yes it definetly is!

Change in /etc/selinux/config:
SELINUX=permissive
and reboot, to see, if it makes a difference.

Yes!!!   That has made a difference.

With SELINUX=permissive, I rebooted the host and now udevadm settle completes immediately.



But this cannot be considered a fix or even a workaround, right?

(In reply to comment #57)
> Yes!!!   That has made a difference.
> 
> With SELINUX=permissive, I rebooted the host and now udevadm settle completes
> immediately.
> 
> 
> 
> But this cannot be considered a fix or even a workaround, right?

correct!

I'll clone this bug, because of the udevadm "debug" issue.

reassigning to selinux-policy

Dan, the problem is:

udevd is started

userspace launches:

# udevadm settle

udevadm connects to netlink socket and messages own $pid to udevd

udevd works on its queue, and if queue is emtpy, signals "udevadm settle", that udevd has settled. This is done via a kill($pid, SIGUSR1).

So, we see:
kill(2429, SIGUSR1)                     = -1 EACCES (Permission denied)

I can't reproduce this on my machine. But you should be able to diagnose it further.

With SELINUX=permissive, the kill works as expected.

oh... s/Dan/Miroslav Grepl/g :-)

Gopinath,
could add your output of

# grep udev /var/log/audit/audit.log

Created attachment 463516 [details]
log10.tar.gz

Attached log10.tar.gz - contains relevant logs from a host reboot and a udevadm settle (took 3 mins).

Rawhide has the allow rules.

#============= udev_t ==============
#!!!! This avc is allowed in the current policy

allow udev_t self:process signal;
#!!!! This avc is allowed in the current policy

allow udev_t unconfined_t:process signal;


RHEL6 policy looks like it has this access also.

	unconfined_signal(udev_t)
selinux-policy-3.7.19-58.el6

With the latest RHEL6 policy


audit2allow < /tmp/audit.log

#============= udev_t ==============
#!!!! This avc is allowed in the current policy

allow udev_t self:process signal;
#!!!! This avc is allowed in the current policy

allow udev_t unconfined_t:process signal;

Could you test it with selinux-policy-3.7.19-59.el6

I meant with

selinux-policy-3.7.19-58.el6

which is available from

http://people.redhat.com/dwalsh/SELinux/RHEL6/noarch/

I upgraded selinux policy to 3.7.19-58.el6 and it seems to fix this the udevadm settle issue.  That is, even with enforcing mode, udevadm settle completes almost immediately now.

Thanks Miroslav!

Btw, when will this fix be formally available?

An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHBA-2011-0526.html