With the -rc4 based wireless tree:
[ 1810.855457] usb 1-1: firmware: requesting zd1211/zd1211b_ub
[ 1810.868857] usb 1-1: firmware: requesting zd1211/zd1211b_uphr
[ 1810.926526] zd1211rw 1-1:1.0: firmware version 4725
[ 1810.966529] zd1211rw 1-1:1.0: zd1211b chip 1582:6003 v4810 high 00-11-f6 AL2230_RF pa0 -----
[ 1810.969518] cfg80211: Calling CRDA for country: DE
[ 1811.970118] zd1211rw 1-1:1.0: error ioread32(CR_REG1): -110
[ 1812.030460] =============================================================================
[ 1812.030467] BUG kmalloc-64: Poison overwritten
[ 1812.030470] -----------------------------------------------------------------------------
[ 1812.030471]
[ 1812.030474] INFO: 0xffff880055000550-0xffff88005500057f. First byte 0x1 instead of 0x6b
[ 1812.030487] INFO: Allocated in zd_usb_enable_int+0xa5/0x180 [zd1211rw] age=114 cpu=0 pid=4209
[ 1812.030496] INFO: Freed in int_urb_complete+0x92/0x1bc [zd1211rw] age=107 cpu=0 pid=4209
[ 1812.030499] INFO: Slab 0xffffe20002288000 objects=30 used=28 fp=0xffff880055000550 flags=0x40000000000000c3
[ 1812.030503] INFO: Object 0xffff880055000550 @offset=1360 fp=0xffff8800550003b8
[ 1812.030504]
[ 1812.030507] Bytes b4 0xffff880055000540: 42 c8 01 00 01 00 00 00 5a 5a 5a 5a 5a 5a 5a 5a B�......ZZZZZZZZ
[ 1812.030529] Object 0xffff880055000550: 01 90 82 96 00 00 80 96 a0 00 00 00 00 00 6b a5 ..............k�
[ 1812.030551] Object 0xffff880055000560: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
[ 1812.030573] Object 0xffff880055000570: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
[ 1812.030594] Object 0xffff880055000580: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b a5 kkkkkkkkkkkkkkk�
[ 1812.030616] Redzone 0xffff880055000590: bb bb bb bb bb bb bb bb ��������
[ 1812.030638] Padding 0xffff8800550005d0: 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZ
[ 1812.030662] Pid: 4, comm: ksoftirqd/0 Not tainted 2.6.29-rc4-wl-13559-g0416c58-dirty #40
[ 1812.030666] Call Trace:
[ 1812.030669] <IRQ> [<ffffffff802d3116>] print_trailer+0x106/0x160
[ 1812.030681] [<ffffffff802d3875>] check_bytes_and_report+0x125/0x180
[ 1812.030685] [<ffffffff802d397c>] check_object+0xac/0x270
[ 1812.030704] [<ffffffffa005d7ae>] ? ohci_urb_enqueue+0xae/0x360 [ohci_hcd]
[ 1812.030709] [<ffffffff802d4595>] alloc_debug_processing+0x105/0x1a0
[ 1812.030714] [<ffffffff802d59d6>] __slab_alloc+0x96/0x2f0
[ 1812.030721] [<ffffffffa005d7ae>] ? ohci_urb_enqueue+0xae/0x360 [ohci_hcd]
[ 1812.030728] [<ffffffffa005d7ae>] ? ohci_urb_enqueue+0xae/0x360 [ohci_hcd]
[ 1812.030732] [<ffffffff802d6a06>] __kmalloc+0x106/0x140
[ 1812.030739] [<ffffffffa005d7ae>] ohci_urb_enqueue+0xae/0x360 [ohci_hcd]
[ 1812.030762] [<ffffffffa0017838>] usb_hcd_submit_urb+0x88/0x1c0 [usbcore]
[ 1812.030779] [<ffffffffa0017dfd>] usb_submit_urb+0x10d/0x340 [usbcore]
[ 1812.030789] [<ffffffffa00934ce>] hid_irq_in+0x9e/0x210 [usbhid]
[ 1812.030806] [<ffffffffa0016050>] usb_hcd_giveback_urb+0x60/0xe0 [usbcore]
[ 1812.030813] [<ffffffffa005ab11>] finish_urb+0xa1/0x110 [ohci_hcd]
[ 1812.030820] [<ffffffffa005ac3b>] takeback_td+0xbb/0x160 [ohci_hcd]
[ 1812.030826] [<ffffffffa005ad93>] dl_done_list+0xb3/0x110 [ohci_hcd]
[ 1812.030833] [<ffffffffa005f470>] ohci_irq+0x2f0/0x3cc [ohci_hcd]
[ 1812.030850] [<ffffffffa0015930>] ? usb_hcd_irq+0x20/0xb0 [usbcore]
[ 1812.030867] [<ffffffffa0015950>] usb_hcd_irq+0x40/0xb0 [usbcore]
[ 1812.030873] [<ffffffff8029166b>] handle_IRQ_event+0x3b/0x80
[ 1812.030877] [<ffffffff802931f1>] handle_fasteoi_irq+0x91/0x110
[ 1812.030883] [<ffffffff8020e43c>] do_IRQ+0x9c/0x150
[ 1812.030887] [<ffffffff8020c6d3>] ret_from_intr+0x0/0xf
[ 1812.030893] [<ffffffff8024ccb0>] ? tasklet_action+0x140/0x160
[ 1812.030898] [<ffffffff8024ccac>] ? tasklet_action+0x13c/0x160
[ 1812.030902] [<ffffffff8024d71d>] ? __do_softirq+0x9d/0x190
[ 1812.030907] [<ffffffff8020cebc>] ? call_softirq+0x1c/0x40
[ 1812.030909] <EOI> [<ffffffff8020e1a5>] ? do_softirq+0x75/0xc0
[ 1812.030916] [<ffffffff8024cd54>] ? ksoftirqd+0x84/0x1b0
[ 1812.030920] [<ffffffff8024ccd0>] ? ksoftirqd+0x0/0x1b0
[ 1812.030924] [<ffffffff8024ccd0>] ? ksoftirqd+0x0/0x1b0
[ 1812.030929] [<ffffffff8025f2e9>] ? kthread+0x49/0x90
[ 1812.030934] [<ffffffff8020cdba>] ? child_rip+0xa/0x20
[ 1812.030938] [<ffffffff8020c780>] ? restore_args+0x0/0x30
[ 1812.030942] [<ffffffff8025f2a0>] ? kthread+0x0/0x90
[ 1812.030946] [<ffffffff8020cdb0>] ? child_rip+0x0/0x20
[ 1812.030949] FIX kmalloc-64: Restoring 0xffff880055000550-0xffff88005500057f=0x6b
[ 1812.030950]
[ 1812.030953] FIX kmalloc-64: Marking all objects used
[ 1812.057052] ADDRCONF(NETDEV_UP): wlan1: link is not ready
[ 1819.141519] wlan1: authenticate with AP 8e:b5:9c:32:62:6e
[ 1819.340080] wlan1: authenticate with AP 8e:b5:9c:32:62:6e
[ 1819.550073] wlan1: authenticate with AP 8e:b5:9c:32:62:6e
[ 1819.750061] wlan1: authentication with AP 8e:b5:9c:32:62:6e timed out
johannes
Hello,
- Can you please elaborate on under which sequence of operations
does this occur ? is it the wireless-testing tree? the reason is:
I am using the latest git wireless-testing (from today; -rc4 based tre=
e).
I can associate to an Access Point without errors; and I tried more tha=
n once.
I had tried both when encryption is off in the Access Point and when
encryption is on in the Access Point.
What I tried first is:
modprobe zd1211rw
ifconfig wlan2 up
iwconfig wlan2 essid homeNet ap 00:1F:1F:25:C6:CA
and I could connect:
In the log, I see:
=46eb 10 15:24:52 localhost kernel: zd1211rw 2-8.2:1.0: firmware versio=
n 4605
=46eb 10 15:24:52 localhost kernel: zd1211rw 2-8.2:1.0: zd1211 chip
0ace:1211 v4810 full 00-0e-2e AL2230_RF pa0 -----
=46eb 10 15:24:52 localhost kernel: cfg80211: Calling CRDA for country:=
DE
=46eb 10 15:25:11 localhost kernel: wlan2: authenticate with AP 00:1f:1=
f:25:c6:ca
=46eb 10 15:25:11 localhost kernel: wlan2: authenticated
=46eb 10 15:25:11 localhost kernel: wlan2: associate with AP 00:1f:1f:2=
5:c6:ca
=46eb 10 15:25:11 localhost kernel: wlan2: RX AssocResp from
00:1f:1f:25:c6:ca (capab=3D0x401 status=3D0 aid=3D1)
=46eb 10 15:25:11 localhost kernel: wlan2: associated
---
When I tried with encryption on in the Access Point I did it with
NetworkManager, and it was OK. Here is what I saw in the kernel log:
=46eb 10 15:39:43 localhost NetworkManager: <info> (wlan2) Supplicant
interface state change: 3 -> 4
=46eb 10 15:39:44 localhost NetworkManager: <info> (wlan2) Supplicant
interface state change: 4 -> 5
=46eb 10 15:39:44 localhost NetworkManager: <info> (wlan2) Supplicant
interface state change: 5 -> 6
=46eb 10 15:39:44 localhost NetworkManager: <info> (wlan2) Supplicant
interface state change: 6 -> 7
=46eb 10 15:39:44 localhost NetworkManager: <info> Activation
(wlan2/wireless) Stage 2 of 5 (Device Configure) successful.
Connected to wireless network 'shapira'.
=46eb 10 15:39:44 localhost NetworkManager: <info> Activation (wlan2)
Stage 3 of 5 (IP Configure Start) scheduled.
=46eb 10 15:39:44 localhost NetworkManager: <info> Activation (wlan2)
Stage 3 of 5 (IP Configure Start) started...
=46eb 10 15:39:44 localhost NetworkManager: <info> Activation (wlan2)
Beginning DHCP transaction.
=46eb 10 15:39:44 localhost dhclient: Internet Systems Consortium DHCP
Client V3.0.6-Fedora
=46eb 10 15:39:44 localhost dhclient: Copyright 2004-2007 Internet
Systems Consortium.
=46eb 10 15:39:44 localhost dhclient: All rights reserved.
=46eb 10 15:39:44 localhost dhclient: For info, please visit
http://www.isc.org/sw/dhcp/
=46eb 10 15:39:44 localhost dhclient:
=46eb 10 15:39:44 localhost NetworkManager: <info> dhclient started wi=
th pid 3522
=46eb 10 15:39:44 localhost NetworkManager: <info> Activation (wlan2)
Stage 3 of 5 (IP Configure Start) complete.
=46eb 10 15:39:44 localhost NetworkManager: <info> DHCP: device wlan2
state changed (null) -> preinit
=46eb 10 15:39:44 localhost dhclient: Listening on LPF/wlan2/00:0e:2e:8=
4:99:4a
=46eb 10 15:39:44 localhost dhclient: Sending on LPF/wlan2/00:0e:2e:8=
4:99:4a
=46eb 10 15:39:44 localhost dhclient: Sending on Socket/fallback
=46eb 10 15:39:44 localhost dhclient: DHCPDISCOVER on wlan2 to
255.255.255.255 port 67 interval 8
=46eb 10 15:39:46 localhost dhclient: DHCPOFFER from 192.168.2.1
=46eb 10 15:39:46 localhost dhclient: DHCPREQUEST on wlan2 to
255.255.255.255 port 67
=46eb 10 15:39:54 localhost dhclient: DHCPREQUEST on wlan2 to
255.255.255.255 port 67
=46eb 10 15:39:54 localhost dhclient: DHCPACK from 192.168.2.1
=46eb 10 15:39:54 localhost NetworkManager: <info> DHCP: device wlan2
state changed preinit -> bound
=46eb 10 15:39:54 localhost NetworkManager: <info> Activation (wlan2)
Stage 4 of 5 (IP Configure Get) scheduled...
=46eb 10 15:39:54 localhost NetworkManager: <info> Activation (wlan2)
Stage 4 of 5 (IP Configure Get) started...
=46eb 10 15:39:54 localhost NetworkManager: <info> address 192.168.2=
=2E101
=46eb 10 15:39:54 localhost NetworkManager: <info> netmask 255.255.2=
55.0
=46eb 10 15:39:54 localhost NetworkManager: <info> broadcast 192.168=
=2E2.255
=46eb 10 15:39:54 localhost NetworkManager: <info> gateway 192.168.2=
=2E1
=46eb 10 15:39:54 localhost NetworkManager: <info> nameserver '192.1=
68.2.1'
=46eb 10 15:39:54 localhost NetworkManager: <info> Activation (wlan2)
Stage 5 of 5 (IP Configure Commit) scheduled...
=46eb 10 15:39:54 localhost NetworkManager: <info> Activation (wlan2)
Stage 4 of 5 (IP Configure Get) complete.
=46eb 10 15:39:54 localhost NetworkManager: <info> Activation (wlan2)
Stage 5 of 5 (IP Configure Commit) started...
=46eb 10 15:39:54 localhost dhclient: bound to 192.168.2.101 -- renewal
in 387238970 seconds.
=46eb 10 15:39:55 localhost NetworkManager: <info> Activation (wlan2)
successful, device activated.
=46eb 10 15:39:55 localhost NetworkManager: <info> Activation (wlan2)
Stage 5 of 5 (IP Configure Commit) complete.
Note 1: my zd1211rw is build when CONFIG_ZD1211RW_DEBUG is not set.
Note2 (chipset): lsusb gives:
Bus 002 Device 073: ID 0ace:1211 ZyDAS 802.11b/g USB2 WiFi
Regards,
MarkR
On Tue, Feb 10, 2009 at 12:36 PM, Johannes Berg
<[email protected]> wrote:
> With the -rc4 based wireless tree:
>
> [ 1810.855457] usb 1-1: firmware: requesting zd1211/zd1211b_ub
> [ 1810.868857] usb 1-1: firmware: requesting zd1211/zd1211b_uphr
> [ 1810.926526] zd1211rw 1-1:1.0: firmware version 4725
> [ 1810.966529] zd1211rw 1-1:1.0: zd1211b chip 1582:6003 v4810 high 00=
-11-f6 AL2230_RF pa0 -----
> [ 1810.969518] cfg80211: Calling CRDA for country: DE
> [ 1811.970118] zd1211rw 1-1:1.0: error ioread32(CR_REG1): -110
> [ 1812.030460] =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
> [ 1812.030467] BUG kmalloc-64: Poison overwritten
> [ 1812.030470] ------------------------------------------------------=
-----------------------
> [ 1812.030471]
> [ 1812.030474] INFO: 0xffff880055000550-0xffff88005500057f. First byt=
e 0x1 instead of 0x6b
> [ 1812.030487] INFO: Allocated in zd_usb_enable_int+0xa5/0x180 [zd121=
1rw] age=3D114 cpu=3D0 pid=3D4209
> [ 1812.030496] INFO: Freed in int_urb_complete+0x92/0x1bc [zd1211rw] =
age=3D107 cpu=3D0 pid=3D4209
> [ 1812.030499] INFO: Slab 0xffffe20002288000 objects=3D30 used=3D28 f=
p=3D0xffff880055000550 flags=3D0x40000000000000c3
> [ 1812.030503] INFO: Object 0xffff880055000550 @offset=3D1360 fp=3D0x=
ffff8800550003b8
> [ 1812.030504]
> [ 1812.030507] Bytes b4 0xffff880055000540: 42 c8 01 00 01 00 00 00 =
5a 5a 5a 5a 5a 5a 5a 5a B=EF=BF=BD......ZZZZZZZZ
> [ 1812.030529] Object 0xffff880055000550: 01 90 82 96 00 00 80 96 =
a0 00 00 00 00 00 6b a5 ..............k=EF=BF=BD
> [ 1812.030551] Object 0xffff880055000560: 00 00 00 00 00 00 00 00 =
00 00 00 00 00 00 00 00 ................
> [ 1812.030573] Object 0xffff880055000570: 00 00 00 00 00 00 00 00 =
00 00 00 00 00 00 00 00 ................
> [ 1812.030594] Object 0xffff880055000580: 6b 6b 6b 6b 6b 6b 6b 6b =
6b 6b 6b 6b 6b 6b 6b a5 kkkkkkkkkkkkkkk=EF=BF=BD
> [ 1812.030616] Redzone 0xffff880055000590: bb bb bb bb bb bb bb bb =
=EF=BF=BD=EF=BF=BD=EF=BF=BD=EF=BF=BD=EF=BF=BD=EF=
=BF=BD=EF=BF=BD=EF=BF=BD
> [ 1812.030638] Padding 0xffff8800550005d0: 5a 5a 5a 5a 5a 5a 5a 5a =
ZZZZZZZZ
> [ 1812.030662] Pid: 4, comm: ksoftirqd/0 Not tainted 2.6.29-rc4-wl-13=
559-g0416c58-dirty #40
> [ 1812.030666] Call Trace:
> [ 1812.030669] <IRQ> [<ffffffff802d3116>] print_trailer+0x106/0x160
> [ 1812.030681] [<ffffffff802d3875>] check_bytes_and_report+0x125/0x1=
80
> [ 1812.030685] [<ffffffff802d397c>] check_object+0xac/0x270
> [ 1812.030704] [<ffffffffa005d7ae>] ? ohci_urb_enqueue+0xae/0x360 [o=
hci_hcd]
> [ 1812.030709] [<ffffffff802d4595>] alloc_debug_processing+0x105/0x1=
a0
> [ 1812.030714] [<ffffffff802d59d6>] __slab_alloc+0x96/0x2f0
> [ 1812.030721] [<ffffffffa005d7ae>] ? ohci_urb_enqueue+0xae/0x360 [o=
hci_hcd]
> [ 1812.030728] [<ffffffffa005d7ae>] ? ohci_urb_enqueue+0xae/0x360 [o=
hci_hcd]
> [ 1812.030732] [<ffffffff802d6a06>] __kmalloc+0x106/0x140
> [ 1812.030739] [<ffffffffa005d7ae>] ohci_urb_enqueue+0xae/0x360 [ohc=
i_hcd]
> [ 1812.030762] [<ffffffffa0017838>] usb_hcd_submit_urb+0x88/0x1c0 [u=
sbcore]
> [ 1812.030779] [<ffffffffa0017dfd>] usb_submit_urb+0x10d/0x340 [usbc=
ore]
> [ 1812.030789] [<ffffffffa00934ce>] hid_irq_in+0x9e/0x210 [usbhid]
> [ 1812.030806] [<ffffffffa0016050>] usb_hcd_giveback_urb+0x60/0xe0 [=
usbcore]
> [ 1812.030813] [<ffffffffa005ab11>] finish_urb+0xa1/0x110 [ohci_hcd]
> [ 1812.030820] [<ffffffffa005ac3b>] takeback_td+0xbb/0x160 [ohci_hcd=
]
> [ 1812.030826] [<ffffffffa005ad93>] dl_done_list+0xb3/0x110 [ohci_hc=
d]
> [ 1812.030833] [<ffffffffa005f470>] ohci_irq+0x2f0/0x3cc [ohci_hcd]
> [ 1812.030850] [<ffffffffa0015930>] ? usb_hcd_irq+0x20/0xb0 [usbcore=
]
> [ 1812.030867] [<ffffffffa0015950>] usb_hcd_irq+0x40/0xb0 [usbcore]
> [ 1812.030873] [<ffffffff8029166b>] handle_IRQ_event+0x3b/0x80
> [ 1812.030877] [<ffffffff802931f1>] handle_fasteoi_irq+0x91/0x110
> [ 1812.030883] [<ffffffff8020e43c>] do_IRQ+0x9c/0x150
> [ 1812.030887] [<ffffffff8020c6d3>] ret_from_intr+0x0/0xf
> [ 1812.030893] [<ffffffff8024ccb0>] ? tasklet_action+0x140/0x160
> [ 1812.030898] [<ffffffff8024ccac>] ? tasklet_action+0x13c/0x160
> [ 1812.030902] [<ffffffff8024d71d>] ? __do_softirq+0x9d/0x190
> [ 1812.030907] [<ffffffff8020cebc>] ? call_softirq+0x1c/0x40
> [ 1812.030909] <EOI> [<ffffffff8020e1a5>] ? do_softirq+0x75/0xc0
> [ 1812.030916] [<ffffffff8024cd54>] ? ksoftirqd+0x84/0x1b0
> [ 1812.030920] [<ffffffff8024ccd0>] ? ksoftirqd+0x0/0x1b0
> [ 1812.030924] [<ffffffff8024ccd0>] ? ksoftirqd+0x0/0x1b0
> [ 1812.030929] [<ffffffff8025f2e9>] ? kthread+0x49/0x90
> [ 1812.030934] [<ffffffff8020cdba>] ? child_rip+0xa/0x20
> [ 1812.030938] [<ffffffff8020c780>] ? restore_args+0x0/0x30
> [ 1812.030942] [<ffffffff8025f2a0>] ? kthread+0x0/0x90
> [ 1812.030946] [<ffffffff8020cdb0>] ? child_rip+0x0/0x20
> [ 1812.030949] FIX kmalloc-64: Restoring 0xffff880055000550-0xffff880=
05500057f=3D0x6b
> [ 1812.030950]
> [ 1812.030953] FIX kmalloc-64: Marking all objects used
> [ 1812.057052] ADDRCONF(NETDEV_UP): wlan1: link is not ready
> [ 1819.141519] wlan1: authenticate with AP 8e:b5:9c:32:62:6e
> [ 1819.340080] wlan1: authenticate with AP 8e:b5:9c:32:62:6e
> [ 1819.550073] wlan1: authenticate with AP 8e:b5:9c:32:62:6e
> [ 1819.750061] wlan1: authentication with AP 8e:b5:9c:32:62:6e timed =
out
>
> johannes
>
On Tue, 2009-02-10 at 15:45 +0200, Mark Ryden wrote:
> Hello,
> - Can you please elaborate on under which sequence of operations
> does this occur ? is it the wireless-testing tree? the reason is:
> I am using the latest git wireless-testing (from today; -rc4 based tree).
> I can associate to an Access Point without errors; and I tried more than once.
>
> I had tried both when encryption is off in the Access Point and when
> encryption is on in the Access Point.
Odd; I think I might blame it on my hardware. I booted into an older
kernel and it failed similary, though it works just fine with my
unencrypted AP.
> > [ 1819.141519] wlan1: authenticate with AP 8e:b5:9c:32:62:6e
> > [ 1819.340080] wlan1: authenticate with AP 8e:b5:9c:32:62:6e
> > [ 1819.550073] wlan1: authenticate with AP 8e:b5:9c:32:62:6e
> > [ 1819.750061] wlan1: authentication with AP 8e:b5:9c:32:62:6e timed out
Did I mention that address is completely bogus?
johannes