search

sonyxperiadev / bug_tracker

Empty repository that is used as a bugtracker for Open Devices project
52 stars 13 forks source link

[yoshino][maple] excessive bluetooth activity #318

Closed jamuir closed 5 years ago

jamuir commented 5 years ago

Platform: yoshino Device: maple (dual-sim) Kernel version: 4.4.168-g44235a04f24d Android version: 8.1 odm image: 8.1.0_4.4_yoshino_v16

Description /odm/lib64/hw/android.hardware.bluetooth@1.0-impl-qti.so appears to be stuck in some type of loop and emits the same sequence of logcat messages about every 4-5 seconds (see below).

I see this behaviour only after flashing an open-gapps package on top of a sony image ~(and then wiping userdata & cache)~. I do not see this behaviour in a vanilla sony build. It may be that the additional apps are exposing some type of race condition in the qti bluetooth implementation.

01-01 07:18:40.320 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Received IBS_WAKE_IND: 0xFD
01-01 07:18:40.322 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): SerialClockVote: vote for UART CLK ON
01-01 07:18:40.327 E/vendor.qti.bluetooth@1.0-wake_lock(  665): Acquire wake lock not initialized
01-01 07:18:40.328 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Writing IBS_WAKE_ACK
01-01 07:18:40.330 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Received IBS_WAKE_IND: 0xFD
01-01 07:18:40.331 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Writing IBS_WAKE_ACK
01-01 07:18:40.414 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Received IBS_SLEEP_IND: 0xFE
01-01 07:18:40.416 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): SerialClockVote: vote for UART CLK OFF
01-01 07:18:40.417 E/vendor.qti.bluetooth@1.0-wake_lock(  665): Release wake lock not initialized/acquired
01-01 07:18:40.426 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Received IBS_WAKE_IND: 0xFD
01-01 07:18:40.427 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): SerialClockVote: vote for UART CLK ON
01-01 07:18:40.429 E/vendor.qti.bluetooth@1.0-wake_lock(  665): Acquire wake lock not initialized
01-01 07:18:40.430 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Writing IBS_WAKE_ACK
01-01 07:18:40.830 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Received IBS_SLEEP_IND: 0xFE
01-01 07:18:40.831 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): SerialClockVote: vote for UART CLK OFF
01-01 07:18:40.833 E/vendor.qti.bluetooth@1.0-wake_lock(  665): Release wake lock not initialized/acquired
01-01 07:18:45.221 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Received IBS_WAKE_IND: 0xFD
01-01 07:18:45.223 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): SerialClockVote: vote for UART CLK ON
01-01 07:18:45.228 E/vendor.qti.bluetooth@1.0-wake_lock(  665): Acquire wake lock not initialized
01-01 07:18:45.229 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Writing IBS_WAKE_ACK
01-01 07:18:45.730 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Received IBS_SLEEP_IND: 0xFE
01-01 07:18:45.730 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): SerialClockVote: vote for UART CLK OFF
01-01 07:18:45.731 E/vendor.qti.bluetooth@1.0-wake_lock(  665): Release wake lock not initialized/acquired
01-01 07:18:50.395 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Received IBS_WAKE_IND: 0xFD
01-01 07:18:50.396 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): SerialClockVote: vote for UART CLK ON
01-01 07:18:50.400 E/vendor.qti.bluetooth@1.0-wake_lock(  665): Acquire wake lock not initialized
01-01 07:18:50.401 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Writing IBS_WAKE_ACK
01-01 07:18:50.712 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Received IBS_SLEEP_IND: 0xFE
01-01 07:18:50.714 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): SerialClockVote: vote for UART CLK OFF
01-01 07:18:50.716 E/vendor.qti.bluetooth@1.0-wake_lock(  665): Release wake lock not initialized/acquired
01-01 07:18:50.731 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Received IBS_WAKE_IND: 0xFD
01-01 07:18:50.732 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): SerialClockVote: vote for UART CLK ON
01-01 07:18:50.734 E/vendor.qti.bluetooth@1.0-wake_lock(  665): Acquire wake lock not initialized
01-01 07:18:50.735 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Writing IBS_WAKE_ACK
01-01 07:18:50.899 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Received IBS_SLEEP_IND: 0xFE
01-01 07:18:50.901 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): SerialClockVote: vote for UART CLK OFF
01-01 07:18:50.902 E/vendor.qti.bluetooth@1.0-wake_lock(  665): Release wake lock not initialized/acquired
01-01 07:18:54.883 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Received IBS_WAKE_IND: 0xFD
01-01 07:18:54.883 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): SerialClockVote: vote for UART CLK ON
01-01 07:18:54.886 E/vendor.qti.bluetooth@1.0-wake_lock(  665): Acquire wake lock not initialized
01-01 07:18:54.887 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Writing IBS_WAKE_ACK
01-01 07:18:54.932 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Received IBS_SLEEP_IND: 0xFE
01-01 07:18:54.933 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): SerialClockVote: vote for UART CLK OFF
01-01 07:18:54.933 E/vendor.qti.bluetooth@1.0-wake_lock(  665): Release wake lock not initialized/acquired
01-01 07:18:54.936 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Received IBS_WAKE_IND: 0xFD
01-01 07:18:54.936 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): SerialClockVote: vote for UART CLK ON
01-01 07:18:54.937 E/vendor.qti.bluetooth@1.0-wake_lock(  665): Acquire wake lock not initialized
01-01 07:18:54.937 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Writing IBS_WAKE_ACK
01-01 07:18:55.388 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): ProcessIbsCmd: Received IBS_SLEEP_IND: 0xFE
01-01 07:18:55.390 I/vendor.qti.bluetooth@1.0-ibs_handler(  665): SerialClockVote: vote for UART CLK OFF
01-01 07:18:55.391 E/vendor.qti.bluetooth@1.0-wake_lock(  665): Release wake lock not initialized/acquired

Full logcat here: logcat-full.txt

Symptoms The main symptom is excessive logcat spam. I have also noticed some bt audio issues on maple (sound dropping sporadically for 1-2 seconds), but it's unclear if they are related to this.

How to reproduce see above.

(edit: wiping userdata and cache is not necessary)

MarijnS95 commented 5 years ago

Seeing the same spam on Discovery and Akatsuki. The former one being without opengapps (or anything else). Both run a locally compiled Omnirom 9 image on kernel 4.9 and blobs v5. If I remember correctly, this is one of the In-Band Switching messages that should be captured and dealt with elsewhere, but instead end up in the Bluetooth hal. On the other hand, the HAL seems to vote for turning the UART clock on and off (at least according to the logs), which is what's supposed to happen. In that case, these are just debug messages that should be hidden.

jamuir commented 5 years ago

thanks for confirming you see the same logs.

It's possible they are normal debug messages. However, in that case, I don't understand why they would be absent from my vanilla maple build (although you said you see them in a vanilla discovery build).

jamuir commented 5 years ago

@jerpelea : are those repeated log messages normal? do you see them?

oshmoun commented 5 years ago

Noticed these props in crosshatch sources: https://android.googlesource.com/device/google/crosshatch/+/master/device.mk#364 Since these props are not set currently, not sure what the hal implementation defaults to.

jerpelea commented 5 years ago

@jamurir I will silence them in v6

jamuir commented 5 years ago

Thanks. Don't forget about oreo (the logs I posted are from 8.1 with oem v16).

It would be nice to know what is triggering these logs (i.e. why do we see them in some builds and not others).

On Fri, Feb 1, 2019, 2:48 AM Alin Jerpelea <notifications@github.com wrote:

@jamurir I will silence them in v6

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/sonyxperiadev/bug_tracker/issues/318#issuecomment-459636000, or mute the thread https://github.com/notifications/unsubscribe-auth/AFFdoXN0UUqTjtTkGMQRxN0cvROChk_rks5vI_FMgaJpZM4aZACy .

DGoX commented 5 years ago

@jerpelea also fix bluetooth on suzu please

jamuir commented 5 years ago

@jerpelea : do you know what is triggering these logs? why do we see them in some builds but not others?

jerpelea commented 5 years ago

@jamuir I cant replicate reliably

jamuir commented 5 years ago

ok. thanks for your reply.

Here is what I've found with oreo builds:

  1. in a vanilla Sony Open devices build, the bt logs are not generated.
  2. if you flash a nano opengapps package on top of a vanilla Sony Open devices build ~and then wipe the device~, then the bt logs are generated.
jamuir commented 5 years ago

@jerpelea : note that the logs stop when the screen turns off.

oshmoun commented 5 years ago

@jamuir can you try disabling bluetooth scanning? it's an option under location

jamuir commented 5 years ago

good idea.

Unfortunately, it is already disabled. Toggling it on and off does not change the log spew.

Are the logs supposed to disappear if android.hardware.bluetooth@1.0-impl-qti.so successfully acquires a wake-lock? Maybe that is the cause.

jamuir commented 5 years ago

@oshmoun: thanks also for your earlier suggestion re setting ro.vendor.bluetooth.emb_wp_mode=false and ro.vendor.bluetooth.wipower=false. Unfortunately, it did not change anything.

oshmoun commented 5 years ago

@jamuir actually, the hal is successfully acquiring a wakelock i can see hal_bluetooth_lock being acquired here

jamuir commented 5 years ago

@jerpelea do you have a debug version of android.hardware.bluetooth@1.0-impl-qti.so I could try? I could provide more logs to try and figure out the root cause.

jerpelea commented 5 years ago

I will see what I can do

jamuir commented 5 years ago

After some more digging, I think the bt hal is working normally.

The images I examined (the ones with the bt log spam) had no network connectivity. I just noticed that after I connect to wifi, the bt activity stops.

What I think is happening is that one the google apps is repeatedly doing bt scans, possibly in an attempt to determine a location. After the network comes up, the bt scans stop (possibly because it now has a better way to determine location).

If you leave network disconnected and toggle "Location" off and on (under Settings \ Security & Location \ Location), then you can make the bt logs stop and start.

@jerpelea I don't think there is anything broken here (and there is no need to create a debug hal). I will close.

@MarijnS95 I don't understand why you are seeing the bt log spam without Google Play services. Maybe you have some other location provider in your Pie images.

MarijnS95 commented 5 years ago

@jamuir I cannot find a reliable wifi+location on/off state to trigger the spam. Both devices have bluetooth scanning "turned off". Unfortunately, they are very inconsistent on Akatsuki; sometimes don't see them for over 5 minutes The logs occur pretty consistently with NuPlayerDriver: notifyListener_l on Discovery, though.

It would indeed be very interesting to know who and why is requesting these consecutive sleeps and wakes. Best guess is that it's the BT chip itself (or something along the pipeline going there). This could be normal behaviour though.