[4.4.0.64][Xperia 10 III] The sound disappears and video freeze

Bug Reports
, ,
#61

I had it occur again today, without GPS for sure, so that’s not a (hard) requirement. Unfortunately I think my custom journalctl conf is wrong, since I could only save worth ~5,5MB of logs, instead of what I thought would be 50MB… I have some logs, but I don’t think they reveal the cause yet:

journalctl | grep pulseaudio 
20:11:47 pulseaudio[6518]: E: [pulseaudio] classify.c: could not find group
20:11:47 pulseaudio[6518]: E: [pulseaudio] classify.c: could not find group
20:18:26 pulseaudio[6518]:  Diag_LSM_Init: Failed to open handle to diag driver, error = 13diag: In diagpkt_tbl_reg, service not initialized.
20:18:26 pulseaudio[31871]: W: [pulseaudio] pid.c: Stale PID file, overwriting.
20:18:26 pulseaudio[31871]: library "/vendor/lib64/libsndmonitor.so" not found
20:18:26 pulseaudio[31871]: library "/vendor/lib64/libssrec.so" not found
20:18:26 pulseaudio[31871]: library "/vendor/lib64/libhdmiedid.so" not found
20:18:26 pulseaudio[31871]: library "/vendor/lib64/libhfp.so" not found
20:18:26 pulseaudio[31871]: library "/vendor/lib64/libhdmipassthru.so" not found
20:18:26 pulseaudio[31871]: "/vendor/lib/soundfx/libqcomvisualizer.so" is 32-bit instead of 64-bit
20:18:26 pulseaudio[31871]: library "/vendor/lib/libqtigef.so" not found
20:18:26 pulseaudio[31871]: "/vendor/lib/soundfx/libqcompostprocbundle.so" is 32-bit instead of 64-bit
20:18:26 pulseaudio[31871]: "/vendor/lib/hw/sound_trigger.primary.sm6350.so" is 32-bit instead of 64-bit
20:18:28 pulseaudio[31871]: E: [pulseaudio] client-ext.c: can't obtain command line
20:18:30 pulseaudio[31871]: E: [pulseaudio] classify.c: could not find group
20:47:11 pulseaudio[31871]: E: [pulseaudio] classify.c: could not find group

I’ll browse through the log some more, perhaps there’s something there. Not sure when it started, so I don’t know if it could be in the two hours time window I was able to save this time.

1 Like
#62

No, wait, I think I actually have the info. Judging by the flow of the journal, the very first thing that went wrong was actually pulseaudio[6518]: E: [pulseaudio] classify.c: could not find group and after that there’s a lot of rows beginning with [aw882xx_smartpa]. I can’t really see anything “wrong” except the pulseaudio row above, but perhaps that is a clue! Here’s a snippet around that time:

journalctl pulseaudio error 
20:11:46 kernel: done.
20:11:46 kernel: Freezing user space processes ... (elapsed 0.014 seconds) done.
20:11:46 kernel: OOM killer disabled.
20:11:46 kernel: Freezing remaining freezable tasks ... (elapsed 0.003 seconds) done.
20:11:46 kernel: Suspending console(s) (use no_console_suspend to debug)
20:11:46 kernel: sec_ts 1-0048: [sec_input] sec_ts_pm_suspend:enter
20:11:46 kernel: [kworke][0x80be860d700][20:11:28.047309] wlan: [14037:I:HDD] __wlan_hdd_bus_suspend: 1066: starting bus suspend
20:11:46 kernel: Disabling non-boot CPUs ...
20:11:46 kernel: CPU1: shutdown
20:11:46 kernel: psci: CPU1 killed (polled 0 ms)
20:11:46 kernel: CPU2: shutdown
20:11:46 kernel: psci: CPU2 killed (polled 0 ms)
20:11:46 kernel: CPU3: shutdown
20:11:46 kernel: psci: CPU3 killed (polled 1 ms)
20:11:46 kernel: IRQ 5: no longer affine to CPU4
20:11:46 kernel: CPU4: shutdown
20:11:46 kernel: psci: CPU4 killed (polled 1 ms)
20:11:46 kernel: CPU5: shutdown
20:11:46 kernel: psci: CPU5 killed (polled 0 ms)
20:11:46 kernel: CPU6: shutdown
20:11:46 kernel: psci: CPU6 killed (polled 0 ms)
20:11:46 kernel: CPU7: shutdown
20:11:46 kernel: psci: CPU7 killed (polled 0 ms)
20:11:46 kernel: suspend ns:  221190529883832        suspend cycles:    8847237185212
20:11:46 kernel: resume cycles:    8847596253920
20:11:46 kernel: Enabling non-boot CPUs ...
20:11:46 kernel: Detected VIPT I-cache on CPU1
20:11:46 kernel: arch_timer: CPU1: Trapping CNTVCT access
20:11:46 kernel: CPU1: Booted secondary processor 0x0000000100 [0x51df805e]
20:11:46 kernel: CPU1 is up
20:11:46 kernel: Detected VIPT I-cache on CPU2
20:11:46 kernel: arch_timer: CPU2: Trapping CNTVCT access
20:11:46 kernel: CPU2: Booted secondary processor 0x0000000200 [0x51df805e]
20:11:46 kernel: CPU2 is up
20:11:46 kernel: Detected VIPT I-cache on CPU3
20:11:46 kernel: arch_timer: CPU3: Trapping CNTVCT access
20:11:46 kernel: CPU3: Booted secondary processor 0x0000000300 [0x51df805e]
20:11:46 kernel: CPU3 is up
20:11:46 kernel: Detected VIPT I-cache on CPU4
20:11:46 kernel: arch_timer: CPU4: Trapping CNTVCT access
20:11:46 kernel: CPU4: Booted secondary processor 0x0000000400 [0x51df805e]
20:11:46 kernel: CPU4 is up
20:11:46 kernel: Detected VIPT I-cache on CPU5
20:11:46 kernel: arch_timer: CPU5: Trapping CNTVCT access
20:11:46 kernel: CPU5: Booted secondary processor 0x0000000500 [0x51df805e]
20:11:46 kernel: CPU5 is up
20:11:46 kernel: Detected PIPT I-cache on CPU6
20:11:46 kernel: arch_timer: CPU6: Trapping CNTVCT access
20:11:46 kernel: CPU6: Booted secondary processor 0x0000000600 [0x411fd0d0]
20:11:46 kernel: CPU6 is up
20:11:46 kernel: Detected PIPT I-cache on CPU7
20:11:46 kernel: arch_timer: CPU7: Trapping CNTVCT access
20:11:46 kernel: CPU7: Booted secondary processor 0x0000000700 [0x411fd0d0]
20:11:46 kernel: CPU7 is up
20:11:46 kernel: no screen_state.
20:11:46 kernel: no screen_state.
20:11:46 kernel: [kworke][0x80bfddac3a6][20:11:46.813566] wlan: [14037:I:HDD] wlan_hdd_bus_resume: 1280: starting bus resume
20:11:46 kernel: ufshcd-qcom 1d84000.ufshc: ufshcd_print_pwr_info:[RX, TX]: gear=[1, 1], lane[1, 1], pwr[SLOWAUTO_MODE, SLOWAUTO_MODE], rate = 0
20:11:46 kernel: ufshcd-qcom 1d84000.ufshc: ufs_fixup_device_setup : vid=01ad, model=H9HQ15AECMADAR, spec ver=0210 , fw ver=A902
20:11:46 kernel: ufshcd-qcom 1d84000.ufshc: ufshcd_print_pwr_info:[RX, TX]: gear=[3, 3], lane[2, 2], pwr[FAST MODE, FAST MODE], rate = 2
20:11:46 kernel: sec_ts 1-0048: [sec_input] sec_ts_pm_resume:enter
20:11:46 kernel: OOM killer enabled.
20:11:46 kernel: Restarting tasks ... 
20:11:46 kernel: i2c_pmic 2-0009: ignoring dependency for device, assuming no driver
20:11:46 kernel: sd 0:0:0:0: Power-on or device reset occurred
20:11:46 kernel: done.
20:11:46 kernel: ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
20:11:46 kernel: sd 0:0:0:1: Power-on or device reset occurred
20:11:46 kernel: PM: suspend exit
20:11:46 kernel: ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
20:11:46 kernel: sd 0:0:0:2: Power-on or device reset occurred
20:11:46 kernel: ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
20:11:46 kernel: ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
20:11:46 kernel: ufshcd-qcom 1d84000.ufshc: ufshcd_ioctl: User buffer is NULL!
20:11:47 pulseaudio[6518]: E: [pulseaudio] classify.c: could not find group
20:11:47 kernel: [aw882xx_smartpa]aw882xx_startup: capture enter
20:11:47 kernel: [aw882xx_smartpa]aw882xx_set_fmt: fmt=0x4001
20:11:47 kernel: msm_mi2s_snd_startup: set sysclk failed, err:-524
20:11:47 kernel: __afe_port_start: port id: 0x1001
20:11:47 kernel: afe_find_cal_topo_id_by_port: port id: 0x1001, dev_acdb_id: -22
20:11:47 kernel: afe_find_cal_topo_id_by_port: top_id:1000ff02 acdb_id:102 afe_port:0x1001
20:11:47 kernel: afe_get_cal_topology_id: port_id = 0x1001 acdb_id = 102 topology_id = 0x1000ff02 cal_type_index=8 ret=0
20:11:47 kernel: afe_send_port_topology_id: AFE set topology id 0x1000ff02  enable for port 0x1001 ret 0
20:11:47 kernel: send_afe_cal_type: cal_index is 1
20:11:47 kernel: send_afe_cal_type: dev_acdb_id[41] is -22
20:11:47 kernel: send_afe_cal_type: Sending cal_index cal 1
20:11:47 kernel: afe_send_hw_delay: port_id 0x1001 rate 48000 delay_usec 578 status 0
20:11:47 kernel: [aw882xx_smartpa]aw882xx_mute: mute state=0
20:11:47 kernel: [aw882xx_smartpa]aw882xx_startup: playback enter
20:11:47 kernel: __afe_port_start: port id: 0x1000
20:11:47 kernel: afe_find_cal_topo_id_by_port: port id: 0x1000, dev_acdb_id: 124
20:11:47 kernel: afe_find_cal_topo_id_by_port: top_id:1001025f acdb_id:124 afe_port_id:0x1000
20:11:47 kernel: afe_get_cal_topology_id: port_id = 0x1000 acdb_id = 124 topology_id = 0x1001025f cal_type_index=8 ret=0
20:11:47 kernel: afe_send_port_topology_id: AFE set topology id 0x1001025f  enable for port 0x1000 ret 0
20:11:47 kernel: send_afe_cal_type: cal_index is 0
20:11:47 kernel: send_afe_cal_type: dev_acdb_id[40] is 124
20:11:47 kernel: afe_find_cal: cal_index 0 port_id 0x1000 port_index 40
20:11:47 kernel: afe_find_cal: acdb_id 124 dev_acdb_id 124 sample_rate 48000 afe_sample_rates 48000
20:11:47 kernel: afe_find_cal: cal block is a match, size is 868
20:11:47 kernel: send_afe_cal_type: Sending cal_index cal 0
20:11:47 kernel: afe_send_hw_delay: port_id 0x1000 rate 48000 delay_usec 474 status 0
20:11:47 kernel: [aw882xx_smartpa]aw882xx_mute: mute state=0
20:11:47 kernel: [aw882xx_smartpa]aw882xx_smartpa_cfg: flag = 1, power status = 0
20:11:47 kernel: [aw882xx_smartpa]aw882xx_clear_sysint: get_sysint=0x4395
20:11:47 kernel: [aw882xx_smartpa]aw882xx_clear_sysint: get_sysint=0x0000
20:11:47 kernel: afe_callback: cmd = 0x100fa returned error = 0x1
20:11:47 kernel: afe_apr_send_pkt: DSP returned error[ADSP_EFAILED]
20:11:47 kernel: [aw882xx_smartpa]aw882xx_set_cali_re_to_dsp : set cali re to dsp failed
20:11:47 kernel: [aw882xx_smartpa]aw882xx_monitor_start: enter
20:11:47 kernel: [aw882xx_smartpa]aw882xx_monitor_get_data: vol: ipeak = 0x6, gain = 0x1, vmax = 0x0
20:11:47 kernel: [aw882xx_smartpa]aw882xx_monitor_get_data: temp: ipeak = 0x8, gain = 0x0, vmax = 0x0
20:11:47 kernel: [aw882xx_smartpa]aw882xx_monitor_set_ipeak: ipeak = 0x6, no change
20:11:47 kernel: [aw882xx_smartpa]aw882xx_monitor_set_gain: set_volume = 0.5 dB
20:11:47 kernel: afe_callback: cmd = 0x100fa returned error = 0x1
20:11:47 kernel: afe_apr_send_pkt: DSP returned error[ADSP_EFAILED]
20:11:47 kernel: [aw882xx_smartpa]aw882xx_monitor_set_vmax: dsp_msg_write error
20:11:47 kernel: [aw882xx_smartpa]aw882xx_monitor_set_vmax: set vmax = 0x0
20:11:47 kernel: q6asm_callback: cmd = 0x10db3 returned error = 0x3
20:11:47 kernel: __q6asm_open_write: DSP returned error[ADSP_EUNSUPPORTED]
20:11:47 kernel: msm_pcm_playback_prepare: q6asm_open_write failed (-95)
20:11:47 kernel: msm_audio_ion_free: dma_buf invalid
20:11:47 kernel: msm-pcm-dsp soc:qcom,msm-pcm: ASoC: platform prepare error: -12
20:11:47 kernel: soc_pcm_prepare: Issue stop stream for codec_dai due to op failure -12 = ret
20:11:47 kernel:  KONA Media1: ASoC: prepare FE KONA Media1 failed
20:11:47 kernel: [aw882xx_smartpa]aw882xx_mute: mute state=1
20:11:47 kernel: [aw882xx_smartpa]aw882xx_smartpa_cfg: flag = 0, power status = 2
20:11:47 kernel: [aw882xx_smartpa]aw882xx_monitor_stop: enter
20:11:47 kernel: [aw882xx_smartpa]aw882xx_stop: get_sysint=0x0000
20:11:47 buteo-oopp-runner[29965]: [W] unknown:0 - QConnmanTechnologyInterface::scanReply() "No carrier"
20:11:47 kernel: afe_close: port_id = 0x1000
20:11:47 kernel: [aw882xx_smartpa]aw882xx_mute: mute state=1
20:11:47 kernel: afe_close: port_id = 0x1001
20:11:47 pulseaudio[6518]: E: [pulseaudio] classify.c: could not find group
20:11:47 kernel: [aw882xx_smartpa]aw882xx_startup: capture enter
20:11:47 kernel: [aw882xx_smartpa]aw882xx_set_fmt: fmt=0x4001
20:11:47 kernel: msm_mi2s_snd_startup: set sysclk failed, err:-524
20:11:47 kernel: __afe_port_start: port id: 0x1001
20:11:47 kernel: afe_find_cal_topo_id_by_port: port id: 0x1001, dev_acdb_id: -22
20:11:47 kernel: afe_find_cal_topo_id_by_port: top_id:1000ff02 acdb_id:102 afe_port:0x1001
20:11:47 kernel: afe_get_cal_topology_id: port_id = 0x1001 acdb_id = 102 topology_id = 0x1000ff02 cal_type_index=8 ret=0
20:11:47 kernel: afe_send_port_topology_id: AFE set topology id 0x1000ff02  enable for port 0x1001 ret 0
20:11:47 kernel: send_afe_cal_type: cal_index is 1
20:11:47 kernel: send_afe_cal_type: dev_acdb_id[41] is -22
20:11:47 kernel: send_afe_cal_type: Sending cal_index cal 1
20:11:47 kernel: afe_send_hw_delay: port_id 0x1001 rate 48000 delay_usec 578 status 0
20:11:47 kernel: [aw882xx_smartpa]aw882xx_mute: mute state=0
20:11:47 kernel: [aw882xx_smartpa]aw882xx_startup: playback enter
20:11:47 kernel: __afe_port_start: port id: 0x1000
20:11:47 kernel: afe_find_cal_topo_id_by_port: port id: 0x1000, dev_acdb_id: 124
20:11:47 kernel: afe_find_cal_topo_id_by_port: top_id:1001025f acdb_id:124 afe_port_id:0x1000
20:11:47 kernel: afe_get_cal_topology_id: port_id = 0x1000 acdb_id = 124 topology_id = 0x1001025f cal_type_index=8 ret=0
20:11:47 kernel: afe_send_port_topology_id: AFE set topology id 0x1001025f  enable for port 0x1000 ret 0
20:11:47 kernel: send_afe_cal_type: cal_index is 0
20:11:47 kernel: send_afe_cal_type: dev_acdb_id[40] is 124
20:11:47 kernel: afe_find_cal: cal_index 0 port_id 0x1000 port_index 40
20:11:47 kernel: afe_find_cal: acdb_id 124 dev_acdb_id 124 sample_rate 48000 afe_sample_rates 48000
20:11:47 kernel: afe_find_cal: cal block is a match, size is 868
20:11:47 kernel: send_afe_cal_type: Sending cal_index cal 0
20:11:47 kernel: afe_send_hw_delay: port_id 0x1000 rate 48000 delay_usec 474 status 0
20:11:47 kernel: [aw882xx_smartpa]aw882xx_mute: mute state=0
20:11:47 kernel: [aw882xx_smartpa]aw882xx_smartpa_cfg: flag = 1, power status = 0
20:11:47 kernel: [aw882xx_smartpa]aw882xx_clear_sysint: get_sysint=0x4395
20:11:47 kernel: [aw882xx_smartpa]aw882xx_clear_sysint: get_sysint=0x0000
20:11:47 kernel: afe_callback: cmd = 0x100fa returned error = 0x1
20:11:47 kernel: afe_apr_send_pkt: DSP returned error[ADSP_EFAILED]
20:11:47 kernel: [aw882xx_smartpa]aw882xx_set_cali_re_to_dsp : set cali re to dsp failed
20:11:47 kernel: [aw882xx_smartpa]aw882xx_monitor_start: enter
20:11:47 kernel: [aw882xx_smartpa]aw882xx_monitor_get_data: vol: ipeak = 0x6, gain = 0x1, vmax = 0x0
20:11:47 kernel: [aw882xx_smartpa]aw882xx_monitor_get_data: temp: ipeak = 0x8, gain = 0x0, vmax = 0x0
20:11:47 kernel: [aw882xx_smartpa]aw882xx_monitor_set_ipeak: ipeak = 0x6, no change
20:11:47 kernel: [aw882xx_smartpa]aw882xx_monitor_set_gain: set_volume = 0.5 dB
20:11:47 kernel: afe_callback: cmd = 0x100fa returned error = 0x1
20:11:47 kernel: afe_apr_send_pkt: DSP returned error[ADSP_EFAILED]
20:11:47 kernel: [aw882xx_smartpa]aw882xx_monitor_set_vmax: dsp_msg_write error
20:11:47 kernel: [aw882xx_smartpa]aw882xx_monitor_set_vmax: set vmax = 0x0
20:11:47 kernel: q6asm_callback: cmd = 0x10db3 returned error = 0x3
20:11:47 kernel: __q6asm_open_write: DSP returned error[ADSP_EUNSUPPORTED]

The rest of the log looks clean, but I do have it saved. @flypig I can send the full log for investigation if that seems necessary; what do you think?

Edit: I noticed that mpris-proxy dies in the pulseaudio restart process (which fixes the issue), but the service auto restart does fix the issue after the restart timeout :slight_smile:

1 Like
#63

Thanks for this Matti. If you could please retain the full log that would be appreciated. I’ll try to find someone who has a better idea about this, but it may be the snippet you’ve provided there is already enough, if not I’ll get back to you. There will be a bit of a delay before I can properly look into it due to the Christmas break (and maybe someone else will come along to give you a better answer in the meantime!).

1 Like
#64

Thanks, I’ll have it ready if it’s needed!

I had another incident this morning; one alarm worked but the next alarm did not. I have the logs of it saved, and will post a similar snippet this evening. In this case pulseaudio didn’t fix sounds, so I saved the logs and rebooted my phone, so I expect to see something different this time.

3 Likes
#65

It’s a mess this time, it took me longer to filter out even somewhat relevant lines, but here’s a snippet from the time I tried to restart pulseaudio which didn’t fix the issue anymore:

pulseaudio restart 
09:31:18 pulseaudio[31488]:  Diag_LSM_Init: Failed to open handle to diag driver, error = 13diag: In diagpkt_tbl_reg, service not initialized.
09:31:18 bluetoothd[4356]: bluetoothd[4356]: Endpoint unregistered: sender=:1.2596 path=/MediaEndpoint/A2DPSink/sbc
09:31:18 bluetoothd[4356]: bluetoothd[4356]: Endpoint unregistered: sender=:1.2596 path=/MediaEndpoint/A2DPSource/sbc
09:31:18 systemd[6104]: Stopped PulseAudio.
09:31:18 bluetoothd[4356]: Endpoint unregistered: sender=:1.2596 path=/MediaEndpoint/A2DPSink/sbc
09:31:18 bluetoothd[4356]: Endpoint unregistered: sender=:1.2596 path=/MediaEndpoint/A2DPSource/sbc
09:31:18 systemd[6104]: Starting PulseAudio...
09:31:18 pulseaudio[31898]: W: [pulseaudio] pid.c: Stale PID file, overwriting.
09:31:18 booster-silica-qt5[31891]: [D] unknown:0 - Using Wayland-EGL
09:31:18 pulseaudio[31898]: library "/vendor/lib64/libsndmonitor.so" not found
09:31:18 pulseaudio[31898]: library "/vendor/lib64/libssrec.so" not found
09:31:18 pulseaudio[31898]: library "/vendor/lib64/libhdmiedid.so" not found
09:31:18 pulseaudio[31898]: library "/vendor/lib64/libhfp.so" not found
09:31:18 pulseaudio[31898]: library "/vendor/lib64/libhdmipassthru.so" not found
09:31:18 kernel: msm_qti_pp_get_rms_value_control, back not active to query rms be_idx:3
09:31:18 kernel: core_get_license_status: cmdrsp_license_result.result = 0x15 for module 0x131ff
09:31:18 kernel: aw_qcom_get_module_enable: read afe rx failed 
09:31:18 kernel: [aw882xx_smartpa]aw882xx_rx_enable_get: dsp_msg error, ret=-22
09:31:18 kernel: aw_qcom_get_module_enable: read afe tx failed 
09:31:18 kernel: [aw882xx_smartpa]aw882xx_tx_enable_get: dsp_msg error, ret=-22
09:31:18 kernel: msm_ext_disp_update_audio_ops: Display not found (EXT_DISPLAY_TYPE_DP) ctld (0) stream (0)
09:31:18 kernel: msm_ext_disp_update_audio_ops: Display not found (EXT_DISPLAY_TYPE_HDMI) ctld (0) stream (0)
09:31:18 kernel: msm-ext-disp-audio-codec-rx soc:qcom,msm-ext-disp:qcom,msm-ext-disp-audio-codec-rx: msm_ext_disp_audio_device_get: invalid dai id: 4
09:31:18 kernel: msm_pcm_chmap_ctl_get: substream ref_count:0 invalid
09:31:18 kernel: msm_pcm_volume_ctl_get substream not found
09:31:18 kernel: wcdcal_hwdep_ioctl_shared: codec didn't set this 0!!
09:31:18 kernel: wcdcal_hwdep_ioctl_shared: codec didn't set this 3!!
09:31:18 pulseaudio[31898]: "/vendor/lib/soundfx/libqcomvisualizer.so" is 32-bit instead of 64-bit
09:31:18 pulseaudio[31898]: library "/vendor/lib/libqtigef.so" not found
09:31:18 pulseaudio[31898]: "/vendor/lib/soundfx/libqcompostprocbundle.so" is 32-bit instead of 64-bit
09:31:18 pulseaudio[31898]: "/vendor/lib/hw/sound_trigger.primary.sm6350.so" is 32-bit instead of 64-bit
09:31:18 kernel: [aw882xx_smartpa]aw882xx_startup: capture enter
09:31:18 kernel: [aw882xx_smartpa]aw882xx_set_fmt: fmt=0x4001
09:31:18 kernel: msm_mi2s_snd_startup: set sysclk failed, err:-524
09:31:18 kernel: __afe_port_start: port id: 0x1001
09:31:18 kernel: afe_find_cal_topo_id_by_port: port id: 0x1001, dev_acdb_id: -22
09:31:18 kernel: afe_find_cal_topo_id_by_port: top_id:1000ff02 acdb_id:102 afe_port:0x1001
09:31:18 kernel: afe_get_cal_topology_id: port_id = 0x1001 acdb_id = 102 topology_id = 0x1000ff02 cal_type_index=8 ret=0
09:31:18 kernel: afe_send_port_topology_id: AFE set topology id 0x1000ff02  enable for port 0x1001 ret 0
09:31:18 kernel: send_afe_cal_type: cal_index is 1
09:31:18 kernel: send_afe_cal_type: dev_acdb_id[41] is -22
09:31:18 kernel: send_afe_cal_type: Sending cal_index cal 1
09:31:18 kernel: afe_send_hw_delay: port_id 0x1001 rate 48000 delay_usec 578 status 0
09:31:18 kernel: [aw882xx_smartpa]aw882xx_mute: mute state=0
09:31:18 kernel: [aw882xx_smartpa]aw882xx_startup: playback enter
09:31:18 kernel: __afe_port_start: port id: 0x1000
09:31:18 kernel: afe_find_cal_topo_id_by_port: port id: 0x1000, dev_acdb_id: 124
09:31:18 kernel: afe_find_cal_topo_id_by_port: top_id:1001025f acdb_id:124 afe_port_id:0x1000
09:31:18 kernel: afe_get_cal_topology_id: port_id = 0x1000 acdb_id = 124 topology_id = 0x1001025f cal_type_index=8 ret=0
09:31:18 kernel: afe_send_port_topology_id: AFE set topology id 0x1001025f  enable for port 0x1000 ret 0
09:31:18 kernel: send_afe_cal_type: cal_index is 0
09:31:18 kernel: send_afe_cal_type: dev_acdb_id[40] is 124
09:31:18 kernel: afe_find_cal: cal_index 0 port_id 0x1000 port_index 40
09:31:18 kernel: afe_find_cal: acdb_id 124 dev_acdb_id 124 sample_rate 48000 afe_sample_rates 48000
09:31:18 kernel: afe_find_cal: cal block is a match, size is 868
09:31:18 kernel: send_afe_cal_type: Sending cal_index cal 0
09:31:18 kernel: afe_send_hw_delay: port_id 0x1000 rate 48000 delay_usec 474 status 0
09:31:18 kernel: [aw882xx_smartpa]aw882xx_mute: mute state=0
09:31:18 kernel: [aw882xx_smartpa]aw882xx_smartpa_cfg: flag = 1, power status = 0
09:31:18 kernel: [aw882xx_smartpa]aw882xx_clear_sysint: get_sysint=0x4395
09:31:18 kernel: [aw882xx_smartpa]aw882xx_clear_sysint: get_sysint=0x0000
09:31:18 kernel: afe_callback: cmd = 0x100fa returned error = 0x1
09:31:18 kernel: afe_apr_send_pkt: DSP returned error[ADSP_EFAILED]
09:31:18 kernel: [aw882xx_smartpa]aw882xx_set_cali_re_to_dsp : set cali re to dsp failed
09:31:18 kernel: [aw882xx_smartpa]aw882xx_monitor_start: enter
09:31:18 kernel: [aw882xx_smartpa]aw882xx_monitor_get_data: vol: ipeak = 0x8, gain = 0x0, vmax = 0x0
09:31:18 kernel: [aw882xx_smartpa]aw882xx_monitor_get_data: temp: ipeak = 0x8, gain = 0x0, vmax = 0x0
09:31:18 kernel: [aw882xx_smartpa]aw882xx_monitor_set_ipeak: ipeak = 0x8, no change
09:31:18 kernel: [aw882xx_smartpa]aw882xx_monitor_set_gain: set db = 0.0 dB, no change
09:31:18 kernel: afe_callback: cmd = 0x100fa returned error = 0x1
09:31:18 kernel: afe_apr_send_pkt: DSP returned error[ADSP_EFAILED]
09:31:18 kernel: [aw882xx_smartpa]aw882xx_monitor_set_vmax: dsp_msg_write error
09:31:18 kernel: [aw882xx_smartpa]aw882xx_monitor_set_vmax: set vmax = 0x0
09:31:18 systemd[6104]: Started PulseAudio.
09:31:18 bluetoothd[4356]: bluetoothd[4356]: Endpoint registered: sender=:1.2630 path=/MediaEndpoint/A2DPSink/sbc
09:31:18 bluetoothd[4356]: bluetoothd[4356]: Endpoint registered: sender=:1.2630 path=/MediaEndpoint/A2DPSource/sbc
09:31:18 bluetoothd[4356]: Endpoint registered: sender=:1.2630 path=/MediaEndpoint/A2DPSink/sbc
09:31:18 bluetoothd[4356]: Endpoint registered: sender=:1.2630 path=/MediaEndpoint/A2DPSource/sbc
09:31:19 kernel: [aw882xx_smartpa]aw882xx_mute: mute state=1
09:31:19 kernel: [aw882xx_smartpa]aw882xx_smartpa_cfg: flag = 0, power status = 2
09:31:19 kernel: [aw882xx_smartpa]aw882xx_monitor_stop: enter
09:31:19 kernel: [aw882xx_smartpa]aw882xx_stop: get_sysint=0x0000
09:31:19 kernel: afe_close: port_id = 0x1000
09:31:19 kernel: [aw882xx_smartpa]aw882xx_mute: mute state=1
09:31:19 kernel: afe_close: port_id = 0x1001
09:31:20 pulseaudio[31898]: E: [pulseaudio] client-ext.c: can't obtain command line

I think the most obvious new thing here is E: [pulseaudio] client-ext.c: can't obtain command line but I wasn’t able to figure that one out. It contains the successful alarm at 08:00 and the non-successful one later on, until I tried to restart pulseaudio three times without success, then grabbed the log, and finally restated the device. The full log is saved this time, too, if it is needed.

The uptime was around around 12.5 days, as it was the last time my device started acting up strangely. I wonder if uptime alone has something to do with this…

I hope this gets us closer to the root cause!

Edit: One million seconds is ~11.5 days, which would be close enough to be a meaningful data point, especially considering Android devices start reminding the user to reboot the device around ten days (or was it seven days?)…

2 Likes
#66

I start to believe it has something to do with the lowmemorykiller (indirectly maybe), if your minfree values are used pulseaudio crashes much less. And restarting in one command does not work for me but stopping and then starting pulseaudio works. Today it crashed after update to sfos 4.5 becaus minfree values were overwritten. But rarely it crashed before too

1 Like
#67

Nope, it wasn’t that. Has happened with <7d uptimes a few times now (with 4.4.0).

It’s possible, but I’ve had sounds die overnight, with no browsers or other “major” applications open. I haven’t been able to catch oomkiller in action once with anything sound-related. But; it could trickle down from the Android side…

Has anyone had this happen without Android support installed? How about with community port devices?

#68

Added to internal bugzilla

4 Likes
#69

Today only a reboot brought the sound back. That’s quite annoying because it’s the last step before this phone becomes perfect with this os. The rest works super well and it is a great joy to use sailfish os on this phone, besides that.

#70

I have had this happen overnight too - when there are no apps open and the phone, on the surface, is idle. Very irritating as the only way I find out is when the alarm doesn’t sound. A reboot is the only fix for me.

I’m starting to wonder whether a lot of things on my phone that just ‘die’ periodically (all sound, Bluetooth, Office365 account synchronization) could be down to the same core issue - out of memory?

#71

It may be memory pressure, but it can be something else altogether. I suspect something else, and haven’t had tgis happen in many weeks.

Are you sure Bluetooth audio dies too? I tested this twice when it happened and both times audio routed to my headphones without issues. (X10III)

1 Like
#72

Not ‘Bluetooth audio’ but bluetooth and audio die periodically.

#73

I think think SFOS has many problems with the lowmemory killer which needs to be improved, but there the problem is that Pulseaudio fails silently without any error, even pulseaudio --check doesn’t show anything. Other processes deal with that much more gracefully.

2 Likes
#74

Yes when i tested it audio also was routed to Bluetooth but audio wasn’t working on the device when it wasn’t routed to Bluetooth

#75

well if it’s a low memory issue, maybe you could just add script to monitor the memory over the time?
The only problem from what I see is to find out it’s not working as pulseaudio doesn’t provide itself any meaningful info regarding it’s working properly or not.

#76

If something is OOM killed it’s easy to see in dmesg log.
If there’s no report of the oom killer event, it was something else.

I have a systemd checker script for that somewhere.

#77

a side question. Is there anyone here that doesn’t have android support and still see this issue?

#78

I remember one time when that happened, and I couldn’t find anything OOM-related in the logs. It’s not to say that it can’t never happen as an OOM side effect, but does rise the pulseaudio crash scenario a lot higher.

#79

Since i only loose audio after the use of GPS, i never lost it while using GPS. Could it be that the bug is triggered by disabling or keeping it enabled and not using it? Has anyone lost audio while using GPS?

#80

Do you also have loud popping and cracking sounds sometimes when you play audio?