[PATCH] bluetooth/l2cap: silence framedrop kmsg noise

[PATCH] bluetooth/l2cap: silence framedrop kmsg noise

[Gregory M. Turner]

>From b222223a4410587ea21b20841581f22614432b77 Mon Sep 17 00:00:00 2001
From: "Gregory M. Turner" <gmt@be-evil.net>
Date: Sun, 22 Feb 2015 10:54:06 -0800
Subject: [PATCH] bluetooth/l2cap: silence framedrop kmsg noise

For years, my logs have often looked like this:

    # dmesg | wc -lc ; \
      dmesg | grep -v \
          'Bluetooth: Unexpected continuation frame (len 0)' \
          | wc -lc
      32769 2096857
         85    5081

Google suggests I'm not alone in this.  AFAICT, it means:

    "Hey, kernel, here.  I was trying to talk to some gizmo by way
    of your tiny $2.50 USB dongle broadcasting a 2.4Ghz near-field
    RF protocol.  Inexplicably, there was some sort of RFI or
    dropout!  I'm deeply offended, and taking it personally.  I'll
    remind you again a few microseconds if the problem continues."

Surely this is causing more harm than benefit; silence the kmsg
unless the frame is nonempty.

Signed-off-by: Gregory M. Turner <gmt@be-evil.net>
---
 net/bluetooth/l2cap_core.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/net/bluetooth/l2cap_core.c b/net/bluetooth/l2cap_core.c
index 6ba33f9..dcec242 100644
--- a/net/bluetooth/l2cap_core.c
+++ b/net/bluetooth/l2cap_core.c
@@ -7493,7 +7493,8 @@ int l2cap_recv_acldata(struct hci_conn *hcon, struct sk_buff *skb, u16 flags)
 		BT_DBG("Cont: frag len %d (expecting %d)", skb->len, conn->rx_len);
 
 		if (!conn->rx_len) {
-			BT_ERR("Unexpected continuation frame (len %d)", skb->len);
+			if (skb->len)
+				BT_ERR("Unexpected continuation frame (len %d)", skb->len);
 			l2cap_conn_unreliable(conn, ECOMM);
 			goto drop;
 		}
-- 
2.3.0

Re: [PATCH] bluetooth/l2cap: silence framedrop kmsg noise

[Marcel Holtmann]

Hi Gregory,

> From b222223a4410587ea21b20841581f22614432b77 Mon Sep 17 00:00:00 2001
> From: "Gregory M. Turner" <gmt@be-evil.net>
> Date: Sun, 22 Feb 2015 10:54:06 -0800
> Subject: [PATCH] bluetooth/l2cap: silence framedrop kmsg noise
> 
> For years, my logs have often looked like this:
> 
>    # dmesg | wc -lc ; \
>      dmesg | grep -v \
>          'Bluetooth: Unexpected continuation frame (len 0)' \
>          | wc -lc
>      32769 2096857
>         85    5081
> 
> Google suggests I'm not alone in this.  AFAICT, it means:
> 
>    "Hey, kernel, here.  I was trying to talk to some gizmo by way
>    of your tiny $2.50 USB dongle broadcasting a 2.4Ghz near-field
>    RF protocol.  Inexplicably, there was some sort of RFI or
>    dropout!  I'm deeply offended, and taking it personally.  I'll
>    remind you again a few microseconds if the problem continues."
> 
> Surely this is causing more harm than benefit; silence the kmsg
> unless the frame is nonempty.

can you send a btmon trace for this and be more specific which devices are these. There seems to be something really off going on here.

Regards

Marcel

Re: [PATCH] bluetooth/l2cap: silence framedrop kmsg noise

[Greg Turner]

On Sun, Feb 22, 2015 at 12:53 PM, Marcel Holtmann <marcel@holtmann.org> wrote:
> can you send a btmon trace for this

sure, check your email.

> and be more specific which devices are these.

It's not pretty.  It's a (usb id) 046d:c709.  They come bundled with
Logitech keyboards.  They require hid2hci (udev, or somebody, does it
for me automagically these days).

I believe the radio is a BCM2045A... or maybe not... it's definitely a
fairly obscure thing to use as a radio, as Logitech pretty much goes
out of their way to pretend it's married to the keyboard it comes
with.

Is there some good way to ask the kernel what board it thinks it's
talking to?  I have heard some grumbling about Logitech recycling the
0xc709 product ID although I'm not sure I trust whoever said it :(

The device has a plastic OEM "shell" but the plastic is
semitransparent.  If I shine my flashlight at it just right, I can see
an inner plastic(?) enclosure with different markings than Logitech's,
but it's partially obscured -- all I can read on that inner device is
the last line: "0541 LF".  I could definitely sacrifice it for
science, if it became necessary.

I only ever use a2dp, avrcp and hfp (or maybe hsp?, can't keep 'em
straight in my head); I have a couple different gizmos and they all
fill my logs with that message.

> There seems to be something really off going on here.

Really?  That's sort-of encouraging... There were so many reports
online and everyone sounded so resigned to this fate that I just
assumed that was the expected result.

One odd behavior I have observed (aside from logs full of garbage) --
if I go too far out of range, the entire connection between my device
and the dongle just "breaks".  If I come back into range, they are
never able to find each other and resume their conversation until
reboot my gizmo (or sometimes it will come back online after a very
long time).  Yet, the dongle still thinks they're connected.  I've
learned to just leave them behind before leaving the room :)

Greg Turner
gmt@be-evil.net

Re: [PATCH] bluetooth/l2cap: silence framedrop kmsg noise

[Marcel Holtmann]

Hi Greg,

>> and be more specific which devices are these.
> 
> It's not pretty.  It's a (usb id) 046d:c709.  They come bundled with
> Logitech keyboards.  They require hid2hci (udev, or somebody, does it
> for me automagically these days).
> 
> I believe the radio is a BCM2045A... or maybe not... it's definitely a
> fairly obscure thing to use as a radio, as Logitech pretty much goes
> out of their way to pretend it's married to the keyboard it comes
> with.
> 
> Is there some good way to ask the kernel what board it thinks it's
> talking to?  I have heard some grumbling about Logitech recycling the
> 0xc709 product ID although I'm not sure I trust whoever said it :(
> 
> The device has a plastic OEM "shell" but the plastic is
> semitransparent.  If I shine my flashlight at it just right, I can see
> an inner plastic(?) enclosure with different markings than Logitech's,
> but it's partially obscured -- all I can read on that inner device is
> the last line: "0541 LF".  I could definitely sacrifice it for
> science, if it became necessary.
> 
> I only ever use a2dp, avrcp and hfp (or maybe hsp?, can't keep 'em
> straight in my head); I have a couple different gizmos and they all
> fill my logs with that message.
> 
>> There seems to be something really off going on here.
> 
> Really?  That's sort-of encouraging... There were so many reports
> online and everyone sounded so resigned to this fate that I just
> assumed that was the expected result.
> 
> One odd behavior I have observed (aside from logs full of garbage) --
> if I go too far out of range, the entire connection between my device
> and the dongle just "breaks".  If I come back into range, they are
> never able to find each other and resume their conversation until
> reboot my gizmo (or sometimes it will come back online after a very
> long time).  Yet, the dongle still thinks they're connected.  I've
> learned to just leave them behind before leaving the room :)

I get the feeling that either dongle or the remote device is broken. If it is the dongle, it might actually needs a firmware update / ROM patch to make this behave properly.

The real problem is that we get a ACL fragment from the controller telling us that it is continuation of a previous packet. However this previous packet seems to never arrive in the first place. Meaning I have no idea what is actually happening here. The error message tells you that.

So instead of removing it, we might want to consider using rate limiting for that specific error message. It is a valid error message.

Regards

Marcel

Re: [PATCH] bluetooth/l2cap: silence framedrop kmsg noise

[Gregory M. Turner]

On Sunday 22 February 2015 16:05:37 Marcel Holtmann wrote:
> Hi Greg,
>
> I get the feeling that either dongle or the remote device is broken. If it
> is the dongle, it might actually needs a firmware update / ROM patch to
> make this behave properly.

I'm pretty sure the firmware's up to date on it.  But this thing is quite old 
and not well supported.  I think it's an old revision of the HW that was 
superseded by something slightly less shitty in future Logitech packages (they 
do still sell this keyboard package, or did the last time I checked, but 
reports were, it came with a different dongle).

This behavior definitely follows the dongle -- all other factors have been 
varied and ruled out over the many years I've put up with this thing.

> The real problem is that we get a ACL fragment from the controller telling
> us that it is continuation of a previous packet. However this previous
> packet seems to never arrive in the first place. Meaning I have no idea
> what is actually happening here. The error message tells you that.

With length zero?  That seems crazy.  Or am I misunderstanding what that 
number signifies?

> So instead of removing it, we might want to consider using rate limiting for
> that specific error message.

In my particular case, it makes sense to just apply the patch I posted even if 
it's wrong.  Clearly, though, this is treating the symptom, not the disease.

> It is a valid error message.

Idunno... obv. it's valid in the sense that this is what the driver thinks the 
device is telling the host, hence, my patch is stupid.

However, it seems I have either a) a broken dongle b) a dongle that's working 
as designed, but whose design is broken or nonstandard*, or c) a broken linux 
driver (but the line between c and b is blurry).

I'm wondering, in particular, about (b).  I used to have a second dongle like 
this one.  It fell apart some years ago (hmm, I may have saved the pieces 
somewhere), but I'm pretty sure it had the same behavior.  That was a long 
time ago, however; I could definitely be remembering incorrectly.

I'll see if I can't learn how to get my android phone to sniff this traffic.  My 
thinking is, if a sniffed dump looked different from the host's dump, I'd have a 
pretty clear indication of a problem arising at or below the driver layer.

Another similar avenue of attack would be to mess around with Windows.  If 
there is some way to generate these dumps in Windows, and everything looked 
fine there, I'd at least have a clear indication that the kernel driver lacks 
some needed quirk support for this device.

-gmt

Re: [PATCH] bluetooth/l2cap: silence framedrop kmsg noise

[Marcel Holtmann]

Hi Greg,

>> I get the feeling that either dongle or the remote device is broken. If it
>> is the dongle, it might actually needs a firmware update / ROM patch to
>> make this behave properly.
> 
> I'm pretty sure the firmware's up to date on it.  But this thing is quite old 
> and not well supported.  I think it's an old revision of the HW that was 
> superseded by something slightly less shitty in future Logitech packages (they 
> do still sell this keyboard package, or did the last time I checked, but 
> reports were, it came with a different dongle).
> 
> This behavior definitely follows the dongle -- all other factors have been 
> varied and ruled out over the many years I've put up with this thing.
> 
>> The real problem is that we get a ACL fragment from the controller telling
>> us that it is continuation of a previous packet. However this previous
>> packet seems to never arrive in the first place. Meaning I have no idea
>> what is actually happening here. The error message tells you that.
> 
> With length zero?  That seems crazy.  Or am I misunderstanding what that 
> number signifies?

the problem is that the controller tells us that this is continuation fragment with zero length. Meaning that there has to be a start packet in the first place. That one seems to never happen or it gets out of sync at some point.

If you say that whenever you use the controller, you see this behavior, then it sounds like a problem with the controller. So maybe investing in a 10 USD dongle from China would help.

>> So instead of removing it, we might want to consider using rate limiting for
>> that specific error message.
> 
> In my particular case, it makes sense to just apply the patch I posted even if 
> it's wrong.  Clearly, though, this is treating the symptom, not the disease.
> 
>> It is a valid error message.
> 
> Idunno... obv. it's valid in the sense that this is what the driver thinks the 
> device is telling the host, hence, my patch is stupid.
> 
> However, it seems I have either a) a broken dongle b) a dongle that's working 
> as designed, but whose design is broken or nonstandard*, or c) a broken linux 
> driver (but the line between c and b is blurry).
> 
> I'm wondering, in particular, about (b).  I used to have a second dongle like 
> this one.  It fell apart some years ago (hmm, I may have saved the pieces 
> somewhere), but I'm pretty sure it had the same behavior.  That was a long 
> time ago, however; I could definitely be remembering incorrectly.
> 
> I'll see if I can't learn how to get my android phone to sniff this traffic.  My 
> thinking is, if a sniffed dump looked different from the host's dump, I'd have a 
> pretty clear indication of a problem arising at or below the driver layer.
> 
> Another similar avenue of attack would be to mess around with Windows.  If 
> there is some way to generate these dumps in Windows, and everything looked 
> fine there, I'd at least have a clear indication that the kernel driver lacks 
> some needed quirk support for this device.

If this is on purpose, then I can not figure out why it would be. It makes no sense to me and since Bluetooth is a rather old technology these days, this would have come up more often.

We should rate limit the error message, but we should not suppress it completely. So I am fine adding a patch that rate limits it.

Sniffing the air traffic and USB HCI traffic comes with a 40k EUR price point. So I would go for a new dongle and throw this in a trashcan ;)

Regards

Marcel

Re: [PATCH] bluetooth/l2cap: silence framedrop kmsg noise

[Gregory M. Turner]

On Monday 23 February 2015 13:18:39 Marcel Holtmann wrote:
> Hi Greg,
[snip]
> the problem is that the controller tells us that this is continuation
> fragment with zero length. Meaning that there has to be a start packet in
> the first place. That one seems to never happen or it gets out of sync at
> some point.
>
> If you say that whenever you use the controller, you see this behavior, then
> it sounds like a problem with the controller. So maybe investing in a 10
> USD dongle from China would help.

undoubtedly.

[snip]
> If this is on purpose, then I can not figure out why it would be. It makes
> no sense to me and since Bluetooth is a rather old technology these days,
> this would have come up more often.

My suspicion is that the dongle (which is almost as old as bluetooth 2.1+EDR, 
which IIRC it supports) mostly works but misbehaves.  If it was more widely 
deployed, and if these things didn't cost $10

> We should rate limit the error message, but we should not suppress it
> completely. So I am fine adding a patch that rate limits it.
> 
> Sniffing the air traffic and USB HCI traffic comes with a 40k EUR price
> point.

Holy crap-hole, are you serious?  I'm a bit surprised.  I was hoping I could 
just cross-compile bluez and be off to the races.  Oh well, at least this means 
I have little cause to worry that the neighbors are spying on my phone calls 
:)

I guess this must be because it's much harder for a sniffer to figure out the 
channel hop timings negotiated between two devices than to negotiate the that 
timing directly with another device that's playing nice with you?

> So I would go for a new dongle and throw this in a trashcan ;)

I probably should have done this ages ago anyhow.  I'll send a rate-limiting 
patch.

-gmt

Re: [PATCH] bluetooth/l2cap: silence framedrop kmsg noise

[Gregory M. Turner]

On Monday 23 February 2015 14:49:10 Gregory M. Turner wrote:
> My suspicion is that the dongle (which is almost as old as bluetooth
> 2.1+EDR,  which IIRC it supports) mostly works but misbehaves.  If it was
> more widely deployed, and if these things didn't cost $10

 oops.  meant to finish this sentence with something like "then maybe I'd have 
enough incentive to break my balls getting to the bottom of it." :)

-gmt

Re: [PATCH] bluetooth/l2cap: silence framedrop kmsg noise

[Gregory M. Turner]

On Monday 23 February 2015 13:18:39 Marcel Holtmann wrote:
> So I am fine adding a patch that rate limits it.

While I'm at it, I'd might as well go whole-hog and implement 
BT_*_RATELIMITED, no?  Since, obviously, 50 lines of elegant 90% untested code 
is way better than two lines of ugly 100% tested code* :)

To that end, I notice bt_{err,info} are exports in lib.c, while the rest are 
macros.  I'm trying to determine how tragic and/or useful it would be if those 
symbols proliferated into bt_{err,info}{,_ratelimited}.

"git blame" suggests they are object-file-size optimizations and therefore, 
there is probably no good reason not to just make them macros -- since there 
will only be the single consumer.

Any objections out there?

-
* Just kidding, sort of -- I'd at least make sure they work, by means of some 
ugly offline experiment.

-gmt