**Platform**: Seine
**Device**: pdx201
**Kernel version**: 4.14 (be667ecc267b8…1)
**Android version**: 10
**Software binaries version**: SW_binaries_for_Xperia_Android_10.0.7.1_r1_v12b_seine.img
**Previously working on**
Stock image doesn't have this issue.
**Description**
When in regular (GSM/LTE) phone call and enable loud speaker microphone on the device starts picking sound from the speaker creating annoying echo on the other side of the call.
**How to reproduce**
Make a call, enable loud speaker and hear echo on the other end of the call.
**Additional context**
I made some investigation of this problem but eventually get out of ideas what might be the reason for this. So here what I've found so far:
1. I've looked through `mixer_paths.xml` file and noticed paths like these:
```xml
<path name="echo-reference">
<ctl name="AUDIO_REF_EC_UL1 MUX" value="PRI_MI2S_TX" />
</path>
<path name="echo-reference headphones">
<ctl name="AUDIO_REF_EC_UL1 MUX" value="RX_CDC_DMA_RX_0" />
</path>
```
These paths looks related to echo cancellation :)
2. After searching codebase for usages of these paths I've found that only place where these are touched is in `platform_set_echo_reference` function in `vendor/qcom/opensource/audio-hal/primary-hal/hal/msm8974/platform.c` file (well one that is relevant for this platform at least). This method is called from several places, but it looks like one that is relevant to loud speaker mode is this:
```c
} else if (out_device & AUDIO_DEVICE_OUT_SPEAKER ||
out_device & AUDIO_DEVICE_OUT_SPEAKER_SAFE ||
out_device & AUDIO_DEVICE_OUT_WIRED_HEADPHONE ||
out_device & AUDIO_DEVICE_OUT_LINE ||
out_device & AUDIO_DEVICE_OUT_BUS) {
if (my_data->fluence_type != FLUENCE_NONE &&
(my_data->fluence_in_voice_call ||
my_data->fluence_in_hfp_call) &&
my_data->fluence_in_spkr_mode) {
...
if (audio_extn_hfp_is_active(adev)){
ALOGV("%s: audio_extn_hfp_is_active returned true! ", __func__);
platform_set_echo_reference(adev, true, out_device);
} else {
ALOGV("%s: audio_extn_hfp_is_active returned FALSE! ", __func__);
}
```
These are additional log statements I've added to track it down.
3. Function `audio_extn_hfp_is_active` is defined in `vendor/qcom/opensource/audio-hal/primary-hal/hal/audio_extn/audio_extn.c ` and it checks if `hfp_is_active` function is defined and call it for answer. This function only get defined if `vendor.audio.feature.hfp.enable` property is `true` and it is set to true in `device/sony/common/common-prop.mk`. I see followint log messages in both stock and aosp logs:
```
03-22 15:30:36.579 776 776 D audio_hw_extn: hfp_feature_init: Called with feature Enabled
```
But but aosp version cannot enable this properly because it can't find `libhfp.so` library, so I have to include it into my mk file like this:
```
PRODUCT_PACKAGES += \
libhfp
```
After had done that I got following messages in aosp image log:
```
07-31 03:39:19.728 686 766 D audio_hw_extn: hfp_feature_init: Called with feature Enabled
07-31 03:39:19.728 818 818 E QMI_FW : QMUXD: WARNING qmi_qmux_if_pwr_up_init failed! rc=-6
07-31 03:39:19.729 0 0 I ueventd : firmware: loading 'cdsp.b10' for '/devices/platform/soc/b300000.qcom,turing/firmware/cdsp.b10'
07-31 03:39:19.730 0 0 E CP : charge_pump missing
07-31 03:39:19.732 688 688 I mm-camera: <SENSOR>< INFO> 311: sensor_sdk_util_get_i2c_freq_mode: Invalid i2c_freq_mode = 4
07-31 03:39:19.732 0 0 E msm_sensor_fill_eeprom_subdevid_by_name: 222 Eeprom userspace probe for s5k4h7yx_front
07-31 03:39:19.733 686 766 D audio_hw_extn: hfp_feature_init:: ---- Feature HFP is Enabled ----
```
Though this was not enough to make `hfp_is_active` to return true during call because even feature is enabled it was not initialized properly.
4. `hfp_is_active` is defined in `vendor/qcom/opensource/audio-hal/primary-hal/hal/audio_extn/hfp.c" file and call into `fp_get_usecase_from_list`:
```c
bool hfp_is_active(struct audio_device *adev)
{
struct audio_usecase *hfp_usecase = NULL;
hfp_usecase = fp_get_usecase_from_list(adev, hfpmod.ucid);
if (hfp_usecase != NULL){
ALOGI("%s: usecase for hfp found", __func__);
return true;
} else {
ALOGI("%s: usecase for hfp not found", __func__);
return false;
}
}
```
Again, additional logging added by me. This `fp_get_usecase_from_list` function comes from `audio_extn.c` file in form of reference to `get_usecase_from_list` from `vendor/qcom/opensource/audio-hal/primary-hal/hal/audio_hw.c`. This function just goes through list of all usecases that are assigned to `adev` struct and looking for `USECASE_AUDIO_HFP_SCO`, which is added by `start_hfp` function like this:
```c
list_add_tail(&adev->usecase_list, &uc_info->list);
```
I'm not very familiar with C and this took me a while to understand that this is basically "append" operation, especially confusing is `uc_info->list` since this is not actually "list" but rather a "listnode".
Anyway I started looking what is calling this `start_hfp` function.
5. Apparently it is called from very same `hfp.c` file from `hfp_set_parameters` function, but there is a condition around it:
```c
ret = str_parms_get_str(parms, AUDIO_PARAMETER_HFP_ENABLE, value,
sizeof(value));
if (ret >= 0) {
...
if (!strncmp(value, "true", sizeof(value))) {
ret = start_hfp(adev,parms);
...
```
I.e. it will only get invoked if `AUDIO_PARAMETER_HFP_ENABLE` configuration parameter is set to "true". This parameter could be set via `audio_platform_info.xml` `<config_params>` section, so I did that and now my device refused to boot because of following error:
```
07-31 03:39:23.060 1463 1463 F DEBUG : *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
07-31 03:39:23.060 1463 1463 F DEBUG : Build fingerprint: 'Acme/aosp_xqau52/pdx201:10/QQ3A.200805.001/eng.acme.20210325.112824:userdebug/dev-keys'
07-31 03:39:23.060 1463 1463 F DEBUG : Revision: '0'
07-31 03:39:23.060 1463 1463 F DEBUG : ABI: 'arm'
07-31 03:39:23.060 1463 1463 F DEBUG : Timestamp: 1970-07-31 03:39:23+0000
07-31 03:39:23.060 1463 1463 F DEBUG : pid: 686, tid: 766, name: HwBinder:686_2 >>> /vendor/bin/hw/android.hardware.audio@2.0-service <<<
07-31 03:39:23.060 1463 1463 F DEBUG : uid: 1041
07-31 03:39:23.060 1463 1463 F DEBUG : signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 0x0
07-31 03:39:23.060 1463 1463 F DEBUG : Cause: null pointer dereference
07-31 03:39:23.060 1463 1463 F DEBUG : r0 f00a202a r1 00000000 r2 eea6b250 r3 00000003
07-31 03:39:23.061 1463 1463 F DEBUG : r4 00000000 r5 00000000 r6 00000000 r7 ee9b081e
07-31 03:39:23.061 1463 1463 F DEBUG : r8 f0a9e260 r9 f0c5d150 r10 ee6ef9c0 r11 f0bdd300
07-31 03:39:23.061 1463 1463 F DEBUG : ip ef1b1148 sp ef1b15f8 lr ee9b18e1 pc eea6b274
07-31 03:39:23.085 818 818 I QC-NETMGR-LIB: NetmgrNetdClientInit(): Looking for Netd service
07-31 03:39:23.089 818 818 D QC-NETMGR-LIB: registerServerNotification(): Successfully registered for Netd HAL service
07-31 03:39:23.089 1463 1463 F DEBUG :
07-31 03:39:23.089 1463 1463 F DEBUG : backtrace:
07-31 03:39:23.089 1463 1463 F DEBUG : #00 pc 0004d274 /vendor/lib/hw/audio.primary.sm6125.so (platform_set_mic_mute+36) (BuildId: 8bbfcc7a41151050b88551f6b1e0557d)
07-31 03:39:23.089 1463 1463 F DEBUG : #01 pc 000028df /vendor/lib/libhfp.so (hfp_set_parameters+930) (BuildId: 4e5e1bb0853b5b7a08c642f7d2bbbb2b)
07-31 03:39:23.089 1463 1463 F DEBUG : #02 pc 0005112c /vendor/lib/hw/audio.primary.sm6125.so (platform_set_parameters+3508) (BuildId: 8bbfcc7a41151050b88551f6b1e0557d)
07-31 03:39:23.089 1463 1463 F DEBUG : #03 pc 00008843 /system/lib/vndk-29/libexpat.so (doContent+1258) (BuildId: b95967a5fb4e2dbc8e0650ab6b5a4c6e)
07-31 03:39:23.089 1463 1463 F DEBUG : #04 pc 000070cb /system/lib/vndk-29/libexpat.so (contentProcessor+36) (BuildId: b95967a5fb4e2dbc8e0650ab6b5a4c6e)
07-31 03:39:23.089 1463 1463 F DEBUG : #05 pc 00004673 /system/lib/vndk-29/libexpat.so (XML_ParseBuffer+86) (BuildId: b95967a5fb4e2dbc8e0650ab6b5a4c6e)
07-31 03:39:23.089 1463 1463 F DEBUG : #06 pc 0003fa38 /vendor/lib/hw/audio.primary.sm6125.so (platform_info_init+444) (BuildId: 8bbfcc7a41151050b88551f6b1e0557d)
07-31 03:39:23.089 1463 1463 F DEBUG : #07 pc 00046b98 /vendor/lib/hw/audio.primary.sm6125.so (platform_init+9200) (BuildId: 8bbfcc7a41151050b88551f6b1e0557d)
07-31 03:39:23.089 1463 1463 F DEBUG : #08 pc 00038658 /vendor/lib/hw/audio.primary.sm6125.so (adev_open+1020) (BuildId: 8bbfcc7a41151050b88551f6b1e0557d)
07-31 03:39:23.089 1463 1463 F DEBUG : #09 pc 0001b681 /vendor/lib/hw/android.hardware.audio@5.0-impl.so (android::hardware::audio::V5_0::implementation::DevicesFactory::loadAudioInterface(char const*, audio_hw_device**)+72) (BuildId: a3b7cd5320c57fde9b203c116c2f2de5)
07-31 03:39:23.089 1463 1463 F DEBUG : #10 pc 0001b2bd /vendor/lib/hw/android.hardware.audio@5.0-impl.so (android::hardware::Return<void> android::hardware::audio::V5_0::implementation::DevicesFactory::openDevice<android::hardware::audio::V5_0::implementation::PrimaryDevice, std::__1::function<void (android::hardware::audio::V5_0::Result, android::sp<android::hardware::audio::V5_0::IDevice> const&)>>(char const*, std::__1::function<void (android::hardware::audio::V5_0::Result, android::sp<android::hardware::audio::V5_0::IDevice> const&)>)+28) (BuildId: a3b7cd5320c57fde9b203c116c2f2de5)
07-31 03:39:23.089 1463 1463 F DEBUG : #11 pc 0001b275 /vendor/lib/hw/android.hardware.audio@5.0-impl.so (android::hardware::audio::V5_0::implementation::DevicesFactory::openDevice(android::hardware::hidl_string const&, std::__1::function<void (android::hardware::audio::V5_0::Result, android::sp<android::hardware::audio::V5_0::IDevice> const&)>)+216) (BuildId: a3b7cd5320c57fde9b203c116c2f2de5)
07-31 03:39:23.090 1463 1463 F DEBUG : #12 pc 0003f041 /system/lib/vndk-29/android.hardware.audio@5.0.so (android::hardware::audio::V5_0::BnHwDevicesFactory::_hidl_openDevice(android::hidl::base::V1_0::BnHwBase*, android::hardware::Parcel const&, android::hardware::Parcel*, std::__1::function<void (android::hardware::Parcel&)>)+220) (BuildId: 97f44903b2ff203f68a0d8f27ce4d390)
07-31 03:39:23.090 1463 1463 F DEBUG : #13 pc 0003f4a3 /system/lib/vndk-29/android.hardware.audio@5.0.so (android::hardware::audio::V5_0::BnHwDevicesFactory::onTransact(unsigned int, android::hardware::Parcel const&, android::hardware::Parcel*, unsigned int, std::__1::function<void (android::hardware::Parcel&)>)+194) (BuildId: 97f44903b2ff203f68a0d8f27ce4d390)
07-31 03:39:23.090 1463 1463 F DEBUG : #14 pc 00068bb7 /system/lib/vndk-sp-29/libhidlbase.so (android::hardware::BHwBinder::transact(unsigned int, android::hardware::Parcel const&, android::hardware::Parcel*, unsigned int, std::__1::function<void (android::hardware::Parcel&)>)+46) (BuildId: a1f85c0ad927d6cf45a73be8f70a94ff)
07-31 03:39:23.090 1463 1463 F DEBUG : #15 pc 0006b0ed /system/lib/vndk-sp-29/libhidlbase.so (android::hardware::IPCThreadState::getAndExecuteCommand()+924) (BuildId: a1f85c0ad927d6cf45a73be8f70a94ff)
07-31 03:39:23.090 1463 1463 F DEBUG : #16 pc 0006c277 /system/lib/vndk-sp-29/libhidlbase.so (android::hardware::IPCThreadState::joinThreadPool(bool)+110) (BuildId: a1f85c0ad927d6cf45a73be8f70a94ff)
07-31 03:39:23.090 1463 1463 F DEBUG : #17 pc 00076c91 /system/lib/vndk-sp-29/libhidlbase.so (android::hardware::PoolThread::threadLoop()+12) (BuildId: a1f85c0ad927d6cf45a73be8f70a94ff)
07-31 03:39:23.090 1463 1463 F DEBUG : #18 pc 0000d853 /system/lib/vndk-sp-29/libutils.so (android::Thread::_threadLoop(void*)+182) (BuildId: 081b7de3d6307c4ac2d946b2280c98eb)
07-31 03:39:23.090 1463 1463 F DEBUG : #19 pc 000a5ea3 /apex/com.android.runtime/lib/bionic/libc.so (__pthread_start(void*)+20) (BuildId: 7b0c9b68af6fcfcb1364f04b4b069424)
07-31 03:39:23.090 1463 1463 F DEBUG : #20 pc 00060773 /apex/com.android.runtime/lib/bionic/libc.so (__start_thread+30) (BuildId: 7b0c9b68af6fcfcb1364f04b4b069424)
```
Looking at this error closely I saw that this is merely an NPE (Null pointer exception) somewhere in `platform_set_mic_mute` function, so I've looked into it and eventually found that it was invoked with `platform` parameter being null and this happens because at the moment when `start_hfp` get called `adev->platform` is not yet initialized. Actually it is called from inside function that right now initializes this field in `audio_hw.c`:
```c
adev->platform = platform_init(adev);
```
I.e. it calls it prematurely and this `start_hfp` have to be delayed. I've fixed this error by adding `is_hfp_enabled_by_config` into `hfp_module` struct and by adding some sanity checks in `hfp_set_parameters` function.
`hfp_set_parameters` get called multiple times and if platform is not initialized at first call - I just store flag that it need to be initialized next time.
6. Finally `hfp` starts and I got `usecase for hfp found` message in the logs and I assumed that this is enough to enable echo cancellation.... though it isn't. Even that I got `start_hfp` invoked it immediately stops because devices it tries to open/use are either do not exist or do not respond properly. This happens here in `start_hfp` function:
```c
hfpmod.hfp_sco_rx = pcm_open(adev->snd_card,
pcm_dev_asm_rx_id,
PCM_OUT, &pcm_config_hfp);
if (hfpmod.hfp_sco_rx && !pcm_is_ready(hfpmod.hfp_sco_rx)) {
ALOGE("%s: %s", __func__, pcm_get_error(hfpmod.hfp_sco_rx));
ret = -EIO;
goto exit;
}
hfpmod.hfp_pcm_rx = pcm_open(adev->snd_card,
pcm_dev_rx_id,
PCM_OUT, &pcm_config_hfp);
if (hfpmod.hfp_pcm_rx && !pcm_is_ready(hfpmod.hfp_pcm_rx)) {
ALOGE("%s: %s", __func__, pcm_get_error(hfpmod.hfp_pcm_rx));
ret = -EIO;
goto exit;
}
hfpmod.hfp_sco_tx = pcm_open(adev->snd_card,
pcm_dev_asm_tx_id,
PCM_IN, &pcm_config_hfp);
if (hfpmod.hfp_sco_tx && !pcm_is_ready(hfpmod.hfp_sco_tx)) {
ALOGE("%s: %s", __func__, pcm_get_error(hfpmod.hfp_sco_tx));
ret = -EIO;
goto exit;
}
hfpmod.hfp_pcm_tx = pcm_open(adev->snd_card,
pcm_dev_tx_id,
PCM_IN, &pcm_config_hfp);
if (hfpmod.hfp_pcm_tx && !pcm_is_ready(hfpmod.hfp_pcm_tx)) {
ALOGE("%s: %s", __func__, pcm_get_error(hfpmod.hfp_pcm_tx));
ret = -EIO;
goto exit;
}
if (pcm_start(hfpmod.hfp_sco_rx) < 0) {
ALOGE("%s: pcm start for hfp sco rx failed", __func__);
ret = -EINVAL;
goto exit;
}
if (pcm_start(hfpmod.hfp_sco_tx) < 0) {
ALOGE("%s: pcm start for hfp sco tx failed", __func__);
ret = -EINVAL;
goto exit;
}
if (pcm_start(hfpmod.hfp_pcm_rx) < 0) {
ALOGE("%s: pcm start for hfp pcm rx failed", __func__);
ret = -EINVAL;
goto exit;
}
if (pcm_start(hfpmod.hfp_pcm_tx) < 0) {
ALOGE("%s: pcm start for hfp pcm tx failed", __func__);
ret = -EINVAL;
goto exit;
}
hfpmod.is_hfp_running = true;
hfp_set_volume(adev, hfpmod.hfp_volume);
/* Set mic volume by mute status, we don't provide set mic volume in phone app, only
provide mute and unmute. */
hfp_set_mic_mute(adev, adev->mic_muted);
ALOGD("%s: exit: status(%d)", __func__, ret);
return 0;
exit:
stop_hfp(adev);
ALOGE("%s: Problem in HFP start: status(%d)", __func__, ret);
return ret;
```
Related logs looks like this:
```
08-01 09:13:54.462 684 1590 E audio_hw_hfp: start_hfp: Problem in HFP start: status(-22)
```
Initially it failed at attempt to call `pcm_open` and bark something like `/dev/snd/pcmC0D39p does't exists` and it ideed does not exist on device (only 'c' ending one does):
```console
pdx201:/ # ls -la /dev/snd/pcmC0D39*
crw-rw---- 1 system audio 116, 55 2021-03-22 16:40 /dev/snd/pcmC0D39c
```
I know that `p` stands for "playback" and `c` for capture, and I also know that devices it will try to use controlled by either `hfp_pcm_dev_id` parameter in `<config_params>` section of `audio_platform.xml` or by definitions of usecases in `pcm_ids` section of the same file. So I've tried to assign them to some values that will match existing sound devices, though this didn't work either. This time it failed at `pcm_start` call with error like this:
```
03-26 19:23:09.144 0 0 I msm-pcm-loopback soc: qcom,msm-pcm-loopback: msm_pcm_open: Instance = 2, Stream ID = MultiMedia6 (*)
03-26 19:23:09.145 0 0 E : SM6150 ASM Loopback: ASoC: no backend DAIs enabled for SM6150 ASM Loopback
03-26 19:23:09.145 684 767 E audio_hw_hfp: start_hfp: pcm start for hfp sco rx failed
```
I can assume that I choose devices for this poorly (I was basically guessing) and if someone knows what values should be - I would very much appreciate your advice.
And one last note... I don't know if all of the above make any sense (i.e. at all related to lack of echo cancellation) because `HFP` stands for `Hands free profile` and apparently have something to do with bluetooth. Though I do see that it get mentioned in code path for enabling speaker. If someone knows if this is at all a correct goal to pursue for solving this issue - please tell me.