Ticket #417 (closed defect: fixed)

Opened 6 years ago

Last modified 4 years ago

Power Save Mode handling and Packet Queuing

Reported by: ebree@nltinc.com Assigned to: mentor
Priority: major Milestone: version 0.9.1
Component: madwifi: 802.11 stack Version: trunk
Keywords: Cc:
Patch is attached: 1 Pending:

Description

I have a Spectralink i640 phone which connects fine to ap mode VAP with 128bit WEP...

auto ath015
iface ath015 inet static
address 0.0.0.0
netmask 255.255.255.255
network 0.0.0.0
broadcast 255.255.255.255
mtu 1504
pre-up /usr/bin/wlanconfig ath015 create wlandev wifi0 wlanmode ap
up /usr/sbin/brctl addif br15 ath015
up /sbin/iwpriv ath015 authmode 2
down /usr/sbin/brctl delif br15 ath015
post-down /usr/bin/wlanconfig ath015 destroy
wireless-essid VLAN_VoIP
wireless-key1 00000000000000000000000000
wireless-key2 00000000000000000000000000
wireless-key3 00000000000000000000000000
wireless-key4 00000000000000000000000000
wireless-defaultkey 1

ath015    IEEE 802.11g  ESSID:"VLAN_VoIP"
          Mode:Master  Frequency:2.412 GHz  Access Point: 0E:02:6F:3E:1C:94
          Bit Rate:0 kb/s   Tx-Power:19 dBm   Sensitivity=0/3
          Retry:off   RTS thr:off   Fragment thr:off
          Encryption key:A012-B5D9-6696-BB01-2963-F0FD-FF   Security mode:restricted
          Power Management:off
          Link Quality=0/94  Signal level=-95 dBm  Noise level=-95 dBm
          Rx invalid nwid:656  Rx invalid crypt:0  Rx invalid frag:0
          Tx excessive retries:0  Invalid misc:0   Missed beacon:0

I am able to make calls, utilize PTT (Push To Talk) as long as I do it before the Spectralink sends the ps-poll packet. As soon as the Spectralink phones sends the ps-poll packet, communication to/from the device fails.

This works fine with a Cisco AP. I can provide ethereal captures using a monitor mode VAP for both the Cisco and the madwifi AP.

Attachments

Cisco - Spectralink Phone.bz2 (157.2 kB) - added by ebree@nltinc.com on 02/24/06 14:20:44.
MadWifi - Spectralink Phone.bz2 (192.0 kB) - added by ebree@nltinc.com on 02/24/06 14:21:36.
madwifi-parent_queue.diff (4.4 kB) - added by mentor on 05/20/06 00:35:35.
Trial solution
madwifi-parent_queue.2.diff (3.5 kB) - added by mentor on 05/20/06 01:52:13.
Slightly better.
madwifi-parent.diff (3.6 kB) - added by mentor on 05/21/06 16:27:34.
Patch - Set parent at the correct time.
madwifi-parent.2.diff (3.6 kB) - added by mentor on 05/25/06 19:06:24.
Manage Reference Counting properly
madwifi-parent.3.diff (3.6 kB) - added by mentor on 05/25/06 19:09:54.
Changed . to ->
package-loss-icmp.tar.bz2 (1.2 kB) - added by foodoc on 05/29/06 19:35:53.
ethereal - icmp reply for sequence 0x8785 is missing!
madwifi-parent.3.2.diff (5.0 kB) - added by mentor on 05/30/06 02:29:02.
To go to the list
madwifi-parent.6.diff (5.5 kB) - added by mentor on 05/30/06 21:18:02.

Change History

02/24/06 06:30:47 changed by mrenzmann

Yes, please do so (provide the captures, I mean). In addition, could you please enable related debugging messages (DevDocs/AthDebug) and see what happens to the driver when the ps-poll is sent by the phone?

02/24/06 14:20:44 changed by ebree@nltinc.com

  • attachment Cisco - Spectralink Phone.bz2 added.

02/24/06 14:21:36 changed by ebree@nltinc.com

  • attachment MadWifi - Spectralink Phone.bz2 added.

02/24/06 14:25:40 changed by ebree@nltinc.com

I used the following filter to see all the data from the phone but the captures include everything... 

wlan.ta == 00:90:7a:03:2d:b5 || wlan.da == 00:90:7a:03:2d:b5 || wlan.sa == 00:90:7a:03:2d:b5

I also experience the same problem with a Lantronix Wi-Port with Power Save Mode enabled. If I turn off the Power Save mode, it works fine.

80211debug +power will follow shortly.

02/24/06 15:03:18 changed by ebree@nltinc.com

80211debug -i ath015 +power 

ath015: [00:90:7a:03:59:ce] UAPSD bit settings from STA: 00
ath015: [00:90:7a:03:59:ce] UAPSD bit settings from STA: 00
ath015: [00:90:7a:03:59:ce] power save mode on, 1 sta's in ps mode
ath015: [00:90:7a:03:59:ce] save frame, 1 now queued
ath015: [0e:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath015: [00:90:7a:03:59:ce] recv ps-poll, send packet, queue empty
ath015: [00:90:7a:03:59:ce] save frame, 1 now queued
ath015: [0e:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath015: [00:90:7a:03:59:ce] recv ps-poll, send packet, queue empty
ath015: [00:90:7a:03:59:ce] save frame, 1 now queued
ath015: [0e:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath015: [00:90:7a:03:59:ce] recv ps-poll, send packet, queue empty
ath015: [00:90:7a:03:59:ce] save frame, 1 now queued
ath015: [0e:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath015: [00:90:7a:03:59:ce] recv ps-poll, send packet, queue empty
ath015: [00:90:7a:03:59:ce] save frame, 1 now queued
ath015: [0e:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath015: [00:90:7a:03:59:ce] recv ps-poll, send packet, queue empty
ath015: [00:90:7a:03:59:ce] save frame, 1 now queued
ath015: [0e:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath015: [00:90:7a:03:59:ce] recv ps-poll, send packet, queue empty
ath015: [00:90:7a:03:59:ce] save frame, 1 now queued
ath015: [0e:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath015: [00:90:7a:03:59:ce] recv ps-poll, send packet, queue empty
ath015: [00:90:7a:03:59:ce] save frame, 1 now queued
ath015: [0e:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath015: [00:90:7a:03:59:ce] recv ps-poll, send packet, queue empty
ath015: [00:90:7a:03:59:ce] save frame, 1 now queued
ath015: [0e:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath015: [00:90:7a:03:59:ce] recv ps-poll, send packet, queue empty
ath015: [00:90:7a:03:59:ce] save frame, 1 now queued
ath015: [0e:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath015: [00:90:7a:03:59:ce] recv ps-poll, send packet, queue empty
ath015: [00:90:7a:03:59:ce] save frame, 1 now queued
ath015: [0e:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath015: [00:90:7a:03:59:ce] recv ps-poll, send packet, queue empty
ath015: [00:90:7a:03:59:ce] save frame, 1 now queued
ath015: [00:90:7a:03:59:ce] discard frame, age 7
ath015: [00:90:7a:03:59:ce] discard 1 frames for age

04/03/06 17:49:01 changed by bell_kin

could you verify the tx count using ifconfig, is there an tx packet when you see "recv ps-poll, send packet"?

05/08/06 19:53:42 changed by ebree@nltinc.com 

[root@an0001ap08 ~]# ifconfig ath008
ath008    Link encap:Ethernet  HWaddr 00:02:6F:3E:1C:94
          UP BROADCAST RUNNING MULTICAST  MTU:2290  Metric:1
          RX packets:701 errors:0 dropped:0 overruns:0 frame:0
          TX packets:367 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:0
          RX bytes:13665 (13.3 KiB)  TX bytes:23473 (22.9 KiB)

[root@an0001ap08 ~]# ping -c 1 172.25.1.91
PING 172.25.1.91 (172.25.1.91): 56 data bytes
ath008: [00:20:4a:82:52:5e] power save mode off, 0 sta's in ps mode
84 bytes from 172.25.1.91: icmp_seq=0 ttl=64 time=38.9 ms

--- 172.25.1.91 ping statistics ---
1 packets transmitted, 1 packets received, 0% packet loss
round-trip min/avg/max = 38.9/38.9/38.9 ms
[root@an0001ap08 ~]# ath008: [00:20:4a:82:52:5e] power save mode on, 1 sta's in ps mode

[root@an0001ap08 ~]# ping -c 1 172.25.1.91
PING 172.25.1.91ath008: [00:20:4a:82:52:5e] save frame, 1 now queued
 (172.25.1.91): 56 data bytes
ath008: [00:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath008: [00:20:4a:82:52:5e] recv ps-poll, send packet, queue empty
ath008: [00:20:4a:82:52:5e] save frame, 1 now queued
ath008: [00:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath008: [00:20:4a:82:52:5e] recv ps-poll, send packet, queue empty
ath008: [00:20:4a:82:52:5e] save frame, 1 now queued
ath008: [00:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath008: [00:20:4a:82:52:5e] recv ps-poll, send packet, queue empty
ath008: [00:20:4a:82:52:5e] save frame, 1 now queued
ath008: [00:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath008: [00:20:4a:82:52:5e] recv ps-poll, send packet, queue empty
ath008: [00:20:4a:82:52:5e] save frame, 1 now queued
ath008: [00:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath008: [00:20:4a:82:52:5e] recv ps-poll, send packet, queue empty
ath008: [00:20:4a:82:52:5e] save frame, 1 now queued
ath008: [00:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath008: [00:20:4a:82:52:5e] recv ps-poll, send packet, queue empty
ath008: [00:20:4a:82:52:5e] save frame, 1 now queued
ath008: [00:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath008: [00:20:4a:82:52:5e] recv ps-poll, send packet, queue empty
ath008: [00:20:4a:82:52:5e] save frame, 1 now queued
ath008: [00:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath008: [00:20:4a:82:52:5e] recv ps-poll, send packet, queue empty
ath008: [00:20:4a:82:52:5e] save frame, 1 now queued
ath008: [00:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath008: [00:20:4a:82:52:5e] recv ps-poll, send packet, queue empty
ath008: [00:20:4a:82:52:5e] save frame, 1 now queued
ath008: [00:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath008: [00:20:4a:82:52:5e] recv ps-poll, send packet, queue empty
ath008: [00:20:4a:82:52:5e] save frame, 1 now queued
ath008: [00:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath008: [00:20:4a:82:52:5e] recv ps-poll, send packet, queue empty
ath008: [00:20:4a:82:52:5e] save frame, 1 now queued
ath008: [00:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath008: [00:20:4a:82:52:5e] recv ps-poll, send packet, queue empty
ath008: [00:20:4a:82:52:5e] save frame, 1 now queued
ath008: [00:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath008: [00:20:4a:82:52:5e] recv ps-poll, send packet, queue empty
ath008: [00:20:4a:82:52:5e] save frame, 1 now queued
ath008: [00:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath008: [00:20:4a:82:52:5e] recv ps-poll, send packet, queue empty
ath008: [00:20:4a:82:52:5e] save frame, 1 now queued
ath008: [00:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath008: [00:20:4a:82:52:5e] recv ps-poll, send packet, queue empty
ath008: [00:20:4a:82:52:5e] save frame, 1 now queued
ath008: [00:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath008: [00:20:4a:82:52:5e] recv ps-poll, send packet, queue empty
ath008: [00:20:4a:82:52:5e] save frame, 1 now queued
ath008: [00:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
ath008: [00:20:4a:82:52:5e] discard frame, age 0
ath008: [00:20:4a:82:52:5e] discard 1 frames for age
ath008: [00:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 0, off 0, len 1


--- 172.25.1.91 ping statistics ---
1 packets transmitted, 0 packets received, 100% packet loss
[root@an0001ap08 ~]#
[root@an0001ap08 ~]# ifconfig ath008
ath008    Link encap:Ethernet  HWaddr 00:02:6F:3E:1C:94
          UP BROADCAST RUNNING MULTICAST  MTU:2290  Metric:1
          RX packets:723 errors:0 dropped:0 overruns:0 frame:0
          TX packets:369 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:0
          RX bytes:14105 (13.7 KiB)  TX bytes:23633 (23.0 KiB)

[root@an0001ap08 ~]# ath008: [00:20:4a:82:52:5e] power save mode off, 0 sta's in ps mode
ath008: [00:20:4a:82:52:5e] power save mode on, 1 sta's in ps mode
ath008: [00:90:96:f2:a2:c3] UAPSD bit settings from STA: 00

05/08/06 19:54:45 changed by anonymous

I had to use a different device for testing (Lantronix Wi-Port), but yes the TX count on the ifconfig increases.

05/08/06 20:19:17 changed by ebree@nltinc.com

Forgot to mention revision used which is svn 1543.

05/16/06 20:37:48 changed by nighty

There *was* the exact same problem on FreeBSD , I believe it has been fixed by Sam Leffler in the HEAD CVS code a while ago and has been committed down to 6.x.

Maybe a good idea to check the FreeBSD code, I believe sam changed the from the hardware queue to the software queue.

Could you look at this too for madwifi ?

05/16/06 20:38:41 changed by nighty

I believe it was in the if_ath.c code

05/16/06 21:19:53 changed by anonymous

same problem here, with ICQ! I can connect and everyting but the connection is very unstable:

ath0: [00:ff:ff:ff:ff:10] power save mode on, 1 sta's in ps mode ath0: [00:ff:ff:ff:ff:10] power save mode off, 0 sta's in ps mode ath0: [00:ff:ff:ff:ff:10] send station disassociate (reason 8)

and reconnect...

svn 1546

05/18/06 17:11:14 changed by mentor

Referring to the TX count, am I right in thinking that the interface has only seen 2 outgoing packets during the ping?

05/18/06 17:20:50 changed by ebree@nltinc.com

Yes, and I sent 2 ping packets, one which was successfull, and the second was not.

05/18/06 18:03:46 changed by mentor

So, is that the same packet being queued over and over again? In which case, are we not actually transmitting the packet or not receiving an ack, causing the packet to be requeued?

05/18/06 18:06:47 changed by ebree@nltinc.com

AFAIK, yes, at least that is what it appears to do.

05/18/06 19:49:51 changed by mentor

Right, I looked at the packet captures, and in the MadWifi case the PSPoll packet is sent, and is ACK'ed. And then nothing happens.

Whereas with the Cisco AP, the PSPoll packet is sent, is ACK'ed, data is sent back, data is ACK'ed. So, it look like for some rason that the saved packet queue is not being sent properly.

05/18/06 19:59:52 changed by mentor

Ah. I suspect dev_queue_xmit at the end of ieee80211_recv_pspoll (net80211/ieee80211_input.c) is not doing the right thing. I think the packet is resubmitted, but shunted straight into the saved queue again.

05/18/06 20:17:20 changed by nighty

That's right :)

05/18/06 21:33:38 changed by mentor

OK, so we set a flag in a skb->cb and then call dev_queue_xmit. Presumably this then links back into ieee80211_hardstart (in ieee80211_output.c) which... clears the skb->cb.

oops?

05/20/06 00:35:35 changed by mentor

  • attachment madwifi-parent_queue.diff added.

Trial solution

05/20/06 00:48:18 changed by dyqith

patch looks good,

additional comments:

  1. why have the M_FLAG_KEEP_ONLY call if its sanitized ?
  1. you shouldn't need to create a new .h file, just put the declaration in proto.h also (where hardstart is)
  1. ieee80211_power.c also has a call like this, line 319

05/20/06 01:51:32 changed by mentor

Changed.

I'm not convinced that the logic for setting the MORE_DATA flag is robust/elegant now, though.

I'll put this on the list for feedback, and get nightly_ to test.

Signed-Off-By: Matthew W. S. Bell <m.bell@bvrh.co.uk>

05/20/06 01:52:13 changed by mentor

  • attachment madwifi-parent_queue.2.diff added.

Slightly better.

05/20/06 19:57:22 changed by anonymous

thanks, I'm compiling it right now (on the current svn 1587)... will report back in a _few_ minutes!

05/20/06 20:57:39 changed by anonymous

madwifi-parent_queue.2.diff: makes my router to panic as soon as I do "ifup ath0". sorry, I can't provide any traces or other useful information...since the router has no _monitor_ and I can't see anything on netconsole/serialconsole.

05/20/06 21:09:48 changed by anonymous

tried madwifi-parent_queue.diff too... same result! instant panic.

madwifi-ng: svn 1587 kernel: 2.6.16.16 (with grsecurity) hostapd: 0.5.3 "AR5212 802.11abg NIC (rev 01)"

05/20/06 22:03:35 changed by mentor

I win again!

05/20/06 22:21:56 changed by anonymous

what?

BTW, does anybody know a good Atheros Windows Driver (which doesn't ignore "Power Saving": off - feature and supports WPA2-PSK in CCMP?)

Card is a: Netgear WG311T v400

05/20/06 22:36:03 changed by mentor

WRT My Remarkably Unreliable Patches.

05/20/06 22:49:37 changed by mentor

Sadly, I have no idea what I am making panic here. The only thing I can think of is that we might need to cancel scanning again when we resubmit the packets.

I'll get someone more intelligent to look at it.

05/20/06 23:27:06 changed by anonymous

so tell me what to do!

_test_-setup: 1. Windows XP Client (can be two, or three) with a _broken_ driver (=Power saving ON!) 2. Hostapd + madwifi (I only have a atheros cards!) setup with WPA2-PSK 3. ping -f "Windows XP Client" (flood it!!!) and wait for ..........

that's how I trigger the package loss!

(It probably panics because: struct ieee80211com *ic = vap->iv_ic; (ic is NULL or rubbish!)

05/21/06 16:02:46 changed by ebree@nltinc.com

I've tried the patch against 1552 and get the following on my serial console 

ath015
Unable to handle kernel NULL pointer dereference at virtual address 00000978
 printing eip:
c8876a66
*pde = 00000000
Oops: 0002 [#1]
PREEMPT
Modules linked in: wlan_xauth wlan_wep wlan_tkip wlan_scan_sta wlan_scan_ap wlan_ccmp wlan_acl ath_pci ath_rate_sample wlan ath_hal
CPU:    0
EIP:    0060:[<c8876a66>]    Tainted: P      VLI
EFLAGS: 00010216   (2.6.16 #1)
EIP is at ieee80211_parent_queue_xmit+0x1f/0x2b [wlan]
eax: c134e180   ebx: 00000000   ecx: 0000003c   edx: fffef9ea
esi: c114a260   edi: c7f24000   ebp: c134e180   esp: c1387e70
ds: 007b   es: 007b   ss: 0068
Process sh (pid: 990, threadinfo=c1386000 task=c7f1a560)
Stack: <0>c1340000 c8876a0a c13c1000 c134d810 c7f24000 c114a000 c134e180 c1386000
       fffffff4 c0247bd4 c134d844 c1387f02 c134d84c 00000016 c02a3071 c114a000
       c1387edc c134e180 000000fa c1387f20 c75e43e0 c1387edc c02a31d3 00000000
Call Trace:
 [<c8876a0a>] ieee80211_hardstart+0x1bb/0x1f8 [wlan]
 [<c0247bd4>] dev_queue_xmit+0x14f/0x1fe
 [<c02a3071>] br_send_bpdu+0x18d/0x195
 [<c02a31d3>] br_send_config_bpdu+0x15a/0x162
 [<c012d6b2>] find_get_page+0x14/0x44
 [<c02a2978>] br_transmit_config+0xed/0x10f
 [<c02a2bca>] br_config_bpdu_generation+0x44/0x51
 [<c02a3a3d>] br_hello_timer_expired+0x25/0x46
 [<c011961e>] run_timer_softirq+0x145/0x186
 [<c02a3a18>] br_hello_timer_expired+0x0/0x46
 [<c012c5b0>] handle_IRQ_event+0x21/0x4a
 [<c0116279>] __do_softirq+0x35/0x7d
 [<c01162e3>] do_softirq+0x22/0x26
 [<c0116378>] irq_exit+0x29/0x34
 [<c0103c2c>] do_IRQ+0x1e/0x24
 [<c010272a>] common_interrupt+0x1a/0x20
Code: ff ff 83 c4 0c 31 c0 5b 5e 5f 5d c3 53 8b 50 14 8b 92 30 01 00 00 ff 42 08 8b 9a b8 00 00 00 8b 48 60 01 4a 10 8b 15 f8 79 30 c0 <89> 93 78 09 00 00 5b e9 13 10 9d f7 55 57 56 53 89 c3 8b 44 24
 <0>Kernel panic - not syncing: Fatal exception in interrupt

and against 1587 

Unable to handle kernel NULL pointer dereference at virtual address 00000978
 printing eip:
c8876a6a
*pde = 00000000
Oops: 0002 [#1]
PREEMPT
Modules linked in: wlan_xauth wlan_wep wlan_tkip wlan_scan_sta wlan_scan_ap wlan_ccmp wlan_acl ath_pci ath_rate_sample wlan ath_hal
CPU:    0
EIP:    0060:[<c8876a6a>]    Tainted: P      VLI
EFLAGS: 00010216   (2.6.16 #1)
EIP is at ieee80211_parent_queue_xmit+0x1f/0x2b [wlan]
eax: c59ff240   ebx: 00000000   ecx: 0000003c   edx: fffef9e0
esi: c114b260   edi: c75ea000   ebp: c59ff240   esp: c7f7be70
ds: 007b   es: 007b   ss: 0068
Process modprobe (pid: 984, threadinfo=c7f7a000 task=c79faab0)
Stack: <0>c59f0000 c8876a0e c13d7000 c1356a10 c75ea000 c114b000 c59ff240 c7f7a000
       fffffff4 c0247bd4 c1356a44 c7f7bf02 c1356a4c 00000016 c02a3071 c114b000
       c7f7bedc c59ff240 000000fa c7f7bf20 c75e43e0 c7f7bedc c02a31d3 c7f7bf00
Call Trace:
 [<c8876a0e>] ieee80211_hardstart+0x1bb/0x1f8 [wlan]
 [<c0247bd4>] dev_queue_xmit+0x14f/0x1fe
 [<c02a3071>] br_send_bpdu+0x18d/0x195
 [<c02a31d3>] br_send_config_bpdu+0x15a/0x162
 [<c02a2978>] br_transmit_config+0xed/0x10f
 [<c02a2bca>] br_config_bpdu_generation+0x44/0x51
 [<c02a3a3d>] br_hello_timer_expired+0x25/0x46
 [<c011961e>] run_timer_softirq+0x145/0x186
 [<c02a3a18>] br_hello_timer_expired+0x0/0x46
 [<c012c5b0>] handle_IRQ_event+0x21/0x4a
 [<c0116279>] __do_softirq+0x35/0x7d
 [<c01162e3>] do_softirq+0x22/0x26
 [<c0116378>] irq_exit+0x29/0x34
 [<c0103c2c>] do_IRQ+0x1e/0x24
 [<c010272a>] common_interrupt+0x1a/0x20
Code: ff ff 83 c4 0c 31 c0 5b 5e 5f 5d c3 53 8b 50 14 8b 92 30 01 00 00 ff 42 08 8b 9a b8 00 00 00 8b 48 60 01 4a 10 8b 15 f8 79 30 c0 <89> 93 78 09 00 00 5b e9 0f 10 9d f7 55 57 56 53 89 c3 8b 44 24
 <0>Kernel panic - not syncing: Fatal exception in interrupt

05/21/06 16:27:34 changed by mentor

  • attachment madwifi-parent.diff added.

Patch - Set parent at the correct time.

05/21/06 16:30:47 changed by mentor

Thanks. I think I was setting the skb to belong to the parent device at the wrong time, thus causing the code to try and look at a pointer from the worng device. If you want to test this again, you can... but my patches are remarkably unreliable.

Signed-Off-By: Matthew W. S. Bell <m.bell@bvrh.co.uk>

05/21/06 16:56:48 changed by anonymous

compile errors: 

  CC [M]  net80211/ieee80211_output.o
net80211/ieee80211_output.c: In function 'ieee80211_parent_queue_xmit':
net80211/ieee80211_output.c:308: error: request for member 'ic_lastdata' in something not a structure or union

anyway, so, I _fixed_ it myself: 

void ieee80211_parent_queue_xmit(struct sk_buff *skb) {
        struct ieee80211vap *vap = skb->dev->priv;
        struct ieee80211com *ic = vap->iv_ic;

        vap->iv_devstats.tx_packets++;
        vap->iv_devstats.tx_bytes += skb->len;
        ic->ic_lastdata = jiffies;

        // Dispatch the packet to the parent device
        skb->dev = vap->iv_ic->ic_dev;
        (void) dev_queue_xmit(skb);
}

but it still doesn't work correctly: 

ath0: [CLIENT-MAC] power save mode off, 0 sta's in ps mode
ath0: [CLIENT-MAC] flush ps queue, 3 packets queued
ath0: [CLIENT-MAC] send station deauthenticate (reason 6)
ath0: [CLIENT-MAC] send station deauthenticate (reason 6)
ath0: [SERV-MAC] ieee80211_beacon_update: TIM updated, pending 0, off 0, len 1
ath0: [CLIENT-MAC] recv auth frame with algorithm 0 seq 1
ath0: [CLIENT-MAC] station authenticated (open)
ath0: [CLIENT-MAC] UAPSD bit settings from STA: 00

05/21/06 17:05:33 changed by anonymous

ohh, but I think, you're on the right track!!

(setup _before_ the patch!) 

ath0: [CLIENT-MAC] save frame, 1 now queued
ath0: [CLIENT-MAC] save frame, 2 now queued
ath0: [CLIENT-MAC] save frame, 3 now queued
ath0: [CLIENT-MAC] save frame, 4 now queued
ath0: [CLIENT-MAC] power save mode off, 0 sta's in ps mode
ath0: [CLIENT-MAC] flush ps queue, 4 packets queued
ath0: [SRV-MAC] ieee80211_beacon_update: TIM updated, pending 0, off 0, len 1

with patch 

ath0: [CLIENT-MAC] power save mode off, 0 sta's in ps mode
ath0: [CLIENT-MAC] flush ps queue, 3 packets queued
---->ath0: [CLIENT-MAC] send station deauthenticate (reason 6) <---- damn drivers!
---->ath0: [CLIENT-MAC] send station deauthenticate (reason 6) <---- 
ath0: [SERV-MAC] ieee80211_beacon_update: TIM updated, pending 0, off 0, len 1
ath0: [CLIENT-MAC] recv auth frame with algorithm 0 seq 1
ath0: [CLIENT-MAC] station authenticated (open)
ath0: [CLIENT-MAC] UAPSD bit settings from STA: 00

05/21/06 18:03:25 changed by mentor

OK, well it doesn't help that it doesn't work... but I notice that the client is not using power save mode, or you are turning power save mode off mid-way. Is this intentional?

05/21/06 18:07:54 changed by ebree@nltinc.com

I get the following now with the new patch applied against 1552. After the initial assoc and going into power save, I do 

[root@an0001ap01 ~]# ping -c 5 172.25.254.220
PING 172.25.254.220 (172.25.254.220): 56 data bytes
84 bytes from 172.25.254.220: icmp_seq=0 ttl=64 time=90.0 ms
84 bytes from 172.25.254.220: icmp_seq=1 ttl=64 time=97.5 ms

--- 172.25.254.220 ping statistics ---
5 packets transmitted, 2 packets received, 60% packet loss
round-trip min/avg/max = 90.0/93.7/97.5 ms

with the following in the log. 

Aug  5 08:02:15 an0001ap01 daemon.info hostapd: ath008: STA 00:20:4a:82:43:c8 IEEE 802.11: associated
Aug  5 08:02:15 an0001ap01 daemon.debug hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: event 1 notification
Aug  5 08:02:15 an0001ap01 daemon.debug hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: event 4 notification
Aug  5 08:02:15 an0001ap01 daemon.debug hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: sending 1/4 msg of 4-Way Handshake
Aug  5 08:02:15 an0001ap01 daemon.debug hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: received EAPOL-Key frame (2/4 Pairwise)
Aug  5 08:02:15 an0001ap01 daemon.debug hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: sending 3/4 msg of 4-Way Handshake
Aug  5 08:02:15 an0001ap01 daemon.debug hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: received EAPOL-Key frame (4/4 Pairwise)
Aug  5 08:02:15 an0001ap01 daemon.debug hostapd: ath008: STA 00:20:4a:82:43:c8 IEEE 802.1X: authorizing port
Aug  5 08:02:15 an0001ap01 daemon.info hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: pairwise key handshake completed (WPA)
Aug  5 08:02:15 an0001ap01 daemon.debug hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: sending 1/2 msg of Group Key Handshake
Aug  5 08:02:15 an0001ap01 daemon.debug hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: received EAPOL-Key frame (2/2 Group)
Aug  5 08:02:15 an0001ap01 daemon.info hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: group key handshake completed (WPA)
Aug  5 08:02:15 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] power save mode on, 1 sta's in ps mode
Aug  5 08:02:26 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] save frame, 1 now queued
Aug  5 08:02:26 an0001ap01 user.warn kernel: ath008: [00:02:6f:3e:1c:88] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
Aug  5 08:02:26 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] recv ps-poll, send packet, queue empty
Aug  5 08:02:26 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] power save mode off, 0 sta's in ps mode
Aug  5 08:02:26 an0001ap01 user.warn kernel: ath008: [00:02:6f:3e:1c:88] ieee80211_beacon_update: TIM updated, pending 0, off 0, len 1
Aug  5 08:02:26 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] power save mode on, 1 sta's in ps mode
Aug  5 08:02:27 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] save frame, 1 now queued
Aug  5 08:02:27 an0001ap01 user.warn kernel: ath008: [00:02:6f:3e:1c:88] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
Aug  5 08:02:27 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] recv ps-poll, send packet, queue empty
Aug  5 08:02:27 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] power save mode off, 0 sta's in ps mode
Aug  5 08:02:27 an0001ap01 user.warn kernel: ath008: [00:02:6f:3e:1c:88] ieee80211_beacon_update: TIM updated, pending 0, off 0, len 1
Aug  5 08:02:27 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] power save mode on, 1 sta's in ps mode
Aug  5 08:02:27 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] power save mode off, 0 sta's in ps mode
Aug  5 08:02:28 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
Aug  5 08:02:29 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
Aug  5 08:02:30 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
Aug  5 08:02:31 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
Aug  5 08:02:32 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
Aug  5 08:02:33 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
Aug  5 08:02:36 an0001ap01 user.warn kernel: [ath008:00:02:6f:3e:1c:88] discard data frame, unknown src
Aug  5 08:02:36 an0001ap01 user.warn kernel: [ath015:00:02:6f:3e:1c:88] discard frame, not to bss or xrbss
Aug  5 08:02:36 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] recv probe req
Aug  5 08:02:36 an0001ap01 user.warn kernel: [00:20:4a:82:43:c8] discard probe_req frame, ssid mismatch: "VLAN_Messenger"
Aug  5 08:02:36 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] recv probe req
Aug  5 08:02:36 an0001ap01 user.warn kernel: [00:20:4a:82:43:c8] discard probe_req frame, ssid mismatch: "VLAN_Messenger"
Aug  5 08:02:36 an0001ap01 user.warn kernel: [ath015:00:02:6f:3e:1c:88] discard frame, not to bss or xrbss
Aug  5 08:02:36 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] station needs long slot time, count 4
Aug  5 08:02:36 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] station is !ERP, 4 non-ERP stations associated
Aug  5 08:02:36 an0001ap01 user.warn kernel: ath008: ieee80211_node_join_11g: enable use of protection
Aug  5 08:02:36 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] station needs long preamble
Aug  5 08:02:36 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] station associated at aid 1: long preamble, long slot time, protection
Aug  5 08:02:36 an0001ap01 daemon.info hostapd: ath008: STA 00:20:4a:82:43:c8 IEEE 802.11: associated
Aug  5 08:02:36 an0001ap01 daemon.debug hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: event 1 notification
Aug  5 08:02:36 an0001ap01 daemon.debug hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: event 4 notification
Aug  5 08:02:36 an0001ap01 daemon.debug hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: sending 1/4 msg of 4-Way Handshake
Aug  5 08:02:36 an0001ap01 daemon.debug hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: received EAPOL-Key frame (2/4 Pairwise)
Aug  5 08:02:36 an0001ap01 daemon.debug hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: sending 3/4 msg of 4-Way Handshake
Aug  5 08:02:36 an0001ap01 daemon.debug hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: received EAPOL-Key frame (4/4 Pairwise)
Aug  5 08:02:36 an0001ap01 daemon.debug hostapd: ath008: STA 00:20:4a:82:43:c8 IEEE 802.1X: authorizing port
Aug  5 08:02:36 an0001ap01 daemon.info hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: pairwise key handshake completed (WPA)
Aug  5 08:02:36 an0001ap01 daemon.debug hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: sending 1/2 msg of Group Key Handshake
Aug  5 08:02:36 an0001ap01 daemon.debug hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: received EAPOL-Key frame (2/2 Group)
Aug  5 08:02:36 an0001ap01 daemon.info hostapd: ath008: STA 00:20:4a:82:43:c8 WPA: group key handshake completed (WPA)
Aug  5 08:02:36 an0001ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] power save mode on, 1 sta's in ps mode

05/21/06 18:43:22 changed by anonymous

@mentor: well it seems that the client always switchs between the power saving modes . I _forced_ Windows to disable Power Saving **** completely, but the setting doesn't stick! 

ath0: [CLIENT-MAC] power save mode on, 1 sta's in ps mode
ath0: [CLIENT-MAC] power save mode off, 0 sta's in ps mode
ath0: [CLIENT-MAC] power save mode on, 1 sta's in ps mode
ath0: [CLIENT-MAC] save frame, 1 now queued
ath0: [CLIENT-MAC] power save mode off, 0 sta's in ps mode
ath0: [CLIENT-MAC] flush ps queue, 1 packets queued
ath0: [SRV-MAC] ieee80211_beacon_update: TIM updated, pending 0, off 0, len 1
ath0: [CLIENT-MAC] power save mode on, 1 sta's in ps mode
ath0: [CLIENT-MAC] power save mode off, 0 sta's in ps mode
ath0: [CLIENT-MAC] power save mode on, 1 sta's in ps mode
ath0: [CLIENT-MAC] power save mode off, 0 sta's in ps mode

05/22/06 13:58:41 changed by anonymous

Ok, I experimented a bit yesterday, it seem's like that _not_ all frames are discarded, so it works to some degree - and that's what make it even harder to debug. :( 

[00:20:4a:82:43:c8] power save mode on, 1 sta's in ps mode
[00:20:4a:82:43:c8] power save mode off, 0 sta's in ps mode
[00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
[00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
[00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
[00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
[00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
[00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
[00:02:6f:3e:1c:88] discard data frame, unknown src
[00:02:6f:3e:1c:88] discard frame, not to bss or xrbss

could it be that the _nodes_ are freed after they've queued up?

05/22/06 18:16:12 changed by anonymous

@nighty so, does the madwifi-old codebase includes this fix? I tried madwifi-old-r1417 (_current_ cvs snapsho) and it's a better... (only loosing 1 instead of 6 packages)

05/23/06 18:29:02 changed by anonymous

Just a little update... some kind of success!

some kind... I found another driver for the Windows Client, now madwifi-ng & madwifi-old looses the same amount of frames!

anyone knows a good drivers for windows?

05/24/06 00:46:30 changed by mentor

Does the madwifi-ng packet loss go down, or the madwifi-old go up?

05/24/06 00:46:50 changed by mentor

  • owner set to mentor.
  • milestone set to version 0.9.x - progressive release candidate phase.

05/24/06 00:47:41 changed by mentor

  • summary changed from ps-poll packet with a Spectralink i640 phone to Power Save Mode handling and Packet Queuing.

05/24/06 00:47:52 changed by mentor

  • status changed from new to assigned.

05/24/06 01:14:46 changed by mentor

What debugging levels did you have set, when you produced the log with no node packet discards? Can you provide alog with more debugging?

05/24/06 13:22:15 changed by anonymous

Thank you!

@mentor, do you mean this:

(this is an extract of ebree@nltinc.com post on 05/21/06 18:07:54) 

[00:20:4a:82:43:c8] power save mode on, 1 sta's in ps mode
[00:20:4a:82:43:c8] power save mode off, 0 sta's in ps mode
[00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
[00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
[00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
[00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
[00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
[00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
[00:02:6f:3e:1c:88] discard data frame, unknown src
[00:02:6f:3e:1c:88] discard frame, not to bss or xrbss

about madwifi-ng vs. madwifi-old and windows... with the _new_ driver on the windows client, madwifi-ng package loss went _down_ (=is better).

BTW: I've holidays (2 1/2 weeks, is there a good reference about 802.11g/b ... and about madwifi-ng?)

05/24/06 13:27:56 changed by mentor

Yes, I was referring to that excerpt with reference to debugging levels.

05/24/06 13:56:47 changed by anonymous

Sorry, I don't have such a this nice phone. :(

anyway, (it's probalby just a wild guess but) 

13:37:58 ath0: [CLIENT] power save mode on, 1 sta's in ps mode
13:37:58 router kernel: ath0: [CLIENT] save frame, 1 now queued
13:37:58 router kernel: ath0: [SERVER] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
13:37:58 router kernel: ath0: [CLIENT] save frame, 2 now queued
13:37:58 router kernel: ath0: [CLIENT] power save mode off, 0 sta's in ps mode
13:37:58 router kernel: ath0: [CLIENT] flush ps queue, 2 packets queued

so, can you tell me what TIMs are ( I googled for it, but TIM is a very common Name!) ? since, I've a slight suspicion, that _all_ packages which went into the power-save queue _after_ the TIM update are dropped)

BTW... I've seen another thing: with 80211stats 

545 rx discard due to it's a dup
45 rx frame ssid mismatch
"214 rx fast frames"
1 tx failed due to no defkey
15 tx atheros fast frames successful
1 nodes timed out inactivity

whenever I lost a package, the _rx discard due to_ "rx fast frames" count increases! see: 

546 rx discard due to 
45 rx frame ssid mismatch
"215 rx fast frames"
1 tx failed due to no defkey
16 tx atheros fast frames successful
1 nodes timed out inactivity

05/24/06 21:18:06 changed by mentor

TIM is the Traffic Indication Map, which tells the AP which nodes/STAs are in power saving mode, so the AP can queue traffic. It's included in the beacons and beacon ACKs or something.

05/25/06 00:35:25 changed by anonymous

hmm, here're some _patches_ which have something to do with the powersave queue. or, nighty, do you know which patch was it?

http://perforce.freebsd.org/changeView.cgi?CH=77599

http://perforce.freebsd.org/chv.cgi?CH=77273

http://perforce.freebsd.org/depotTreeBrowser.cgi?FSPC=//depot/projects/vap/sys/net80211

05/25/06 15:57:30 changed by mentor

These appear to mostly affect power saving in AP mode.

05/25/06 16:14:37 changed by ebree@nltinc.com

Updated debug against svn 1552 with patches. 

net.ath008.debug: 0x09d40080<input,node,assoc,auth,output,power,inact>

May 25 10:10:15 an0010ap01 daemon.info ntpd[1016]: synchronized to 172.30.0.1, stratum=5
May 25 10:10:21 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] power save mode off, 0 sta's in ps mode
May 25 10:10:21 an0010ap01 user.warn kernel: ath008: ath_tx_start: c5a31000<06:02:6f:3e:1c:94> refcnt 4
May 25 10:10:21 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] power save mode on, 1 sta's in ps mode
May 25 10:10:32 an0010ap01 user.warn kernel: ath008: ath_tx_start: c5a31000<06:02:6f:3e:1c:94> refcnt 4
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] save frame, 1 now queued
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: [06:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 1, off 0, len 1
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] recv ps-poll, send packet, queue empty
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: ath_tx_start: c5a31000<06:02:6f:3e:1c:94> refcnt 2
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: _ieee80211_free_node: c5531000<00:20:4a:82:43:c8> in station table, refcnt 0
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] power save mode off, 0 sta's in ps mode
May 25 10:10:41 an0010ap01 user.warn kernel: [ath008:06:02:6f:3e:1c:94] discard data frame, unknown src
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: ieee80211_tmp_node: c54d5000<00:20:4a:82:43:c8> refcnt 1
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: ieee80211_ref_node (ieee80211_send_mgmt:1789) c54d5000<00:20:4a:82:43:c8> refcnt 2
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] send station deauthenticate (reason 6)
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: ath_tx_start: c5a31000<06:02:6f:3e:1c:94> refcnt 3
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: ieee80211_tmp_node: c550d000<00:20:4a:82:43:c8> refcnt 1
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] recv probe req
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: ieee80211_ref_node (ieee80211_send_mgmt:1789) c550d000<00:20:4a:82:43:c8> refcnt 2
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: [06:02:6f:3e:1c:94] ieee80211_beacon_update: TIM updated, pending 0, off 0, len 1
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: ath_tx_start: c5a31000<06:02:6f:3e:1c:94> refcnt 3
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: _ieee80211_free_node: c54d5000<00:20:4a:82:43:c8> in <gone> table, refcnt 0
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: ieee80211_tmp_node: c5531000<00:20:4a:82:43:c8> refcnt 1
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] recv probe req
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: ieee80211_ref_node (ieee80211_send_mgmt:1789) c5531000<00:20:4a:82:43:c8> refcnt 2
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: ath_tx_start: c5a31000<06:02:6f:3e:1c:94> refcnt 3
May 25 10:10:41 an0010ap01 user.warn kernel: ath008: _ieee80211_free_node: c550d000<00:20:4a:82:43:c8> in <gone> table, refcnt 0
May 25 10:10:42 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
May 25 10:10:42 an0010ap01 user.warn kernel: ath008: ieee80211_tmp_node: c54d5000<00:20:4a:82:43:c8> refcnt 1
May 25 10:10:42 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] recv probe req
May 25 10:10:42 an0010ap01 user.warn kernel: ath008: ieee80211_ref_node (ieee80211_send_mgmt:1789) c54d5000<00:20:4a:82:43:c8> refcnt 2
May 25 10:10:42 an0010ap01 user.warn kernel: ath008: ath_tx_start: c5a31000<06:02:6f:3e:1c:94> refcnt 3
May 25 10:10:42 an0010ap01 user.warn kernel: ath008: _ieee80211_free_node: c5531000<00:20:4a:82:43:c8> in <gone> table, refcnt 0
May 25 10:10:44 an0010ap01 user.warn kernel: ath008: ieee80211_tmp_node: c550d000<00:20:4a:82:43:c8> refcnt 1
May 25 10:10:44 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] recv probe req
May 25 10:10:44 an0010ap01 user.warn kernel: ath008: ieee80211_ref_node (ieee80211_send_mgmt:1789) c550d000<00:20:4a:82:43:c8> refcnt 2
May 25 10:10:44 an0010ap01 user.warn kernel: ath008: ath_tx_start: c5a31000<06:02:6f:3e:1c:94> refcnt 3
May 25 10:10:44 an0010ap01 user.warn kernel: ath008: _ieee80211_free_node: c54d5000<00:20:4a:82:43:c8> in <gone> table, refcnt 0
May 25 10:10:46 an0010ap01 user.warn kernel: ath008: _ieee80211_free_node: c550d000<00:20:4a:82:43:c8> in <gone> table, refcnt 0
May 25 10:10:46 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
May 25 10:10:47 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
May 25 10:10:48 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] no node, discard frame (ieee80211_find_txnode)
May 25 10:10:49 an0010ap01 user.warn kernel: ath008: ieee80211_tmp_node: c5531000<00:20:4a:82:43:c8> refcnt 1
May 25 10:10:49 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] recv probe req
May 25 10:10:49 an0010ap01 user.warn kernel: ath008: ieee80211_ref_node (ieee80211_send_mgmt:1789) c5531000<00:20:4a:82:43:c8> refcnt 2
May 25 10:10:49 an0010ap01 user.warn kernel: ath008: ath_tx_start: c5a31000<06:02:6f:3e:1c:94> refcnt 3
May 25 10:10:50 an0010ap01 user.warn kernel: ath008: _ieee80211_free_node: c5531000<00:20:4a:82:43:c8> in <gone> table, refcnt 0
May 25 10:10:57 an0010ap01 user.warn kernel: ath008: ieee80211_tmp_node: c550d000<00:20:4a:82:43:c8> refcnt 1
May 25 10:10:57 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] recv probe req
May 25 10:10:57 an0010ap01 user.warn kernel: ath008: ieee80211_ref_node (ieee80211_send_mgmt:1789) c550d000<00:20:4a:82:43:c8> refcnt 2
May 25 10:10:57 an0010ap01 user.warn kernel: ath008: ath_tx_start: c5a31000<06:02:6f:3e:1c:94> refcnt 3
May 25 10:10:57 an0010ap01 user.warn kernel: ath008: ieee80211_tmp_node: c5531000<00:20:4a:82:43:c8> refcnt 1
May 25 10:10:57 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] recv probe req
May 25 10:10:57 an0010ap01 user.warn kernel: ath008: ieee80211_ref_node (ieee80211_send_mgmt:1789) c5531000<00:20:4a:82:43:c8> refcnt 2
May 25 10:10:57 an0010ap01 user.warn kernel: ath008: ath_tx_start: c5a31000<06:02:6f:3e:1c:94> refcnt 3
May 25 10:10:57 an0010ap01 user.warn kernel: ath008: _ieee80211_free_node: c550d000<00:20:4a:82:43:c8> in <gone> table, refcnt 0
May 25 10:11:13 an0010ap01 user.warn kernel: ath008: ieee80211_tmp_node: c7e01000<00:20:4a:82:43:c8> refcnt 1
May 25 10:11:13 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] recv probe req
May 25 10:11:13 an0010ap01 user.warn kernel: ath008: ieee80211_ref_node (ieee80211_send_mgmt:1789) c7e01000<00:20:4a:82:43:c8> refcnt 2
May 25 10:11:13 an0010ap01 user.warn kernel: ath008: ath_tx_start: c5a31000<06:02:6f:3e:1c:94> refcnt 3
May 25 10:11:13 an0010ap01 user.warn kernel: ath008: _ieee80211_free_node: c5531000<00:20:4a:82:43:c8> in <gone> table, refcnt 0
May 25 10:11:19 an0010ap01 user.warn kernel: ath008: _ieee80211_free_node: c7e01000<00:20:4a:82:43:c8> in <gone> table, refcnt 0
May 25 10:11:44 an0010ap01 user.warn kernel: ath008: ieee80211_tmp_node: c7800000<00:20:4a:82:43:c8> refcnt 1
May 25 10:11:44 an0010ap01 user.warn kernel: ath008: [00:20:4a:82:43:c8] recv probe req
May 25 10:11:44 an0010ap01 user.warn kernel: ath008: ieee80211_ref_node (ieee80211_send_mgmt:1789) c7800000<00:20:4a:82:43:c8> refcnt 2
May 25 10:11:44 an0010ap01 user.warn kernel: ath008: ath_tx_start: c5a31000<06:02:6f:3e:1c:94> refcnt 3
May 25 10:11:51 an0010ap01 user.warn kernel: ath008: _ieee80211_free_node: c7800000<00:20:4a:82:43:c8> in <gone> table, refcnt 0

05/25/06 19:06:24 changed by mentor

  • attachment madwifi-parent.2.diff added.

Manage Reference Counting properly

05/25/06 19:09:32 changed by mentor

Right. This patch hopefully means the station node won't be unreferenced wrongly. SIAS. Note: remarkably unreliable patches. So much so that I've just updated it while writing this entry.

05/25/06 19:09:54 changed by mentor

  • attachment madwifi-parent.3.diff added.

Changed . to ->

05/25/06 22:11:12 changed by anonymous

thx!!

here's the report:

latest patch produces (madwifi-parent.3.diff on r1593) 

[ath0:SERVER] discard duplicate frame, seqno <3675,3675> fragno <0,0> tid 1
[ath0:SERVER] discard duplicate frame, seqno <1243,1243> fragno <0,0> tid 1
[ath0:SERVER] discard duplicate frame, seqno <2282,2282> fragno <0,0> tid 1
[ath0:SERVER] discard duplicate frame, seqno <3045,3045> fragno <0,0> tid 1
[ath0:SERVER] discard duplicate frame, seqno <3445,3445> fragno <0,0> tid 1

debug options were: 

net.ath0.debug: 0x08d40080<input,assoc,auth,output,power,inact>

05/25/06 22:32:25 changed by mentor

I don't suppose you could get a packet capture for that? ~And could you add your name when you comment, or at least a unique identifier, I'm easily confused.

*sigh* Just one problem after another.

05/26/06 01:36:13 changed by foodoc

1.I've three common sniffers tethereal, tcpdump and madwifi's debug options. but I _could_ get Kismet and WifiScanner? too! so, can you give me any hints what I should look out for?

2. ok, "have a name now" (although this name is not unique, since google has about 1320 entries! ;) ) foodoc

05/26/06 16:02:57 changed by mentor

I wanted to check the packet waws being sent twice, and whether or not it was getting ACK'ed correctly.

05/26/06 20:16:29 changed by ebree@nltinc.com

The lastest patch works for me against 1593 as long as I don't enable +node debug. I am creating a VAP with the following command... 

/usr/bin/wlanconfig ath015 create wlandev wifi0 wlanmode ap

and I am using WEP128. I can't test using WPA-PSK as that doesn't work me atm, ticket 633.

05/26/06 21:01:36 changed by foodoc

ok, I've a WPA2-PSK (WPA2-EAP) setup, so let's try if WEP _does_ the trick!

05/26/06 21:54:38 changed by foodoc

one more thing, with the latest patch (madwifi-parent.3.diff)

when I apply the patch (r1593 from snapshot.madwifi.org) this hunk fails:

ieee80211_output.c.rej 

***************
*** 266,279 ****
                ieee80211_pwrsave(ni, skb);
-               goto reclaim;
        }
-       M_FLAG_KEEP_ONLY(skb, M_UAPSD | M_PWR_SAV);
-       cb->ni = ni;

-       vap->iv_devstats.tx_packets++;
-       vap->iv_devstats.tx_bytes += skb->len;
-       ic->ic_lastdata = jiffies;
-
-       skb->dev = parent;
  #ifdef ATH_SUPERG_XR
        /*
         * broadcast/multicast  packets need to be sent on XR vap in addition to
--- 269,275 ----
                ieee80211_pwrsave(ni, skb);
+               return 0;
        }

  #ifdef ATH_SUPERG_XR
        /*
         * broadcast/multicast  packets need to be sent on XR vap in addition to

so I did it by hand... is this _normal_, or is my codebase screwed up?

05/27/06 01:33:27 changed by mentor

The patch should apply cleanly.

@merkbree: What happens if you enable node debug?

05/29/06 13:41:06 changed by mrenzmann

  • reporter changed from eric@nltinc.com to ebree@nltinc.com.

05/29/06 19:35:53 changed by foodoc

  • attachment package-loss-icmp.tar.bz2 added.

ethereal - icmp reply for sequence 0x8785 is missing!

05/29/06 19:41:56 changed by foodoc

@mentor... 

b7acebdd04506a6527667cec3360e006  madwifi-parent.3.diff
}}} is this _the_ correct m5sum of your patch? (I tried it again, against 1611 it won't apply _cleanly_!)

anyway, I've attached _hopefully_ the right files... 
look for sequence number 0x8785 ... it's send at the _same_ time as sta goes into
powersave...

@ebree:

does this patch _really_ solves your problem?

05/29/06 19:46:42 changed by foodoc

(resend: sorry for my silly mistake ;) )

@mentor: 

b7acebdd04506a6527667cec3360e006  madwifi-parent.3.diff

is this _the_ correct m5sum of your patch? (I tried it again against 1611 and it won't apply _cleanly_!)

anyway, I've attached _hopefully_ the right files... look for sequence number 0x8785 ... it's send at the _same_ time as sta goes into powersave...

@ebree: does this patch _really_ solves your problem?

05/29/06 20:04:44 changed by mentor

Actually it doens't apply cleanly.

I'm going to look at all the other dev_queue_xmit cases, and check varius bits of cleanup code, befcore finalising this patch; then I'll ask the list for comments, because I'm not confident enough to apply straight away.

@foodoc: I'll look at this packet dump later.

05/29/06 20:17:54 changed by ebree@nltinc.com

@foodoc

It worked for me against revision 1593, not so well with 1611. What revision(s) have you tried?

05/29/06 21:18:52 changed by foodoc

@mentor: ok!

@ebree: umm, alot :D ! basicly every _daily_ revision (starting with: 1593, to 1611) BTW: the main difference between 1593 and 1611 is the new HAL code.

05/30/06 02:28:30 changed by mentor

Right. New patch in its version that I will get around to submitting for comments. The unclean application appears to be due to whitespace. sorry.

Regarding r1611, the only relevant change is the HAL code, so any other issues would appear to be due to that.

05/30/06 02:29:02 changed by mentor

  • attachment madwifi-parent.3.2.diff added.

To go to the list

05/30/06 02:30:16 changed by anonymous

  • patch_attached set to 1.

05/30/06 13:30:20 changed by foodoc

Compile errors: (with the latest patch madwifi-parent.3.2.diff) 

cc1: warnings being treated as errors
/home/router/router/build/madwifi-ng/1611-20060531/sources/net80211/ieee80211_output.c: In function 'ieee80211_hardstart':
/home/router/router/build/madwifi-ng/1611-20060531/sources/net80211/ieee80211_output.c:298: warning: control reaches end of non-void function
make[4]: *** [/home/router/router/build/madwifi-ng/1611-20060531/sources/net80211/ieee80211_output.o] Error 1

I fixed it by hand: 

ieee80211_output.c @ line 295
bad:
        if (skb != NULL)
                dev_kfree_skb(skb);
+        return 0;
}

just in case: this is my gcc 

Using built-in specs.
Target: i486-linux-gnu
Configured with: ../src/configure -v --enable-languages=c,c++,java,fortran,objc,obj-c++,ada,treelang --prefix=/usr --enable-shared --with-system-zlib --libexecdir=/usr/lib --without-included-gettext --enable-threads=posix --enable-nls --program-suffix=-4.1 --enable-__cxa_atexit --enable-clocale=gnu --enable-libstdcxx-debug --enable-java-awt=gtk --enable-gtk-cairo --with-java-home=/usr/lib/jvm/java-1.4.2-gcj-4.1-1.4.2.0/jre --enable-mpfr --with-tune=i686 --enable-checking=release i486-linux-gnu
Thread model: posix
gcc version 4.1.1 20060511 (prerelease) (Debian 4.1.0-4)

05/30/06 21:18:02 changed by mentor

  • attachment madwifi-parent.6.diff added.

05/30/06 21:30:20 changed by mentor

This gets it right. It also removes the setting of the MORE_DATA bit on unicast packets when a node is not in PS mode.

05/31/06 13:28:06 changed by foodoc

@ebree: do you have some kind of success with the latest patch? (if so, we can close this ticket and I'll open a new one with my specific problem...)

06/02/06 00:27:56 changed by anonymous

any updates? or a good hint? since I _really_ doubt now that the problem is just reordering the queues...

since I get alot of duplicated frames now and there's no real progress. I'll try setup a network monitor on client, but unfortunatly there's no way to get ethereal or airsnort working in Windows (I can start it, but no packages/frames are been captured!)

06/08/06 00:38:10 changed by foodoc

Ok, it seems like noone (except myself) _maintains_ this ticket :p... I ordered a Prism Card (should arrive probably in the next few days), I'll report back!

OT: There's a new HAL! But, Is there a official Changelog for the HAL? Thx!

06/10/06 04:18:14 changed by mentor

I've committed a patch in r1637. Test Test Test :)

06/19/06 09:34:26 changed by mrenzmann

  • milestone changed from version 0.9.x - progressive release candidate phase to version 0.9.1.

@mentor: Do you think that your patch fixes the issues described in this ticket? If so, I suggest we close this ticket for now (no reports received about problems) and ask people to open a new ticket with reference to this one in case any related issues show up later.

06/19/06 13:54:49 changed by ebree@nltinc.com

I have tested this with the revision 1645 and so far I have had no problems with client devices that operate in powersave mode. I seem to have an issue with multicast traffic, but I think I will raise a separate ticket for that issue.

06/20/06 05:43:25 changed by mrenzmann

  • status changed from assigned to closed.
  • resolution set to fixed.

Ok, so for now I close this ticket. In case there are problems left over, please open a new ticket. Thanks everyone for the work done in investigating and fixing this issue.

10/24/06 14:09:26 changed by anonymous

could this be the same deal as the ticket #974?

07/07/08 15:50:36 changed by ravikishore.s@redpinesignals.com

I have a general doubt regarding power ssenario here. AP has added data packets for Station A in Hardware Queue (not transmitted in Air). How will we handle the case when the same station goes into Power Save mode (before its packet are actually transmitted in air). Is there any way to check station's Power Save mode just before throwing the packet in Air. Or these packets are dropped??

In present madwifi implementation we check Station's Power Save mode in hardstart function in ieee80211.c file. If PS Mode is enabled then it is queued o.w. given to parent_queue_xmit function in if_ath.c file. What if station changes its Power Save mode in between i.e., after packet is given to parent_queue_xmit but before actually sent in Air.

Add/Change #417 (Power Save Mode handling and Packet Queuing)