Bluebinder busy-waiting is back

[Flohack74]

Seems like an issue similar to #20 is back again on the same device:

• When using the device without rebooting for more than a week or so
• Not actually having BT turned on, or any devices paired
• Noticed huge battery drain suddenly and inspected then top and an strace

I could only do this with a screen shot, since I needed the device to work normally and so rebooted. Also fishy are 10% of mem usage for bluebinder.

[Flohack74]

Here is some trace from logcat, too:

09-20 07:01:29.692   234  1232 I vendor.qti.bluetooth@1.0-ibs_handler: ProcessIbsCmd: Received IBS_WAKE_IND: 0xFD
09-20 07:01:29.692   234  1232 D vendor.qti.bluetooth@1.0-ibs_handler: SerialClockVote: vote for UART CLK ON
09-20 07:01:29.692   234  1232 I vendor.qti.bluetooth@1.0-ibs_handler: ProcessIbsCmd: Writing IBS_WAKE_ACK
09-20 07:01:29.733   234  1232 I vendor.qti.bluetooth@1.0-ibs_handler: ProcessIbsCmd: Received IBS_SLEEP_IND: 0xFE
09-20 07:01:29.733   234  1232 D vendor.qti.bluetooth@1.0-ibs_handler: SerialClockVote: vote for UART CLK OFF
09-20 07:01:29.800   234  1232 I vendor.qti.bluetooth@1.0-ibs_handler: ProcessIbsCmd: Received IBS_WAKE_IND: 0xFD
09-20 07:01:29.800   234  1232 D vendor.qti.bluetooth@1.0-ibs_handler: SerialClockVote: vote for UART CLK ON
09-20 07:01:29.800   234  1232 I vendor.qti.bluetooth@1.0-ibs_handler: ProcessIbsCmd: Writing IBS_WAKE_ACK
09-20 07:01:29.841   234  1232 I vendor.qti.bluetooth@1.0-ibs_handler: ProcessIbsCmd: Received IBS_SLEEP_IND: 0xFE
09-20 07:01:29.841   234  1232 D vendor.qti.bluetooth@1.0-ibs_handler: SerialClockVote: vote for UART CLK OFF
09-20 07:01:29.992   234   824 D vendor.qti.bluetooth@1.0-wake_lock: Release wakelock is released
09-20 07:01:30.027   234  1232 I vendor.qti.bluetooth@1.0-ibs_handler: ProcessIbsCmd: Received IBS_WAKE_IND: 0xFD
09-20 07:01:30.027   234  1232 D vendor.qti.bluetooth@1.0-ibs_handler: SerialClockVote: vote for UART CLK ON
09-20 07:01:30.028   234  1232 D vendor.qti.bluetooth@1.0-wake_lock: Acquire wakelock is acquired
09-20 07:01:30.028   234  1232 I vendor.qti.bluetooth@1.0-ibs_handler: ProcessIbsCmd: Writing IBS_WAKE_ACK
09-20 07:01:30.069   234  1232 I vendor.qti.bluetooth@1.0-ibs_handler: ProcessIbsCmd: Received IBS_SLEEP_IND: 0xFE
09-20 07:01:30.069   234  1232 D vendor.qti.bluetooth@1.0-ibs_handler: SerialClockVote: vote for UART CLK OFF
09-20 07:01:30.114   234  1232 I vendor.qti.bluetooth@1.0-ibs_handler: ProcessIbsCmd: Received IBS_WAKE_IND: 0xFD
09-20 07:01:30.114   234  1232 D vendor.qti.bluetooth@1.0-ibs_handler: SerialClockVote: vote for UART CLK ON
09-20 07:01:30.114   234  1232 I vendor.qti.bluetooth@1.0-ibs_handler: ProcessIbsCmd: Writing IBS_WAKE_ACK
09-20 07:01:30.155   234  1232 I vendor.qti.bluetooth@1.0-ibs_handler: ProcessIbsCmd: Received IBS_SLEEP_IND: 0xFE
09-20 07:01:30.155   234  1232 D vendor.qti.bluetooth@1.0-ibs_handler: SerialClockVote: vote for UART CLK OFF

[krnlyng]

It looks like the HAL is trying to tell us something, but the vhci interface has been rfkilled. I'm not sure how this should be handled...

[krnlyng]

Could you show the output of "rfkill" and "hciconfig" in this state? Also was bluetooth ever turned on in this boot cycle?

[Flohack74]

@krnlyng I dont remember if BT was on but I guess not. Exept for testing stuff I dont turn it on, and I think I rebooted this thing for an update last days.

phablet@ubuntu-phablet:~$ rfkill list
0: bt_power: Bluetooth
        Soft blocked: yes
        Hard blocked: no
1: hci0: Bluetooth
        Soft blocked: yes
        Hard blocked: no
2: phy0: Wireless LAN
        Soft blocked: no
        Hard blocked: no

phablet@ubuntu-phablet:~$ hciconfig
hci0:   Type: Primary  Bus: Virtual
        BD Address: 78:53:64:05:81:13  ACL MTU: 1024:7  SCO MTU: 60:8
        DOWN
        RX bytes:0 acl:0 sco:0 events:61 errors:0
        TX bytes:3736 acl:0 sco:0 commands:60 errors:0

[krnlyng]

Oh and the journal of bluebinder, and would also be interesting to see what the HAL wants to send.

[Flohack74]

@krnlyng how to obtain journal of bluebinder :)

[krnlyng]

Does this not work?

journalctl -u bluebinder

[Flohack74]

No @krnlyng UT does not use systemd, as such the logging might be different. Will try to find how this works:

phablet@ubuntu-phablet:~$ sudo journalctl -u bluebinder
[sudo] password for phablet:
No journal files were found.
-- No entries --

[Thaodan]

No @krnlyng UT does not use systemd, as such the logging might be different. Will try to find how this works: ``` @.***:~$ sudo journalctl -u bluebinder [sudo] password for phablet: No journal files were found. -- No entries --

Hey, is this enabled for you? https://upstart.ubuntu.com/cookbook/#console-log

In such as case the logs should be in /var/log/upstart/$service.

[Flohack74]

@Thaodan thanks, yes this was missing in this job... @krnlyng its spamming this (again):

Writing packet from HAL to vhci device failed: No such device or address
Writing packet from HAL to vhci device failed: No such device or address
Writing packet from HAL to vhci device failed: No such device or address
Writing packet from HAL to vhci device failed: No such device or address
Writing packet from HAL to vhci device failed: No such device or address
Writing packet from HAL to vhci device failed: No such device or address
Writing packet from HAL to vhci device failed: No such device or address
Writing packet from HAL to vhci device failed: No such device or address
Writing packet from HAL to vhci device failed: No such device or address
Writing packet from HAL to vhci device failed: No such device or address
Writing packet from HAL to vhci device failed: No such device or address
Writing packet from HAL to vhci device failed: No such device or address

So Bluetooth was off at start. We have actually a delayed start for the service to determine the BT address, could that affect it in some way?

[Flohack74]

Ok wait this is not fully true, after reboot it is silent:

Bluetooth service running
Own hci index: 1
delaying writing host command to controller until bt is up
delaying writing host command to controller until bt is up
Turning bluetooth on
Bluetooth initialized successfully
successfully initialized bluetooth
Turning bluetooth off

I guess I have to wait until I can catch it again...

[krnlyng]

Oh and the journal of bluebinder, and would also be interesting to see what the HAL wants to send.

For the latter part we would need to change the code and add a printf with the data where that message is printed.