Attachment 295083 Details for Bug 433157 – /var/log/messages when NetworkManager starts, system hangs

/var/log/messages when NetworkManager starts, system hangs

50-hang.txt (text/plain), 15.27 KB, created by Tom London on 2008-02-17 00:47:42 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Tom London

Created: 2008-02-17 00:47:42 UTC

Size: 15.27 KB

patch

obsolete

>Feb 16 15:56:13 localhost NetworkManager: <info>  starting...
>Feb 16 15:56:13 localhost NetworkManager: <info>  Found radio killswitch /org/freedesktop/Hal/devices/ipw_wlan_switch
>Feb 16 15:56:13 localhost NetworkManager: <info>  eth1: Device is fully-supported using driver 'e1000e'.
>Feb 16 15:56:13 localhost NetworkManager: <info>  Now managing wired Ethernet (802.3) device 'eth1'.
>Feb 16 15:56:13 localhost NetworkManager: <info>  Bringing up device eth1
>Feb 16 15:56:13 localhost kernel: ADDRCONF(NETDEV_UP): eth1: link is not ready
>Feb 16 15:56:13 localhost NetworkManager: <info>  Deactivating device eth1.
>Feb 16 15:56:13 localhost NetworkManager: <info>  (eth1): exported as /org/freedesktop/Hal/devices/net_00_16_d3_26_85_6f
>Feb 16 15:56:13 localhost NetworkManager: <info>  wlan0: Device is fully-supported using driver 'iwl3945'.
>Feb 16 15:56:13 localhost NetworkManager: <info>  wlan0: driver supports SSID scans (scan_capa 0x01).
>Feb 16 15:56:13 localhost NetworkManager: <info>  Now managing wireless (802.11) device 'wlan0'.
>Feb 16 15:56:13 localhost NetworkManager: <info>  Bringing up device wlan0
>Feb 16 15:56:13 localhost kernel: ACPI: PCI Interrupt 0000:03:00.0[A] -> GSI 17 (level, low) -> IRQ 17
>Feb 16 15:56:13 localhost kernel: ADDRCONF(NETDEV_UP): wlan0: link is not ready
>Feb 16 15:56:13 localhost NetworkManager: <info>  Deactivating device wlan0.
>Feb 16 15:56:13 localhost NetworkManager: <info>  (wlan0): exported as /org/freedesktop/Hal/devices/net_00_13_02_6f_fc_3c
>Feb 16 15:56:13 localhost NetworkManager: <info>  Trying to start the supplicant...
>Feb 16 15:56:13 localhost NetworkManager: <info>  Trying to start the system settings daemon...
>Feb 16 15:56:14 localhost NetworkManager: <info>  (eth1) supplicant interface is now in state 1 (from 0).
>Feb 16 15:56:14 localhost NetworkManager: <info>  (wlan0) supplicant manager is now in state 1 (from 0).
>Feb 16 15:56:14 localhost kernel: 
>Feb 16 15:56:14 localhost kernel: =============================================
>Feb 16 15:56:14 localhost kernel: [ INFO: possible recursive locking detected ]
>Feb 16 15:56:14 localhost kernel: 2.6.25-0.50.rc2.fc9 #1
>Feb 16 15:56:14 localhost kernel: ---------------------------------------------
>Feb 16 15:56:14 localhost kernel: wpa_supplicant/2490 is trying to acquire lock:
>Feb 16 15:56:14 localhost kernel:  (dev_base_lock){-.--}, at: [<c05cdccc>] do_setlink+0x2d6/0x34a
>Feb 16 15:56:14 localhost kernel: 
>Feb 16 15:56:14 localhost kernel: but task is already holding lock:
>Feb 16 15:56:14 localhost kernel:  (dev_base_lock){-.--}, at: [<c05cdcb0>] do_setlink+0x2ba/0x34a
>Feb 16 15:56:14 localhost kernel: 
>Feb 16 15:56:14 localhost kernel: other info that might help us debug this:
>Feb 16 15:56:14 localhost kernel: 2 locks held by wpa_supplicant/2490:
>Feb 16 15:56:14 localhost kernel:  #0:  (rtnl_mutex){--..}, at: [<c05ceb21>] rtnetlink_rcv+0x12/0x26
>Feb 16 15:56:14 localhost kernel:  #1:  (dev_base_lock){-.--}, at: [<c05cdcb0>] do_setlink+0x2ba/0x34a
>Feb 16 15:56:14 localhost kernel: 
>Feb 16 15:56:14 localhost kernel: stack backtrace:
>Feb 16 15:56:14 localhost kernel: Pid: 2490, comm: wpa_supplicant Not tainted 2.6.25-0.50.rc2.fc9 #1
>Feb 16 15:56:14 localhost kernel:  [<c044574d>] __lock_acquire+0x8d2/0xbf4
>Feb 16 15:56:14 localhost kernel:  [<c0445ad9>] lock_acquire+0x6a/0x90
>Feb 16 15:56:14 localhost kernel:  [<c05cdccc>] ? do_setlink+0x2d6/0x34a
>Feb 16 15:56:14 localhost kernel:  [<c063a78d>] _write_lock_bh+0x21/0x4e
>Feb 16 15:56:14 localhost kernel:  [<c05cdccc>] ? do_setlink+0x2d6/0x34a
>Feb 16 15:56:14 localhost kernel:  [<c05cdccc>] do_setlink+0x2d6/0x34a
>Feb 16 15:56:14 localhost kernel:  [<c063a416>] ? _read_unlock+0x1d/0x20
>Feb 16 15:56:14 localhost kernel:  [<c05cde07>] rtnl_setlink+0xc7/0xe6
>Feb 16 15:56:14 localhost kernel:  [<c05cdd40>] ? rtnl_setlink+0x0/0xe6
>Feb 16 15:56:14 localhost kernel:  [<c05cecda>] rtnetlink_rcv_msg+0x1a5/0x1bf
>Feb 16 15:56:14 localhost kernel:  [<c05ceb35>] ? rtnetlink_rcv_msg+0x0/0x1bf
>Feb 16 15:56:14 localhost kernel:  [<c05dbdba>] netlink_rcv_skb+0x30/0x86
>Feb 16 15:56:14 localhost kernel:  [<c05ceb2d>] rtnetlink_rcv+0x1e/0x26
>Feb 16 15:56:14 localhost kernel:  [<c05db8de>] netlink_unicast+0x1b7/0x215
>Feb 16 15:56:14 localhost kernel:  [<c05dbb94>] netlink_sendmsg+0x258/0x265
>Feb 16 15:56:14 localhost kernel:  [<c05bbe3b>] sock_sendmsg+0xde/0xf9
>Feb 16 15:56:14 localhost kernel:  [<c0439733>] ? autoremove_wake_function+0x0/0x33
>Feb 16 15:56:14 localhost kernel:  [<c040a37c>] ? native_sched_clock+0xb5/0xd1
>Feb 16 15:57:16 localhost kernel:last message repeated 3 times
>Feb 16 15:56:14 localhost kernel:  [<c05bc712>] sys_sendto+0xa4/0xc3
>Feb 16 15:56:14 localhost kernel:  [<c0483bf7>] ? check_object+0x111/0x185
>Feb 16 15:56:14 localhost kernel:  [<c04849c6>] ? __slab_free+0xb2/0x2fc
>Feb 16 15:56:14 localhost kernel:  [<c044495b>] ? trace_hardirqs_on+0xe9/0x10a
>Feb 16 15:56:14 localhost kernel:  [<c04860fb>] ? kmem_cache_free+0x70/0x8b
>Feb 16 15:56:14 localhost kernel:  [<c0498181>] ? d_free+0x3b/0x4d
>Feb 16 15:56:14 localhost kernel:  [<c05bc749>] sys_send+0x18/0x1a
>Feb 16 15:56:14 localhost kernel:  [<c05bce44>] sys_socketcall+0xe6/0x186
>Feb 16 15:56:14 localhost kernel:  [<c0405d66>] syscall_call+0x7/0xb
>Feb 16 15:56:14 localhost kernel:  =======================
>Feb 16 15:56:14 localhost kernel: 0000:02:00.0: eth1: Link is Up 100 Mbps Full Duplex, Flow Control: RX/TX
>Feb 16 15:56:14 localhost kernel: 0000:02:00.0: eth1: 10/100 speed: disabling TSO
>Feb 16 15:56:15 localhost smartd[2497]: smartd version 5.37 [i386-redhat-linux-gnu] Copyright (C) 2002-6 Bruce Allen
>Feb 16 15:56:15 localhost smartd[2497]: Home page is http://smartmontools.sourceforge.net/#012
>Feb 16 15:56:15 localhost smartd[2497]: Opened configuration file /etc/smartd.conf
>Feb 16 15:56:15 localhost smartd[2497]: Configuration file /etc/smartd.conf parsed.
>Feb 16 15:56:15 localhost smartd[2497]: Device: /dev/sda, opened
>Feb 16 15:56:15 localhost smartd[2497]: Device: /dev/sda, found in smartd database.
>Feb 16 15:56:16 localhost smartd[2497]: Device: /dev/sda, is SMART capable. Adding to "monitor" list.
>Feb 16 15:56:16 localhost smartd[2497]: Monitoring 1 ATA and 0 SCSI devices
>Feb 16 15:56:16 localhost smartd[2499]: smartd has fork()ed into background mode. New PID=2499.
>Feb 16 15:56:19 localhost console-kit-daemon[2326]: WARNING: Couldn't read /proc/2469/environ: Error reading file '/proc/2469/environ': No such process
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Adding handler 1: signum=15 0x804c080
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Registering for 15 signals
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Adding handler 2: signum=2 0x804c080
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Registering for 2 signals
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Adding handler 3: signum=4 0x804c080
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Registering for 4 signals
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Adding handler 4: signum=7 0x804c080
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Registering for 7 signals
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Adding handler 5: signum=8 0x804c080
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Registering for 8 signals
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Adding handler 6: signum=1 0x804c080
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Registering for 1 signals
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Adding handler 7: signum=11 0x804c080
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Registering for 11 signals
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Adding handler 8: signum=6 0x804c080
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Registering for 6 signals
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Adding handler 9: signum=10 0x804c080
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Registering for 10 signals
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSlave: Registering /org/gnome/DisplayManager/Slave1
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSlave: starting slave
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSlave: Starting slave
>Feb 16 15:56:19 localhost gdm-simple-slave[2560]: DEBUG: GdmSlave: Creating proxy for /org/gnome/DisplayManager/Display1
>Feb 16 15:56:39 localhost NetworkManager: <WARN>  nm_supplicant_interface_add_cb(): Unexpected supplicant error getting interface: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
>Feb 16 15:56:39 localhost NetworkManager: <WARN>  iface_state_cb(): could not get interface state: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken..
>Feb 16 15:56:44 localhost gdm-simple-slave[2560]: WARNING: Failed to get display id /org/gnome/DisplayManager/Display1: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
>Feb 16 15:56:44 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Adding handler 10: signum=10 0x80528d0
>Feb 16 15:56:44 localhost gdm-simple-slave[2560]: DEBUG: GdmServer: Starting X server process: /usr/bin/Xorg
>Feb 16 15:56:44 localhost gdm-simple-slave[2581]: DEBUG: GdmServer: Opening logfile for server /var/log/gdm
>Feb 16 15:56:44 localhost gdm-simple-slave[2581]: WARNING: gdm_server_spawn: Could not open logfile for display (null)!
>Feb 16 15:56:44 localhost gdm-simple-slave[2560]: DEBUG: GdmServer: Started X server process 2581 - waiting for READY
>Feb 16 15:56:44 localhost gdm-simple-slave[2560]: DEBUG: GdmSimpleSlave: Started X server
>Feb 16 15:56:55 localhost shutdown[2586]: shutting down for system reboot
>Feb 16 15:56:56 localhost init: Switching to runlevel: 6
>Feb 16 15:56:56 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: handling signal 15
>Feb 16 15:56:56 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Found 1 callbacks
>Feb 16 15:56:56 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: running 15 handler: 0x804c080
>Feb 16 15:56:56 localhost gdm-simple-slave[2560]: DEBUG: Got callback for signal 15
>Feb 16 15:56:56 localhost gdm-simple-slave[2560]: DEBUG: Caught signal 15, shutting down normally.
>Feb 16 15:56:56 localhost gdm-simple-slave[2560]: DEBUG: GdmSignalHandler: Caught termination signal - exiting main loop
>Feb 16 15:56:56 localhost gdm-simple-slave[2560]: DEBUG: GdmSimpleSlave: Stopping simple_slave
>Feb 16 15:56:56 localhost gdm-simple-slave[2560]: DEBUG: GdmSlave: Stopping slave
>Feb 16 15:56:56 localhost gdm-simple-slave[2560]: DEBUG: GdmSlave: Disconnected from display
>Feb 16 15:56:56 localhost gdm-simple-slave[2560]: DEBUG: GdmServer: Stopping server
>Feb 16 15:56:56 localhost gdm-simple-slave[2560]: DEBUG: sending signal 15 to process 2581
>Feb 16 15:56:56 localhost gdm-simple-slave[2560]: DEBUG: GdmServer: Waiting on process 2581
>Feb 16 15:57:00 localhost shutdown[2592]: shutting down for system reboot
>Feb 16 15:57:16 localhost NetworkManager: <WARN>  nm_signal_handler(): Caught signal 15, shutting down normally.
>Feb 16 15:57:16 localhost NetworkManager: <info>  Bringing down device eth1
>Feb 16 15:57:19 localhost kernel: BUG: soft lockup - CPU#1 stuck for 61s! [wpa_supplicant:2490]
>Feb 16 15:57:19 localhost kernel: 
>Feb 16 15:57:19 localhost kernel: Pid: 2490, comm: wpa_supplicant Not tainted (2.6.25-0.50.rc2.fc9 #1)
>Feb 16 15:57:19 localhost kernel: EIP: 0060:[<c063a012>] EFLAGS: 00200287 CPU: 1
>Feb 16 15:57:19 localhost kernel: EIP is at __write_lock_failed+0x12/0x20
>Feb 16 15:57:19 localhost kernel: EAX: c074c7d0 EBX: c074c7d0 ECX: c074c7e0 EDX: c06ec022
>Feb 16 15:57:19 localhost kernel: ESI: c074c7d0 EDI: f5369b00 EBP: f4066c30 ESP: f4066c30
>Feb 16 15:57:19 localhost kernel:  DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
>Feb 16 15:57:19 localhost kernel: CR0: 8005003b CR2: 0067c784 CR3: 3577d000 CR4: 000026d0
>Feb 16 15:57:19 localhost kernel: DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
>Feb 16 15:57:19 localhost kernel: DR6: ffff0ff0 DR7: 00000400
>Feb 16 15:57:19 localhost kernel:  [<c0501833>] _raw_write_lock+0x57/0x6c
>Feb 16 15:57:19 localhost kernel:  [<c063a7ac>] _write_lock_bh+0x40/0x4e
>Feb 16 15:57:19 localhost kernel:  [<c05cdccc>] do_setlink+0x2d6/0x34a
>Feb 16 15:57:19 localhost kernel:  [<c063a416>] ? _read_unlock+0x1d/0x20
>Feb 16 15:57:19 localhost kernel:  [<c05cde07>] rtnl_setlink+0xc7/0xe6
>Feb 16 15:57:19 localhost kernel:  [<c05cdd40>] ? rtnl_setlink+0x0/0xe6
>Feb 16 15:57:19 localhost kernel:  [<c05cecda>] rtnetlink_rcv_msg+0x1a5/0x1bf
>Feb 16 15:57:19 localhost kernel:  [<c05ceb35>] ? rtnetlink_rcv_msg+0x0/0x1bf
>Feb 16 15:57:19 localhost kernel:  [<c05dbdba>] netlink_rcv_skb+0x30/0x86
>Feb 16 15:57:19 localhost kernel:  [<c05ceb2d>] rtnetlink_rcv+0x1e/0x26
>Feb 16 15:57:19 localhost kernel:  [<c05db8de>] netlink_unicast+0x1b7/0x215
>Feb 16 15:57:19 localhost kernel:  [<c05dbb94>] netlink_sendmsg+0x258/0x265
>Feb 16 15:57:19 localhost kernel:  [<c05bbe3b>] sock_sendmsg+0xde/0xf9
>Feb 16 15:57:19 localhost kernel:  [<c0439733>] ? autoremove_wake_function+0x0/0x33
>Feb 16 15:57:19 localhost kernel:  [<c040a37c>] ? native_sched_clock+0xb5/0xd1
>Feb 16 15:57:19 localhost kernel:last message repeated 3 times
>Feb 16 15:57:19 localhost kernel:  [<c05bc712>] sys_sendto+0xa4/0xc3
>Feb 16 15:57:19 localhost kernel:  [<c0483bf7>] ? check_object+0x111/0x185
>Feb 16 15:57:19 localhost kernel:  [<c04849c6>] ? __slab_free+0xb2/0x2fc
>Feb 16 15:57:19 localhost kernel:  [<c044495b>] ? trace_hardirqs_on+0xe9/0x10a
>Feb 16 15:57:19 localhost kernel:  [<c04860fb>] ? kmem_cache_free+0x70/0x8b
>Feb 16 15:57:19 localhost kernel:  [<c0498181>] ? d_free+0x3b/0x4d
>Feb 16 15:57:19 localhost kernel:  [<c05bc749>] sys_send+0x18/0x1a
>Feb 16 15:57:19 localhost kernel:  [<c05bce44>] sys_socketcall+0xe6/0x186
>Feb 16 15:57:19 localhost kernel:  [<c0405d66>] syscall_call+0x7/0xb
>Feb 16 15:57:19 localhost kernel:  =======================
>Feb 16 15:57:20 localhost smartd[2499]: smartd received signal 15: Terminated
>Feb 16 15:57:20 localhost smartd[2499]: smartd is exiting (exit status 0)
>Feb 16 15:57:20 localhost audio-entropyd: audio-entropyd stopping
>Feb 16 15:57:20 localhost avahi-daemon[2313]: Got SIGTERM, quitting.
>Feb 16 15:57:21 localhost acpid: exiting
>Feb 16 15:57:21 localhost auditd[2196]: The audit daemon is exiting.
>Feb 16 15:57:21 localhost kernel: printk: 1 messages suppressed.
>Feb 16 15:57:21 localhost kernel: audit(1203206241.501:13): audit_pid=0 old=2196 by auid=4294967295 subj=system_u:system_r:auditd_t:s0 res=1
>Feb 16 15:57:21 localhost console-kit-daemon[2326]: GLib-CRITICAL: g_async_queue_unref: assertion `queue->waiting_threads == 0' failed
>Feb 16 15:57:21 localhost ntpd[2276]: ntpd exiting on signal 15
>Feb 16 15:57:23 localhost kernel: Kernel logging (proc) stopped.
>Feb 16 15:57:23 localhost kernel: Kernel log daemon terminating.

Actions: View

Attachments on bug 433157: 295083 | 295122