Re: [PATCH 2/2] Bluetooth: hci_qca: wcn3990: Drop baudrate change vendor event

From: Balakrishna Godavarthi
Date: Wed Apr 03 2019 - 02:23:31 EST

+ Harish to update his findings on wcn3998.
Mean time i will perform a regression to detect the failure.

On 2019-04-02 23:35, Matthias Kaehlcke wrote:
On Tue, Apr 02, 2019 at 05:32:54PM +0530, Balakrishna Godavarthi wrote:
Hi Matthias,

On 2019-04-01 22:42, Matthias Kaehlcke wrote:
> On Mon, Apr 01, 2019 at 01:48:23PM +0530, Balakrishna Godavarthi wrote:
> > Hi Matthias,
> >
> > On 2019-04-01 13:29, Balakrishna Godavarthi wrote:
> > > Hi Matthias,
> > >
> > > Sorry for the late reply i was on vacation.
> > >
> > > On 2019-03-08 05:00, Matthias Kaehlcke wrote:
> > > > On Thu, Mar 07, 2019 at 10:20:09AM -0800, Matthias Kaehlcke wrote:
> > > > > Hi Balakrishna,
> > > > >
> > > > > On Thu, Mar 07, 2019 at 10:35:08AM +0530, Balakrishna Godavarthi
> > > > > wrote:
> > > > > > hi Matthias,
> > > > > >
> > > > > > On 2019-03-07 06:10, Matthias Kaehlcke wrote:
> > > > > > > Firmware download to the WCN3990 often fails with a 'TLV response size
> > > > > > > mismatch' error:
> > > > > > >
> > > > > > > [ 133.064659] Bluetooth: hci0: setting up wcn3990
> > > > > > > [ 133.489150] Bluetooth: hci0: QCA controller version 0x02140201
> > > > > > > [ 133.495245] Bluetooth: hci0: QCA Downloading qca/crbtfw21.tlv
> > > > > > > [ 133.507214] Bluetooth: hci0: QCA TLV response size mismatch
> > > > > > > [ 133.513265] Bluetooth: hci0: QCA Failed to download patch (-84)
> > > > > > >
> > > > > > > This is caused by a vendor event that corresponds to an earlier command
> > > > > > > to change the baudrate. The event is not processed in the context of the
> > > > > > > baudrate change and later interpreted as response to the firmware
> > > > > > > download command (which is also a vendor command), but the driver
> > > > > > > detects
> > > > > > > that the event doesn't have the expected amount of associated data.
> > > > > > >
> > > > > > > More details:
> > > > > > >
> > > > > > > For the WCN3990 the vendor command for a baudrate change isn't sent as
> > > > > > > synchronous HCI command, because the controller sends the corresponding
> > > > > > > vendor event with the new baudrate. The event is received and decoded
> > > > > > > after the baudrate change of the host port.
> > > > > > >
> > > > > > > Identify the 'unused' event when it is received and don't add it to
> > > > > > > the queue of RX frames.
> > > > > > >
> > > > > > > Signed-off-by: Matthias Kaehlcke <mka@xxxxxxxxxxxx>
> > > > > > > ---
> > > > > >
> > > > > > ...
> > > > > >
> > > > > > Can you test by reverting this change "94d6671473924".
> > > > >
> > > > > The issue is still reproducible.
> > > > >
> > > > > > We need at least 15ms minimum delay for the soc to change its baud rate and
> > > > > > respond to the with command complete event.
> > > > >
> > > > > The baudrate change has clearly been successful when the problem is
> > > > > observed, since the host receives the vendor event with the new
> > > > > baudrate.
> > > >
> > > > I forgot to mention this earlier: the controller doesn't send a
> > > > command complete event for the command, or at least not a correct
> > > > one.
> > > >
> > > > That's the data that is received:
> > > >
> > > > 04 0e 04 01 00 00 00
> > > > ~~ ~~
> > > >
> > > [Bala]: can you share me the command sent and event recevied.
> > > I see that we receive a command complete event for the baud rate
> > > change command.
> > >
> > > command sent: 01 48 fc 01 11
> > > vendor specific event: 04 ff 02 92 01
> > > command complete event: 04 0e 04 01 00 00 00.
> > >
> > >
> > >
> > > > This is *a* command complete event, but the opcode is 0x0000 instead
> > > > of the earlier command. The same happens for the firmware
> > > > download/read version command, which is the reason why the command
> > > > complete injection mess
> > > > (https://lore.kernel.org/patchwork/patch/1027955/) is needed in one
> > > > way or another.
> > > >
> > > [Bala]: fw download approach is different where we use
> > > __hci_cmd_sync() where as here we use hci_uart_tx_wakeup()
> > > which directly calls the hci_uart_write_work(). so even we
> > > send an valid opcode or not for baudrate change will bot matter.
> > >
> > [Bala]: i miss understood the comment. Yes your true. in the all
> > vendor
> > commands SoC responds with an 0x0000 opcode.
>
> And IIUC this is not compliant with the spec, or at least the BT core
> expects the actual opcode to consider the command to be completed.

[Bala]: Did you try increasing the the baud rate change timeout to 50ms
instead of 10ms.

It is even reproducible with the ROME timeout of 300ms.

The timeout doesn't help here. With 78e8fa2972e5 ("Bluetooth: hci_qca:
Deassert RTS while baudrate change command") RTS is deasserted during
the baudrate change, hence the controller only sends the response when
RTS is asserted again. Before the event resulted in a frame reassembly
error and the data was discarded.

i suspect it is an timing issue.

Timing is certainly also a factor here (the problem isn't seen
always), but I don't think 'timing issue' is a proper description of
this issue. The problem is an event that the Bluetooth core doesn't
expect due to the hack of sending a raw command behind the core's back
to work around the firmware 'feature' of sending the command response
with the new baudrate.

Maybe a delay after re-asserting RTS can address is reliably, I don't
remember if I already experimented with that in the past. If a delay
can 'fix' the issue reliably I'm open to consider it for the sake of
simplicity, but only with a detailed comment that describes the
problem.

--
Regards
Balakrishna.