problem with libertas driver, Marvell W8686, and PXA270 on 2.6.27-rc7

Thu Oct 2 21:56:30 EDT 2008

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, as luck would have it, instrumenting the code has fixed the problem.  I 
can not get to fail anymore.  Not once, no way.  See the transcript below.  
Before, when things went bad it was always somewhere around sequence number 
25 or 26.  I'll try fiddling with the debug level to see if I can get it to 
fail whilst also producing something that might be informative.

Thanks!
-Jeff

Setting up IP spoofing protection: rp_filter.
Configuring network interfaces...
libertas cmd: DNLD_CMD: command 0x0010, seq 7, size 18
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 22 bytes
libertas cmd: CMD_RESP: response 0x8010, seq 7, size 18
libertas cmd: DNLD_CMD: command 0x0028, seq 8, size 12
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 16 bytes
libertas cmd: CMD_RESP: response 0x8028, seq 8, size 12
libertas cmd: DNLD_CMD: command 0x001e, seq 9, size 14
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 18 bytes
libertas cmd: CMD_RESP: response 0x801e, seq 9, size 14
libertas cmd: SET_WEP: add key 0 (104 bit)
libertas cmd: DNLD_CMD: command 0x0013, seq 10, size 80
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 84 bytes
libertas cmd: CMD_RESP: response 0x8013, seq 10, size 80
libertas cmd: DNLD_CMD: command 0x0028, seq 11, size 12
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 16 bytes
libertas cmd: CMD_RESP: response 0x8028, seq 11, size 12
libertas cmd: DNLD_CMD: command 0x0028, seq 12, size 12
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 16 bytes
libertas cmd: CMD_RESP: response 0x8028, seq 12, size 12
libertas cmd: DNLD_CMD: command 0x002f, seq 13, size 12
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 16 bytes
libertas cmd: CMD_RESP: response 0x802f, seq 13, size 12
libertas cmd: DNLD_CMD: command 0x0016, seq 14, size 142
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 146 bytes
libertas cmd: CMD_RESP: response 0x8016, seq 14, size 142
libertas cmd: DNLD_CMD: command 0x0006, seq 15, size 75
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 15 bytes
libertas cmd: CMD_RESP: response 0x8006, seq 15, size 11
libertas cmd: DNLD_CMD: command 0x0016, seq 16, size 142
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 146 bytes
libertas cmd: CMD_RESP: response 0x8016, seq 16, size 142
libertas cmd: DNLD_CMD: command 0x0006, seq 17, size 75
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 15 bytes
libertas cmd: CMD_RESP: response 0x8006, seq 17, size 11
libertas cmd: DNLD_CMD: command 0x0016, seq 18, size 142
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 146 bytes
libertas cmd: CMD_RESP: response 0x8016, seq 18, size 142
libertas cmd: DNLD_CMD: command 0x0006, seq 19, size 68
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 94 bytes
libertas cmd: CMD_RESP: response 0x8006, seq 19, size 90
libertas cmd: DNLD_CMD: command 0x0011, seq 20, size 25
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 29 bytes
libertas cmd: CMD_RESP: response 0x8011, seq 20, size 25
libertas cmd: RADIO_CONTROL: radio ON, preamble 0
libertas cmd: DNLD_CMD: command 0x001c, seq 21, size 12
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 16 bytes
libertas cmd: CMD_RESP: response 0x801c, seq 21, size 12
libertas cmd: DNLD_CMD: command 0x0050, seq 22, size 64
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 45 bytes
libertas cmd: CMD_RESP: response 0x8012, seq 22, size 41
libertas cmd: DNLD_CMD: command 0x001f, seq 23, size 16
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 20 bytes
libertas cmd: CMD_RESP: response 0x801f, seq 23, size 16
libertas cmd: RSSI: beacon 217, avg 0
libertas cmd: DNLD_CMD: command 0x000b, seq 24, size 60
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 64 bytes
libertas cmd: CMD_RESP: response 0x800b, seq 24, size 60
libertas cmd: DNLD_CMD: command 0x001f, seq 25, size 16
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 20 bytes
libertas cmd: CMD_RESP: response 0x801f, seq 25, size 16
libertas cmd: RSSI: beacon 218, avg 0
libertas cmd: DNLD_CMD: command 0x001e, seq 26, size 14
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 18 bytes
libertas cmd: CMD_RESP: response 0x801e, seq 26, size 14
libertas cmd: DNLD_CMD: command 0x0016, seq 27, size 142
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 146 bytes
libertas cmd: CMD_RESP: response 0x8016, seq 27, size 142
libertas cmd: DNLD_CMD: command 0x0016, seq 28, size 142
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 146 bytes
libertas cmd: CMD_RESP: response 0x8016, seq 28, size 142
libertas cmd: DNLD_CMD: command 0x0016, seq 29, size 142
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 146 bytes
libertas cmd: CMD_RESP: response 0x8016, seq 29, 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 30, size 18
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 22 bytes
libertas cmd: CMD_RESP: response 0x8010, seq 30, size 18
Sending discover...
udhcpc[1502]: Sending discover...
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 0 and size 92 bytes
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 0 and size 390 bytes
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 0 and size 92 bytes
Sending select for 192.168.13.49...
udhcpc[1502]: Sending select for 192.168.13.49...
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 0 and size 92 bytes
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 0 and size 390 bytes
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 31, size 18
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 22 bytes
libertas cmd: CMD_RESP: response 0x8010, seq 31, size 18
libertas cmd: DNLD_CMD: command 0x0010, seq 32, size 18
libertas sdio: interrupt: 0x2
libertas sdio: interrupt: 0x1
libertas sdio: packet of type 1 and size 22 bytes
libertas cmd: CMD_RESP: response 0x8010, seq 32, size 18
adding dns 192.168.13.200
adding dns 192.168.13.1
done.
Starting portmap daemon: portmap.

-- 
FOM Systems Inc.   www.fomsystems.com