Gentoo Websites Logo
Go to: Gentoo Home Documentation Forums Lists Bugs Planet Store Wiki Get Gentoo!
Bug 320097 - net-wireless/wpa_supplicant-0.7.2: let network-manager crash with nm_call_store_remove(): Trying to remove a non-existant call id.
Summary: net-wireless/wpa_supplicant-0.7.2: let network-manager crash with nm_call_sto...
Status: RESOLVED FIXED
Alias: None
Product: Gentoo Linux
Classification: Unclassified
Component: Current packages (show other bugs)
Hardware: All Linux
: High normal (vote)
Assignee: Bjarke Istrup Pedersen (RETIRED)
URL:
Whiteboard:
Keywords: InVCS
Depends on:
Blocks:
 
Reported: 2010-05-17 07:13 UTC by Martin Dummer
Modified: 2010-05-19 18:38 UTC (History)
15 users (show)

See Also:
Package list:
Runtime testing required: ---


Attachments
upstream patch (do-not-call-dbus-functions-with-NULL-path.patch,1.89 KB, patch)
2010-05-18 12:00 UTC, Matthias Fulz
Details | Diff
ebuild which includes patch (wpa_supplicant-0.7.2-r1.ebuild,7.16 KB, text/plain)
2010-05-18 12:00 UTC, Matthias Fulz
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Martin Dummer 2010-05-17 07:13:26 UTC
since net-wireless/wpa_supplicant-0.7.2 was upgraded from 0.7.1 the networkmanager service crashes during initialization with 

nm_call_store_remove(): Trying to remove a non-existant call id.

to make sure that wpa_supplicant is causing this I downgraded to 0.6.10 - this is working, problem comes again with 0.7.2

Reproducible: Always

Steps to Reproduce:
1.have net-misc/networkmanager-0.8-r1 on your system
2.upgrade wpa_supplicant from 0.7.1 to 0.7.2
3.see if it's running

Actual Results:  
NetworkManager daemon crashes during initialize

Expected Results:  
NetworkManager should start

This is a syslog excerpt from crashing NetworkManager, 

2010-05-17T08:10:11.681117+02:00 localhost NetworkManager: <info>  starting...
2010-05-17T08:10:11.683569+02:00 localhost NetworkManager: <info>  modem-manager is now available
2010-05-17T08:10:11.685337+02:00 localhost NetworkManager: Loaded plugin keyfile: (c) 2007 - 2008 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
2010-05-17T08:10:11.686729+02:00 localhost NetworkManager: <info>  Found wlan radio killswitch rfkill2 (at /sys/devices/pci0000:00/0000:00:1c.2/0000:08:00.0/ieee80211/phy0/rfkill2) (driver <unknown>)
2010-05-17T08:10:11.686902+02:00 localhost NetworkManager: <info>  Found wwan radio killswitch rfkill0 (at /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-5/rfkill/rfkill0) (driver usb)
2010-05-17T08:10:11.688898+02:00 localhost NetworkManager: <info>  WiFi enabled by radio killswitch; enabled by state file
2010-05-17T08:10:11.688963+02:00 localhost NetworkManager: <info>  WWAN enabled by radio killswitch; disabled by state file
2010-05-17T08:10:11.690630+02:00 localhost NetworkManager: Ignoring insecure configuration file '/etc/NetworkManager/system-connections/.keep_net-misc_networkmanager-0'
2010-05-17T08:10:11.691641+02:00 localhost NetworkManager: <info>  (eth0): carrier is OFF
2010-05-17T08:10:11.691714+02:00 localhost NetworkManager: <info>  (eth0): new Ethernet device (driver: 'e1000e')
2010-05-17T08:10:11.691732+02:00 localhost NetworkManager: <info>  (eth0): exported as /org/freedesktop/NetworkManager/Devices/0
2010-05-17T08:10:11.695057+02:00 localhost NetworkManager: <info>  (eth0): now managed
2010-05-17T08:10:11.695736+02:00 localhost NetworkManager: <info>  (eth0): device state change: 1 -> 2 (reason 2)
2010-05-17T08:10:11.695786+02:00 localhost NetworkManager: <info>  (eth0): preparing device.
2010-05-17T08:10:11.695827+02:00 localhost NetworkManager: <info>  (eth0): deactivating device (reason: 2).
2010-05-17T08:10:11.695937+02:00 localhost NetworkManager: Added default wired connection 'Auto eth0' for /sys/devices/pci0000:00/0000:00:19.0/net/eth0
2010-05-17T08:10:11.696456+02:00 localhost NetworkManager: <info>  (wlan0): driver supports SSID scans (scan_capa 0x01).
2010-05-17T08:10:11.696531+02:00 localhost NetworkManager: <info>  (wlan0): new 802.11 WiFi device (driver: 'iwlagn')
2010-05-17T08:10:11.696579+02:00 localhost NetworkManager: <info>  (wlan0): exported as /org/freedesktop/NetworkManager/Devices/1
2010-05-17T08:10:11.696620+02:00 localhost NetworkManager: <info>  (wlan0): now managed
2010-05-17T08:10:11.696660+02:00 localhost NetworkManager: <info>  (wlan0): device state change: 1 -> 2 (reason 2)
2010-05-17T08:10:11.696700+02:00 localhost NetworkManager: <info>  (wlan0): preparing device.
2010-05-17T08:10:11.696739+02:00 localhost NetworkManager: <info>  (wlan0): deactivating device (reason: 2).
2010-05-17T08:10:11.696779+02:00 localhost NetworkManager: supplicant_interface_acquire: assertion `mgr_state == NM_SUPPLICANT_MANAGER_STATE_IDLE' failed
2010-05-17T08:10:11.697045+02:00 localhost NetworkManager: <WARN>  device_creator(): /sys/devices/virtual/net/virbr0: couldn't determine device driver; ignoring...
2010-05-17T08:10:11.697108+02:00 localhost NetworkManager: <WARN>  device_creator(): /sys/devices/virtual/net/vmnet1: couldn't determine device driver; ignoring...
2010-05-17T08:10:11.697170+02:00 localhost NetworkManager: <WARN>  device_creator(): /sys/devices/virtual/net/vmnet8: couldn't determine device driver; ignoring...
2010-05-17T08:10:11.721678+02:00 localhost NetworkManager: <info>  (hso0): new GSM device (driver: 'hso')
2010-05-17T08:10:11.721697+02:00 localhost NetworkManager: <info>  (hso0): exported as /org/freedesktop/NetworkManager/Devices/2
2010-05-17T08:10:11.721703+02:00 localhost NetworkManager: <info>  (hso0): now managed
2010-05-17T08:10:11.721708+02:00 localhost NetworkManager: <info>  (hso0): device state change: 1 -> 2 (reason 2)
2010-05-17T08:10:11.721735+02:00 localhost NetworkManager: <info>  (hso0): deactivating device (reason: 2).
2010-05-17T08:10:11.722444+02:00 localhost NetworkManager: <WARN>  default_adapter_cb(): bluez error getting default adapter: The name org.bluez was not provided by any .service files
2010-05-17T08:10:11.722764+02:00 localhost NetworkManager: <info>  Trying to start the supplicant...
2010-05-17T08:10:11.723007+02:00 localhost NetworkManager: <info>  (hso0): device state change: 2 -> 3 (reason 0)
2010-05-17T08:10:11.728383+02:00 localhost NetworkManager: <info>  (wlan0): supplicant manager state:  down -> idle
2010-05-17T08:10:11.728397+02:00 localhost NetworkManager: <info>  (wlan0): device state change: 2 -> 3 (reason 0)
2010-05-17T08:10:11.741067+02:00 localhost NetworkManager: <WARN>  nm_call_store_remove(): Trying to remove a non-existant call id.
2010-05-17T08:10:11.741086+02:00 localhost NetworkManager: <WARN>  nm_call_store_remove(): Trying to remove a non-existant call id.

last line repeats about 25000 (!) times
Comment 1 Matthias Fulz 2010-05-17 08:24:49 UTC
excactly same problem here ~amd64.

With wpa_supplicant-0.7.1 all is working fine.
Comment 2 reno reckling 2010-05-17 12:59:50 UTC
I can confirm this bug.
I can observe the exact same behavior on ~amd64 with wpa_supplicant 0.7.2.
Downgrading to 0.6.10 solved the issue.
Comment 3 reno reckling 2010-05-17 13:10:56 UTC
Adding the following block to /etc/dbus-1/system.d/wpa_supplicant.conf solves the issue with wpa_supplicant version 0.7.2:
---------------------------
<policy group="users">
<allow own="fi.epitest.hostap.WPASupplicant"/>
<allow send_destination="fi.epitest.hostap.WPASupplicant"/>
<allow send_interface="fi.epitest.hostap.WPASupplicant"/>
<allow own="fi.w1.wpa_supplicant1"/>
<allow send_destination="fi.w1.wpa_supplicant1"/>
<allow send_interface="fi.w1.wpa_supplicant1"/>
<allow receive_sender="fi.w1.wpa_supplicant1" receive_type="signal"/>
</policy>
---------------------------
I think the problem exists because
1. wpa_supplicant only allows access via the root user and denies everything else and
2. NetworkManager tries to reconnect to the wpa_supplicant service over and over again on every denied permission.

So NetworkManager should probably only try to use wpa_supplicant once and the policies of wpa_supplicant should be altered.

I one thing i don't understand is, why is Networkmanager not permitted to access wpa_supplicant although it's running as root? Is it possible that at some point in the chain NetworkManager is spawning a normal user process?
Comment 4 Matthias Fulz 2010-05-17 14:10:48 UTC
(In reply to comment #3)
> Adding the following block to /etc/dbus-1/system.d/wpa_supplicant.conf solves
> the issue with wpa_supplicant version 0.7.2:
> ---------------------------
> <policy group="users">
> <allow own="fi.epitest.hostap.WPASupplicant"/>
> <allow send_destination="fi.epitest.hostap.WPASupplicant"/>
> <allow send_interface="fi.epitest.hostap.WPASupplicant"/>
> <allow own="fi.w1.wpa_supplicant1"/>
> <allow send_destination="fi.w1.wpa_supplicant1"/>
> <allow send_interface="fi.w1.wpa_supplicant1"/>
> <allow receive_sender="fi.w1.wpa_supplicant1" receive_type="signal"/>
> </policy>
> ---------------------------

This is NOT working for me.

> I think the problem exists because
> 1. wpa_supplicant only allows access via the root user and denies everything
> else and
> 2. NetworkManager tries to reconnect to the wpa_supplicant service over and
> over again on every denied permission.
> 
> So NetworkManager should probably only try to use wpa_supplicant once and the
> policies of wpa_supplicant should be altered.
> 
> I one thing i don't understand is, why is Networkmanager not permitted to
> access wpa_supplicant although it's running as root? Is it possible that at
> some point in the chain NetworkManager is spawning a normal user process?
> 
Perhaps the problem is related to something else and it is just a lucky hit that
this is working for you?
Comment 5 reno reckling 2010-05-17 20:04:46 UTC
(In reply to comment #4)
> (In reply to comment #3)
> Perhaps the problem is related to something else and it is just a lucky hit
> that
> this is working for you?
> 

You are right, it's not working. I was only reloading dbus, not restarting ist, which caused the previously compiled wpa_supplicant 0.6.10 to be still running.
After dbus restart the error appeared again. Sorry
Comment 6 reno reckling 2010-05-17 21:28:44 UTC
I looked into the problem in greater depth now and found the error in wpa_supplicant.
after creating the new interface data in wpa_supplicant/dbus/dbus_old_handlers.c line 174:
if ((wpa_s = wpa_supplicant_add_iface(global, &iface))) {
    const char *path = wpa_s->dbus_path;

wpa_s->dbus_path is used, but never initialized, because wpa_supplicant_add_iface uses wpa_supplicant_alloc in wpa_supplicant/wpa_supplicant.c line 2125

wpa_s = wpa_supplicant_alloc();

but wpa_supplicant_alloc doesn't set the dbus_path variable.

the inherent gdb backtrace looks like the following:

(gdb) run -u
Starting program: /tmp/wpa_supplicant-0.7.2/wpa_supplicant/wpa_supplicant -u
warning: no loadable sections found in added symbol-file /usr/lib64/debug/usr/lib64/libssl.so.0.9.8.debug
warning: no loadable sections found in added symbol-file /usr/lib64/debug/usr/lib64/libcrypto.so.0.9.8.debug
warning: no loadable sections found in added symbol-file /usr/lib64/debug/usr/lib64/libdbus-1.so.3.4.0.debug
[Thread debugging using libthread_db enabled]
warning: no loadable sections found in added symbol-file /usr/lib64/debug/lib64/libz.so.1.2.5.debug
process 13497: arguments to dbus_message_new_signal() were incorrect, assertion "path != NULL" failed in file dbus-message.c line 1162.
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

Program received signal SIGABRT, Aborted.
0x00007ffff6c6e1a5 in raise () from /lib/libc.so.6
(gdb) backtrace
#0  0x00007ffff6c6e1a5 in raise () from /lib/libc.so.6
#1  0x00007ffff6c6f5d0 in abort () from /lib/libc.so.6
#2  0x00007ffff73e5915 in _dbus_abort () from /usr/lib/libdbus-1.so.3
#3  0x00007ffff73e185a in _dbus_warn_check_failed () from /usr/lib/libdbus-1.so.3
#4  0x00007ffff73d637b in dbus_message_new_signal () from /usr/lib/libdbus-1.so.3
#5  0x00000000004406a4 in wpa_supplicant_dbus_notify_state_change (wpa_s=0x6819a0, new_state=WPA_INACTIVE, old_state=WPA_DISCONNECTED) at dbus/dbus_old.c:424
#6  0x000000000040ab0c in wpas_notify_state_changed (wpa_s=0x6819a0, new_state=WPA_INACTIVE, old_state=WPA_DISCONNECTED) at notify.c:79
#7  0x00000000004472e6 in wpa_supplicant_set_state (wpa_s=0x6819a0, state=WPA_INACTIVE) at wpa_supplicant.c:554
#8  0x0000000000449bfd in wpa_supplicant_driver_init (wpa_s=0x6819a0) at wpa_supplicant.c:1843
#9  0x000000000044a3b5 in wpa_supplicant_init_iface (wpa_s=0x6819a0, iface=0x7fffffffda50) at wpa_supplicant.c:2033
#10 0x000000000044a6c3 in wpa_supplicant_add_iface (global=0x67e4d0, iface=0x7fffffffdb00) at wpa_supplicant.c:2144
#11 0x0000000000440fcf in wpas_dbus_global_add_interface (message=0x67f4a0, global=0x67e4d0) at dbus/dbus_old_handlers.c:174
#12 0x00000000004404c6 in wpas_message_handler (connection=0x67f190, message=0x67f4a0, user_data=0x67e580) at dbus/dbus_old.c:341
#13 0x00007ffff73d7ece in _dbus_object_tree_dispatch_and_unlock () from /usr/lib/libdbus-1.so.3
#14 0x00007ffff73cbbac in dbus_connection_dispatch () from /usr/lib/libdbus-1.so.3
#15 0x0000000000444552 in dispatch_data (con=0x67f190) at dbus/dbus_common.c:43
#16 0x000000000044461a in process_watch (priv=0x67e580, watch=0x67ec50, type=EVENT_TYPE_READ) at dbus/dbus_common.c:79
#17 0x000000000044468e in process_watch_read (sock=5, eloop_ctx=0x67e580, sock_ctx=0x67ec50) at dbus/dbus_common.c:95
#18 0x000000000040efba in eloop_sock_table_dispatch (table=0x67dae8, fds=0x6816a0) at ../src/utils/eloop.c:216
#19 0x000000000040fa0d in eloop_run () at ../src/utils/eloop.c:548
#20 0x000000000044ad3e in wpa_supplicant_run (global=0x67e4d0) at wpa_supplicant.c:2353
#21 0x0000000000451a52 in main (argc=2, argv=0x7fffffffe088) at main.c:274
Comment 7 Benjamin Lee 2010-05-18 07:33:16 UTC
I have this issue also after upgrading from 0.7.1 to 0.7.2.
Comment 8 Tony Vroon (RETIRED) gentoo-dev 2010-05-18 08:54:55 UTC
+  18 May 2010; <chainsaw@gentoo.org> +wpa_supplicant-0.7.1.ebuild,
+  +files/wpa_supplicant-0.7.1-dbus_path_fix.patch:
+  Reinstating wpa_supplicant 0.7.1 for bug #320097; it is completely broken
+  when used with NetworkManager.
Comment 9 Tony Vroon (RETIRED) gentoo-dev 2010-05-18 08:58:45 UTC
With 0.7.1 reinstated, I can now mask 0.7.2 to unbreak your systems. Apologies for the inconvenience everyone.

+  18 May 2010; <chainsaw@gentoo.org> package.mask:
+  Masking wpa_supplicant 0.7.2 for bug #320097, it is completely broken with
+  NetworkManager.

Bjarke, I think a 0.7.2-r1 would be safest. Please test the D-Bus support / NetworkManager support if you can.
Comment 10 Bjarke Istrup Pedersen (RETIRED) gentoo-dev 2010-05-18 09:10:31 UTC
Hmm, I'm not using BetworkManager myself, since I'm only using the console for development, and not an X desktop ;-)

Could you try the patch here and see if it fixes the problem:
http://w1.fi/bugz/show_bug.cgi?id=356
Comment 11 Tony Vroon (RETIRED) gentoo-dev 2010-05-18 09:41:21 UTC
(In reply to comment #10)
> Could you try the patch here and see if it fixes the problem:
> http://w1.fi/bugz/show_bug.cgi?id=356

If it is an upstream bug, perhaps they can release a 0.7.3 or 0.7.2.1 that actually works and save you the trouble?

Comment 12 Bjarke Istrup Pedersen (RETIRED) gentoo-dev 2010-05-18 10:00:05 UTC
Well, lets start by figuring out if it is the same bug we are hitting here.

Once we know that, I'll take it upstream and see what happens.
Comment 13 Matthias Fulz 2010-05-18 12:00:01 UTC
Created attachment 231957 [details, diff]
upstream patch

upstream path, which fixes NM crash
Comment 14 Matthias Fulz 2010-05-18 12:00:46 UTC
Created attachment 231959 [details]
ebuild which includes patch

r1-ebuild, which includes upstream path - tested
Comment 15 Matthias Fulz 2010-05-18 12:01:54 UTC
(In reply to comment #10)
> Hmm, I'm not using BetworkManager myself, since I'm only using the console for
> development, and not an X desktop ;-)
> 
> Could you try the patch here and see if it fixes the problem:
> http://w1.fi/bugz/show_bug.cgi?id=356
> 

I tried the patch and all is working fine again - THX

Also I created an r1-ebuild which includes the patch - hope this is ok for all ;)
Comment 16 Bjarke Istrup Pedersen (RETIRED) gentoo-dev 2010-05-18 16:58:40 UTC
Great :-)

I'm currently not able to get to my developer box, but any Gentoo Developer with write access to the tree is welcome to bump it to -r1, remove -r0 and unmask it. (And close this bug).

If not, I'll see if I get around to do it friday.
Comment 17 Richard 2010-05-18 19:31:49 UTC
I was having issues with KNetworkManager under KDE with wpa_supplicant-0.7.2. The proposed wpa_supplicant-0.7.2-r1 ebuild fixed them for me.
Comment 18 Patrick McLean gentoo-dev 2010-05-19 18:33:42 UTC
I added net-wireless/wpa_supplicant-0.7.2-r1 to the tree with the attached patch and removed the entry for net-wireless/wpa_supplicant-0.7.2 from package.mask.