PROBLEM: Bluetooth mouse not working after resume since commit 2ff1389

PROBLEM: Bluetooth mouse not working after resume since commit 2ff1389

[Tore Anderson]

Starting with commit 2ff1389, =C2=ABPerform HCI update for power on
synchronously=C2=BB, my Logitech M555b bluetooth mouse no longer works after
resuming the system from suspend. The devices is handled by Blueman, and
after resuming from suspend the white lines/triangles inside the
systray icon doesn't turn green even though I move the mouse around.
(The lines turning green normally indicates that a device is active.)

In order to revive it, I need to manually disable and then re-enable
bluetooth, at which point it will re-connects fine.

I've also noticed that I need to press Blueman's =C2=ABTurn Bluetooth Off=
=C2=BB
menu selection twice for it to take effect (so that Blueman's systray
icon gets overlayed with a little red X symbol). This only happens once
after each resume from suspend - after having been through one
off-off-on cycle, bluetooth will turn off normally on the first attempt
(until the next suspend/resume cycle). It also turns off normally on
the first attempt after the initial boot-up. This "double-off after
resume" behaviour also first occurred with commit 2ff1389.

Let me know if there's any other information I can provide.

Tore

Re: PROBLEM: Bluetooth mouse not working after resume since commit 2ff1389

[Johan Hedberg]

Hi Tore,

On Sat, Feb 20, 2016, Tore Anderson wrote:
> Starting with commit 2ff1389, «Perform HCI update for power on
> synchronously», my Logitech M555b bluetooth mouse no longer works after
> resuming the system from suspend. The devices is handled by Blueman, and
> after resuming from suspend the white lines/triangles inside the
> systray icon doesn't turn green even though I move the mouse around.
> (The lines turning green normally indicates that a device is active.)
> 
> In order to revive it, I need to manually disable and then re-enable
> bluetooth, at which point it will re-connects fine.
> 
> I've also noticed that I need to press Blueman's «Turn Bluetooth Off»
> menu selection twice for it to take effect (so that Blueman's systray
> icon gets overlayed with a little red X symbol). This only happens once
> after each resume from suspend - after having been through one
> off-off-on cycle, bluetooth will turn off normally on the first attempt
> (until the next suspend/resume cycle). It also turns off normally on
> the first attempt after the initial boot-up. This "double-off after
> resume" behaviour also first occurred with commit 2ff1389.
> 
> Let me know if there's any other information I can provide.

Do you see the same issue if you don't use blueman? (a piece of software
I'm not really familiar with).

What exactly do you do when you say you "manually disable and then
re-enable bluetooth"? "btmgmt power off; btmgmt power on"? bluetoothctl
power off/on? Something else?

It'd be important to understand what exactly your user space software
(blueman) does when you resume. So any logs that you can take of this
would be helpful. You could e.g. take a HCI log using btmon and enable
kernel debug logs for the bluetooth module (see
Documentation/dynamic-debug-howto.txt in the kernel documentation).

Johan

Re: PROBLEM: Bluetooth mouse not working after resume since commit 2ff1389

[Johan Hedberg]

Hi,

On Sat, Feb 20, 2016, Johan Hedberg wrote:
> On Sat, Feb 20, 2016, Tore Anderson wrote:
> > Starting with commit 2ff1389, «Perform HCI update for power on
> > synchronously», my Logitech M555b bluetooth mouse no longer works after
> > resuming the system from suspend. The devices is handled by Blueman, and
> > after resuming from suspend the white lines/triangles inside the
> > systray icon doesn't turn green even though I move the mouse around.
> > (The lines turning green normally indicates that a device is active.)
> > 
> > In order to revive it, I need to manually disable and then re-enable
> > bluetooth, at which point it will re-connects fine.
> > 
> > I've also noticed that I need to press Blueman's «Turn Bluetooth Off»
> > menu selection twice for it to take effect (so that Blueman's systray
> > icon gets overlayed with a little red X symbol). This only happens once
> > after each resume from suspend - after having been through one
> > off-off-on cycle, bluetooth will turn off normally on the first attempt
> > (until the next suspend/resume cycle). It also turns off normally on
> > the first attempt after the initial boot-up. This "double-off after
> > resume" behaviour also first occurred with commit 2ff1389.
> > 
> > Let me know if there's any other information I can provide.
> 
> Do you see the same issue if you don't use blueman? (a piece of software
> I'm not really familiar with).
> 
> What exactly do you do when you say you "manually disable and then
> re-enable bluetooth"? "btmgmt power off; btmgmt power on"? bluetoothctl
> power off/on? Something else?
> 
> It'd be important to understand what exactly your user space software
> (blueman) does when you resume. So any logs that you can take of this
> would be helpful. You could e.g. take a HCI log using btmon and enable
> kernel debug logs for the bluetooth module (see
> Documentation/dynamic-debug-howto.txt in the kernel documentation).

Another thing to try in addition to disabling blueman: Add
AutoEnable=true under the [Policy] section in /etc/bluetooth/main.conf.
It might make a difference assuming that your Bluetooth adapter gets
detached and reattached to the USB bus when you suspend/resume.

Johan

Re: PROBLEM: Bluetooth mouse not working after resume since commit 2ff1389

[Tore Anderson]

Hi Johan,

> > Do you see the same issue if you don't use blueman? (a piece of
> > software I'm not really familiar with).

If I disable or uninstall blueman, the mouse doesn't come back to life
after a suspend/resume (or initial bootup) until I manually issue
"hciconfig hci0 up". This is the case for both pre- and post-2ff1389
kernels.

> > What exactly do you do when you say you "manually disable and then
> > re-enable bluetooth"? "btmgmt power off; btmgmt power on"?
> > bluetoothctl power off/on? Something else?

I right-click the blueman systray icon, and it pops up a meny where I
can select either =C2=ABTurn Bluetooth Off=C2=BB or =C2=ABTurn Bluetooth On=
=C2=BB (only one
of the options are shown, depending on blueman's idea of the current
status).

> > It'd be important to understand what exactly your user space
> > software (blueman) does when you resume. So any logs that you can
> > take of this would be helpful. You could e.g. take a HCI log using
> > btmon and enable kernel debug logs for the bluetooth module (see
> > Documentation/dynamic-debug-howto.txt in the kernel
> > documentation).

I uploaded debug files to http://filebin.net/pfmb8043cx :

- timestamps.$KVER.txt: my notes of the timestamps of when I did
  specific actions, for easy cross-referencing with the other files.
- blueman-applet.$KVER.txt: output from "blueman-applet |& ts".
- btmon.$KVER.txt: output from "btmon -T".
- kernel-debug-messages.$KVER.txt: kernel output (journalctl -k), after
  having written "module bluetooth +p" to
  the /sys/kernel/debug/dynamic_debug/control file.

Where $KVER is either 4.4.0-rc3-00801-gbf943cb (the last rev where the
bluetooth mouse comes back to life automatically after resume) or
4.4.0-rc3-00802-g2ff1389 (the first rev where it doesn't).

> Another thing to try in addition to disabling blueman: Add
> AutoEnable=3Dtrue under the [Policy] section
> in /etc/bluetooth/main.conf. It might make a difference assuming that
> your Bluetooth adapter gets detached and reattached to the USB bus
> when you suspend/resume.

This made no difference. Note that I had to create that file and its
containing directory anew, it didn't already exist on my Fedora 23
system.

Tore

Re: PROBLEM: Bluetooth mouse not working after resume since commit 2ff1389

[Johan Hedberg]

Hi Tore,

On Sat, Feb 20, 2016, Tore Anderson wrote:
> I uploaded debug files to http://filebin.net/pfmb8043cx :

Thanks.

> - kernel-debug-messages.$KVER.txt: kernel output (journalctl -k), after
>   having written "module bluetooth +p" to
>   the /sys/kernel/debug/dynamic_debug/control file.

These are unfortunately not very useful without function information
since most functions log very similar things. Could you do +pf instead
of +p and try to get these again? To avoid any unnecessary noise, start
the logs right before suspending and stop them right after resuming (I
hope this is how the other logs were taken).

> > Another thing to try in addition to disabling blueman: Add
> > AutoEnable=true under the [Policy] section
> > in /etc/bluetooth/main.conf. It might make a difference assuming that
> > your Bluetooth adapter gets detached and reattached to the USB bus
> > when you suspend/resume.
> 
> This made no difference. Note that I had to create that file and its
> containing directory anew, it didn't already exist on my Fedora 23
> system.

You could have also used src/main.conf from the BlueZ tree as a starting
point and removed the '#' from the AutoEnable line:

https://git.kernel.org/cgit/bluetooth/bluez.git/plain/src/main.conf

Are you sure that you restarted bluetoothd after this change? And you've
got a BlueZ version greater than 5.35 (where the feature was
introduced)?

Johan

Re: PROBLEM: Bluetooth mouse not working after resume since commit 2ff1389

[Tore Anderson]

Good morning,

* Johan Hedberg

> You could have also used src/main.conf from the BlueZ tree as a
> starting point and removed the '#' from the AutoEnable line:
> 
> https://git.kernel.org/cgit/bluetooth/bluez.git/plain/src/main.conf
> 
> Are you sure that you restarted bluetoothd after this change? And
> you've got a BlueZ version greater than 5.35 (where the feature was
> introduced)?

I've got version 5.36, and I had rebooted the system from scratch. I
experimented a bit more, though, and I found out that with
AutoEnable=true (and blueman uninstalled), my system behaves exactly
the same as it did with blueman, that is:

- with a pre-2ff1389 kernel: the mouse is auto-enabled and works fine
  after bootup and resume from suspend.
- with a post-2ff1389 kernel: the mouse is auto-enabled and works fine
  after bootup, but stops working after resume from suspend (until
  "hciconfig hci0 up" is issued manually).

That means we can exclude blueman as a potential cause of the problem,
so I left it uninstalled when I generated the new debug files with +pf,
which you can find here: http://filebin.net/wf9edcjbju

I added a new file too: hciconfig_hci0.$KVER.txt. This shows the
output of "while sleep .5; do hciconfig hci0; done | ts %H:%M:%.S". I
noticed something that seems highly relevant, namely that with the
post-2ff1389 kernel, the hci0 state changes to DOWN a couple of seconds
after resuming. This does not happen with the pre-2ff1389 kernel.

Tore

Re: PROBLEM: Bluetooth mouse not working after resume since commit 2ff1389

[Tore Anderson]

* Tore Anderson <tore@fud.no>

> * Johan Hedberg
> 
> > You could have also used src/main.conf from the BlueZ tree as a
> > starting point and removed the '#' from the AutoEnable line:
> > 
> > https://git.kernel.org/cgit/bluetooth/bluez.git/plain/src/main.conf
> > 
> > Are you sure that you restarted bluetoothd after this change? And
> > you've got a BlueZ version greater than 5.35 (where the feature was
> > introduced)?  
> 
> I've got version 5.36, and I had rebooted the system from scratch. I
> experimented a bit more, though, and I found out that with
> AutoEnable=true (and blueman uninstalled), my system behaves exactly
> the same as it did with blueman, that is:
> 
> - with a pre-2ff1389 kernel: the mouse is auto-enabled and works fine
>   after bootup and resume from suspend.
> - with a post-2ff1389 kernel: the mouse is auto-enabled and works fine
>   after bootup, but stops working after resume from suspend (until
>   "hciconfig hci0 up" is issued manually).
> 
> That means we can exclude blueman as a potential cause of the problem,
> so I left it uninstalled when I generated the new debug files with +pf,
> which you can find here: http://filebin.net/wf9edcjbju
> 
> I added a new file too: hciconfig_hci0.$KVER.txt. This shows the
> output of "while sleep .5; do hciconfig hci0; done | ts %H:%M:%.S". I
> noticed something that seems highly relevant, namely that with the
> post-2ff1389 kernel, the hci0 state changes to DOWN a couple of seconds
> after resuming. This does not happen with the pre-2ff1389 kernel.

Hi Johan,

I thought I'd just ping you quickly about this issue - did you get a
chance to look at the log files, and if so did you figure out what's
going on?

If on the other hand you don't have time to look into the issue, let me
know if I should file this issue in the kernel.org bugzilla (or
anywhere else) so as to avoid it being forgotten about (also note that
the logs will be expired from filebin.net after a couple of weeks).

Tore

Re: PROBLEM: Bluetooth mouse not working after resume since commit 2ff1389

[Johan Hedberg]

Hi Tore,

On Thu, Mar 03, 2016, Tore Anderson wrote:
> > > You could have also used src/main.conf from the BlueZ tree as a
> > > starting point and removed the '#' from the AutoEnable line:
> > > 
> > > https://git.kernel.org/cgit/bluetooth/bluez.git/plain/src/main.conf
> > > 
> > > Are you sure that you restarted bluetoothd after this change? And
> > > you've got a BlueZ version greater than 5.35 (where the feature was
> > > introduced)?  
> > 
> > I've got version 5.36, and I had rebooted the system from scratch. I
> > experimented a bit more, though, and I found out that with
> > AutoEnable=true (and blueman uninstalled), my system behaves exactly
> > the same as it did with blueman, that is:
> > 
> > - with a pre-2ff1389 kernel: the mouse is auto-enabled and works fine
> >   after bootup and resume from suspend.
> > - with a post-2ff1389 kernel: the mouse is auto-enabled and works fine
> >   after bootup, but stops working after resume from suspend (until
> >   "hciconfig hci0 up" is issued manually).
> > 
> > That means we can exclude blueman as a potential cause of the problem,
> > so I left it uninstalled when I generated the new debug files with +pf,
> > which you can find here: http://filebin.net/wf9edcjbju
> > 
> > I added a new file too: hciconfig_hci0.$KVER.txt. This shows the
> > output of "while sleep .5; do hciconfig hci0; done | ts %H:%M:%.S". I
> > noticed something that seems highly relevant, namely that with the
> > post-2ff1389 kernel, the hci0 state changes to DOWN a couple of seconds
> > after resuming. This does not happen with the pre-2ff1389 kernel.
> 
> Hi Johan,
> 
> I thought I'd just ping you quickly about this issue - did you get a
> chance to look at the log files, and if so did you figure out what's
> going on?
> 
> If on the other hand you don't have time to look into the issue, let me
> know if I should file this issue in the kernel.org bugzilla (or
> anywhere else) so as to avoid it being forgotten about (also note that
> the logs will be expired from filebin.net after a couple of weeks).

Sorry for the delayed response.

I tried looking at the logs but couldn't find anything helpful there. I
also tried to reproduce this myself by configuring my bluetoothd with
the AutoEnable=true and unplugging/plugging a USB dongle, but no luck
(it should roughly match what happens when you suspend/resume). I
suppose you don't have any ideas how I could successfully reproduce this
myself? (other than getting the same HW as you).

One thing you could still try is use an even newer kernel, such as the
bluetooth-next tree or the latest 4.5-rc release, and see if the issue
still persists.

Johan

Re: PROBLEM: Bluetooth mouse not working after resume since commit 2ff1389

[Tore Anderson]

* Johan Hedberg

> One thing you could still try is use an even newer kernel, such as the
> bluetooth-next tree or the latest 4.5-rc release, and see if the issue
> still persists.

I did with fresh git pulls:

bluetooth-next @ 9dbadc0: Works
linux (torvalds) @ f983cd3: Broken

If you'd like I can try to bisect it this weekend to figure out exactly
where it got fixed, if not I'll just content myself with the knowledge
that it'll probably get fixed in the mainline kernel eventually.

Tore

Re: PROBLEM: Bluetooth mouse not working after resume since commit 2ff1389

[Johan Hedberg]

Hi Tore,

On Thu, Mar 03, 2016, Tore Anderson wrote:
> > One thing you could still try is use an even newer kernel, such as the
> > bluetooth-next tree or the latest 4.5-rc release, and see if the issue
> > still persists.
> 
> I did with fresh git pulls:
> 
> bluetooth-next @ 9dbadc0: Works
> linux (torvalds) @ f983cd3: Broken
> 
> If you'd like I can try to bisect it this weekend to figure out exactly
> where it got fixed, if not I'll just content myself with the knowledge
> that it'll probably get fixed in the mainline kernel eventually.

It's a relief to hear that the issue seems to be fixed, but it would
indeed be good to get to the bottom of this and understand what exactly
fixed it, since I can't right now remember any recent patches that would
have influenced this behavior (who knows - maybe it's something external
to the Bluetooth subsystem).

Johan

Re: PROBLEM: Bluetooth mouse not working after resume since commit 2ff1389

[Tore Anderson]

Hi Johan,

> It's a relief to hear that the issue seems to be fixed, but it would
> indeed be good to get to the bottom of this and understand what
> exactly fixed it, since I can't right now remember any recent patches
> that would have influenced this behavior (who knows - maybe it's
> something external to the Bluetooth subsystem).

It got fixed by:

commit d82142a8b1338e6a4339920863423379c27b0b16
Author: Wei-Ning Huang <wnhuang@chromium.org>
Date:   Mon Feb 15 17:09:51 2016 +0800

    Bluetooth: hci_core: cancel power off delayed work properly

    When the HCI_AUTO_OFF flag is cleared, the power_off delayed work need
    to be cancel or HCI will be powered off even if it's managed.

    Signed-off-by: Wei-Ning Huang <wnhuang@chromium.org>
    Signed-off-by: Marcel Holtmann <marcel@holtmann.org>

Tore