problem with libertas driver, Marvell W8686, and PXA270 on 2.6.27-rc7
Jeff Sutherland
jeffs at fomsystems.com
Mon Oct 6 11:38:46 EDT 2008
On Thursday 02 October 2008, Jeff Sutherland wrote:
> On Thursday 02 October 2008, Dan Williams wrote:
> > On Thu, 2008-10-02 at 10:17 -0400, Jeff Sutherland wrote:
> > > I'm seeking some insight into the structure of the command flow when
> > > communicating with a Murata wifi module using the W8686 chip connected
> > > via SDIO on a PXA270-based system. On about 2 out of 3 boot ups, and
> > > occasionally when configuring the network interface by hand after the
> > > system is up and running, the kernel will oops from the BUG()
> > > instruction at line 147 of drivers/net/wireless/libertas/if_sdio.c.
> > > When this happens, the value of priv->resp_len[resp_idx] is always
> > > sitting at 142. It's almost as if the command processing in
> > > drivers/net/wireless/libertas/main.c is missing a command somehow.
> > > Curiously, this only seems to happen when the interface is
> >
> > Hmm, could well be. The flow is supposed to be that the interface code
> > puts responses into the unused slot and wakes up the main thread, and
> > the main thread processes the response. Could be that if a second
> > command response comes back from the card too soon the main thread
> > wouldn't be woken up to process it yet.
> >
> > Everything I've seen and read indicates that commands are serialized and
> > thus we can only have one command outstanding at any one time. Thus we
> > can probably rule out fundamental problems with the implementation, but
> > instead focus on bugs and/or quirks.
> >
> > Could you by any chance minimally parse the command response in
> > if_sdio_handle_cmd() with something like:
> >
> > diff --git a/drivers/net/wireless/libertas/if_sdio.c
> > b/drivers/net/wireless/libertas/if_sdio.c index b54e2ea..024a81e 100644
> > --- a/drivers/net/wireless/libertas/if_sdio.c
> > +++ b/drivers/net/wireless/libertas/if_sdio.c
> > @@ -144,6 +144,18 @@ static int if_sdio_handle_cmd(struct if_sdio_card
> > *card, spin_lock_irqsave(&priv->driver_lock, flags);
> >
> > i = (priv->resp_idx == 0) ? 1 : 0;
> > +
> > +if (priv->resp_len[i])
> > +{
> > +struct cmd_header *resp = (void *) buffer;
> > +uint16_t respcmd = le16_to_cpu(resp->command);
> > +uint16_t result = le16_to_cpu(resp->result);
> > +uint16_t seqnum = le16_to_cpu(resp->seqnum);
> > +
> > +lbs_deb_sdio("CMD_RESP: response 0x%04x, result 0x%04x, seq %d, size
> > %d\n", + respcmd, result, seqnum, size);
> > +}
> > +
> > BUG_ON(priv->resp_len[i]);
> > priv->resp_len[i] = size;
> > memcpy(priv->resp_buf[i], buffer, size);
> >
> > that coupled with turning on LBS_DEB_CMD and LBS_DEB_SDIO would be quite
> > interesting to see the results of and should help narrow down what's
> > going on. I'm especially interested in the sequence number to see if if
> > the before-BUG_ON response is the same sequence # as the BUG_ON
> > response.
> >
> > Dan
>
> Well I've had a bit of luck here. The driver will not BUG() with
> LBS_DEB_CMD and LBS_DEB_SDIO enabled at the same time, but WILL bug pretty
> regularly if these are enabled singly in turn. The transcript is getting
> pretty long so please see attached log file.
Continuing to pursue this (Thanks Dan for that code snippet), I've made the
following observations. With libertas_debug=0x404000 the system will boot
and the wifi module will associate and acquire an ip address using WEP
encryption just fine every single time. However, with libertas_debug=0x4000
most of the time it will not boot. But what's really interesting here is the
command sequence to the radio module changes depending on what debug levels
are set. I think that's the real problem, since it appears that a command
0x0016 (CMD_802_11_SNMP_MIB) following a command 0x0050
(CMD_802_11_ASSOCIATE) must cockup the firmware in the radio module. In the
normal startup a command 0x001f (CMD_802_11_RSSI) follows command 0x0050 and
everything appears to work fine. Note how command 0x0016 will time out, but
that the driver (provided the kernel doesn't oops) will recover and continue
with module initialization. How is it that command execution order gets
shuffled depending on the setting of debug levels? That seems to be the real
problem here. If the data in columns below gets munged by the mailers, see
attached file for the same thing in (hopefully) readable form. Data is
[sequence number]:[abbreviated hex command code].
Command sequences on system startup:
libertas_debug= libertas_debug= libertas_debug=0x4000
0x00404000 0x4000
Good startup: Oops occured: Timeouts but no oops:
7:10 7:10 7:10
8:28 8:28 8:28
9:1e 9:1e 9:1e
10:13 10:16 10:16
11:28 11:16 11:16
12:28 12:13 12:13
13:2F 13:16 13:16
14:16 14:28 14:28
15:06 15:28 15:28
16:16 16:2f 16:2f
17:06 17:06 17:06
18:16 18:06 18:06
19:06 19:06 19:06
20:11 20:1e 20:1e
21:1C 21:11 21:11
22:50 (resp: 8012) 22:16 22:16
23:1F 23:1C 23:1C
24:0B 24:16 24:16
25:1F 25:50 (resp:8012) 25:50 (resp:8012)
26:1E 26:16 (cmd timed out) 26:16 (cmd timed out)
27:16 (makes 3 attempts at seq. 26, (makes 3 attempts at seq. 26,
28:16 then error -110, cmd failed) then PREP_CMD: cmd 0016 failed
29:16 27:1F (resp:8016, len 142) 27:1F (resp 8016, seq 26,size142)
30:10 Received CMD_RESP with invalid Received CMD_RESP with invalid
Sending sequence 26 (expected 27) sequence 26 (expected 27)
discover BUG() then Received response 801f, seq 27
28:0b
29:1F
30:1e
31:16
32:16
33:16
34:10
Sending discover
--
FOM Systems Inc. www.fomsystems.com
phone: (USA) +1-330-628-2102 or 800-936-0561, (UK) +44-161-408-3072
mobile: (USA) +1-330-802-1364, (World) +44-7793-827386, Skype: Adekguru
=+=+=+=+=+=+=+=+=+=+=+=+=+=
And He saith unto them, "Follow me, and I will make you fishers of men."
(Matthew 4:19)
-------------- next part --------------
libertas_debug= libertas_debug= libertas_debug=0x4000
0x00404000 0x4000
Good startup: Oops occured: Timeouts but no oops:
7:10 7:10 7:10
8:28 8:28 8:28
9:1e 9:1e 9:1e
10:13 10:16 10:16
11:28 11:16 11:16
12:28 12:13 12:13
13:2F 13:16 13:16
14:16 14:28 14:28
15:06 15:28 15:28
16:16 16:2f 16:2f
17:06 17:06 17:06
18:16 18:06 18:06
19:06 19:06 19:06
20:11 20:1e 20:1e
21:1C 21:11 21:11
22:50 (resp: 8012) 22:16 22:16
23:1F 23:1C 23:1C
24:0B 24:16 24:16
25:1F 25:50 (resp:8012) 25:50 (resp:8012)
26:1E 26:16 (cmd timed out) 26:16 (cmd timed out)
27:16 (makes 3 attempts at seq. 26, (makes 3 attempts at seq. 26,
28:16 then error -110, cmd failed) then PREP_CMD: cmd 0016 failed
29:16 27:1F (resp:8016, len 142) 27:1F (resp 8016, seq 26, size 142)
30:10 Received CMD_RESP with invalid Received CMD_RESP with invalid
Sending sequence 26 (expected 27) sequence 26 (expected 27)
discover BUG() then Received response 801f, seq 27
28:0b
29:1F
30:1e
31:16
32:16
33:16
34:10
Sending discover
-------------- next part --------------
libertas_sdio: Libertas SDIO driver
libertas_sdio: Copyright Pierre Ossman
firmware: requesting sd8686_helper.bin
PM: Adding info for No Bus:mmc0:0001:1
PM: Removing info for No Bus:mmc0:0001:1
firmware: requesting sd8686.bin
PM: Adding info for No Bus:mmc0:0001:1
PM: Removing info for No Bus:mmc0:0001:1
libertas cmd: DNLD_CMD: command 0x0003, seq 1, size 46
libertas cmd: CMD_RESP: response 0x8003, seq 1, size 46
libertas: 00:13:e0:ab:6e:a7, fw 9.70.3p30, cap 0x00000303
libertas cmd: GET_HW_SPEC: hardware interface 0x2, hardware spec 0x0011
libertas: unidentified region code; using the default (USA)
libertas cmd: DNLD_CMD: command 0x001e, seq 2, size 14
libertas cmd: CMD_RESP: response 0x801e, seq 2, size 14
PM: Adding info for No Bus:eth0
libertas cmd: DNLD_CMD: command 0x0028, seq 3, size 12
libertas cmd: CMD_RESP: response 0x8028, seq 3, size 12
libertas cmd: DNLD_CMD: command 0x001d, seq 4, size 48
libertas cmd: CMD_RESP: response 0x801d, seq 4, size 48
libertas cmd: current radio channel is 1
libertas cmd: mesh config action 1 type 223 channel 1 SSID mesh
libertas cmd: DNLD_CMD: command 0x00a3, seq 5, size 144
libertas cmd: CMD_RESP: response 0x80a3, seq 5, size 144
libertas: PREP_CMD: command 0x00a3 failed: 2
libertas cmd: mesh config action 1 type 125 channel 1 SSID mesh
libertas cmd: DNLD_CMD: command 0x00a3, seq 6, size 144
libertas cmd: CMD_RESP: response 0x80a3, seq 6, size 144
libertas: PREP_CMD: command 0x00a3 failed: 2
libertas: eth0: Marvell WLAN 802.11 adapter
PM: Adding info for No Bus:timer
ASoC version 0.13.2
PM: Adding info for platform:soc-audio
WM9713/WM9714 SoC Audio Codec 0.15
asoc: AC97 HiFi <-> pxa2xx-ac97 mapping ok
asoc: AC97 Aux <-> pxa2xx-ac97-aux mapping ok
pxa2xx_ac97_cold_reset: cold reset timeout (GSR=0x0)
pxa2xx_ac97_read: read error (ac97_reg=0 GSR=0x44)
dapm: WM9713: configuring unknown pin RXP
dapm: WM9713: configuring unknown pin RXN
PM: Adding info for No Bus:pcmC0D1p
PM: Adding info for No Bus:pcmC0D0p
PM: Adding info for No Bus:pcmC0D0c
PM: Adding info for No Bus:controlC0
PM: Adding info for ac97:0-0:WM9713
Setting up IP spoofing protection: rp_filter.
Configuring network interfaces... libertas cmd: DNLD_CMD: command 0x0010, seq
7, size 18
libertas cmd: CMD_RESP: response 0x8010, seq 7, size 18
libertas cmd: DNLD_CMD: command 0x0028, seq 8, size 12
libertas cmd: CMD_RESP: response 0x8028, seq 8, size 12
libertas cmd: DNLD_CMD: command 0x001e, seq 9, size 14
libertas cmd: CMD_RESP: response 0x801e, seq 9, size 14
libertas cmd: DNLD_CMD: command 0x0016, seq 10, size 142
libertas cmd: CMD_RESP: response 0x8016, seq 10, size 142
libertas cmd: DNLD_CMD: command 0x0016, seq 11, size 142
libertas cmd: CMD_RESP: response 0x8016, seq 11, size 142
libertas cmd: SET_WEP: add key 0 (104 bit)
libertas cmd: DNLD_CMD: command 0x0013, seq 12, size 80
libertas cmd: CMD_RESP: response 0x8013, seq 12, size 80
libertas cmd: DNLD_CMD: command 0x0016, seq 13, size 142
libertas cmd: CMD_RESP: response 0x8016, seq 13, size 142
libertas cmd: DNLD_CMD: command 0x0028, seq 14, size 12
libertas cmd: CMD_RESP: response 0x8028, seq 14, size 12
libertas cmd: DNLD_CMD: command 0x0028, seq 15, size 12
libertas cmd: CMD_RESP: response 0x8028, seq 15, size 12
libertas cmd: DNLD_CMD: command 0x002f, seq 16, size 12
libertas cmd: CMD_RESP: response 0x802f, seq 16, size 12
libertas cmd: DNLD_CMD: command 0x0006, seq 17, size 75
libertas cmd: CMD_RESP: response 0x8006, seq 17, size 11
libertas cmd: DNLD_CMD: command 0x0006, seq 18, size 75
libertas cmd: CMD_RESP: response 0x8006, seq 18, size 11
libertas cmd: DNLD_CMD: command 0x0006, seq 19, size 68
libertas cmd: CMD_RESP: response 0x8006, seq 19, size 90
libertas cmd: DNLD_CMD: command 0x001e, seq 20, size 14
libertas cmd: CMD_RESP: response 0x801e, seq 20, size 14
libertas cmd: DNLD_CMD: command 0x0011, seq 21, size 25
libertas cmd: CMD_RESP: response 0x8011, seq 21, size 25
libertas cmd: DNLD_CMD: command 0x0016, seq 22, size 142
libertas cmd: RADIO_CONTROL: radio ON, preamble 0
libertas cmd: CMD_RESP: response 0x8016, seq 22, size 142
libertas cmd: DNLD_CMD: command 0x001c, seq 23, size 12
libertas cmd: CMD_RESP: response 0x801c, seq 23, size 12
libertas cmd: DNLD_CMD: command 0x0016, seq 24, size 142
libertas cmd: CMD_RESP: response 0x8016, seq 24, size 142
libertas cmd: DNLD_CMD: command 0x0050, seq 25, size 64
libertas cmd: CMD_RESP: response 0x8012, seq 25, size 41
libertas cmd: DNLD_CMD: command 0x0016, seq 26, size 142
libertas: command 0x0016 timed out
libertas: requeueing command 0x0016 due to timeout (#1)
libertas cmd: DNLD_CMD: command 0x0016, seq 26, size 142
libertas: command 0x0016 timed out
libertas: requeueing command 0x0016 due to timeout (#2)
libertas cmd: DNLD_CMD: command 0x0016, seq 26, size 142
libertas: command 0x0016 timed out
libertas: requeueing command 0x0016 due to timeout (#3)
libertas cmd: DNLD_CMD: command 0x0016, seq 26, size 142
libertas: command 0x0016 timed out
libertas: Excessive timeouts submitting command 0x0016
libertas: PREP_CMD: command 0x0016 failed: -110
libertas cmd: DNLD_CMD: command 0x001f, seq 27, size 16
libertas cmd: CMD_RESP: response 0x8016, seq 26, size 142
libertas: Received CMD_RESP with invalid sequence 26 (expected 27)
libertas cmd: CMD_RESP: response 0x801f, seq 27, size 16
libertas cmd: RSSI: beacon 226, avg 0
libertas cmd: DNLD_CMD: command 0x000b, seq 28, size 60
libertas cmd: CMD_RESP: response 0x800b, seq 28, size 60
libertas cmd: DNLD_CMD: command 0x001f, seq 29, size 16
libertas cmd: CMD_RESP: response 0x801f, seq 29, size 16
libertas cmd: RSSI: beacon 220, avg 0
libertas cmd: DNLD_CMD: command 0x001e, seq 30, size 14
libertas cmd: CMD_RESP: response 0x801e, seq 30, size 14
libertas cmd: DNLD_CMD: command 0x0016, seq 31, size 142
libertas cmd: CMD_RESP: response 0x8016, seq 31, size 142
libertas cmd: DNLD_CMD: command 0x0016, seq 32, size 142
libertas cmd: CMD_RESP: response 0x8016, seq 32, size 142
libertas cmd: DNLD_CMD: command 0x0016, seq 33, size 142
libertas cmd: CMD_RESP: response 0x8016, seq 33, size 142
udhcpc (v1.2.1) started
udhcpc[1502]: udhcpc (v1.2.1) started
run-parts: /etc/udhcpc.d/00avahi-autoipd exited with return code 1: Success
libertas cmd: DNLD_CMD: command 0x0010, seq 34, size 18
libertas cmd: CMD_RESP: response 0x8010, seq 34, size 18
Sending discover...
udhcpc[1502]: Sending discover...
Sending select for 192.168.13.49...
udhcpc[1502]: Sending select for 192.168.13.49...
Lease of 192.168.13.49 obtained, lease time 999999
udhcpc[1502]: Lease of 192.168.13.49 obtained, lease time 999999
run-parts: /etc/udhcpc.d/00avahi-autoipd exited with return code 1: Success
libertas cmd: DNLD_CMD: command 0x0010, seq 35, size 18
libertas cmd: CMD_RESP: response 0x8010, seq 35, size 18
libertas cmd: DNLD_CMD: command 0x0010, seq 36, size 18
libertas cmd: CMD_RESP: response 0x8010, seq 36, size 18
adding dns 192.168.13.200
adding dns 192.168.13.1
done.
Starting portmap daemon: portmap.
Fri Oct 3 02:11:00 UTC 2008
Nothing to be done
INIT: Entering runlevel: 5
ALSA: Restoring mixer settings...
Starting Dropbear SSH server: dropbear.
Starting system message bus: dbus.
Starting syslogd/klogd: done
* Starting Avahi mDNS/DNS-SD Daemon: avahi-daemon
libertas cmd: DNLD_CMD: command 0x0010, seq 37, size 24
libertas cmd: CMD_RESP: response 0x8010, seq 37, size 24
[ ok ]
PM: Adding info for No Bus:vcs1
PM: Adding info for No Bus:vcsa1
More information about the libertas-dev
mailing list