Bug 311901 - iwl3945: wlan0: RX WEP frame, but no key set (repeats, and repeats!)
iwl3945: wlan0: RX WEP frame, but no key set (repeats, and repeats!)
Status: CLOSED CURRENTRELEASE
Product: Fedora
Classification: Fedora
Component: kernel (Show other bugs)
rawhide
All Linux
low Severity low
: ---
: ---
Assigned To: John W. Linville
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2007-09-28 17:59 EDT by Tom London
Modified: 2007-11-30 17:12 EST (History)
2 users (show)

See Also:
Fixed In Version: 2.6.23.1-49.fc8
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2007-11-20 17:50:33 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
/var/log/messages of iwlwifi "...., but have no key" (12.35 KB, text/plain)
2007-10-22 10:51 EDT, Tom London
no flags Details
0001-mac80211-no-missing-key-complaint-if-frame-may-no.patch (1.80 KB, patch)
2007-10-23 17:48 EDT, John W. Linville
no flags Details | Diff
0002-mac80211-no-decrypt-failed-complaint-if-frame-may.patch (3.91 KB, patch)
2007-10-23 17:49 EDT, John W. Linville
no flags Details | Diff
linux-2.6-mac80211-decryption-noise.patch (3.17 KB, patch)
2007-10-23 20:31 EDT, John W. Linville
no flags Details | Diff

  None (edit)
Description Tom London 2007-09-28 17:59:54 EDT
Description of problem:
enabling and then disabling a wireless connection via 'nm-applet' causes the
following spew:

Sep 28 14:57:19 localhost kernel: wlan0: RX WEP frame, but no key set
Sep 28 14:57:24 localhost kernel: printk: 26 messages suppressed.
Sep 28 14:57:24 localhost kernel: wlan0: RX WEP frame, but no key set
Sep 28 14:57:29 localhost kernel: printk: 34 messages suppressed.
Sep 28 14:57:29 localhost kernel: wlan0: RX WEP frame, but no key set
Sep 28 14:57:34 localhost kernel: printk: 31 messages suppressed.
Sep 28 14:57:34 localhost kernel: wlan0: RX WEP frame, but no key set
Sep 28 14:57:39 localhost kernel: printk: 50 messages suppressed.
Sep 28 14:57:39 localhost kernel: wlan0: RX WEP frame, but no key set
Sep 28 14:57:44 localhost kernel: printk: 36 messages suppressed.
Sep 28 14:57:44 localhost kernel: wlan0: RX WEP frame, but no key set
Sep 28 14:57:49 localhost kernel: printk: 36 messages suppressed.
Sep 28 14:57:49 localhost kernel: wlan0: RX WEP frame, but no key set
Sep 28 14:57:54 localhost kernel: printk: 26 messages suppressed.
Sep 28 14:57:54 localhost kernel: wlan0: RX WEP frame, but no key set
Sep 28 14:57:59 localhost kernel: printk: 50 messages suppressed.
Sep 28 14:57:59 localhost kernel: wlan0: RX WEP frame, but no key set
Sep 28 14:58:04 localhost kernel: printk: 29 messages suppressed.
Sep 28 14:58:04 localhost kernel: wlan0: RX WEP frame, but no key set



Version-Release number of selected component (if applicable):
kernel-2.6.23-0.213.rc8.git2.fc8

How reproducible:
yes

Steps to Reproduce:
1.
2.
3.
  
Actual results:


Expected results:


Additional info:
Comment 1 John W. Linville 2007-10-01 10:48:32 EDT
Which hardware are you using?  Does the spew stop, or continue forever?  Was 
the wireless working reasonably well before you disabled the connection?  Does 
it work again if you re-enable the connection?  Does the spew stop if you 
re-enable the connection?
Comment 2 Tom London 2007-10-01 11:12:44 EDT
Uhhh.....

With .214, I'm seeing something slightly different:

When I disable the wireless by selecting the wired interface,  I get a flush of
these for about 15 seconds, and then a much reduced spew:

Oct  1 08:06:25 localhost kernel: wlan0: RX WEP frame, but no key set
Oct  1 08:06:26 localhost kernel:last message repeated 7 times
Oct  1 08:06:26 localhost NetworkManager: <info>  Activation (eth1) successful,
device activated.
Oct  1 08:06:26 localhost NetworkManager: <info>  Activation (eth1) successful,
device activated.
Oct  1 08:06:26 localhost NetworkManager: <info>  Activation (eth1) Stage 5 of 5
(IP Configure Commit) complete.
Oct  1 08:06:27 localhost avahi-daemon[4247]: Registering new address record for
fe80::216:d3ff:fe26:856f on eth1.*.
Oct  1 08:06:30 localhost kernel: printk: 19 messages suppressed.
Oct  1 08:06:30 localhost kernel: wlan0: RX WEP frame, but no key set
Oct  1 08:06:30 localhost kernel: wlan0: RX WEP frame, but no key set
Oct  1 08:06:35 localhost kernel: printk: 4 messages suppressed.
Oct  1 08:06:35 localhost kernel: wlan0: RX WEP frame, but no key set
Oct  1 08:06:36 localhost kernel: eth1: no IPv6 routers present
Oct  1 08:06:40 localhost kernel: wlan0: RX WEP frame, but no key set
Oct  1 08:08:32 localhost kernel:last message repeated 3 times
Oct  1 08:10:40 localhost kernel: wlan0: RX WEP frame, but no key set

Spew slows down after the first 15 seconds.


I'm running Thinkpad X60, with iwl3945, with latest Rawhide.

Output of 'lspci':
[tbl@localhost ~]$ /sbin/lspci
00:00.0 Host bridge: Intel Corporation Mobile 945GM/PM/GMS, 943/940GML and 945GT
Express Memory Controller Hub (rev 03)
00:02.0 VGA compatible controller: Intel Corporation Mobile 945GM/GMS,
943/940GML Express Integrated Graphics Controller (rev 03)
00:02.1 Display controller: Intel Corporation Mobile 945GM/GMS, 943/940GML
Express Integrated Graphics Controller (rev 03)
00:1b.0 Audio device: Intel Corporation 82801G (ICH7 Family) High Definition
Audio Controller (rev 02)
00:1c.0 PCI bridge: Intel Corporation 82801G (ICH7 Family) PCI Express Port 1
(rev 02)
00:1c.1 PCI bridge: Intel Corporation 82801G (ICH7 Family) PCI Express Port 2
(rev 02)
00:1c.2 PCI bridge: Intel Corporation 82801G (ICH7 Family) PCI Express Port 3
(rev 02)
00:1c.3 PCI bridge: Intel Corporation 82801G (ICH7 Family) PCI Express Port 4
(rev 02)
00:1d.0 USB Controller: Intel Corporation 82801G (ICH7 Family) USB UHCI
Controller #1 (rev 02)
00:1d.1 USB Controller: Intel Corporation 82801G (ICH7 Family) USB UHCI
Controller #2 (rev 02)
00:1d.2 USB Controller: Intel Corporation 82801G (ICH7 Family) USB UHCI
Controller #3 (rev 02)
00:1d.3 USB Controller: Intel Corporation 82801G (ICH7 Family) USB UHCI
Controller #4 (rev 02)
00:1d.7 USB Controller: Intel Corporation 82801G (ICH7 Family) USB2 EHCI
Controller (rev 02)
00:1e.0 PCI bridge: Intel Corporation 82801 Mobile PCI Bridge (rev e2)
00:1f.0 ISA bridge: Intel Corporation 82801GBM (ICH7-M) LPC Interface Bridge
(rev 02)
00:1f.1 IDE interface: Intel Corporation 82801G (ICH7 Family) IDE Controller
(rev 02)
00:1f.2 SATA controller: Intel Corporation 82801GBM/GHM (ICH7 Family) SATA AHCI
Controller (rev 02)
00:1f.3 SMBus: Intel Corporation 82801G (ICH7 Family) SMBus Controller (rev 02)
02:00.0 Ethernet controller: Intel Corporation 82573L Gigabit Ethernet Controller
03:00.0 Network controller: Intel Corporation PRO/Wireless 3945ABG Network
Connection (rev 02)
15:00.0 CardBus bridge: Ricoh Co Ltd RL5c476 II (rev b4)
15:00.1 FireWire (IEEE 1394): Ricoh Co Ltd R5C552 IEEE 1394 Controller (rev 09)
15:00.2 Generic system peripheral [0805]: Ricoh Co Ltd R5C822
SD/SDIO/MMC/MS/MSPro Host Adapter (rev 18)

Comment 3 Tom London 2007-10-01 12:42:53 EDT
A more complete answer:

I repeated the test in my 'work environment' (multiple access points, multiple
networks).

Here the spew persists without the quenching I observed in my simpler 'home
environment'.

The messages continued for several minutes after I switched to wired interface.

However, when I reselected the wireless interface, the spew stopped.

Here are the last of the spew:

Oct  1 09:37:18 localhost NetworkManager: <info>  (wlan0) Supplicant interface
state change: 4 -> 5
Oct  1 09:37:22 localhost kernel: wlan0: RX WEP frame, but no key set
Oct  1 09:37:27 localhost kernel: printk: 39 messages suppressed.
Oct  1 09:37:27 localhost kernel: wlan0: RX WEP frame, but no key set
Oct  1 09:37:28 localhost kernel: wlan0: disassociate(reason=3)
Oct  1 09:37:28 localhost NetworkManager: <info>  (wlan0) Supplicant interface
state change: 5 -> 0
Oct  1 09:37:28 localhost NetworkManager: <info>  (wlan0) Supplicant interface
state change: 0 -> 2
Oct  1 09:37:28 localhost NetworkManager: <info>  (wlan0) Supplicant interface
state change: 2 -> 0
Oct  1 09:37:28 localhost kernel: wlan0: RX deauthentication from
00:14:69:3b:af:60 (reason=2)
Oct  1 09:37:28 localhost kernel: wlan0: deauthenticated
Oct  1 09:37:29 localhost kernel: wlan0: authenticate with AP 00:14:69:3b:af:60
Oct  1 09:37:29 localhost kernel: wlan0: RX authentication from
00:14:69:3b:af:60 (alg=0 transaction=2 status=0)
Oct  1 09:37:29 localhost kernel: wlan0: authenticated
Oct  1 09:37:29 localhost kernel: wlan0: associate with AP 00:14:69:3b:af:60
Oct  1 09:37:29 localhost kernel: wlan0: authentication frame received from
00:14:69:3b:af:60, but not in authenticate state - ignored
Comment 4 Tom London 2007-10-01 13:21:48 EDT
In case this has something to do with 'multiple APs', here is the output of
'iwlist wlan0 scan'.

Looks like my office is 'mid way' between 2 equal strength 'same network' WPA
access points, an within range of a single WEP access point.

wlan0     Scan completed :
          Cell 01 - Address: 00:14:6A:5B:3A:80
                    ESSID:"INSIDE"
                    Mode:Master
                    Channel:2
                    Frequency:2.417 GHz (Channel 2)
                    Quality=59/100  Signal level=-72 dBm  Noise level=-89 dBm
                    Encryption key:on
                    IE: WPA Version 1
                        Group Cipher : TKIP
                        Pairwise Ciphers (1) : TKIP
                        Authentication Suites (1) : PSK
                    Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 6 Mb/s; 9 Mb/s
                              11 Mb/s; 12 Mb/s; 18 Mb/s; 24 Mb/s; 36 Mb/s
                              48 Mb/s; 54 Mb/s
                    Extra:tsf=00000060dcc824df
          Cell 02 - Address: 00:14:69:3B:AF:60
                    ESSID:"INSIDE"
                    Mode:Master
                    Channel:3
                    Frequency:2.422 GHz (Channel 3)
                    Quality=59/100  Signal level=-72 dBm  Noise level=-89 dBm
                    Encryption key:on
                    IE: WPA Version 1
                        Group Cipher : TKIP
                        Pairwise Ciphers (1) : TKIP
                        Authentication Suites (1) : PSK
                    Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 6 Mb/s; 9 Mb/s
                              11 Mb/s; 12 Mb/s; 18 Mb/s; 24 Mb/s; 36 Mb/s
                              48 Mb/s; 54 Mb/s
                    Extra:tsf=0000006f76ba80c1
          Cell 03 - Address: 00:12:17:BB:4B:4A
                    ESSID:"OUTSIDE"
                    Mode:Master
                    Channel:10
                    Frequency:2.457 GHz (Channel 10)
                    Quality=63/100  Signal level=-69 dBm  Noise level=-89 dBm
                    Encryption key:on
                    Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 11 Mb/s; 18 Mb/s
                              24 Mb/s; 36 Mb/s; 54 Mb/s; 6 Mb/s; 9 Mb/s
                              12 Mb/s; 48 Mb/s
                    Extra:tsf=00000037d
Comment 5 Tom London 2007-10-08 10:41:54 EDT
This seems to be a bit intermittant, but I am getting this again with .222.

In this case, I am connected via wired, and have not associated at all.

Again, believe this is a 'stock' Thinkpad X60 (3945) with 'stock' rawhide.

Does no always seem to happen.

Oct  8 07:14:55 localhost kernel: wlan0: RX WEP frame, but no key set
Oct  8 07:15:00 localhost kernel: printk: 12 messages suppressed.
Oct  8 07:15:00 localhost kernel: wlan0: RX WEP frame, but no key set
Oct  8 07:15:05 localhost kernel: printk: 8 messages suppressed.
Oct  8 07:15:05 localhost kernel: wlan0: RX WEP frame, but no key set
Oct  8 07:15:10 localhost kernel: printk: 11 messages suppressed.
Oct  8 07:15:10 localhost kernel: wlan0: RX WEP frame, but no key set
Oct  8 07:15:15 localhost kernel: printk: 9 messages suppressed.
Oct  8 07:15:15 localhost kernel: wlan0: RX WEP frame, but no key set
Oct  8 07:15:21 localhost kernel: wlan0: RX deauthentication from
00:0d:97:04:0c:be (reason=7)
Oct  8 07:15:21 localhost kernel: wlan0: privacy configuration mismatch and
mixed-cell disabled - disassociate
Oct  8 07:15:22 localhost kernel: printk: 8 messages suppressed.
Oct  8 07:15:22 localhost kernel: wlan0: RX WEP frame, but no key set
Oct  8 07:15:25 localhost kernel: printk: 7 messages suppressed.
Oct  8 07:15:25 localhost kernel: wlan0: RX WEP frame, but no key set

When this is happening, I am about 1 meter from access point:
[root@localhost ~]# iwlist wlan0 scan
wlan0     Scan completed :
          Cell 01 - Address: 00:12:17:46:42:51
                    ESSID:"free4all"
                    Mode:Master
                    Channel:10
                    Frequency:2.457 GHz (Channel 10)
                    Quality=96/100  Signal level=-30 dBm  Noise level=-93 dBm
                    Encryption key:on
                    IE: WPA Version 1
                        Group Cipher : TKIP
                        Pairwise Ciphers (2) : CCMP TKIP
                        Authentication Suites (1) : PSK
                    IE: IEEE 802.11i/WPA2 Version 1
                        Group Cipher : TKIP
                        Pairwise Ciphers (2) : CCMP TKIP
                        Authentication Suites (1) : PSK
                    Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 11 Mb/s; 18 Mb/s
                              24 Mb/s; 36 Mb/s; 54 Mb/s; 6 Mb/s; 9 Mb/s
                              12 Mb/s; 48 Mb/s
                    Extra:tsf=0000083f1574a2b0

[root@localhost ~]# 

But there are others in the area, in particular, GoogleWiFi (and
GoogleSecureWiFi?) although these don't always show up on 'iwlist' or in nm-applet.
Comment 6 Tom London 2007-10-09 10:56:46 EDT
Some more data:

On start up, I see the following 'wlan0 associate' messages right after
completing DHCP dance with my wired interface:

Oct  9 07:09:00 localhost NetworkManager: <info>  Activation (eth1) Stage 5 of 5
(IP Configure Commit) started...
Oct  9 07:09:00 localhost avahi-daemon[2859]: Joining mDNS multicast group on
interface eth1.IPv4 with address 192.168.1.101.
Oct  9 07:09:00 localhost avahi-daemon[2859]: New relevant interface eth1.IPv4
for mDNS.
Oct  9 07:09:00 localhost avahi-daemon[2859]: Registering new address record for
192.168.1.101 on eth1.IPv4.
Oct  9 07:09:01 localhost kernel: wlan0: Initial auth_alg=0
Oct  9 07:09:01 localhost kernel: wlan0: authenticate with AP 00:0d:97:04:0c:be
Oct  9 07:09:01 localhost kernel: vmnet8: no IPv6 routers present
Oct  9 07:09:01 localhost NetworkManager: <info>  Activation (eth1) successful,
device activated.
Oct  9 07:09:01 localhost NetworkManager: <info>  Activation (eth1) Stage 5 of 5
(IP Configure Commit) complete.
Oct  9 07:09:01 localhost kernel: wlan0: authenticate with AP 00:0d:97:04:0c:be
Oct  9 07:09:01 localhost kernel: wlan0: RX authentication from
00:0d:97:04:0c:be (alg=0 transaction=2 status=0)
Oct  9 07:09:01 localhost kernel: wlan0: authenticated
Oct  9 07:09:01 localhost kernel: wlan0: associate with AP 00:0d:97:04:0c:be
Oct  9 07:09:01 localhost kernel: wlan0: authentication frame received from
00:0d:97:04:0c:be, but not in authenticate state - ignored
Oct  9 07:09:01 localhost kernel: wlan0: authentication frame received from
00:0d:97:04:0c:be, but not in authenticate state - ignored
Oct  9 07:09:01 localhost kernel: wlan0: RX AssocResp from 00:0d:97:04:0c:be
(capab=0x1 status=0 aid=438)
Oct  9 07:09:01 localhost kernel: wlan0: associated
Oct  9 07:09:01 localhost kernel: wlan0: CTS protection enabled
(BSSID=00:0d:97:04:0c:be)
Oct  9 07:09:01 localhost kernel: wlan0: switched to short barker preamble
(BSSID=00:0d:97:04:0c:be)
Oct  9 07:09:01 localhost kernel: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Oct  9 07:09:01 localhost gdm-binary[3008]: (null): cannot open shared object
file: No such file or directory
Oct  9 07:09:02 localhost kernel: wlan0: RX WEP frame, but no key set

Since there have been no prompts for keys, keyring, etc., I'm assuming this is
associating with an 'open' network.

Here is the culprit:

          Cell 01 - Address: 00:0D:97:04:0C:BE
                    ESSID:"GoogleWiFi"
                    Mode:Master
                    Channel:1
                    Frequency:2.412 GHz (Channel 1)
                    Quality=61/100  Signal level=-71 dBm  Noise level=-60 dBm
                    Encryption key:off
                    Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 6 Mb/s; 9 Mb/s
                              11 Mb/s; 12 Mb/s; 18 Mb/s; 24 Mb/s; 36 Mb/s
                              48 Mb/s; 54 Mb/s
                    Extra:tsf=00000166af3b8d6a

Once I associate with my 'strong' local AP, the messages seem to stop.

So the (possible) scenario seems to be:
    a. wireless environment with a strong WPA AP and a weaker unencrypted AP
(GoogleWiFi)
    b. wired connection is active
    c. system starts and activates wired connection
    d. just afterwards, NM sees open wireless network (GoogleWiFi) and associates
    e. almost immediately, start getting 'RX WEP frame, but no key set' messages

[BTW, should NM 'associate' in d) above if wired is active?]

At some time, GoogleWiFi disappears from the nm-applet list of available
networks (iwlist scan too).

Not sure this is helpful.....
Comment 7 Tom London 2007-10-11 09:54:51 EDT
One additional piece of info:

The Google AP also supports a "hidden essid" WPA network 'GoogleWiFiSecure'
using the same MAC address:

          Cell 02 - Address: 00:0D:97:04:0C:BE
                    ESSID:"GoogleWiFiSecure"
                    Mode:Master
                    Channel:1
                    Frequency:2.412 GHz (Channel 1)
                    Quality=58/100  Signal level=-73 dBm  Noise level=-127 dBm
                    Encryption key:on
                    IE: WPA Version 1
                        Group Cipher : TKIP
                        Pairwise Ciphers (2) : TKIP CCMP
                        Authentication Suites (1) : 802.1x
                    IE: IEEE 802.11i/WPA2 Version 1
                        Group Cipher : TKIP
                        Pairwise Ciphers (2) : TKIP CCMP
                        Authentication Suites (1) : 802.1x
                    Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 6 Mb/s; 9 Mb/s
                              11 Mb/s; 12 Mb/s; 18 Mb/s; 24 Mb/s; 36 Mb/s
                              48 Mb/s; 54 Mb/s
                    Extra:tsf=0000018e1b9e1be3
Comment 8 John W. Linville 2007-10-22 10:01:11 EDT
Would you mind testing these F8-based kernels?

   http://koji.fedoraproject.org/koji/taskinfo?taskID=203296

Do they improve the situation for you?
Comment 9 Tom London 2007-10-22 10:51:11 EDT
Created attachment 234141 [details]
/var/log/messages of iwlwifi "...., but have no key" 

Well, the message appears to have changed.....

It is now: "wlan0: RX protected frame, but have no key".

No. This has not improved.  Here is a snippet:

Oct 22 07:42:46 localhost kernel: wlan0: RX protected frame, but have no key
Oct 22 07:42:46 localhost kernel: [drm] Initialized drm 1.1.0 20060810
Oct 22 07:42:46 localhost kernel: [drm] Initialized i915 1.6.0 20060119 on
minor 0
Oct 22 07:42:46 localhost kernel: wlan0: RX protected frame, but have no key
Oct 22 07:42:49 localhost kernel: vmnet1: no IPv6 routers present
Oct 22 07:42:50 localhost kernel: vmnet8: no IPv6 routers present
Oct 22 07:42:51 localhost kernel: printk: 8 messages suppressed.
Oct 22 07:42:51 localhost kernel: wlan0: RX protected frame, but have no key
Oct 22 07:42:54 localhost kernel: wlan0: no IPv6 routers present
Oct 22 07:42:56 localhost kernel: printk: 11 messages suppressed.
Oct 22 07:42:56 localhost kernel: wlan0: RX protected frame, but have no key


Bigger slice of /var/log/messages attached.
Comment 10 Tom London 2007-10-22 11:00:22 EDT
I'm probably over-reading this, but I've only noticed this happening when the
GoogleWifi (or GoogleWiFiSecure) associate dance 'hits' roughly in this spot:

Oct 22 07:42:41 localhost NetworkManager: <info>  Deactivating device eth1.
Oct 22 07:42:41 localhost avahi-daemon[3529]: Withdrawing address record for
192.168.1.101 on eth1.
Oct 22 07:42:41 localhost avahi-daemon[3529]: Leaving mDNS multicast group on
interface eth1.IPv4 with address 192.168.1.101.
Oct 22 07:42:41 localhost avahi-daemon[3529]: Interface eth1.IPv4 no longer
relevant for mDNS.
Oct 22 07:42:41 localhost NetworkManager: <info>  wlan0: Device is
fully-supported using driver 'iwl3945'.
Oct 22 07:42:41 localhost NetworkManager: <info>  Now managing wireless (802.11)
device 'wlan0'.
Oct 22 07:42:41 localhost NetworkManager: <info>  Bringing up device wlan0
Oct 22 07:42:41 localhost kernel: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Oct 22 07:42:41 localhost NetworkManager: <info>  Deactivating device wlan0.
Oct 22 07:42:43 localhost kernel: wlan0: Initial auth_alg=0
Oct 22 07:42:43 localhost kernel: wlan0: authenticate with AP 00:0d:97:04:0c:be
Oct 22 07:42:43 localhost kernel: wlan0: authenticate with AP 00:0d:97:04:0c:be
Oct 22 07:42:43 localhost kernel: wlan0: RX authentication from
00:0d:97:04:0c:be (alg=0 transaction=2 status=0)
Oct 22 07:42:43 localhost kernel: wlan0: authenticated
Oct 22 07:42:43 localhost kernel: wlan0: associate with AP 00:0d:97:04:0c:be
Oct 22 07:42:43 localhost kernel: wlan0: RX AssocResp from 00:0d:97:04:0c:be
(capab=0x1 status=0 aid=278)
Oct 22 07:42:43 localhost kernel: wlan0: associated
Oct 22 07:42:43 localhost kernel: wlan0: CTS protection enabled
(BSSID=00:0d:97:04:0c:be)
Oct 22 07:42:43 localhost kernel: wlan0: switched to short barker preamble
(BSSID=00:0d:97:04:0c:be)
Oct 22 07:42:43 localhost kernel: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Comment 11 Tom London 2007-10-22 13:32:51 EDT
Why is the system trying to associate with a wireless AP when the wired device
is available (and was active just a few seconds before)?

Here is my 'scenario':

I have a laptop with a wired (e1000) NIC and iwl3945 wireless NIC.

The wired NIC (eth1) is setup for 'ONBOOT=yes', the wireless (wlan0) is setup
for 'ONBOOT=no'.

So during initscripts, eth1 comes up, gets a DHCP address, and is used (e.g.,
for ntpd, etc.).  Appears that wlan0 does not come up.

Just after smartd comes up, when NetworkManager starts, it appears to deactivate
 eth1, and then appears to activate both eth1 and wlan0.

Is it possible that some kind of (unencrypted AP) beacon arrives on wlan0 before
eth1 is completely activated causing NM to try to associate with it?

[To confuse matters, I believe Google supports 2 networks on the same AP: one
open, the other WPA protected.]

If the wired interface 'comes up' fast enough, I don't seem to get this problem.

The likelihood of this happening dramatically increases if there are
non-encrypted networks (therefore not requiring keyring, passphrase....)?
Comment 12 Tom London 2007-10-23 10:07:25 EDT
I can appear to get these messages to start and stop at will by the selection of
particular wireless networks.

Here is the setup:

Thinkpad X60, e1000 wired, ipw3945 wireless.

Two AP visible from iwlist scan (sometimes), three wireless networks visible:
1. free4all (my WPA network from my Linksys router/AP.... about 1 meter from my
laptop)
2. GoogleWiFi (about 300 feet from my laptop). This is unencrypted.
3. GoogleWiFiSecure from same AP as GoogleWiFi. Believe this is WPA.

Booting system with active wired connection, I get the 'wlan0: RX protected
frame, but have no key' messages about 80% of the time.

When I am getting these, using NM applet to select 'free4all' (WPA network)
causes these kernel messages to stop after the association is made.

If I then use NM applet to select 'GoogleWiFi', these messages start again after
association is made.  Selecting 'free4all' stops, selecting 'GoogleWifi'
restarts, etc.

Could there be some issue due to the fact that there are multiple networks
(unenrypted/WPA) from the same AP/MAC?

Comment 13 John W. Linville 2007-10-23 10:13:10 EDT
"Could there be some issue due to the fact that there are multiple networks
(unenrypted/WPA) from the same AP/MAC?"

Yes, I'm sure that is the root of the problem.  The mac80211 component has 
failed to distinguish multiple networks on the same BSSID in the past.  What 
kernel are you using?
Comment 14 Tom London 2007-10-23 10:27:20 EDT
Currently running kernel-2.6.23.1-30.fc8.
Comment 15 John W. Linville 2007-10-23 17:48:35 EDT
Created attachment 235621 [details]
0001-mac80211-no-missing-key-complaint-if-frame-may-no.patch
Comment 16 John W. Linville 2007-10-23 17:49:14 EDT
Created attachment 235631 [details]
0002-mac80211-no-decrypt-failed-complaint-if-frame-may.patch
Comment 17 Tom London 2007-10-23 18:54:34 EDT
Uhh... I can't seem to apply these patches against 2.6.23.1-30.

Better yet, this is being built in koji?! :-)
Comment 18 John W. Linville 2007-10-23 20:31:03 EDT
Created attachment 235711 [details]
linux-2.6-mac80211-decryption-noise.patch

Same idea, applies to current F-8
Comment 19 John W. Linville 2007-10-23 20:42:55 EDT
Original patches are for upstream -- sorry, upstream comes first. :-)

Building now:

   http://koji.fedoraproject.org/koji/buildinfo?buildID=22094

Does that help?
Comment 20 Tom London 2007-10-24 10:22:19 EDT
Thanks.

Installed koji packages (-33).

This appears to squelch the spew.

I'm 'looking into' 2 'new' things:

1. I'm now getting this when connected to wired interface, before I ever
associated with wireless.

Oct 24 07:06:54 localhost kernel: wlan0: RX deauthentication from
00:0d:97:04:0c:be (reason=4)
Oct 24 07:06:54 localhost kernel: wlan0: deauthenticated
Oct 24 07:06:55 localhost kernel: wlan0: authenticate with AP 00:0d:97:04:0c:be
Oct 24 07:06:55 localhost kernel: wlan0: RX authentication from
00:0d:97:04:0c:be (alg=0 transaction=2 status=0)
Oct 24 07:06:55 localhost kernel: wlan0: authenticated
Oct 24 07:06:55 localhost kernel: wlan0: associate with AP 00:0d:97:04:0c:be
Oct 24 07:06:55 localhost kernel: wlan0: RX ReassocResp from 00:0d:97:04:0c:be
(capab=0x1 status=0 aid=278)
Oct 24 07:06:55 localhost kernel: wlan0: associated
Oct 24 07:06:55 localhost kernel: wlan0: CTS protection enabled
(BSSID=00:0d:97:04:0c:be)
Oct 24 07:06:55 localhost kernel: wlan0: switched to short barker preamble
(BSSID=00:0d:97:04:0c:be)
Oct 24 07:06:55 localhost kernel: wlan0: disassociate(reason=3)
Oct 24 07:07:44 localhost kernel: wlan0: RX deauthentication from
00:0d:97:04:0c:be (reason=4)
Oct 24 07:07:44 localhost kernel: wlan0: deauthenticated
Oct 24 07:07:45 localhost kernel: wlan0: authenticate with AP 00:0d:97:04:0c:be
Oct 24 07:07:45 localhost kernel: wlan0: RX authentication from
00:0d:97:04:0c:be (alg=0 transaction=2 status=0)
Oct 24 07:07:45 localhost kernel: wlan0: authenticated
Oct 24 07:07:45 localhost kernel: wlan0: associate with AP 00:0d:97:04:0c:be
Oct 24 07:07:45 localhost kernel: wlan0: RX ReassocResp from 00:0d:97:04:0c:be
(capab=0x1 status=0 aid=278)
Oct 24 07:07:45 localhost kernel: wlan0: associated
Oct 24 07:07:45 localhost kernel: wlan0: CTS protection enabled
(BSSID=00:0d:97:04:0c:be)
Oct 24 07:07:45 localhost kernel: wlan0: switched to short barker preamble
(BSSID=00:0d:97:04:0c:be)
Oct 24 07:07:45 localhost kernel: wlan0: disassociate(reason=3)

Got this about every 3 minutes or so when I have never associated on wlan0.

2. Before updating to rawhide NetworkManager, appeared that I could only
associate with 'GoogleWiFi' once. Could associate with WPA network as often as I
wished.  I'll dig into this after completing updates, etc.  

Could these be related to patch?
Comment 21 Tom London 2007-10-24 13:00:54 EDT
I don't seem to get the 'kernel: wlan0: RX deauthentication from .....' @ work
(not in Mountain View, so no GoogleWiFi).

GoogleWiFi is open, but you must 'login' through the browser.  Could that be the
3 minute interval?
Comment 22 Tom London 2007-10-25 10:07:37 EDT
Running -33, I seem to have gotten a 2 second batch of the original 'no key set'
message again.  After 2 seconds, no more messages.... 

Not a real issue.... filing for completeness.

Here is the setup:
1. Boot, NM sets up connection to wired interface.
2. Use nm-applet to select 'GoogleWiFi' (open, no encryption)
3. After 5-10 minutes, use nm-applet to select 'free4all' (WPA)
4. After 3-5 minutes, use nm-applet to select 'wired'.

Log snippet below starts right after step 4 above.

Oct 25 06:56:23 localhost NetworkManager: <info>  User request for activation of
eth1.
Oct 25 06:56:23 localhost NetworkManager: <info>  Deactivating device wlan0.
Oct 25 06:56:23 localhost NetworkManager: <info>  wlan0: canceled DHCP
transaction, dhclient pid 7083
Oct 25 06:56:23 localhost kernel: wlan0: disassociate(reason=3)
Oct 25 06:56:23 localhost kernel: wlan0: disassociate(reason=3)
Oct 25 06:56:23 localhost avahi-daemon[3817]: Withdrawing address record for
192.168.1.103 on wlan0.
Oct 25 06:56:23 localhost avahi-daemon[3817]: Leaving mDNS multicast group on
interface wlan0.IPv4 with address 192.168.1.103.
Oct 25 06:56:23 localhost avahi-daemon[3817]: Interface wlan0.IPv4 no longer
relevant for mDNS.
Oct 25 06:56:23 localhost avahi-daemon[3817]: Withdrawing address record for
fe80::213:2ff:fe6f:fc3c on wlan0.
Oct 25 06:56:23 localhost NetworkManager: <info>  Activating device eth1
Oct 25 06:56:23 localhost NetworkManager: <info>  Activation (eth1) Stage 1 of 5
(Device Prepare) scheduled...
Oct 25 06:56:23 localhost NetworkManager: <info>  Activation (eth1) Stage 1 of 5
(Device Prepare) started...
Oct 25 06:56:23 localhost NetworkManager: <info>  Activation (eth1) Stage 2 of 5
(Device Configure) scheduled...
Oct 25 06:56:23 localhost NetworkManager: <info>  Activation (eth1) Stage 1 of 5
(Device Prepare) complete.
Oct 25 06:56:23 localhost NetworkManager: <info>  Activation (eth1) Stage 2 of 5
(Device Configure) starting...
Oct 25 06:56:23 localhost NetworkManager: <info>  Activation (eth1) Stage 2 of 5
(Device Configure) successful.
Oct 25 06:56:23 localhost NetworkManager: <info>  Activation (eth1) Stage 3 of 5
(IP Configure Start) scheduled.
Oct 25 06:56:23 localhost NetworkManager: <info>  Activation (eth1) Stage 2 of 5
(Device Configure) complete.
Oct 25 06:56:23 localhost NetworkManager: <info>  Activation (eth1) Stage 3 of 5
(IP Configure Start) started...
Oct 25 06:56:23 localhost NetworkManager: <info>  Activation (eth1) Beginning
DHCP transaction.
Oct 25 06:56:23 localhost NetworkManager: <info>  dhclient started with pid 7195
Oct 25 06:56:23 localhost NetworkManager: <info>  Activation (eth1) Stage 3 of 5
(IP Configure Start) complete.
Oct 25 06:56:23 localhost dhclient: Internet Systems Consortium DHCP Client
V3.0.6-Fedora
Oct 25 06:56:23 localhost dhclient: Copyright 2004-2007 Internet Systems Consortium.
Oct 25 06:56:23 localhost dhclient: All rights reserved.
Oct 25 06:56:23 localhost dhclient: For info, please visit
http://www.isc.org/sw/dhcp/
Oct 25 06:56:23 localhost dhclient: 
Oct 25 06:56:23 localhost dhclient: wmaster0: unknown hardware address type 801
Oct 25 06:56:23 localhost NetworkManager: <info>  DHCP: device eth1 state
changed normal exit -> preinit
Oct 25 06:56:23 localhost dhclient: wmaster0: unknown hardware address type 801
Oct 25 06:56:23 localhost dhclient: Listening on LPF/eth1/00:16:d3:26:85:6f
Oct 25 06:56:23 localhost dhclient: Sending on   LPF/eth1/00:16:d3:26:85:6f
Oct 25 06:56:23 localhost dhclient: Sending on   Socket/fallback
Oct 25 06:56:23 localhost dhclient: DHCPDISCOVER on eth1 to 255.255.255.255 port
67 interval 4
Oct 25 06:56:24 localhost dhclient: DHCPOFFER from 192.168.1.1
Oct 25 06:56:24 localhost dhclient: DHCPREQUEST on eth1 to 255.255.255.255 port 67
Oct 25 06:56:24 localhost dhclient: DHCPACK from 192.168.1.1
Oct 25 06:56:24 localhost dhclient: bound to 192.168.1.101 -- renewal in 38660
seconds.
Oct 25 06:56:24 localhost NetworkManager: <info>  DHCP: device eth1 state
changed preinit -> bound
Oct 25 06:56:24 localhost NetworkManager: <info>  Activation (eth1) Stage 4 of 5
(IP Configure Get) scheduled...
Oct 25 06:56:24 localhost NetworkManager: <info>  Activation (eth1) Stage 4 of 5
(IP Configure Get) started...
Oct 25 06:56:24 localhost NetworkManager: <info>    address 192.168.1.101
Oct 25 06:56:24 localhost NetworkManager: <info>    netmask 255.255.255.0
Oct 25 06:56:24 localhost NetworkManager: <info>    broadcast 192.168.1.255
Oct 25 06:56:24 localhost NetworkManager: <info>    gateway 192.168.1.1
Oct 25 06:56:24 localhost NetworkManager: <info>    nameserver '68.87.76.178'
Oct 25 06:56:24 localhost NetworkManager: <info>    nameserver '68.87.78.130'
Oct 25 06:56:24 localhost NetworkManager: <info>    domain name
'hsd1.ca.comcast.net.'
Oct 25 06:56:24 localhost NetworkManager: <info>  Activation (eth1) Stage 5 of 5
(IP Configure Commit) scheduled...
Oct 25 06:56:24 localhost NetworkManager: <info>  Activation (eth1) Stage 4 of 5
(IP Configure Get) complete.
Oct 25 06:56:24 localhost NetworkManager: <info>  Activation (eth1) Stage 5 of 5
(IP Configure Commit) started...
Oct 25 06:56:24 localhost avahi-daemon[3817]: Joining mDNS multicast group on
interface eth1.IPv4 with address 192.168.1.101.
Oct 25 06:56:24 localhost avahi-daemon[3817]: New relevant interface eth1.IPv4
for mDNS.
Oct 25 06:56:24 localhost avahi-daemon[3817]: Registering new address record for
192.168.1.101 on eth1.IPv4.
Oct 25 06:56:24 localhost ntpd[3681]: sendto(67.106.77.184) (fd=27): Invalid
argument
Oct 25 06:56:25 localhost NetworkManager: <info>  Activation (eth1) successful,
device activated.
Oct 25 06:56:25 localhost NetworkManager: <info>  Activation (eth1) Stage 5 of 5
(IP Configure Commit) complete.
Oct 25 06:56:25 localhost ntpd[3681]: sendto(72.18.206.198) (fd=27): Invalid
argument
Oct 25 06:56:26 localhost kernel: wlan0: RX WEP frame, but no key set
Oct 25 06:56:27 localhost kernel:last message repeated 3 times
Oct 25 06:56:27 localhost avahi-daemon[3817]: Registering new address record for
fe80::216:d3ff:fe26:856f on eth1.*.
Oct 25 06:56:27 localhost kernel: wlan0: RX WEP frame, but no key set
Oct 25 06:56:32 localhost kernel:last message repeated 5 times
Oct 25 06:56:32 localhost kernel: printk: 19 messages suppressed.
Oct 25 06:56:32 localhost kernel: wlan0: RX WEP frame, but no key set
Oct 25 06:56:36 localhost kernel: eth1: no IPv6 routers present
Oct 25 06:56:36 localhost kernel: printk: 6 messages suppressed.
Oct 25 06:56:36 localhost kernel: wlan0: RX WEP frame, but no key set
Oct 25 06:56:46 localhost kernel: printk: 6 messages suppressed.
Oct 25 06:56:46 localhost kernel: wlan0: RX WEP frame, but no key set
Oct 25 06:56:46 localhost kernel: printk: 3 messages suppressed.
Oct 25 06:56:46 localhost kernel: wlan0: RX WEP frame, but no key set
Comment 23 John W. Linville 2007-11-09 14:44:57 EST
Please try these kernels:

   http://koji.fedoraproject.org/koji/buildinfo?buildID=23734

Do they work better for you?
Comment 24 Tom London 2007-11-10 13:11:16 EST
Running in 'steady state' wired (that is, nm-applet running, connected to wired
interface), I get lots of these:

Nov 10 10:06:55 localhost kernel: wlan0: RX deauthentication from
00:0d:97:04:0c:be (reason=4)
Nov 10 10:06:55 localhost kernel: wlan0: deauthenticated
Nov 10 10:06:56 localhost kernel: wlan0: authenticate with AP 00:0d:97:04:0c:be
Nov 10 10:06:56 localhost kernel: wlan0: RX authentication from
00:0d:97:04:0c:be (alg=0 transaction=2 status=0)
Nov 10 10:06:56 localhost kernel: wlan0: authenticated
Nov 10 10:06:56 localhost kernel: wlan0: associate with AP 00:0d:97:04:0c:be
Nov 10 10:06:56 localhost kernel: wlan0: RX ReassocResp from 00:0d:97:04:0c:be
(capab=0x1 status=0 aid=275)
Nov 10 10:06:56 localhost kernel: wlan0: associated
Nov 10 10:06:56 localhost kernel: wlan0: CTS protection enabled
(BSSID=00:0d:97:04:0c:be)
Nov 10 10:06:56 localhost kernel: wlan0: switched to short barker preamble
(BSSID=00:0d:97:04:0c:be)
Nov 10 10:06:56 localhost kernel: wlan0: disassociate(reason=3)
Nov 10 10:07:46 localhost kernel: wlan0: RX deauthentication from
00:0d:97:04:0c:be (reason=7)
Nov 10 10:07:46 localhost kernel: wlan0: deauthenticated
Nov 10 10:07:47 localhost kernel: wlan0: authenticate with AP 00:0d:97:04:0c:be
Nov 10 10:07:47 localhost kernel: wlan0: RX authentication from
00:0d:97:04:0c:be (alg=0 transaction=2 status=0)
Nov 10 10:07:47 localhost kernel: wlan0: authenticated
Nov 10 10:07:47 localhost kernel: wlan0: associate with AP 00:0d:97:04:0c:be
Nov 10 10:07:47 localhost kernel: wlan0: RX ReassocResp from 00:0d:97:04:0c:be
(capab=0x1 status=0 aid=275)
Nov 10 10:07:47 localhost kernel: wlan0: associated
Nov 10 10:07:47 localhost kernel: wlan0: CTS protection enabled
(BSSID=00:0d:97:04:0c:be)
Nov 10 10:07:47 localhost kernel: wlan0: switched to short barker preamble
(BSSID=00:0d:97:04:0c:be)
Nov 10 10:07:47 localhost kernel: wlan0: disassociate(reason=3)


I'll run through some testing on the wireless side, and see if anything changes.
Comment 25 Tom London 2007-11-10 13:25:58 EST
Seems to work OK.

I ran it through some lightweight testing: connect to my home WLAN, connect to
GoogleWiFi, connect to wired, etc.

I did not see any 'RX WEP' messages.

Continue to see the following, even though I am not associated/active on wlan0:

ov 10 10:23:32 localhost kernel: wlan0: RX deauthentication from
00:0d:97:04:0c:be (reason=4)
Nov 10 10:23:32 localhost kernel: wlan0: deauthenticated
Nov 10 10:23:33 localhost kernel: wlan0: authenticate with AP 00:0d:97:04:0c:be
Nov 10 10:23:33 localhost kernel: wlan0: RX authentication from
00:0d:97:04:0c:be (alg=0 transaction=2 status=0)
Nov 10 10:23:33 localhost kernel: wlan0: authenticated
Nov 10 10:23:33 localhost kernel: wlan0: associate with AP 00:0d:97:04:0c:be
Nov 10 10:23:33 localhost kernel: wlan0: RX ReassocResp from 00:0d:97:04:0c:be
(capab=0x1 status=0 aid=275)
Nov 10 10:23:33 localhost kernel: wlan0: associated
Nov 10 10:23:33 localhost kernel: wlan0: CTS protection enabled
(BSSID=00:0d:97:04:0c:be)
Nov 10 10:23:33 localhost kernel: wlan0: switched to short barker preamble
(BSSID=00:0d:97:04:0c:be)
Nov 10 10:23:33 localhost kernel: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Nov 10 10:23:33 localhost kernel: wlan0: disassociate(reason=3)
Nov 10 10:23:34 localhost avahi-daemon[2501]: Registering new address record for
fe80::213:2ff:fe6f:fc3c on wlan0.*.
Nov 10 10:23:43 localhost kernel: wlan0: no IPv6 routers present

Except for spew, appears to not break anything.
Comment 26 Tom London 2007-11-18 19:36:47 EST
I no longer see the spew referred in the summary.

Close?

Note You need to log in before you can comment on or make changes to this bug.