[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]

Re: NetworkManager and "illegal" SSID chars = crash?



On Wed, Sep 05, 2007 at 01:01:45PM -0400, Dan Williams wrote:
> > Anyone else recognize this behavior?
> RPM versions, kernel version, wpa_supplicant version, and any changes
> you may have made to drivers or whatever could help.  Also, was it NM,
> or the applet that died?

Originally NM itself. But see below...

This is rawhide; it's been happening since Fedora 7-era or so, but it just
dawned on me what the cause of the problem is. Or likely is -- I haven't
actually proved it yet. Currently, NetworkManager 0.6.5-9.fc8, kernel
2.6.23-0.164.rc5.fc8, and wpa_supplicant-0.5.7-7. I'm using the stock
orinoco_pci driver.

In the last couple of days (weeks?) NM doesn't completely die, but instead
logs crashy sorts of things while nm-applet vanishes and can't be restarted.
There's backtraces like this in /var/log/messages, but I'm not exactly sure what's
going on when they appear. (Note: see below the log message for more text.)

Sep  3 11:37:16 ylla NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 0
Sep  3 11:37:17 ylla NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 1
Sep  3 11:41:26 ylla NetworkManager: <WARN>  nm_hal_deinit(): libhal shutdown failed - Connection is closed
Sep  3 11:41:26 ylla NetworkManager: <WARN>  nm_signal_handler(): Caught signal 11.  Generating backtrace...
Sep  3 11:41:26 ylla NetworkManager: <info>  Successfully reconnected to the system bus.
Sep  3 11:41:27 ylla NetworkManager: ******************* START **********************************
Sep  3 11:41:28 ylla NetworkManager: (no debugging symbols found)
Sep  3 11:41:29 ylla NetworkManager: Using host libthread_db library "/lib/libthread_db.so.1".
Sep  3 11:41:29 ylla NetworkManager: (no debugging symbols found)
Sep  3 11:41:29 ylla NetworkManager:last message repeated 12 times
Sep  3 11:41:29 ylla NetworkManager: [Thread debugging using libthread_db enabled]
Sep  3 11:41:29 ylla NetworkManager: [New Thread -1208538624 (LWP 1909)]
Sep  3 11:41:29 ylla NetworkManager: [New Thread -1208542320 (LWP 15022)]
Sep  3 11:41:29 ylla NetworkManager: [New Thread -1219032176 (LWP 15019)]
Sep  3 11:41:29 ylla NetworkManager: [New Thread -1229522032 (LWP 2139)]
Sep  3 11:41:29 ylla NetworkManager: (no debugging symbols found)
Sep  3 11:41:29 ylla NetworkManager:last message repeated 6 times
Sep  3 11:41:29 ylla NetworkManager: 0x0012d402 in __kernel_vsyscall ()
Sep  3 11:41:29 ylla NetworkManager: #0  0x0012d402 in __kernel_vsyscall ()
Sep  3 11:41:29 ylla NetworkManager: #1  0x0035b47b in waitpid () from /lib/libpthread.so.0
Sep  3 11:41:29 ylla NetworkManager: #2  0x0806d3b0 in ?? ()
Sep  3 11:41:29 ylla NetworkManager: #3  0x0806d4a1 in ?? ()
Sep  3 11:41:29 ylla NetworkManager: #4  <signal handler called>
Sep  3 11:41:29 ylla NetworkManager: #5  0x08056147 in nm_get_device_by_iface ()
Sep  3 11:41:29 ylla NetworkManager: #6  0x0807bb9f in nm_dhcp_manager_process_signal ()
Sep  3 11:41:29 ylla NetworkManager: #7  0x0805faed in ?? ()
Sep  3 11:41:29 ylla NetworkManager: #8  0x001bc664 in dbus_connection_dispatch () from /lib/libdbus-1.so.3
Sep  3 11:41:29 ylla NetworkManager: #9  0x00198e7d in ?? () from /usr/lib/libdbus-glib-1.so.2
Sep  3 11:41:29 ylla NetworkManager: #10 0x0025917c in g_main_context_dispatch () from /lib/libglib-2.0.so.0
Sep  3 11:41:29 ylla NetworkManager: #11 0x0025c5bf in ?? () from /lib/libglib-2.0.so.0
Sep  3 11:41:29 ylla NetworkManager: #12 0x0025c969 in g_main_loop_run () from /lib/libglib-2.0.so.0
Sep  3 11:41:29 ylla NetworkManager: #13 0x080693c8 in main ()
Sep  3 11:41:29 ylla NetworkManager: 
Sep  3 11:41:29 ylla NetworkManager: Thread 4 (Thread -1229522032 (LWP 2139)):
Sep  3 11:41:29 ylla NetworkManager: #0  0x0012d402 in __kernel_vsyscall ()
Sep  3 11:41:29 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:29 ylla NetworkManager: #1  0x0035a52b in read () from /lib/libpthread.so.0
Sep  3 11:41:29 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:29 ylla NetworkManager: #2  0x0025a11d in ?? () from /lib/libglib-2.0.so.0
Sep  3 11:41:29 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:29 ylla NetworkManager: #3  0x0027c77f in ?? () from /lib/libglib-2.0.so.0
Sep  3 11:41:29 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:29 ylla NetworkManager: #4  0x0035353b in start_thread () from /lib/libpthread.so.0
Sep  3 11:41:29 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:29 ylla NetworkManager: #5  0x004380ee in clone () from /lib/libc.so.6
Sep  3 11:41:29 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:29 ylla NetworkManager: 
Sep  3 11:41:29 ylla NetworkManager: Thread 3 (Thread -1219032176 (LWP 15019)):
Sep  3 11:41:29 ylla NetworkManager: #0  0x0012d402 in __kernel_vsyscall ()
Sep  3 11:41:29 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:29 ylla NetworkManager: #1  0x0042e053 in poll () from /lib/libc.so.6
Sep  3 11:41:29 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:29 ylla NetworkManager: #2  0x0025c5f3 in ?? () from /lib/libglib-2.0.so.0
Sep  3 11:41:29 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:29 ylla NetworkManager: #3  0x0025c969 in g_main_loop_run () from /lib/libglib-2.0.so.0
Sep  3 11:41:29 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:29 ylla NetworkManager: #4  0x0805696e in ?? ()
Sep  3 11:41:29 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:29 ylla NetworkManager: #5  0x0027c77f in ?? () from /lib/libglib-2.0.so.0
Sep  3 11:41:29 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:29 ylla NetworkManager: #6  0x0035353b in start_thread () from /lib/libpthread.so.0
Sep  3 11:41:29 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:29 ylla NetworkManager: #7  0x004380ee in clone () from /lib/libc.so.6
Sep  3 11:41:29 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:29 ylla NetworkManager: 
Sep  3 11:41:29 ylla NetworkManager: Thread 2 (Thread -1208542320 (LWP 15022)):
Sep  3 11:41:29 ylla NetworkManager: #0  0x0012d402 in __kernel_vsyscall ()
Sep  3 11:41:29 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:29 ylla NetworkManager: #1  0x0042e053 in poll () from /lib/libc.so.6
Sep  3 11:41:29 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:29 ylla NetworkManager: #2  0x0025c5f3 in ?? () from /lib/libglib-2.0.so.0
Sep  3 11:41:29 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:29 ylla NetworkManager: #3  0x0025c969 in g_main_loop_run () from /lib/libglib-2.0.so.0
Sep  3 11:41:29 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:29 ylla NetworkManager: #4  0x0805696e in ?? ()
Sep  3 11:41:30 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:30 ylla NetworkManager: #5  0x0027c77f in ?? () from /lib/libglib-2.0.so.0
Sep  3 11:41:30 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:30 ylla NetworkManager: #6  0x0035353b in start_thread () from /lib/libpthread.so.0
Sep  3 11:41:30 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:30 ylla NetworkManager: #7  0x004380ee in clone () from /lib/libc.so.6
Sep  3 11:41:30 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:30 ylla NetworkManager: 
Sep  3 11:41:30 ylla NetworkManager: Thread 1 (Thread -1208538624 (LWP 1909)):
Sep  3 11:41:30 ylla NetworkManager: #0  0x0012d402 in __kernel_vsyscall ()
Sep  3 11:41:30 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:30 ylla NetworkManager: #1  0x0035b47b in waitpid () from /lib/libpthread.so.0
Sep  3 11:41:30 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:30 ylla NetworkManager: #2  0x0806d3b0 in ?? ()
Sep  3 11:41:30 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:30 ylla NetworkManager: #3  0x0806d4a1 in ?? ()
Sep  3 11:41:30 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:30 ylla NetworkManager: #4  <signal handler called>
Sep  3 11:41:30 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:30 ylla NetworkManager: #5  0x08056147 in nm_get_device_by_iface ()
Sep  3 11:41:30 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:30 ylla NetworkManager: #6  0x0807bb9f in nm_dhcp_manager_process_signal ()
Sep  3 11:41:30 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:30 ylla NetworkManager: #7  0x0805faed in ?? ()
Sep  3 11:41:30 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:30 ylla NetworkManager: #8  0x001bc664 in dbus_connection_dispatch () from /lib/libdbus-1.so.3
Sep  3 11:41:30 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:30 ylla NetworkManager: #9  0x00198e7d in ?? () from /usr/lib/libdbus-glib-1.so.2
Sep  3 11:41:30 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:30 ylla NetworkManager: #10 0x0025917c in g_main_context_dispatch () from /lib/libglib-2.0.so.0
Sep  3 11:41:30 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:30 ylla NetworkManager: #11 0x0025c5bf in ?? () from /lib/libglib-2.0.so.0
Sep  3 11:41:30 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:30 ylla NetworkManager: #12 0x0025c969 in g_main_loop_run () from /lib/libglib-2.0.so.0
Sep  3 11:41:30 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:30 ylla NetworkManager: #13 0x080693c8 in main ()
Sep  3 11:41:30 ylla NetworkManager: No symbol table info available.
Sep  3 11:41:30 ylla NetworkManager: #0  0x0012d402 in __kernel_vsyscall ()
Sep  3 11:41:30 ylla NetworkManager: The program is running.  Quit anyway (and detach it)? (y or n) [answered Y; input not from terminal]
Sep  3 11:41:30 ylla NetworkManager: ******************* END **********************************


Just now, when I rebooted to try to generate a nice clean log of the problem
under a semi-controlled environment, everything came up apparently fine and
working. (First time ever at my house.) Then I realized that for whatever
reason, iwlist scan wasn't showing the URL SSID. So I moved around the house
until it showed up -- and boom, there goes nm-applet.

When I try to restart nm-applet, I get this error (familiar to me from the
times nm-applet isn't even there at boot time):

  process 2230: arguments to dbus_message_new_method_call() were incorrect, assertion "_dbus_check_is_valid_path (path)" failed in file dbus-message.c line 1074.
  This is normally a bug in some application using the D-Bus library.
    D-Bus not built with -rdynamic so unable to print a backtrace
  Aborted

So I then try to restart NetworkManager (sudo service NetworkManager
restart), and then I get this in the logs. (Again, more text below the log.)

Sep  5 21:50:17 ylla NetworkManager: <info>  starting...
Sep  5 21:50:18 ylla NetworkManager: <info>  New VPN service 'vpnc' (org.freedesktop.NetworkManager.vpnc).
Sep  5 21:50:18 ylla NetworkManager: <info>  New VPN service 'openvpn' (org.freedesktop.NetworkManager.openvpn).
Sep  5 21:50:18 ylla NetworkManager: <info>  wlan0: Device is fully-supported using driver 'orinoco_pci'.
Sep  5 21:50:18 ylla NetworkManager: <info>  nm_device_init(): waiting for device's worker thread to start
Sep  5 21:50:18 ylla NetworkManager: <info>  nm_device_init(): device's worker thread started, continuing.
Sep  5 21:50:18 ylla NetworkManager: <info>  Now managing wireless (802.11) device 'wlan0'.
Sep  5 21:50:18 ylla NetworkManager: <info>  Deactivating device wlan0.
Sep  5 21:50:18 ylla NetworkManager: <info>  eth0: Device is fully-supported using driver 'e100'.
Sep  5 21:50:18 ylla NetworkManager: <info>  nm_device_init(): waiting for device's worker thread to start
Sep  5 21:50:18 ylla NetworkManager: <info>  nm_device_init(): device's worker thread started, continuing.
Sep  5 21:50:18 ylla NetworkManager: <info>  Now managing wired Ethernet (802.3) device 'eth0'.
Sep  5 21:50:18 ylla NetworkManager: <info>  Deactivating device eth0.
Sep  5 21:50:18 ylla NetworkManager: <info>  Found dial up configuration for Verizon via Modem: Verizon
Sep  5 21:50:18 ylla NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device eth0 link now 0
Sep  5 21:50:18 ylla NetworkManager: <info>  nm-device-802-3-ethernet.c - nm_device_802_3_ethernet_link_deactivated (149) device eth0 scheduled link_deactivated_helper
Sep  5 21:50:18 ylla NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 0
Sep  5 21:50:18 ylla NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 0
Sep  5 21:50:18 ylla NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device eth0 link now 1
Sep  5 21:50:18 ylla NetworkManager: <info>  nm-device-802-3-ethernet.c - link_deactivated_helper (129) device eth0 will set active link to FALSE
Sep  5 21:50:18 ylla NetworkManager: <info>  nm-device-802-3-ethernet.c - link_activated_helper (102) device eth0 will set active link to TRUE
Sep  5 21:50:18 ylla NetworkManager: <info>  nm-device.c - nm_device_set_active_link (596) device eth0 link state set to 1
Sep  5 21:50:18 ylla NetworkManager: <info>  Will activate wired connection 'eth0' because it now has a link.
Sep  5 21:50:18 ylla NetworkManager: <info>  nm-device-802-3-ethernet.c - nm_device_802_3_ethernet_link_activated (122) device eth0 scheduled link_activated_helper
Sep  5 21:50:18 ylla NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device eth0 link now 0
Sep  5 21:50:18 ylla NetworkManager: <info>  nm-device-802-3-ethernet.c - nm_device_802_3_ethernet_link_deactivated (149) device eth0 scheduled link_deactivated_helper
Sep  5 21:50:18 ylla NetworkManager: <info>  nm-device-802-3-ethernet.c - link_deactivated_helper (129) device eth0 will set active link to FALSE
Sep  5 21:50:18 ylla NetworkManager: <info>  nm-device.c - nm_device_set_active_link (596) device eth0 link state set to 0
Sep  5 21:50:18 ylla NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 1
Sep  5 21:50:32 ylla NetworkManager: <WARN>  request_and_convert_scan_results(): card took too much time scanning.  Get a better one.
Sep  5 21:50:55 ylla NetworkManager: <info>  Updating allowed wireless network lists.
Sep  5 21:50:55 ylla NetworkManager: <WARN>  nm_dbus_get_networks_cb(): error received: org.freedesktop.NetworkManagerInfo.NoNetworks - There are no wireless networks stored..
Sep  5 21:50:55 ylla NetworkManager: <info>  Updating VPN Connections...
Sep  5 21:51:02 ylla NetworkManager: <WARN>  nm_hal_deinit(): libhal shutdown failed - Connection is closed
Sep  5 21:51:02 ylla NetworkManager: nm_get_device_by_iface: assertion `data != NULL' failed
Sep  5 21:51:02 ylla NetworkManager: <info>  Successfully reconnected to the system bus.
Sep  5 21:51:52 ylla NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 0
Sep  5 21:51:54 ylla NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 1
Sep  5 21:52:32 ylla NetworkManager: <WARN>  nm_hal_deinit(): libhal shutdown failed - Connection is closed
Sep  5 21:52:32 ylla NetworkManager: <info>  Successfully reconnected to the system bus.
Sep  5 21:54:42 ylla NetworkManager: <WARN>  nm_hal_deinit(): libhal shutdown failed - Connection is closed
Sep  5 21:54:42 ylla NetworkManager: <info>  Successfully reconnected to the system bus.
Sep  5 21:55:10 ylla NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 0
Sep  5 21:55:10 ylla NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 0
Sep  5 21:55:12 ylla NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 1


So then I say "screw it", and type "/sbin/ifup wlan0", which just works,
enabling me to scp those logs to you over the network with the URL ssid.

Oh -- hmmm, there's this NetworkManagerDispatcher thing -- sorry, I hadn't
thought to restart that. Well, if I restart NetworkManagerDispatcher *and*
NetworkManager, I can run nm-applet, and it'll be several seconds before
it crashes with the above assertion failure again.



-- 
Matthew Miller           mattdm mattdm org          <http://mattdm.org/>
Boston University Linux      ------>              <http://linux.bu.edu/>


[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]