Bug 502097

Summary: crash when nm_supplicant_interface_add_cb() fails
Product: [Fedora] Fedora Reporter: David Woodhouse <dwmw2>
Component: NetworkManagerAssignee: Dan Williams <dcbw>
Status: CLOSED WORKSFORME QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: low    
Version: 11CC: arxs, danw, dcbw
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2009-11-27 11:02:26 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
usbreset.c
none
typescript none

Description David Woodhouse 2009-05-21 20:35:03 UTC 
The PC in my car has a rt73usb wireless device, so that when it's parked outside my house it can rsync my music collection.

I've configured it to hibernate when the ignition is turned off, to improve the "boot" time. USB devices seem not to like this much, so I added a script in /usr/lib/pm-utils/sleep.d to do a USBDEVFS_RESET on each one after resume.

This worked for the first few attempts, but then NetworkManager died.

May 21 17:59:44 audi NetworkManager: <info>  Waking up...
May 21 17:59:44 audi kernel: eth0: link down
May 21 17:59:44 audi kernel: ADDRCONF(NETDEV_UP): eth0: link is not ready
May 21 17:59:44 audi NetworkManager: <info>  (eth0): now managed
May 21 17:59:44 audi NetworkManager: <info>  (eth0): device state change: 1 -> 2
May 21 17:59:44 audi NetworkManager: <info>  (eth0): bringing up device.
May 21 17:59:44 audi NetworkManager: <info>  (eth0): preparing device.
May 21 17:59:44 audi NetworkManager: <info>  (eth0): deactivating device (reason: 2).
May 21 17:59:44 audi NetworkManager: <info>  (wlan0): now managed
May 21 17:59:44 audi NetworkManager: <info>  (wlan0): device state change: 1 -> 2
May 21 17:59:44 audi NetworkManager: <info>  (wlan0): bringing up device.
May 21 17:59:44 audi NetworkManager: <info>  (wlan0): deactivating device (reason: 2).
May 21 17:59:44 audi NetworkManager: <info>  (ttyS0): ignoring due to lack of mobile broadband capabilties
May 21 17:59:44 audi NetworkManager: <info>  (wlan0): device state change: 2 -> 3
May 21 17:59:44 audi logger: Resetting USB devices
May 21 17:59:44 audi kernel: usb 1-2: USB disconnect, address 11
May 21 17:59:44 audi kernel: phy7 -> rt2x00usb_vendor_request: Error - Vendor Request 0x0a failed for offset 0x0000 with error -19.
May 21 17:59:44 audi kernel: phy7 -> rt2x00usb_vendor_request: Error - Vendor Request 0x0a failed for offset 0x0000 with error -19.
May 21 17:59:44 audi kernel: phy7 -> rt2x00usb_vendor_request: Error - Vendor Request 0x0a failed for offset 0x0000 with error -19.
May 21 17:59:44 audi NetworkManager: <info>  (wlan0): now unmanaged
May 21 17:59:44 audi NetworkManager: <info>  (wlan0): device state change: 3 -> 1
May 21 17:59:44 audi NetworkManager: <WARN>  nm_supplicant_interface_add_cb(): Unexpected supplicant error getting interface: wpa_supplicant couldn't grab this interface.
May 21 17:59:44 audi NetworkManager: <WARN>  nm_signal_handler(): Caught signal 11.  Generating backtrace...
May 21 17:59:44 audi NetworkManager: ******************* START **********************************
May 21 17:59:44 audi kernel: usb 2-1: USB disconnect, address 8
May 21 17:59:44 audi kernel: btusb_intr_complete: hci0 urb c8524380 failed to resubmit (19)
May 21 17:59:44 audi kernel: btusb_bulk_complete: hci0 urb c8524c80 failed to resubmit (19)
May 21 17:59:44 audi kernel: btusb_bulk_complete: hci0 urb c8524e80 failed to resubmit (19)
May 21 17:59:44 audi bluetoothd[1180]: HCI dev 0 down
May 21 17:59:44 audi bluetoothd[1180]: Adapter /org/bluez/1180/hci0 has been disabled
May 21 17:59:44 audi bluetoothd[1180]: Stopping security manager 0
May 21 17:59:44 audi kernel: btusb_send_frame: hci0 urb ce955a80 submission failed
May 21 17:59:44 audi kernel: usb 1-2: new high speed USB device using ehci_hcd and address 12
May 21 17:59:45 audi bluetoothd[1180]: HCI dev 0 unregistered
May 21 17:59:45 audi bluetoothd[1180]: Unregister path: /org/bluez/1180/hci0
May 21 17:59:45 audi NetworkManager: [Thread debugging using libthread_db enabled]
May 21 17:59:45 audi NetworkManager: [New Thread 0xb7ef4b70 (LWP 1888)]
May 21 17:59:45 audi kernel: usb 1-2: string descriptor 0 read error: -61
May 21 17:59:45 audi kernel: usb 1-2: string descriptor 0 read error: -61
May 21 17:59:45 audi kernel: usb 1-2: New USB device found, idVendor=0411, idProduct=00f4
May 21 17:59:45 audi kernel: usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
May 21 17:59:45 audi kernel: usb 1-2: configuration #1 chosen from 1 choice
May 21 17:59:45 audi NetworkManager: 0x00c58416 in __kernel_vsyscall ()
May 21 17:59:45 audi NetworkManager: #0  0x00c58416 in __kernel_vsyscall ()
May 21 17:59:45 audi NetworkManager: #1  0x003f7e1b in waitpid () from /lib/libpthread.so.0
May 21 17:59:45 audi NetworkManager: #2  0x08075e01 in nm_logging_backtrace ()
May 21 17:59:45 audi NetworkManager: #3  0x08070505 in ?? ()
May 21 17:59:45 audi NetworkManager: #4  <signal handler called>
May 21 17:59:45 audi NetworkManager: #5  0x002e9053 in strlen () from /lib/libc.so.6
May 21 17:59:45 audi NetworkManager: #6  0x0058884d in ?? () from /lib/libdbus-1.so.3
May 21 17:59:45 audi NetworkManager: #7  0x00574773 in ?? () from /lib/libdbus-1.so.3
May 21 17:59:45 audi NetworkManager: #8  0x00579506 in dbus_message_iter_append_basic () from /lib/libdbus-1.so.3
May 21 17:59:45 audi NetworkManager: #9  0x00d65dea in ?? () from /usr/lib/libdbus-glib-1.so.2
May 21 17:59:45 audi NetworkManager: #10 0x00d640c5 in ?? () from /usr/lib/libdbus-glib-1.so.2
May 21 17:59:45 audi NetworkManager: #11 0x00d5f763 in ?? () from /usr/lib/libdbus-glib-1.so.2
May 21 17:59:45 audi NetworkManager: #12 0x00d5fa09 in dbus_g_proxy_call_no_reply ()
May 21 17:59:45 audi NetworkManager:    from /usr/lib/libdbus-glib-1.so.2
May 21 17:59:45 audi NetworkManager: #13 0x080969b1 in ?? ()
May 21 17:59:45 audi NetworkManager: #14 0x005ae458 in g_object_unref () from /lib/libgobject-2.0.so.0
May 21 17:59:45 audi NetworkManager: #15 0x0809415f in ?? ()
May 21 17:59:45 audi NetworkManager: #16 0x00d5e719 in ?? () from /usr/lib/libdbus-glib-1.so.2
May 21 17:59:45 audi NetworkManager: #17 0x00585bb4 in ?? () from /lib/libdbus-1.so.3
May 21 17:59:45 audi NetworkManager: #18 0x00585c02 in ?? () from /lib/libdbus-1.so.3
May 21 17:59:45 audi NetworkManager: #19 0x0057d5ca in ?? () from /lib/libdbus-1.so.3
May 21 17:59:45 audi NetworkManager: #20 0x0056d0be in ?? () from /lib/libdbus-1.so.3
May 21 17:59:45 audi NetworkManager: #21 0x0056f682 in dbus_connection_dispatch () from /lib/libdbus-1.so.3
May 21 17:59:45 audi NetworkManager: #22 0x00d5a19d in ?? () from /usr/lib/libdbus-glib-1.so.2
May 21 17:59:45 audi NetworkManager: #23 0x0049b1e8 in g_main_context_dispatch () from /lib/libglib-2.0.so.0
May 21 17:59:45 audi NetworkManager: #24 0x0049e7f8 in ?? () from /lib/libglib-2.0.so.0
May 21 17:59:45 audi NetworkManager: #25 0x0049ecaf in g_main_loop_run () from /lib/libglib-2.0.so.0
Comment 1 Niels Haase 2009-05-22 00:59:49 UTC 
Thank you for taking the time to report this bug report. Unfortunately, that stack trace is not very useful in determining the cause of the crash, because there is not a symbolic stack trace. In order to get a symbolic stack trace, the appropriate debuginfo packages need to be installed. In order to accomplish this, you can run the command: 

debuginfo-install NetworkManager 

Please see http://fedoraproject.org/wiki/StackTraces for more information about stack traces. 

-- 
Fedora Bugzappers volunteer triage team
https://fedoraproject.org/wiki/BugZappers
Comment 2 Bug Zapper 2009-06-09 16:17:42 UTC 
This bug appears to have been reported against 'rawhide' during the Fedora 11 development cycle.
Changing version to '11'.

More information and reason for this action is here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping
Comment 3 Dan Williams 2009-11-11 17:27:50 UTC 
Need to verify that error path in nm_supplicant_interface_add_cb().
Comment 4 Dan Williams 2009-11-12 01:02:18 UTC 
Any chance you could attach your usbdevfs_reset script so I can use that to test and verify?  I think it's related to that specifically.
Comment 5 David Woodhouse 2009-11-12 17:14:20 UTC 
This is /usr/lib/pm-utils/sleep.d/99usb:

#!/bin/sh

. "${PM_FUNCTIONS}"

case "$1" in
	hibernate|suspend)
		rmmod rt73usb
		/usr/sbin/hciconfig hci0 down ; rmmod btusb || :
		;;
	thaw|resume)
		lsusb | egrep 0411:00f4\|0bf8:1003\|1131:1004\|0403:abcf |
			sed 's/Bus \(...\) Device \(...\):.*/\1 \2/' |
			while read A B ; do 
				logger Resetting USB bus $A dev $B
				/root/usbreset /proc/bus/usb/$A/$B ; 
			done
		/sbin/modprobe rt73usb
		/sbin/modprobe btusb
		ifconfig wlan0
		;;
	*) exit $NA
		;;
esac
Comment 6 David Woodhouse 2009-11-12 17:15:07 UTC 
Created attachment 369263 [details]
usbreset.c
Comment 7 Dan Williams 2009-11-23 05:45:57 UTC 
I assume the wifi connection is a system connection, right?
Comment 8 Dan Williams 2009-11-23 06:36:50 UTC 
I can't reproduce this with latest F11 updates (2.6.30.9-96.fc11.i686.PAE), current NM 0.7.x git, an rt73usb device, and about 10 hibernate/thaw cycles on my Dell D410.  Can you try latest updates-testing NM update and see if you can still reproduce the issue?
Comment 9 David Woodhouse 2009-11-27 11:02:26 UTC 
I updated, then set things up so I could SSH into the box over a Bluetooth RFCOMM socket without needing networking, and did some controlled tests -- and everything worked fine. I don't see this crash anywhere in the last month's logs, either.

Will re-open if I ever see it again.
Comment 10 David Woodhouse 2009-11-27 13:40:01 UTC 
Created attachment 374217 [details]
typescript

Heh, as soon as it's not being watched, it misbehaves. Not the original crash, but a failure to connect. The wireless device is working correctly after the resume, but NetworkManager doesn't use it.

When I turned it on at about 1pm, it failed to connect to the wireless. I was able to SSH in and poke at it, without much enlightenment. Restarting NetworkManager made it connect.
Comment 11 David Woodhouse 2009-11-27 15:51:50 UTC 
Nov 27 07:29:04 audi NetworkManager: <info>  Marking connection 'Auto Baythorne Wavelan' invalid.

Perhaps I upset it by turning the car on and then immediately leaving the vicinity of the access point :)

Looking at the code, the INVALID_TAG ought to be cleared on all connections after a suspend/resume though. So why, when it comes back up at 13:00, does it not connect?

Btw, shouldn't it clear the INVALID_TAG if the network in question disappears from the scan for a while, then turns up again? Or just after a timeout if it _is_ constantly visible in scan. Surely it's better to try again than to just remain disconnected?