search

termux / termux-packages

A package build system for Termux.
https://termux.dev
Other
13.26k stars 3.05k forks source link

[Bug]: mpd restarts after playing exactly for 10 seconds #14582

Closed dxcvvxd closed 10 months ago

dxcvvxd commented 1 year ago

Problem description

trying to use mpd with ncmpcpp now, and when i play a track after 10 seconds it either switches to the next one or restarts depending on repeat mode

What steps will reproduce the bug?

start mpd start ncmpcpp play a track for 10 seconds

What is the expected behavior?

it should play the whole track and then switch to next one if needed

System information

termux-info:

TERMUX_API_APP__VERSION_NAME=0.50.1+2c6674f
TERMUX_APP_PACKAGE_MANAGER=apt
TERMUX_APP__AM_SOCKET_SERVER_ENABLED=true
TERMUX_APP__APK_PATH=/data/app/~~ab5x9SiJYPo-1vUt46Guxw==/com.termux-etB5XC8Q7uD_n5hFXZ7Gyg==/base.apk
TERMUX_APP__APK_RELEASE=GITHUB
TERMUX_APP__FILES_DIR=/data/user/0/com.termux/files
TERMUX_APP__IS_DEBUGGABLE_BUILD=true
TERMUX_APP__IS_INSTALLED_ON_EXTERNAL_STORAGE=false
TERMUX_APP__PACKAGE_MANAGER=apt
TERMUX_APP__PACKAGE_NAME=com.termux
TERMUX_APP__PACKAGE_VARIANT=apt-android-5
TERMUX_APP__PID=31985
TERMUX_APP__SE_FILE_CONTEXT=u:object_r:app_data_file:s0:c147,c256,c512,c768
TERMUX_APP__SE_INFO=default:targetSdkVersion=28:complete
TERMUX_APP__SE_PROCESS_CONTEXT=u:r:untrusted_app_27:s0:c147,c256,c512,c768
TERMUX_APP__TARGET_SDK=28
TERMUX_APP__UID=10147
TERMUX_APP__USER_ID=0
TERMUX_APP__VERSION_CODE=118
TERMUX_APP__VERSION_NAME=0.118.0+be66cff
TERMUX_MAIN_PACKAGE_FORMAT=debian
TERMUX_VERSION=0.118.0+be66cff
Packages CPU architecture:
aarch64
Subscribed repositories:
# sources.list
deb https://grimler.se/termux/termux-main stable main
# root-repo (sources.list.d/root.list)
deb https://grimler.se/termux/termux-root root stable
# x11-repo (sources.list.d/x11.list)
deb https://grimler.se/termux/termux-x11 x11 main
Updatable packages:
All packages up to date
termux-tools version:
1.35.0
Android version:
12
Kernel build information:
Linux localhost 4.9.190+ #1 SMP PREEMPT Wed Apr 7 19:02:35 CST 2021 aarch64 Android
Device manufacturer:
Blackview
Device model:
BV5900
Grimler91 commented 1 year ago

I can't reproduce the issue on aarch64 android 10, please post logs, run mpd in verbose mode if needed: mpd --no-daemon --verbose 2>&1 | tee mpd.log.

It says that you are using the app variant that is compiled for android-5 and 6, even though you are on android 12:

TERMUX_APP__PACKAGE_VARIANT=apt-android-5

It's pretty weird that you seem to be subscribed to the correct repos though. Possibly you had the correct app variant installed and then "upgraded" to an apt-android-5 variant instead

dxcvvxd commented 1 year ago

no idea how i could've done that, but here are the logs mpd.log it's got nothing useful though, so i don't really know how is this fixable

dxcvvxd commented 1 year ago

i installed 118 again and termux-info has changed a little:

Termux Variables:
TERMUX_API_VERSION=0.50.1+2c6674f
TERMUX_APK_RELEASE=GITHUB
TERMUX_APP_PACKAGE_MANAGER=apt
TERMUX_APP_PID=21207
TERMUX_IS_DEBUGGABLE_BUILD=1
TERMUX_MAIN_PACKAGE_FORMAT=debian
TERMUX_VERSION=0.118.0
Packages CPU architecture:
aarch64
Subscribed repositories:
# sources.list
deb https://grimler.se/termux/termux-main stable main
# root-repo (sources.list.d/root.list)
deb https://grimler.se/termux/termux-root root stable
# x11-repo (sources.list.d/x11.list)
deb https://grimler.se/termux/termux-x11 x11 main
Updatable packages:
All packages up to date
termux-tools version:
1.35.0
Android version:
12
Kernel build information:
Linux localhost 4.9.190+ #1 SMP PREEMPT Wed Apr 7 19:02:35 CST 2021 aarch64 Android
Device manufacturer:
Blackview
Device model:
BV5900
Grimler91 commented 1 year ago

Latest debug apk is available here: https://github.com/termux/termux-app/suites/9903101676/artifacts/478597812

Does issue remain after installation of 0.118 or the one linked above? The mpd.log doesn't contain any useful information unfortunately

dxcvvxd commented 1 year ago

it does remain, I'll try to install latest build

nothing really changed, maybe i should remove and reinstall something?

dxcvvxd commented 1 year ago

i just noticed that after updating termux-info says TERMUX_APP__PACKAGE_VARIANT=apt-android-7 should it say apt-android-12?

TomJo2000 commented 1 year ago

That's just a distinction from the legacy versions of Termux for Android 5 and 6. The apt-android-7 version supports all Android versions starting with Android 7. (As far as I am aware)

dxcvvxd commented 1 year ago

oh ok, but it still doesnt work so maybe i should actually reinstall something?

Grimler91 commented 1 year ago

@dxcvvxd I don't really have any idea why it doesn't work for you. You could try removing with rm -rf $PREFIX to remove all installed packages and the restart the app to reset to bootstrap installation, after that upgrade all packages, install mpd, ncmpcpp and try again. You could also check if anything relevant is printed in a logcat (captured from adb or as root) when it changes song

dxcvvxd commented 1 year ago

I've reset everything, deleted and reinstalled termux, installed just what i need (also did pkg upgrade ofc) and the issue remains, it always seems to restart when it reaches 10, 20, 30 etc seconds. I'll try to look at logcat, maybe there's something useful.

edit: logs (just grepped mpd) Screenshot_20230116-214450_Termux

xtkoba commented 1 year ago

I see SIGSEGV in that log. Can you please share the full logcat output in some time range? Backtrace should be included in it, though not very useful unless debug build of packages are used.

xtkoba commented 1 year ago

Debug build:

https://github.com/termux/termux-packages/actions/runs/3947258535

You can get more meaningful backtrace with this.

dxcvvxd commented 1 year ago

Debug build:

i have no idea how to install it (it's neither a .zip nor a .apk)

share the full logcat

sure, I've copied the part where i do the mpd thing

01-19 20:32:03.744  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581164): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:system_server:s0 tclass=process permissive=0
01-19 20:32:03.756  2341  2387 W WindowManager: Unable to start animation, surface is null or no children.
01-19 20:32:03.756  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581165): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:system_server:s0 tclass=process permissive=0
01-19 20:32:03.769  1736  1736 I hwcomposer: [HWCDisplay] [Display_0 (type:1)] fps:28.964684,dur:1001.22,max:296.01,min:11.17  
01-19 20:32:03.771  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Reallocate Slot(2), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:03.927  1736  1824 I hwcomposer: [OVL] (0) Overlay input(4) was used with queue previously  
01-19 20:32:03.927  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Buffer queue is destroyed  
01-19 20:32:03.927  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Free Slot(0), handle=0x6fb86f1550, 4377600 -> 0  
01-19 20:32:03.927  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Free Slot(1), handle=0x6fb86efa50, 4377600 -> 0  
01-19 20:32:03.927  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Free Slot(2), handle=0x6fb86ef150, 4377600 -> 0  
01-19 20:32:03.944  2341  4094 I NotificationService: cancelToast pkg=com.termux token=android.os.BinderProxy@ea1e5ee
01-19 20:32:03.944  2341  4094 W NotificationService: Toast already cancelled. pkg=com.termux token=android.os.BinderProxy@ea1e5ee
01-19 20:32:04.051 20144 20215 I OpenGLRenderer: Davey! duration=9223349749501ms; Flags=0, FrameTimelineVsyncId=1448972, IntendedVsync=22287352948189, Vsync=22287402948190, InputEventId=0, HandleInputStart=22287412232865, AnimationStart=22287412236481, PerformTraversalsStart=22287412764789, DrawStart=22287413057327, FrameDeadline=22287386281523, FrameInterval=22287412224558, FrameStartTime=16666667, SyncQueued=22287415359712, SyncStart=22287415662327, IssueDrawCommandsStart=22287415923327, SwapBuffers=22287418033942, FrameCompleted=9223372036854775807, DequeueBufferDuration=0, QueueBufferDuration=890385, GpuCompleted=9223372036854775807, SwapBuffersCompleted=22287419739327, DisplayPresentTime=0, 
01-19 20:32:04.265  2341  2560 E WifiVendorHal: getWifiLinkLayerStats_1_3_Internal(l.1168) failed {.code = ERROR_NOT_SUPPORTED, .description = }
01-19 20:32:04.275  2341  2560 D WifiClientModeImpl[wlan0]: updateLinkLayerStatsRssiSpeedFrequencyCapabilities rssi=-72 TxLinkspeed=65 freq=2412 RxLinkSpeed=0
01-19 20:32:04.276  2341  2560 D WifiDataStall: tx tput in kbps: -1000
01-19 20:32:04.276  2341  2560 D WifiDataStall: rx tput in kbps: -1000
01-19 20:32:04.276  2341  2560 V WifiConfigManager: Updating scan detail cache freq=2412 BSSID=c8:3a:35:d0:b3:08 RSSI=-71 for "Home43"WPA_PSK
01-19 20:32:04.277  2341  2560 D WifiThroughputPredictor:  utilization (BssLoad) -1 utilization (LLStats) 80 isBluetoothConnected: false final utilization: 80
01-19 20:32:04.277  2341  2560 D WifiThroughputPredictor:  utilization (BssLoad) -1 utilization (LLStats) 80 isBluetoothConnected: false final utilization: 80
01-19 20:32:04.277  2341  2560 D WifiScoreReport: Wifi scoring disabled - Stay a notch above the transition score
01-19 20:32:04.277  2341  2572 D ConnectivityService: NetReassign [no changes]
01-19 20:32:04.278  2341  2560 D WifiScoreReport: Wifi scoring disabled - Don't check IP layer
01-19 20:32:04.279  2341  2560 D WifiScoreCard: BSSID update SIGNAL_POLL ID: 1562707524 SSID: "Home43", BSSID: c8:3a:35:d0:b3:08, MAC: 00:45:64:48:a3:25, Security type: 2, Supplicant state: COMPLETED, Wi-Fi standard: 0, RSSI: -72, Link speed: 65Mbps, Tx Link speed: 65Mbps, Max Supported Tx Link speed: -1Mbps, Rx Link speed: -1Mbps, Max Supported Rx Link speed: -1Mbps, Frequency: 2412MHz, Net ID: 1, Metered hint: false, score: 51, CarrierMerged: false, SubscriptionId: -1, IsPrimary: 1
01-19 20:32:04.279  2341  2560 D WifiScoreCard: txRate: 1 txSpeed: 65
01-19 20:32:04.279  2341  2560 D WifiScoreCard: network update SIGNAL_POLL "Home43" ID: 24213653 RSSI -72 txSpeed -1
01-19 20:32:04.281  2341  2560 D WifiClientModeImpl[wlan0]:  L2ConnectedState screen=on 22 0 "Home43" c8:3a:35:d0:b3:08 rssi=-72 f=2412 sc=51 link=65 tx=0.0, 0.0, 0.0  rx=0.0 bcn=0 [on:0 tx:0 rx:0 period:3019] from screen [on:0 period:374644] score=51
01-19 20:32:04.406  3824 19878 I PhenotypeProcessReaper: Memory state is: 125
01-19 20:32:04.555  2124  2240 I  2124  2240 [sunwave-hal] : (733) 'healthMonitoringThread' enter.
01-19 20:32:04.556  2124  2240 I  2124  2240 [sunwave-client] : (90) ---8<---- TA LOG BEGINS ---------
01-19 20:32:04.556  2124  2240 I  2124  2240 [sunwave-ta-core] : (2873) 'sf_get_device_state' state:0008
01-19 20:32:04.556  2124  2240 I  2124  2240 [sunwave-client] : (107) --------- TA LOG FINISH ---->8---
01-19 20:32:04.556  2124  2240 I  2124  2240 [sunwave-hal] : (747) 'healthMonitoringThread' state:0008
01-19 20:32:04.557  2124  2240 I  2124  2240 [sunwave-client] : (90) ---8<---- TA LOG BEGINS ---------
01-19 20:32:04.557  2124  2240 I  2124  2240 [sunwave-ic8201] : (181) low power
01-19 20:32:04.558  2124  2240 I  2124  2240 [sunwave-client] : (107) --------- TA LOG FINISH ---->8---
01-19 20:32:04.740  1736  1824 W hwcomposer: [OVL] (0) No overlay input queue(5)  
01-19 20:32:04.740  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Buffer queue is created with size(3)  
01-19 20:32:04.740  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) setConsumerListener  
01-19 20:32:04.740  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Reallocate Slot(0), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:04.784  2131  2131 W Binder:2131_5: type=1400 audit(0.0:1581234): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:system_server:s0 tclass=process permissive=0
01-19 20:32:04.800  2131  2131 W Binder:2131_5: type=1400 audit(0.0:1581235): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:system_server:s0 tclass=process permissive=0
01-19 20:32:04.820  2131  2131 W Binder:2131_5: type=1400 audit(0.0:1581236): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:system_server:s0 tclass=process permissive=0
01-19 20:32:04.835  1736  1736 I hwcomposer: [HWCDisplay] [Display_0 (type:1)] fps:21.594570,dur:1065.08,max:277.00,min:15.84  
01-19 20:32:04.836  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Reallocate Slot(1), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:04.836  2131  2131 W Binder:2131_5: type=1400 audit(0.0:1581237): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:system_server:s0 tclass=process permissive=0
01-19 20:32:04.852  2131  2131 W Binder:2131_5: type=1400 audit(0.0:1581238): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:untrusted_app_27:s0:c147,c256,c512,c768 tclass=process permissive=0
01-19 20:32:04.863  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Reallocate Slot(2), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:05.018  1736  1824 I hwcomposer: [OVL] (0) Overlay input(5) was used with queue previously  
01-19 20:32:05.018  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Buffer queue is destroyed  
01-19 20:32:05.018  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Free Slot(0), handle=0x6fb86f0290, 4377600 -> 0  
01-19 20:32:05.019  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Free Slot(1), handle=0x6fb86efa50, 4377600 -> 0  
01-19 20:32:05.019  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Free Slot(2), handle=0x6fb86ee910, 4377600 -> 0  
01-19 20:32:05.264  1736  1824 W hwcomposer: [OVL] (0) No overlay input queue(5)  
01-19 20:32:05.264  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Buffer queue is created with size(3)  
01-19 20:32:05.264  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) setConsumerListener  
01-19 20:32:05.264  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Reallocate Slot(0), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:05.295  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Reallocate Slot(1), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:05.329  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Reallocate Slot(2), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:05.387 20225 20632 D ProcessState: Binder ioctl to enable oneway spam detection failed: Invalid argument
01-19 20:32:05.395 20225 20632 D mpd     : PlayerBase::PlayerBase()
01-19 20:32:05.399 20225 20632 D mpd     : TrackPlayerBase::TrackPlayerBase()
01-19 20:32:05.399 20225 20632 I libOpenSLES: Emulating old channel mask behavior (ignoring positional mask 0x3, using default mask 0x3 based on channel count of 2)
01-19 20:32:05.416  2129 30442 D AudioFlinger: Client defaulted notificationFrames to 2050 for frameCount 4100
01-19 20:32:05.420  2129 30442 D AF::TrackHandle: OpPlayAudio: track:208 usage:1 not muted
01-19 20:32:05.429  2129 23432 W AudioFlinger: moveEffectChain_l() effect chain for session 0 not on source thread 0x7dc386ea60
01-19 20:32:05.438  2090 15179 D AudioALSAStreamManager: +syncSharedOutDevice(), routingSharedOutDevice: 4
01-19 20:32:05.438  2090 15179 D AudioALSAStreamManager: -syncSharedOutDevice()
01-19 20:32:05.439 20225 20635 D mpd     : PlayerBase::stop() from IPlayer
01-19 20:32:05.439 20225 20635 D AudioTrack: stop(220): called with 0 frames delivered
01-19 20:32:05.440  2090 15179 D AudioMTKGainController: setNormalVolume(), mSceneIndex = 0, stream -1, devices 0x4, index 5, mode 0x0
01-19 20:32:05.440  2090 15179 W AudioMTKGainController: error, stream -1 is invalid, use 3 instead
01-19 20:32:05.440  2090 15179 D AudioMTKGainController: tuneGainForHpImpedance(), after compesate HP impedance idx (2), bufferGain = 6
01-19 20:32:05.440  2090 15179 D AudioALSAStreamOut: open(), flags 8
01-19 20:32:05.440  2090 15179 D AudioALSAStreamManager: +createPlaybackHandler(), mAudioMode = 0, output_devices = 0x4, isMixerOut = 0x0, flag = 8
01-19 20:32:05.440  2090 15179 D AudioALSAStreamManager: needEnableVoip(), output_devices = 0x4, flags: 0x8, mAvailableOutputFlags: 0xe
01-19 20:32:05.440  2090 15179 E AudioCustParam: set_hct_mic_num(), hct_dula_mic_num=1, hct_dula_mic_flag [0, 0], hct_voip_flag [0, 0]
01-19 20:32:05.440  2090 15179 E AudioCustParam: set_hct_mic_num(): ret = 1
01-19 20:32:05.440  2090 15179 E AudioCustParam: set_hct_mic_num(): mic_buf = 11
01-19 20:32:05.440  2090 15179 E AudioCustParam: get_hct_cts_mode. size=2, length = 2 , mic_buf=11
01-19 20:32:05.440  2090 15179 E AudioCustParam: QueryFeatureSupportInfo! set_hct_mic_num() = 1. 
01-19 20:32:05.440  2090 15179 D AudioALSAPlaybackHandlerNormal: +open(), flag = 8, source output_devices = 0x4, audio_format = 3, buffer_size = 16384, sample_rate = 48000
01-19 20:32:05.440  2090 15179 D AudioALSADeviceParser: compare pcm success = 8, stringpair = Deep_Buffer_PLayback
01-19 20:32:05.441  2090 15179 D AudioALSAPlaybackHandlerBase: transferAudioFormatToPcmFormat(), audio_format(0x4) => pcm_format(0x1)
01-19 20:32:05.441  2090 15179 D AudioALSAPlaybackHandlerNormal: open(), flag = 8, mConfig: channels = 2, sample_rate(target) = 48000, period_size = 2048, period_count = 2, format = 1, avail_min = 2048, start_threshold = 0
01-19 20:32:05.441  2090 15179 D AudioALSAPlaybackHandlerNormal: SetLowJitterMode(), bypass low jitter mode, bEnable = 1, device = 0x4, SampleRate = 48000
01-19 20:32:05.463  2090 15179 D AudioALSAPlaybackHandlerBase: openPcmDriverWithFlag(), pcm device = 8 flag = 0x8 mPcm = 0xf17423b0
01-19 20:32:05.463  2090 15179 D AudioALSAPlaybackHandlerBase: CreateAurisysLibManager, voip: 0, mAurisysScenario: 0
01-19 20:32:05.463  2090 15179 D aurisys_utility: input dev: 0x80000010, fmt = 0x3, fs: 48000, max fs: 48000, ch: 1, max ch: 1, ch maks: 0x3, hw_info_mask: 0x0; output dev: 0x4, fmt = 0x3, fs: 48000, max fs: 48000, ch: 2, max ch: 2, ch maks: 0x3, hw_info_mask: 0x0; task_scene: 2, audio_mode: 0, stream_type: -1, output_flags: 0x8, input_source: 0, input_flags: 0x0; network_info: 0, enhancement_feature_mask: 0x0
01-19 20:32:05.463  2090 15179 D aurisys_utility: lib, working fs: 48000, fmt: 0x3, frame = 0, b_interleave = 1, num_ul_ref_buf_array = 0, num_dl_ref_buf_array = 0
01-19 20:32:05.463  2090 15179 D aurisys_utility: dl in[type:2], ch: 2, ch_mask: 0x3, buf fs: 48000, buf content fs: 48000, fmt: 0x3; dl out[type:3], ch: 2, ch_mask: 0x3, buf fs: 48000, buf content fs: 48000, fmt: 0x3
01-19 20:32:05.463  2090 15179 D AudioCompFltCustParam: audioHierarchicalParamEnable [1]
01-19 20:32:05.463  2090 15179 D AudioCompFltCustParam: getPlaybackPostProcessParameterFromXML Type/Name [1]/[PlaybackHCF]
01-19 20:32:05.463  2090 15179 D AudioCompFltCustParam: Load from scene Scene,Default,Profile,Headset
01-19 20:32:05.463  2090 15179 D aurisys_lib_handler: aurisys_arsi_parsing_param_file(), gProductInfo "platform=MT6761,device=BV5900,model=BV5900", file_path "/vendor/etc/audio_param", enhancement_mode 0, param_buf_size 2528, data_size 2528, custom_info SetAudioCustomScene=
01-19 20:32:05.463  2090 15179 D aurisys_lib_handler: aurisys_arsi_create_handler(), lib_name mtk_bessound, 0xefc04390, memory_size 72624, arsi_handler 0xf2ac1450, retval 0x0
01-19 20:32:05.463  2090 15179 D aurisys_lib_handler: aurisys_arsi_create_handler(), arsi_query_process_unit_bytes, ul 0, dl 4096, retval 0
01-19 20:32:05.464  2090 15179 D aurisys_lib_manager: DL Lib, lib_name mtk_bessound, 0xefc04390, sample_rate: 48000 => 48000, num_channels: 2 => 2, audio_format: 0x3 => 0x3, interleave: 1 => 1, frame: 0 => 0
01-19 20:32:05.464  2090 15179 D aurisys_lib_manager: DL out, sample_rate: 48000 => 48000, num_channels: 2 => 2, audio_format: 0x3 => 0x4, interleave: 1 => 1, frame: 0 => 0
01-19 20:32:05.464  2090 15179 D AudioALSAHardwareResourceManager: +startOutputDevice(), new_devices = 0x4, mOutputDevices = 0x0, mStartOutputDevicesCount = 0 SampleRate = 48000
01-19 20:32:05.464  2090 15179 D AudioALSADeviceConfigManager: ApplyDeviceTurnonSequenceByName() DeviceName = headphone_output descriptor->DeviceStatusCounte = 0
01-19 20:32:05.496  2090 15179 D AudioALSAPlaybackHandlerNormal: -open()
01-19 20:32:05.496  2090 15179 D AudioALSAPlaybackHandlerNormal: setScreenState(), flag = 8, rate = 2048, mInterrupt = 0.042667, mode = 1, sample_rate(target) = 48000, buffer_size = 16384, channel = 2, format = 4, reduceInterruptSize = 1024
01-19 20:32:05.519  1736  1824 I hwcomposer: [OVL] (0) Overlay input(5) was used with queue previously  
01-19 20:32:05.520  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Buffer queue is destroyed  
01-19 20:32:05.520  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Free Slot(0), handle=0x6fb86f07d0, 4377600 -> 0  
01-19 20:32:05.520  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Free Slot(1), handle=0x6fb86efa50, 4377600 -> 0  
01-19 20:32:05.520  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Free Slot(2), handle=0x6fb86f1010, 4377600 -> 0  
01-19 20:32:05.541  2129  2296 D AudioFlinger: mixer(0x7dbf57ea60) throttle end: throttle time(18)
01-19 20:32:05.546  2129 23432 E HalHidl : EffectsFactory 0x7b51357aa0 dumpEffects: Status(EX_TRANSACTION_FAILED): 'FAILED_TRANSACTION: ' (from rpc)
01-19 20:32:05.554  2129 23432 E HalHidl : Stream 0x7bd13590e0 dump: Status(EX_TRANSACTION_FAILED): 'FAILED_TRANSACTION: ' (from rpc)
01-19 20:32:05.573  2129 23432 E HalHidl : Stream 0x7bd13574c0 dump: Status(EX_TRANSACTION_FAILED): 'FAILED_TRANSACTION: ' (from rpc)
01-19 20:32:05.573  2129 23432 E HalHidl : Device 0x7b51357c60 dump: Status(EX_TRANSACTION_FAILED): 'FAILED_TRANSACTION: ' (from rpc)
01-19 20:32:05.574  2129 23432 E HalHidl : Device 0x7b51359460 dump: Status(EX_TRANSACTION_FAILED): 'FAILED_TRANSACTION: ' (from rpc)
01-19 20:32:05.576  2129 23432 E HalHidl : Device 0x7b513590a0 dump: Status(EX_TRANSACTION_FAILED): 'FAILED_TRANSACTION: ' (from rpc)
01-19 20:32:05.800  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581295): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:system_server:s0 tclass=process permissive=0
01-19 20:32:05.808  2341  2389 W Choreographer: Frame time is 0.08042 ms in the future!  Check that graphics HAL is generating vsync timestamps using the correct timebase.
01-19 20:32:05.804  2131  2131 W Binder:2131_5: type=1400 audit(0.0:1581296): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:system_server:s0 tclass=process permissive=0
01-19 20:32:05.811  2341  2388 W Choreographer: Frame time is 0.08042 ms in the future!  Check that graphics HAL is generating vsync timestamps using the correct timebase.
01-19 20:32:05.816  2341 13661 W InputManager-JNI: Input channel object '7bcc4c6 Toast (client)' was disposed without first being removed with the input manager!
01-19 20:32:05.808  2131  2131 W Binder:2131_5: type=1400 audit(0.0:1581298): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:system_server:s0 tclass=process permissive=0
01-19 20:32:05.808  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581299): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:untrusted_app_27:s0:c147,c256,c512,c768 tclass=process permissive=0
01-19 20:32:05.824  2341  4094 W NotificationService: Toast already killed. pkg=com.termux token=android.os.BinderProxy@4fd4902
01-19 20:32:05.841  1736  1736 I hwcomposer: [HWCDisplay] [Display_0 (type:1)] fps:21.850359,dur:1006.85,max:245.67,min:11.83  
01-19 20:32:06.057 20144 20161 I OpenGLRenderer: Davey! duration=9223349747495ms; Flags=0, FrameTimelineVsyncId=1449096, IntendedVsync=22289358783035, Vsync=22289358783035, InputEventId=0, HandleInputStart=22289359473019, AnimationStart=22289359477943, PerformTraversalsStart=22289359481250, DrawStart=22289359840789, FrameDeadline=22289375449702, FrameInterval=22289359462019, FrameStartTime=16666667, SyncQueued=22289420457327, SyncStart=22289420574404, IssueDrawCommandsStart=22289420987789, SwapBuffers=22289424685173, FrameCompleted=9223372036854775807, DequeueBufferDuration=42385, QueueBufferDuration=1771923, GpuCompleted=9223372036854775807, SwapBuffersCompleted=22289428738019, DisplayPresentTime=0, 
01-19 20:32:06.248  2017  2111 D AAL     : 01-19 08:32:05.108 BL=  22,ESS= 256, 
01-19 20:32:06.527  1736  1824 W hwcomposer: [OVL] (0) No overlay input queue(4)  
01-19 20:32:06.527  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Buffer queue is created with size(3)  
01-19 20:32:06.527  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) setConsumerListener  
01-19 20:32:06.528  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Reallocate Slot(0), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:06.542  2700  2700 D StatusBar: Received new disable state. Old: enaihbcrso.qingr | New: enaihbcrso.qingr
01-19 20:32:06.558  2124  2240 I  2124  2240 [sunwave-hal] : (733) 'healthMonitoringThread' enter.
01-19 20:32:06.559  2124  2240 I  2124  2240 [sunwave-client] : (90) ---8<---- TA LOG BEGINS ---------
01-19 20:32:06.559  2124  2240 I  2124  2240 [sunwave-ta-core] : (2873) 'sf_get_device_state' state:0008
01-19 20:32:06.559  2124  2240 I  2124  2240 [sunwave-client] : (107) --------- TA LOG FINISH ---->8---
01-19 20:32:06.559  2124  2240 I  2124  2240 [sunwave-hal] : (747) 'healthMonitoringThread' state:0008
01-19 20:32:06.561  2124  2240 I  2124  2240 [sunwave-client] : (90) ---8<---- TA LOG BEGINS ---------
01-19 20:32:06.561  2124  2240 I  2124  2240 [sunwave-ic8201] : (181) low power
01-19 20:32:06.561  2124  2240 I  2124  2240 [sunwave-client] : (107) --------- TA LOG FINISH ---->8---
01-19 20:32:06.572  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Reallocate Slot(1), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:06.574 20144 20163 I OpenGLRenderer: Davey! duration=9223349746994ms; Flags=0, FrameTimelineVsyncId=1449100, IntendedVsync=22289860264607, Vsync=22289860264607, InputEventId=0, HandleInputStart=22289860726019, AnimationStart=22289860732173, PerformTraversalsStart=22289860735789, DrawStart=22289861123481, FrameDeadline=22289893597941, FrameInterval=22289860713943, FrameStartTime=16666667, SyncQueued=22289934519943, SyncStart=22289934662096, IssueDrawCommandsStart=22289935134558, SwapBuffers=22289940211250, FrameCompleted=9223372036854775807, DequeueBufferDuration=46692, QueueBufferDuration=2210846, GpuCompleted=9223372036854775807, SwapBuffersCompleted=22289943116173, DisplayPresentTime=0, 
01-19 20:32:06.603  2341  2388 W Choreographer: Frame time is 0.124657996 ms in the future!  Check that graphics HAL is generating vsync timestamps using the correct timebase.
01-19 20:32:06.605  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Reallocate Slot(2), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:06.619  2341 13661 W Parcel  : **** enforceInterface() expected 'android.app.IActivityManager' but read 'android.os.IUserManager'
01-19 20:32:06.620  2341 13661 E Parcel  : Expecting header 0x53595354 but found 0x0. Mixing copies of libbinder?
01-19 20:32:06.629  2341 13661 W Parcel  : **** enforceInterface() expected 'android.app.IActivityManager' but read 'android.os.IUserManager'
01-19 20:32:06.629  2341 13661 E Parcel  : Expecting header 0x53595354 but found 0x0. Mixing copies of libbinder?
01-19 20:32:06.713  1736  1824 W hwcomposer: [OVL] (0) No overlay input queue(5)  
01-19 20:32:06.713  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) Buffer queue is created with size(3)  
01-19 20:32:06.713  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) setConsumerListener  
01-19 20:32:06.713  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) Reallocate Slot(0), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:06.715  1736  1824 I hwcomposer: [OVL] (0) Overlay input(4) was used with queue previously  
01-19 20:32:06.716  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Buffer queue is destroyed  
01-19 20:32:06.716  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Free Slot(0), handle=0x6fb86f16d0, 4377600 -> 0  
01-19 20:32:06.716  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Free Slot(1), handle=0x6fb86efa50, 4377600 -> 0  
01-19 20:32:06.717  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Free Slot(2), handle=0x6fb86edf50, 4377600 -> 0  
01-19 20:32:06.746  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) Reallocate Slot(1), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:06.781  1736  1824 I hwcomposer: [OVL] (0) Overlay input(5) was used with queue previously  
01-19 20:32:06.781  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) Buffer queue is destroyed  
01-19 20:32:06.781  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) Free Slot(0), handle=0x6fb86eb310, 4377600 -> 0  
01-19 20:32:06.781  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) Free Slot(1), handle=0x6fb86edf50, 4377600 -> 0  
01-19 20:32:06.808  2131  2131 W Binder:2131_4: type=1400 audit(0.0:1581444): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:06.828  2700  2700 W Choreographer: Frame time is 0.180667 ms in the future!  Check that graphics HAL is generating vsync timestamps using the correct timebase.
01-19 20:32:06.824  2131  2131 W Binder:2131_4: type=1400 audit(0.0:1581445): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:06.844  2131  2131 W Binder:2131_4: type=1400 audit(0.0:1581446): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:06.860  2131  2131 W Binder:2131_4: type=1400 audit(0.0:1581447): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:06.876  2131  2131 W Binder:2131_4: type=1400 audit(0.0:1581448): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:07.019  2700  2700 W Choreographer: Frame time is 0.0027969999 ms in the future!  Check that graphics HAL is generating vsync timestamps using the correct timebase.
01-19 20:32:07.284  2341  2560 E WifiVendorHal: getWifiLinkLayerStats_1_3_Internal(l.1168) failed {.code = ERROR_NOT_SUPPORTED, .description = }
01-19 20:32:07.294  2341  2560 D WifiClientModeImpl[wlan0]: updateLinkLayerStatsRssiSpeedFrequencyCapabilities rssi=-73 TxLinkspeed=65 freq=2412 RxLinkSpeed=0
01-19 20:32:07.296  2341  2560 D WifiDataStall: tx tput in kbps: -1000
01-19 20:32:07.296  2341  2560 D WifiDataStall: rx tput in kbps: -1000
01-19 20:32:07.296  2341  2560 V WifiConfigManager: Updating scan detail cache freq=2412 BSSID=c8:3a:35:d0:b3:08 RSSI=-72 for "Home43"WPA_PSK
01-19 20:32:07.296  2341  2560 D WifiThroughputPredictor:  utilization (BssLoad) -1 utilization (LLStats) 80 isBluetoothConnected: false final utilization: 80
01-19 20:32:07.296  2341  2560 D WifiThroughputPredictor:  utilization (BssLoad) -1 utilization (LLStats) 80 isBluetoothConnected: false final utilization: 80
01-19 20:32:07.296  2341  2560 D WifiScoreReport: Wifi scoring disabled - Stay a notch above the transition score
01-19 20:32:07.297  2341  2572 D ConnectivityService: NetReassign [no changes]
01-19 20:32:07.298  2341  2560 D WifiScoreReport: Wifi scoring disabled - Don't check IP layer
01-19 20:32:07.299  2341  2560 D WifiScoreCard: BSSID update SIGNAL_POLL ID: 1562707524 SSID: "Home43", BSSID: c8:3a:35:d0:b3:08, MAC: 00:45:64:48:a3:25, Security type: 2, Supplicant state: COMPLETED, Wi-Fi standard: 0, RSSI: -73, Link speed: 65Mbps, Tx Link speed: 65Mbps, Max Supported Tx Link speed: -1Mbps, Rx Link speed: -1Mbps, Max Supported Rx Link speed: -1Mbps, Frequency: 2412MHz, Net ID: 1, Metered hint: false, score: 51, CarrierMerged: false, SubscriptionId: -1, IsPrimary: 1
01-19 20:32:07.299  2341  2560 D WifiScoreCard: txRate: 1 txSpeed: 65
01-19 20:32:07.299  2341  2560 D WifiScoreCard: network update SIGNAL_POLL "Home43" ID: 24213653 RSSI -73 txSpeed -1
01-19 20:32:07.301  2341  2560 D WifiClientModeImpl[wlan0]:  L2ConnectedState screen=on 22 0 "Home43" c8:3a:35:d0:b3:08 rssi=-73 f=2412 sc=51 link=65 tx=0.0, 0.0, 0.0  rx=0.0 bcn=0 [on:0 tx:0 rx:0 period:3019] from screen [on:0 period:377664] score=51
01-19 20:32:07.575  1736  1736 I hwcomposer: [HWCDisplay] [Display_0 (type:1)] fps:9.227729,dur:1733.90,max:762.77,min:12.63  
01-19 20:32:07.794  2341  2407 I WifiService: getSupportedFeatures uid=1000 returns 4ac889419
01-19 20:32:07.811  1736  1824 W hwcomposer: [OVL] (0) No overlay input queue(5)  
01-19 20:32:07.811  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) Buffer queue is created with size(3)  
01-19 20:32:07.811  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) setConsumerListener  
01-19 20:32:07.811  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) Reallocate Slot(0), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:07.812  2341  2341 W Binder:2341_1B: type=1400 audit(0.0:1581470): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:07.812  2131  2131 W Binder:2131_4: type=1400 audit(0.0:1581471): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:system_server:s0 tclass=process permissive=0
01-19 20:32:07.816  2131  2131 W Binder:2131_4: type=1400 audit(0.0:1581472): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:07.824  2131  2131 W Binder:2131_5: type=1400 audit(0.0:1581473): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:system_server:s0 tclass=process permissive=0
01-19 20:32:07.824  2131  2131 W Binder:2131_5: type=1400 audit(0.0:1581474): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:07.855  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) Reallocate Slot(1), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:07.888  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) Reallocate Slot(2), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:07.939  2700  2700 D StatusBar: Received new disable state. Old: enaihbcrso.qingr | New: enaihbcrso.qingr
01-19 20:32:07.944  2700  3320 I GED     : ged_boost_gpu_freq, level 100, eOrigin 2, final_idx 2, oppidx_max 2, oppidx_min 0
01-19 20:32:07.954  2341  2387 W WindowManager: Unable to start animation, surface is null or no children.
01-19 20:32:07.996  1736  1824 W hwcomposer: [OVL] (0) No overlay input queue(4)  
01-19 20:32:07.996  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Buffer queue is created with size(3)  
01-19 20:32:07.996  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) setConsumerListener  
01-19 20:32:07.996  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Reallocate Slot(0), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:08.006  1736  1824 I hwcomposer: [OVL] (0) Overlay input(5) was used with queue previously  
01-19 20:32:08.006  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) Buffer queue is destroyed  
01-19 20:32:08.006  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) Free Slot(0), handle=0x6fb86ef390, 4377600 -> 0  
01-19 20:32:08.006  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) Free Slot(1), handle=0x6fb86eb310, 4377600 -> 0  
01-19 20:32:08.007  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) Free Slot(2), handle=0x6fb86ed650, 4377600 -> 0  
01-19 20:32:08.027  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Reallocate Slot(1), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:08.061  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Reallocate Slot(2), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:08.096  1736  1824 I hwcomposer: [OVL] (0) Overlay input(4) was used with queue previously  
01-19 20:32:08.096  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Buffer queue is destroyed  
01-19 20:32:08.096  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Free Slot(0), handle=0x6fb86f0290, 4377600 -> 0  
01-19 20:32:08.096  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Free Slot(1), handle=0x6fb86ed650, 4377600 -> 0  
01-19 20:32:08.097  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Free Slot(2), handle=0x6fb86f0f50, 4377600 -> 0  
01-19 20:32:08.561  2124  2240 I  2124  2240 [sunwave-hal] : (733) 'healthMonitoringThread' enter.
01-19 20:32:08.562  2124  2240 I  2124  2240 [sunwave-client] : (90) ---8<---- TA LOG BEGINS ---------
01-19 20:32:08.562  2124  2240 I  2124  2240 [sunwave-ta-core] : (2873) 'sf_get_device_state' state:0008
01-19 20:32:08.562  2124  2240 I  2124  2240 [sunwave-client] : (107) --------- TA LOG FINISH ---->8---
01-19 20:32:08.562  2124  2240 I  2124  2240 [sunwave-hal] : (747) 'healthMonitoringThread' state:0008
01-19 20:32:08.564  2124  2240 I  2124  2240 [sunwave-client] : (90) ---8<---- TA LOG BEGINS ---------
01-19 20:32:08.564  2124  2240 I  2124  2240 [sunwave-ic8201] : (181) low power
01-19 20:32:08.564  2124  2240 I  2124  2240 [sunwave-client] : (107) --------- TA LOG FINISH ---->8---
01-19 20:32:08.654  1736  1736 I hwcomposer: [HWCDisplay] [Display_0 (type:1)] fps:12.046339,dur:1079.17,max:465.82,min:32.34  
01-19 20:32:08.963  2017  2111 D AAL     : 01-19 08:32:07.908 BL=  21,ESS= 256, 01-19 08:32:07.926 BL=  22,ESS= 256, 
01-19 20:32:09.378  2341  2341 W WindowManager: removeWindowToken: Attempted to remove non-existing token: android.os.Binder@4123d3d
01-19 20:32:09.560  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581556): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:untrusted_app_27:s0:c147,c256,c512,c768 tclass=process permissive=0
01-19 20:32:09.636  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581557): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:09.644  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581558): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:09.675  1736  1736 I hwcomposer: [HWCDisplay] [Display_0 (type:1)] fps:2.940177,dur:1020.35,max:895.79,min:25.88  
01-19 20:32:09.768  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581559): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:radio:s0 tclass=process permissive=0
01-19 20:32:09.772  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581560): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:radio:s0 tclass=process permissive=0
01-19 20:32:09.954  2341  2374 I system_server: Background young concurrent copying GC freed 162669(5729KB) AllocSpace objects, 5(116KB) LOS objects, 18% free, 25MB/31MB, paused 837us,248us total 176.226ms
01-19 20:32:10.304  2341  2560 E WifiVendorHal: getWifiLinkLayerStats_1_3_Internal(l.1168) failed {.code = ERROR_NOT_SUPPORTED, .description = }
01-19 20:32:10.316  2341  2560 D WifiClientModeImpl[wlan0]: updateLinkLayerStatsRssiSpeedFrequencyCapabilities rssi=-74 TxLinkspeed=65 freq=2412 RxLinkSpeed=0
01-19 20:32:10.317  2341  2560 D WifiDataStall: tx tput in kbps: -1000
01-19 20:32:10.318  2341  2560 D WifiDataStall: rx tput in kbps: -1000
01-19 20:32:10.318  2341  2560 V WifiConfigManager: Updating scan detail cache freq=2412 BSSID=c8:3a:35:d0:b3:08 RSSI=-73 for "Home43"WPA_PSK
01-19 20:32:10.318  2341  2560 D WifiThroughputPredictor:  utilization (BssLoad) -1 utilization (LLStats) 80 isBluetoothConnected: false final utilization: 80
01-19 20:32:10.318  2341  2560 D WifiThroughputPredictor:  utilization (BssLoad) -1 utilization (LLStats) 80 isBluetoothConnected: false final utilization: 80
01-19 20:32:10.318  2341  2560 D WifiScoreReport: Wifi scoring disabled - Stay a notch above the transition score
01-19 20:32:10.319  2341  2572 D ConnectivityService: NetReassign [no changes]
01-19 20:32:10.320  2341  2560 D WifiScoreReport: Wifi scoring disabled - Don't check IP layer
01-19 20:32:10.321  2341  2560 D WifiScoreCard: BSSID update SIGNAL_POLL ID: 1562707524 SSID: "Home43", BSSID: c8:3a:35:d0:b3:08, MAC: 00:45:64:48:a3:25, Security type: 2, Supplicant state: COMPLETED, Wi-Fi standard: 0, RSSI: -74, Link speed: 65Mbps, Tx Link speed: 65Mbps, Max Supported Tx Link speed: -1Mbps, Rx Link speed: -1Mbps, Max Supported Rx Link speed: -1Mbps, Frequency: 2412MHz, Net ID: 1, Metered hint: false, score: 51, CarrierMerged: false, SubscriptionId: -1, IsPrimary: 1
01-19 20:32:10.321  2341  2560 D WifiScoreCard: txRate: 1 txSpeed: 65
01-19 20:32:10.321  2341  2560 D WifiScoreCard: network update SIGNAL_POLL "Home43" ID: 24213653 RSSI -74 txSpeed -1
01-19 20:32:10.323  2341  2560 D WifiClientModeImpl[wlan0]:  L2ConnectedState screen=on 22 0 "Home43" c8:3a:35:d0:b3:08 rssi=-74 f=2412 sc=51 link=65 tx=0.0, 0.0, 0.0  rx=0.0 bcn=0 [on:0 tx:0 rx:0 period:3022] from screen [on:0 period:380687] score=51
01-19 20:32:10.490  2341  2407 I WifiService: getSupportedFeatures uid=1000 returns 4ac889419
01-19 20:32:10.564  2124  2240 I  2124  2240 [sunwave-hal] : (733) 'healthMonitoringThread' enter.
01-19 20:32:10.565  2124  2240 I  2124  2240 [sunwave-client] : (90) ---8<---- TA LOG BEGINS ---------
01-19 20:32:10.565  2124  2240 I  2124  2240 [sunwave-ta-core] : (2873) 'sf_get_device_state' state:0008
01-19 20:32:10.565  2124  2240 I  2124  2240 [sunwave-client] : (107) --------- TA LOG FINISH ---->8---
01-19 20:32:10.565  2124  2240 I  2124  2240 [sunwave-hal] : (747) 'healthMonitoringThread' state:0008
01-19 20:32:10.566  2124  2240 I  2124  2240 [sunwave-client] : (90) ---8<---- TA LOG BEGINS ---------
01-19 20:32:10.567  2124  2240 I  2124  2240 [sunwave-ic8201] : (181) low power
01-19 20:32:10.567  2124  2240 I  2124  2240 [sunwave-client] : (107) --------- TA LOG FINISH ---->8---
01-19 20:32:10.628  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581571): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:untrusted_app_27:s0:c147,c256,c512,c768 tclass=process permissive=0
01-19 20:32:10.640  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581572): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:10.896  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581573): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:radio:s0 tclass=process permissive=0
01-19 20:32:11.280  2017  2111 D AAL     : 01-19 08:32:11.125 BL=  21,ESS= 256, 
01-19 20:32:11.564  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581574): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:untrusted_app_27:s0:c147,c256,c512,c768 tclass=process permissive=0
01-19 20:32:11.582  1736  1736 I hwcomposer: [HWCDisplay] [Display_0 (type:1)] fps:2.097262,dur:1907.25,max:921.88,min:93.14  
01-19 20:32:11.644  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581575): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:untrusted_app_27:s0:c147,c256,c512,c768 tclass=process permissive=0
01-19 20:32:11.644  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581576): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:11.822  1994  1994 I thermal_repeater: [recvMdThermalInfo] ret=29, strLen=127,  3, 43, -50, -28363, 32767, 0
01-19 20:32:11.984  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581577): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:11.984  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581578): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:11.988  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581579): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:11.988  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581580): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:12.567  2124  2240 I  2124  2240 [sunwave-hal] : (733) 'healthMonitoringThread' enter.
01-19 20:32:12.568  2124  2240 I  2124  2240 [sunwave-client] : (90) ---8<---- TA LOG BEGINS ---------
01-19 20:32:12.568  2124  2240 I  2124  2240 [sunwave-ta-core] : (2873) 'sf_get_device_state' state:0008
01-19 20:32:12.568  2124  2240 I  2124  2240 [sunwave-client] : (107) --------- TA LOG FINISH ---->8---
01-19 20:32:12.568  2124  2240 I  2124  2240 [sunwave-hal] : (747) 'healthMonitoringThread' state:0008
01-19 20:32:12.569  2124  2240 I  2124  2240 [sunwave-client] : (90) ---8<---- TA LOG BEGINS ---------
01-19 20:32:12.569  2124  2240 I  2124  2240 [sunwave-ic8201] : (181) low power
01-19 20:32:12.569  2124  2240 I  2124  2240 [sunwave-client] : (107) --------- TA LOG FINISH ---->8---
01-19 20:32:12.640  1736  1736 I hwcomposer: [HWCDisplay] [Display_0 (type:1)] fps:2.836443,dur:1057.66,max:887.89,min:71.27  
01-19 20:32:12.648  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581583): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:12.691  2341  2341 W WindowManager: removeWindowToken: Attempted to remove non-existing token: android.os.Binder@5128a42
01-19 20:32:13.327  2341  2560 E WifiVendorHal: getWifiLinkLayerStats_1_3_Internal(l.1168) failed {.code = ERROR_NOT_SUPPORTED, .description = }
01-19 20:32:13.336  2341  2560 D WifiClientModeImpl[wlan0]: updateLinkLayerStatsRssiSpeedFrequencyCapabilities rssi=-75 TxLinkspeed=65 freq=2412 RxLinkSpeed=0
01-19 20:32:13.338  2341  2560 D WifiDataStall: tx tput in kbps: -1000
01-19 20:32:13.338  2341  2560 D WifiDataStall: rx tput in kbps: -1000
01-19 20:32:13.338  2341  2560 V WifiConfigManager: Updating scan detail cache freq=2412 BSSID=c8:3a:35:d0:b3:08 RSSI=-74 for "Home43"WPA_PSK
01-19 20:32:13.338  2341  2560 D WifiThroughputPredictor:  utilization (BssLoad) -1 utilization (LLStats) 80 isBluetoothConnected: false final utilization: 80
01-19 20:32:13.338  2341  2560 D WifiThroughputPredictor:  utilization (BssLoad) -1 utilization (LLStats) 80 isBluetoothConnected: false final utilization: 80
01-19 20:32:13.339  2341  2560 D WifiScoreReport: Wifi scoring disabled - Stay a notch above the transition score
01-19 20:32:13.339  2341  2572 D ConnectivityService: NetReassign [no changes]
01-19 20:32:13.340  2341  2560 D WifiScoreReport: Wifi scoring disabled - Don't check IP layer
01-19 20:32:13.341  2341  2560 D WifiScoreCard: BSSID update SIGNAL_POLL ID: 1562707524 SSID: "Home43", BSSID: c8:3a:35:d0:b3:08, MAC: 00:45:64:48:a3:25, Security type: 2, Supplicant state: COMPLETED, Wi-Fi standard: 0, RSSI: -75, Link speed: 65Mbps, Tx Link speed: 65Mbps, Max Supported Tx Link speed: -1Mbps, Rx Link speed: -1Mbps, Max Supported Rx Link speed: -1Mbps, Frequency: 2412MHz, Net ID: 1, Metered hint: false, score: 51, CarrierMerged: false, SubscriptionId: -1, IsPrimary: 1
01-19 20:32:13.341  2341  2560 D WifiScoreCard: txRate: 1 txSpeed: 65
01-19 20:32:13.341  2341  2560 D WifiScoreCard: network update SIGNAL_POLL "Home43" ID: 24213653 RSSI -75 txSpeed -1
01-19 20:32:13.342  2700  4312 V WifiManager: TrafficStateCallbackProxy: onStateChanged state=3
01-19 20:32:13.343  2341  2560 D WifiClientModeImpl[wlan0]:  L2ConnectedState screen=on 22 0 "Home43" c8:3a:35:d0:b3:08 rssi=-75 f=2412 sc=51 link=65 tx=0.4, 0.0, 0.0  rx=0.4 bcn=0 [on:0 tx:0 rx:0 period:3019] from screen [on:0 period:383707] score=51
01-19 20:32:13.568  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581584): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:untrusted_app_27:s0:c147,c256,c512,c768 tclass=process permissive=0
01-19 20:32:13.628  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581585): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:untrusted_app_27:s0:c147,c256,c512,c768 tclass=process permissive=0
01-19 20:32:13.643  1736  1736 I hwcomposer: [HWCDisplay] [Display_0 (type:1)] fps:2.990168,dur:1003.29,max:930.93,min:17.35  
01-19 20:32:13.652  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581586): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:13.988  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581587): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:13.988  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581588): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:13.992  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581589): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:13.992  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581590): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:14.570  2124  2240 I  2124  2240 [sunwave-hal] : (733) 'healthMonitoringThread' enter.
01-19 20:32:14.571  2124  2240 I  2124  2240 [sunwave-client] : (90) ---8<---- TA LOG BEGINS ---------
01-19 20:32:14.571  2124  2240 I  2124  2240 [sunwave-ta-core] : (2873) 'sf_get_device_state' state:0008
01-19 20:32:14.572  2124  2240 I  2124  2240 [sunwave-client] : (107) --------- TA LOG FINISH ---->8---
01-19 20:32:14.572  2124  2240 I  2124  2240 [sunwave-hal] : (747) 'healthMonitoringThread' state:0008
01-19 20:32:14.573  2124  2240 I  2124  2240 [sunwave-client] : (90) ---8<---- TA LOG BEGINS ---------
01-19 20:32:14.573  2124  2240 I  2124  2240 [sunwave-ic8201] : (181) low power
01-19 20:32:14.573  2124  2240 I  2124  2240 [sunwave-client] : (107) --------- TA LOG FINISH ---->8---
01-19 20:32:14.568  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581591): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:untrusted_app_27:s0:c147,c256,c512,c768 tclass=process permissive=0
01-19 20:32:14.632  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581592): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:untrusted_app_27:s0:c147,c256,c512,c768 tclass=process permissive=0
01-19 20:32:14.646  1736  1736 I hwcomposer: [HWCDisplay] [Display_0 (type:1)] fps:2.991823,dur:1002.73,max:930.68,min:17.28  
01-19 20:32:15.080  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581601): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:untrusted_app:s0:c72,c257,c512,c768 tclass=process permissive=0
01-19 20:32:15.416  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581602): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:untrusted_app_27:s0:c147,c256,c512,c768 tclass=process permissive=0
01-19 20:32:15.640  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581603): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:15.651  1736  1736 I hwcomposer: [HWCDisplay] [Display_0 (type:1)] fps:4.975806,dur:1004.86,max:434.18,min:17.52  
01-19 20:32:15.892  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581604): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:gmscore_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:15.900  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581605): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:gmscore_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:15.917 18614 18614 D BoundBrokerSvc: onUnbind: Intent { act=com.google.firebase.dynamiclinks.service.START pkg=com.google.android.gms }
01-19 20:32:16.225  2692  2692 D wpa_supplicant: nl80211: Drv Event 103 (NL80211_CMD_VENDOR) received for wlan0
01-19 20:32:16.225  2666  2681 D WifiHAL : Got a RSSI monitor event
01-19 20:32:16.225  2692  2692 D wpa_supplicant: nl80211: Vendor event: wiphy=0 vendor_id=0x1a11 subcmd=7
01-19 20:32:16.225  2666  2681 I WifiHAL : data: version=1, cur_rssi=-82 BSSID=c8:3a:35:d0:b3:08
01-19 20:32:16.225  2692  2692 D wpa_supplicant: nl80211: Ignore unsupported vendor event
01-19 20:32:16.226  2341  2610 D WifiVendorHal: onRssiThresholdBreached 7551currRssi -82
01-19 20:32:16.226  2341  2610 E WifiClientModeImpl[wlan0]: onRssiThresholdBreach event. Cur Rssi = -82
01-19 20:32:16.228  2341  2560 D WifiClientModeImpl[wlan0]: reported txKbps 10000 rxKbps 10000
01-19 20:32:16.228  2341  2560 D WifiVendorHal: startRssiMonitoring maxRssi=-78 minRssi=-85
01-19 20:32:16.229  2666  2666 I WifiHAL : Stopping RSSI monitoring 7551
01-19 20:32:16.229  2666  2666 D WifiHAL : WifiRequest::create vendor command to iface 33, vendor_id=0x1a11, subcmd=0x0007, res=0
01-19 20:32:16.229  2666  2666 I WifiHAL : set RSSI Monitor, mMax_rssi=127, mMin_rssi=-75, enable=0
01-19 20:32:16.229  2666  2666 D WifiHAL : create request
01-19 20:32:16.230  2666  2666 I WifiHAL : Start RSSI monitoring 7551
01-19 20:32:16.230  2666  2666 D WifiHAL : WifiRequest::create vendor command to iface 33, vendor_id=0x1a11, subcmd=0x0007, res=0
01-19 20:32:16.230  2666  2666 I WifiHAL : set RSSI Monitor, mMax_rssi=-78, mMin_rssi=-85, enable=1
01-19 20:32:16.230  2666  2666 D WifiHAL : create request
01-19 20:32:16.231  2666  2666 D WifiHAL : Successfully set RSSI monitoring
01-19 20:32:16.231  2666  2666 I WifiHAL : Done!
01-19 20:32:16.231  2341  2560 D WifiClientModeImpl[wlan0]: Re-program RSSI thresholds for CMD_RSSI_THRESHOLD_BREACHED: [-85, -78], curRssi=-82 ret=0
01-19 20:32:16.232  2341  2560 D WifiClientModeImpl[wlan0]:  L2ConnectedState screen=on rssi=-82 thresholds=[-128, -88, -85, -78, -75, 127]
01-19 20:32:16.232  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581614): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:16.237  2341  4094 I WifiService: getWifiEnabledState uid=10124
01-19 20:32:16.236  2341  2341 W Binder:2341_1B: type=1400 audit(0.0:1581615): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:untrusted_app:s0:c48,c257,c512,c768 tclass=process permissive=0
01-19 20:32:16.252   322   322 E SELinux : avc:  denied  { find } for interface=vendor.samsung.hardware.light::ISecLight sid=u:r:system_server:s0 pid=2341 scontext=u:r:system_server:s0 tcontext=u:object_r:default_android_hwservice:s0 tclass=hwservice_manager permissive=0
01-19 20:32:16.236  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581616): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:16.236  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581617): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:16.240  2341  2341 W Binder:2341_D: type=1400 audit(0.0:1581618): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:radio:s0 tclass=process permissive=0
01-19 20:32:16.256   322   322 E SELinux : avc:  denied  { find } for interface=vendor.samsung.hardware.light::ISehLight sid=u:r:system_server:s0 pid=2341 scontext=u:r:system_server:s0 tcontext=u:object_r:default_android_hwservice:s0 tclass=hwservice_manager permissive=0
01-19 20:32:16.259  2341  4094 E LightsService: Light requested not available on this device. 2
01-19 20:32:16.344  2341  2560 E WifiVendorHal: getWifiLinkLayerStats_1_3_Internal(l.1168) failed {.code = ERROR_NOT_SUPPORTED, .description = }
01-19 20:32:16.354  2341  2560 D WifiClientModeImpl[wlan0]: updateLinkLayerStatsRssiSpeedFrequencyCapabilities rssi=-82 TxLinkspeed=65 freq=2412 RxLinkSpeed=0
01-19 20:32:16.356  2341  2560 D WifiClientModeImpl[wlan0]: reported txKbps 2500 rxKbps 2500
01-19 20:32:16.356  2341  2560 D WifiDataStall: tx tput in kbps: -1000
01-19 20:32:16.356  2341  2560 D WifiDataStall: rx tput in kbps: -1000
01-19 20:32:16.357  2341  2560 V WifiConfigManager: Updating scan detail cache freq=2412 BSSID=c8:3a:35:d0:b3:08 RSSI=-78 for "Home43"WPA_PSK
01-19 20:32:16.357  2341  2560 D WifiThroughputPredictor:  utilization (BssLoad) -1 utilization (LLStats) 80 isBluetoothConnected: false final utilization: 80
01-19 20:32:16.357  2341  2560 D WifiThroughputPredictor:  utilization (BssLoad) -1 utilization (LLStats) 80 isBluetoothConnected: false final utilization: 80
01-19 20:32:16.357  2341  2560 D WifiScoreReport: Wifi scoring disabled - Stay a notch above the transition score
01-19 20:32:16.359  2341  2560 D WifiScoreReport: Wifi scoring disabled - Don't check IP layer
01-19 20:32:16.359  2341  2560 D WifiScoreCard: BSSID update SIGNAL_POLL ID: 1562707524 SSID: "Home43", BSSID: c8:3a:35:d0:b3:08, MAC: 00:45:64:48:a3:25, Security type: 2, Supplicant state: COMPLETED, Wi-Fi standard: 0, RSSI: -82, Link speed: 65Mbps, Tx Link speed: 65Mbps, Max Supported Tx Link speed: -1Mbps, Rx Link speed: -1Mbps, Max Supported Rx Link speed: -1Mbps, Frequency: 2412MHz, Net ID: 1, Metered hint: false, score: 51, CarrierMerged: false, SubscriptionId: -1, IsPrimary: 1
01-19 20:32:16.359  2341  2560 D WifiScoreCard: txRate: 1 txSpeed: 65
01-19 20:32:16.359  2341  2560 D WifiScoreCard: network update SIGNAL_POLL "Home43" ID: 24213653 RSSI -82 txSpeed -1
01-19 20:32:16.361  2700  4312 V WifiManager: TrafficStateCallbackProxy: onStateChanged state=0
01-19 20:32:16.361  2341  2560 D WifiClientModeImpl[wlan0]:  L2ConnectedState screen=on 22 0 "Home43" c8:3a:35:d0:b3:08 rssi=-82 f=2412 sc=51 link=65 tx=0.2, 0.0, 0.0  rx=0.2 bcn=0 [on:0 tx:0 rx:0 period:3018] from screen [on:0 period:386725] score=51
01-19 20:32:16.365  2341  8793 I WifiService: getWifiEnabledState uid=10124
01-19 20:32:16.382  2341  2572 D ConnectivityService: NetReassign [no changes]
01-19 20:32:16.574  2124  2240 I  2124  2240 [sunwave-hal] : (733) 'healthMonitoringThread' enter.
01-19 20:32:16.575  2124  2240 I  2124  2240 [sunwave-client] : (90) ---8<---- TA LOG BEGINS ---------
01-19 20:32:16.575  2124  2240 I  2124  2240 [sunwave-ta-core] : (2873) 'sf_get_device_state' state:0008
01-19 20:32:16.575  2124  2240 I  2124  2240 [sunwave-client] : (107) --------- TA LOG FINISH ---->8---
01-19 20:32:16.575  2124  2240 I  2124  2240 [sunwave-hal] : (747) 'healthMonitoringThread' state:0008
01-19 20:32:16.576  2124  2240 I  2124  2240 [sunwave-client] : (90) ---8<---- TA LOG BEGINS ---------
01-19 20:32:16.576  2124  2240 I  2124  2240 [sunwave-ic8201] : (181) low power
01-19 20:32:16.576  2124  2240 I  2124  2240 [sunwave-client] : (107) --------- TA LOG FINISH ---->8---
01-19 20:32:16.654  1736  1736 I hwcomposer: [HWCDisplay] [Display_0 (type:1)] fps:3.988070,dur:1002.99,max:363.12,min:76.46  
01-19 20:32:16.812  2341  2341 W WindowManager: removeWindowToken: Attempted to remove non-existing token: android.os.Binder@79750ab
01-19 20:32:17.496  2131  2131 W Binder:2131_1: type=1400 audit(0.0:1581680): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:system_server:s0 tclass=process permissive=0
01-19 20:32:17.500  2131  2131 W Binder:2131_5: type=1400 audit(0.0:1581681): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:system_server:s0 tclass=process permissive=0
01-19 20:32:17.500  2341  2341 W Binder:2341_1B: type=1400 audit(0.0:1581682): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:untrusted_app:s0:c48,c257,c512,c768 tclass=process permissive=0
01-19 20:32:17.504   322   322 E SELinux : avc:  denied  { find } for interface=vendor.samsung.hardware.light::ISecLight sid=u:r:system_server:s0 pid=2341 scontext=u:r:system_server:s0 tcontext=u:object_r:default_android_hwservice:s0 tclass=hwservice_manager permissive=0
01-19 20:32:17.505   322   322 E SELinux : avc:  denied  { find } for interface=vendor.samsung.hardware.light::ISehLight sid=u:r:system_server:s0 pid=2341 scontext=u:r:system_server:s0 tcontext=u:object_r:default_android_hwservice:s0 tclass=hwservice_manager permissive=0
01-19 20:32:17.507  2341  2518 E LightsService: Light requested not available on this device. 2
01-19 20:32:17.524  1736  1824 W hwcomposer: [OVL] (0) No overlay input queue(4)  
01-19 20:32:17.524  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Buffer queue is created with size(3)  
01-19 20:32:17.524  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) setConsumerListener  
01-19 20:32:17.524  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Reallocate Slot(0), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:17.524  2131  2131 W Binder:2131_5: type=1400 audit(0.0:1581683): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:untrusted_app:s0:c48,c257,c512,c768 tclass=process permissive=0
01-19 20:32:17.548  2131  2131 W Binder:2131_5: type=1400 audit(0.0:1581684): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:system_server:s0 tclass=process permissive=0
01-19 20:32:17.572  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Reallocate Slot(1), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:17.607  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Reallocate Slot(2), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:17.629 20225 20632 D mpd     : PlayerBase::pause() from IPlayer
01-19 20:32:17.632 20225 20632 D mpd     : PlayerBase::stop() from IPlayer
01-19 20:32:17.676  1736  1736 I hwcomposer: [HWCDisplay] [Display_0 (type:1)] fps:6.850082,dur:1021.89,max:516.55,min:34.29  
01-19 20:32:17.752  1736  1824 W hwcomposer: [OVL] (0) No overlay input queue(5)  
01-19 20:32:17.752  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) Buffer queue is created with size(3)  
01-19 20:32:17.753  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) setConsumerListener  
01-19 20:32:17.753  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) Reallocate Slot(0), pool(0 -> 0) size(0 -> 4377600)  
01-19 20:32:17.759  2129  2174 W AudioFlinger: moveEffectChain_l() effect chain for session 0 not on source thread 0x7dbf57ea60
01-19 20:32:17.799  1736  1824 I hwcomposer: [OVL] (0) Overlay input(5) was used with queue previously  
01-19 20:32:17.799  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) Buffer queue is destroyed  
01-19 20:32:17.799  1736  1824 I hwcomposer: [DBQ] (q2:0x70186e6330) Free Slot(0), handle=0x6fb86eba90, 4377600 -> 0  
01-19 20:32:17.810 20144 20144 W Termux.TerminalEmulator: Ignoring request to save/recall decset bit=1001
01-19 20:32:17.918 20144 20161 I OpenGLRenderer: Davey! duration=9223349735598ms; Flags=0, FrameTimelineVsyncId=1449371, IntendedVsync=22301255751385, Vsync=22301255751385, InputEventId=0, HandleInputStart=22301256391097, AnimationStart=22301256396097, PerformTraversalsStart=22301256398482, DrawStart=22301256720866, FrameDeadline=22301272418052, FrameInterval=22301256378866, FrameStartTime=16666667, SyncQueued=22301284464020, SyncStart=22301284554174, IssueDrawCommandsStart=22301284790559, SwapBuffers=22301286806559, FrameCompleted=9223372036854775807, DequeueBufferDuration=35616, QueueBufferDuration=1442154, GpuCompleted=9223372036854775807, SwapBuffersCompleted=22301289123405, DisplayPresentTime=0, 
01-19 20:32:18.039  1736  1824 I hwcomposer: [OVL] (0) Overlay input(4) was used with queue previously  
01-19 20:32:18.039  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Buffer queue is destroyed  
01-19 20:32:18.039  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Free Slot(0), handle=0x6fb86ed410, 4377600 -> 0  
01-19 20:32:18.040  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Free Slot(1), handle=0x6fb86ed650, 4377600 -> 0  
01-19 20:32:18.040  1736  1824 I hwcomposer: [DBQ] (q2:0x70186eb150) Free Slot(2), handle=0x6fb86ee790, 4377600 -> 0  
01-19 20:32:18.576  2124  2240 I  2124  2240 [sunwave-hal] : (733) 'healthMonitoringThread' enter.
01-19 20:32:18.578  2124  2240 I  2124  2240 [sunwave-client] : (90) ---8<---- TA LOG BEGINS ---------
01-19 20:32:18.578  2124  2240 I  2124  2240 [sunwave-ta-core] : (2873) 'sf_get_device_state' state:0008
01-19 20:32:18.578  2124  2240 I  2124  2240 [sunwave-client] : (107) --------- TA LOG FINISH ---->8---
01-19 20:32:18.578  2124  2240 I  2124  2240 [sunwave-hal] : (747) 'healthMonitoringThread' state:0008
01-19 20:32:18.579  2124  2240 I  2124  2240 [sunwave-client] : (90) ---8<---- TA LOG BEGINS ---------
01-19 20:32:18.580  2124  2240 I  2124  2240 [sunwave-ic8201] : (181) low power
01-19 20:32:18.580  2124  2240 I  2124  2240 [sunwave-client] : (107) --------- TA LOG FINISH ---->8---
01-19 20:32:18.648  2131  2131 W Binder:2131_4: type=1400 audit(0.0:1581729): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:platform_app:s0:c512,c768 tclass=process permissive=0
01-19 20:32:18.668  2129  2129 W Binder:2129_D: type=1400 audit(0.0:1581730): avc: denied { write } for path="pipe:[1288531]" dev="pipefs" ino=1288531 scontext=u:r:mtk_hal_audio:s0 tcontext=u:r:untrusted_app_29:s0:c146,c256,c512,c768 tclass=fifo_file permissive=0
01-19 20:32:18.672  2129 30442 E HalHidl : EffectsFactory 0x7b51357aa0 dumpEffects: Status(EX_TRANSACTION_FAILED): 'FAILED_TRANSACTION: ' (from rpc)
01-19 20:32:18.668  2129  2129 W Binder:2129_D: type=1400 audit(0.0:1581731): avc: denied { write } for path="pipe:[1288531]" dev="pipefs" ino=1288531 scontext=u:r:mtk_hal_audio:s0 tcontext=u:r:untrusted_app_29:s0:c146,c256,c512,c768 tclass=fifo_file permissive=0
01-19 20:32:18.678  2129 30442 E HalHidl : Stream 0x7bd13590e0 dump: Status(EX_TRANSACTION_FAILED): 'FAILED_TRANSACTION: ' (from rpc)
01-19 20:32:18.676  2129  2129 W Binder:2129_D: type=1400 audit(0.0:1581732): avc: denied { write } for path="pipe:[1288531]" dev="pipefs" ino=1288531 scontext=u:r:mtk_hal_audio:s0 tcontext=u:r:untrusted_app_29:s0:c146,c256,c512,c768 tclass=fifo_file permissive=0
01-19 20:32:18.688  2129 30442 E HalHidl : Stream 0x7bd13574c0 dump: Status(EX_TRANSACTION_FAILED): 'FAILED_TRANSACTION: ' (from rpc)
01-19 20:32:18.684  2129  2129 W Binder:2129_D: type=1400 audit(0.0:1581733): avc:
xtkoba commented 1 year ago

Debug build:

i have no idea how to install it (it's neither a .zip nor a .apk)

.deb package can be installed by:

dpkg -i foo.deb

share the full logcat

sure, I've copied the part where i do the mpd thing

This time no SEGV, unfortunately(?). The log looks normal to me who is unfamiliar to with audio devices on Android.

dxcvvxd commented 1 year ago

well i have installed the packages and nothing has changed at all I haven't checked the logcat but i honestly have no hope for it

dxcvvxd commented 1 year ago

i think im actually onto something:

01-25 23:12:38.559 26508 26508 F DEBUG   : *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
01-25 23:12:38.559 26508 26508 F DEBUG   : Build fingerprint: 'Blackview/BV5900/BV5900:10/QP1A.190711.020/1617762056:user/release-keys'
01-25 23:12:38.559 26508 26508 F DEBUG   : Revision: '0'
01-25 23:12:38.559 26508 26508 F DEBUG   : ABI: 'arm64'
01-25 23:12:38.559 26508 26508 F DEBUG   : Timestamp: 2023-01-25 23:12:38.421513252+0300
01-25 23:12:38.559 26508 26508 F DEBUG   : Process uptime: 0s
01-25 23:12:38.559 26508 26508 F DEBUG   : Cmdline: mpd
01-25 23:12:38.559 26508 26508 F DEBUG   : pid: 26347, tid: 26347, name: mpd  >>> mpd <<<
01-25 23:12:38.559 26508 26508 F DEBUG   : uid: 10147
01-25 23:12:38.559 26508 26508 F DEBUG   : signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 0x8
01-25 23:12:38.559 26508 26508 F DEBUG   : Cause: null pointer dereference
01-25 23:12:38.559 26508 26508 F DEBUG   :     x0  0000000000000000  x1  00000077008a1d7c  x2  0000007700954120  x3  0000000000000008
01-25 23:12:38.559 26508 26508 F DEBUG   :     x4  000000770098a9c0  x5  0000000000000004  x6  00000000fffffffe  x7  00000000fffffffe
01-25 23:12:38.559 26508 26508 F DEBUG   :     x8  000000770098aa58  x9  07b68cc18df3f8a9  x10 0000000000000000  x11 000000761e480880
01-25 23:12:38.559 26508 26508 F DEBUG   :     x12 00000074de48c7c0  x13 0000000095ef5dd2  x14 00000000000000c8  x15 0000000000000000
01-25 23:12:38.559 26508 26508 F DEBUG   :     x16 0000007700950660  x17 00000077291a450c  x18 000000773ee3a000  x19 0000007700954120
01-25 23:12:38.559 26508 26508 F DEBUG   :     x20 0000000000000000  x21 00000077008bc96c  x22 0000000000001000  x23 000000000000042b
01-25 23:12:38.559 26508 26508 F DEBUG   :     x24 00000000000063f0  x25 00000077291b5460  x26 000000000000042a  x27 00000077008b3400
01-25 23:12:38.559 26508 26508 F DEBUG   :     x28 00000077291b5000  x29 0000007fca2ae0f0
01-25 23:12:38.559 26508 26508 F DEBUG   :     lr  000000770093571c  sp  0000007fca2ae0f0  pc  0000007700935728  pst 0000000060000000
01-25 23:12:38.559 26508 26508 F DEBUG   : backtrace:
01-25 23:12:38.559 26508 26508 F DEBUG   :   NOTE: Function names and BuildId information is missing for some frames due
01-25 23:12:38.559 26508 26508 F DEBUG   :   NOTE: to unreadable libraries. For unwinds of apps, only shared libraries
01-25 23:12:38.559 26508 26508 F DEBUG   :   NOTE: found under the lib/ directory are readable.
01-25 23:12:38.559 26508 26508 F DEBUG   :   NOTE: On this device, run setenforce 0 to make the libraries readable.
01-25 23:12:38.560 26508 26508 F DEBUG   :       #00 pc 00000000000b7728  /data/data/com.termux/files/usr/lib/libsoxr.so
01-25 23:12:38.560 26508 26508 F DEBUG   :       #01 pc 000000000003e984  /data/data/com.termux/files/usr/lib/libsoxr.so
01-25 23:12:38.560 26508 26508 F DEBUG   :       #02 pc 00000000000b5230  /apex/com.android.runtime/lib64/bionic/libc.so (__cxa_finalize+288) (BuildId: 77fa03547404bb2bbaa67c8a128f9ff3)
01-25 23:12:38.560 26508 26508 F DEBUG   :       #03 pc 00000000000a69b0  /apex/com.android.runtime/lib64/bionic/libc.so (exit+24) (BuildId: 77fa03547404bb2bbaa67c8a128f9ff3)
01-25 23:12:38.560 26508 26508 F DEBUG   :       #04 pc 00000000000487e0  /apex/com.android.runtime/lib64/bionic/libc.so (__libc_init+100) (BuildId: 77fa03547404bb2bbaa67c8a128f9ff3)
01-25 23:12:38.601  2313  2928 W NativeCrashListener: Couldn't find ProcessRecord for pid 26347
01-25 23:12:38.605   805   805 E tombstoned: Tombstone written to: tombstone_02
01-25 23:12:38.623  2313  2472 I BootReceiver: Copying /data/tombstones/tombstone_02 to DropBox (SYSTEM_TOMBSTONE)
01-25 23:12:38.623  2313  2472 I DropBoxManagerService: add tag=SYSTEM_TOMBSTONE isTagEnabled=true flags=0x6
01-25 23:12:38.638  2313  2368 W BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.stats.service.DropBoxEntryAddedReceiver
01-25 23:12:38.638  2313  2368 W BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver
01-25 23:12:38.647  2313  2472 I DropBoxManagerService: add tag=SYSTEM_TOMBSTONE_PROTO isTagEnabled=true flags=0x4
01-25 23:12:38.655  2313  2313 W Binder:2313_18: type=1400 audit(0.0:6582562): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:gmscore_app:s0:c512,c768 tclass=process permissive=0
01-25 23:12:38.663  2125  2125 W Binder:2125_2: type=1400 audit(0.0:6582563): avc: denied { getattr } for scontext=u:r:surfaceflinger:s0 tcontext=u:r:system_server:s0 tclass=process permissive=0
01-25 23:12:38.667  2313  2313 W Binder:2313_18: type=1400 audit(0.0:6582564): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:gmscore_app:s0:c512,c768 tclass=process permissive=0
01-25 23:12:38.670  2313  9855 W ActivityManager: Unable to start service Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 pkg=com.google.android.gms cmp=com.google.android.gms/.chimera.GmsIntentOperationService (has extras) } U=0: not found
01-25 23:12:38.667  2313  2313 W Binder:2313_18: type=1400 audit(0.0:6582565): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:gmscore_app:s0:c512,c768 tclass=process permissive=0
01-25 23:12:38.671  2313  2313 W Binder:2313_18: type=1400 audit(0.0:6582566): avc: denied { getattr } for scontext=u:r:system_server:s0 tcontext=u:r:gmscore_app:s0:c512,c768 tclass=process permissive=0
01-25 23:12:38.677  2313  2368 W BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.stats.service.DropBoxEntryAddedReceiver
01-25 23:12:38.678  2313  2368 W BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver
01-25 23:12:38.696  2313  9855 W ActivityManager: Unable to start service Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 pkg=com.google.android.gms cmp=com.google.android.gms/.chimera.GmsIntentOperationService (has extras) } U=0: not found
01-25 23:12:38.704  1729  1754 I hwcomposer: [HWCDisplay] [Display_0 (type:1)] fps:26.967360,dur:1001.21,max:276.84,min:16.53  
01-25 23:12:38.706  3876  3876 D BoundBrokerSvc: onBind: Intent { act=com.google.android.gms.udc.service.START dat=chimera-action: cmp=com.google.android.gms/.chimera.PersistentApiService }
01-25 23:12:38.706  3876  3876 D BoundBrokerSvc: Loading bound service for intent: Intent { act=com.google.android.gms.udc.service.START dat=chimera-action: cmp=com.google.android.gms/.chimera.PersistentApiService }
01-25 23:12:38.738  3876 26515 W ccla    : Empty content. Thus might mean that the settings are not synced down.
01-25 23:12:38.740  3876 25726 W ccla    : Empty content. Thus might mean that the settings are not synced down.
01-25 23:12:38.750  3876 25726 W ccla    : Empty content. Thus might mean that the settings are not synced down.
01-25 23:12:38.758  3876 26515 W ccla    : Empty content. Thus might mean that the settings are not synced down.
01-25 23:12:50.662 26540 26557 D ProcessState: Binder ioctl to enable oneway spam detection failed: Invalid argument
01-25 23:12:50.667 26540 26557 D mpd     : PlayerBase::PlayerBase()
01-25 23:12:50.668 26540 26557 D mpd     : TrackPlayerBase::TrackPlayerBase()
01-25 23:12:50.668 26540 26557 I libOpenSLES: Emulating old channel mask behavior (ignoring positional mask 0x3, using default mask 0x3 based on channel count of 2)
01-25 23:12:50.676  2124 22998 D AudioFlinger: Client defaulted notificationFrames to 2050 for frameCount 4100
01-25 23:12:50.679  1729  1834 I hwcomposer: [DBQ] (q2:0x6f6d29b1b0) Reallocate Slot(2), pool(0 -> 0) size(0 -> 4377600)  
01-25 23:12:50.680  2124 22998 D AF::TrackHandle: OpPlayAudio: track:672 usage:1 not muted
01-25 23:12:50.690  2124 22998 W AudioFlinger: moveEffectChain_l() effect chain for session 0 not on source thread 0x7dbb817a60
01-25 23:12:50.693 26540 26560 D mpd     : PlayerBase::stop() from IPlayer
01-25 23:12:50.694 26540 26560 D AudioTrack: stop(792): called with 0 frames delivered
01-25 23:12:50.696  2086 11812 D AudioALSAStreamManager: +syncSharedOutDevice(), routingSharedOutDevice: 2
01-25 23:12:50.696  2086 11812 D AudioALSAStreamManager: -syncSharedOutDevice()
01-25 23:12:50.696  2086 11812 D AudioMTKGainController: setNormalVolume(), mSceneIndex = 0, stream -1, devices 0x2, index 3, mode 0x0
01-25 23:12:50.696  2086 11812 W AudioMTKGainController: error, stream -1 is invalid, use 3 instead
01-25 23:12:50.696  2086 11812 D AudioMTKGainController: setSpeakerGain(), gain = 11, spkAnaType = 3, spkLMixerName = Lineout_PGAL_GAIN, spkRMixerName = Lineout_PGAR_GAIN
01-25 23:12:50.697  2086 11812 D AudioALSAStreamOut: open(), flags 8
01-25 23:12:50.697  2086 11812 D AudioALSAStreamManager: +createPlaybackHandler(), mAudioMode = 0, output_devices = 0x2, isMixerOut = 0x0, flag = 8
01-25 23:12:50.697  2086 11812 D AudioALSAStreamManager: needEnableVoip(), output_devices = 0x2, flags: 0x8, mAvailableOutputFlags: 0xe
01-25 23:12:50.697  2086 11812 E AudioCustParam: set_hct_mic_num(), hct_dula_mic_num=1, hct_dula_mic_flag [0, 0], hct_voip_flag [0, 0]
01-25 23:12:50.697  2086 11812 E AudioCustParam: set_hct_mic_num(): ret = 1
01-25 23:12:50.697  2086 11812 E AudioCustParam: set_hct_mic_num(): mic_buf = 11
01-25 23:12:50.697  2086 11812 E AudioCustParam: get_hct_cts_mode. size=2, length = 2 , mic_buf=11
01-25 23:12:50.697  2086 11812 E AudioCustParam: QueryFeatureSupportInfo! set_hct_mic_num() = 1. 
01-25 23:12:50.701  2086 11812 D AudioALSAPlaybackHandlerNormal: +open(), flag = 8, source output_devices = 0x2, audio_format = 3, buffer_size = 16384, sample_rate = 48000
01-25 23:12:50.701  2086 11812 D AudioALSADeviceParser: compare pcm success = 8, stringpair = Deep_Buffer_PLayback
01-25 23:12:50.704  2086 11812 D AudioALSAPlaybackHandlerBase: transferAudioFormatToPcmFormat(), audio_format(0x4) => pcm_format(0x1)
01-25 23:12:50.704  2086 11812 D AudioALSAPlaybackHandlerNormal: open(), flag = 8, mConfig: channels = 2, sample_rate(target) = 48000, period_size = 2048, period_count = 2, format = 1, avail_min = 2048, start_threshold = 0
01-25 23:12:50.704  2086 11812 D AudioALSAPlaybackHandlerNormal: SetLowJitterMode(), bypass low jitter mode, bEnable = 1, device = 0x2, SampleRate = 48000
01-25 23:12:50.713  2086 11812 D AudioALSAPlaybackHandlerBase: openPcmDriverWithFlag(), pcm device = 8 flag = 0x8 mPcm = 0xe5e42e00
01-25 23:12:50.713  2086 11812 D AudioALSAPlaybackHandlerBase: CreateAurisysLibManager, voip: 0, mAurisysScenario: 0
01-25 23:12:50.715  2086 11812 D aurisys_utility: input dev: 0x80000004, fmt = 0x3, fs: 48000, max fs: 48000, ch: 2, max ch: 1, ch maks: 0x3, hw_info_mask: 0x0; output dev: 0x2, fmt = 0x3, fs: 48000, max fs: 48000, ch: 2, max ch: 2, ch maks: 0x3, hw_info_mask: 0x0; task_scene: 2, audio_mode: 0, stream_type: -1, output_flags: 0x8, input_source: 0, input_flags: 0x0; network_info: 0, enhancement_feature_mask: 0x0
01-25 23:12:50.715  2086 11812 D aurisys_utility: lib, working fs: 48000, fmt: 0x3, frame = 0, b_interleave = 1, num_ul_ref_buf_array = 0, num_dl_ref_buf_array = 0
01-25 23:12:50.715  2086 11812 D aurisys_utility: dl in[type:2], ch: 2, ch_mask: 0x3, buf fs: 48000, buf content fs: 48000, fmt: 0x3; dl out[type:3], ch: 2, ch_mask: 0x3, buf fs: 48000, buf content fs: 48000, fmt: 0x3
01-25 23:12:50.716  2086 11812 D AudioCompFltCustParam: audioHierarchicalParamEnable [1]
01-25 23:12:50.716  2086 11812 D AudioCompFltCustParam: getPlaybackPostProcessParameterFromXML Type/Name [5]/[PlaybackDRC]
01-25 23:12:50.716  2086 11812 D AudioCompFltCustParam: Load from scene Scene,Default,Volume type,Music
01-25 23:12:50.718  2086 11812 D AudioCompFltCustParam: audioHierarchicalParamEnable [1]
01-25 23:12:50.718  2086 11812 D AudioCompFltCustParam: getPlaybackPostProcessParameterFromXML Type/Name [0]/[PlaybackACF]
01-25 23:12:50.718  2086 11812 D AudioCompFltCustParam: Load from scene Scene,Default,Volume type,Music,Profile,Speaker
01-25 23:12:50.718  2086 11812 D AudioCompFltCustParam: audioHierarchicalParamEnable [1]
01-25 23:12:50.718  2086 11812 D AudioCompFltCustParam: getPlaybackPostProcessParameterFromXML Type/Name [6]/[PlaybackDRC]
01-25 23:12:50.718  2086 11812 D AudioCompFltCustParam: Load from scene Scene,Default,Volume type,Ring
01-25 23:12:50.718  2086 11812 D AudioCompFltCustParam: audioHierarchicalParamEnable [1]
01-25 23:12:50.718  2086 11812 D AudioCompFltCustParam: getPlaybackPostProcessParameterFromXML Type/Name [8]/[PlaybackACF]
01-25 23:12:50.718  2086 11812 D AudioCompFltCustParam: Load from scene Scene,Default,Volume type,Music,Profile,Speaker
01-25 23:12:50.718  2086 11812 D aurisys_lib_handler: aurisys_arsi_parsing_param_file(), gProductInfo "platform=MT6761,device=BV5900,model=BV5900", file_path "/vendor/etc/audio_param", enhancement_mode 0, param_buf_size 2528, data_size 2528, custom_info SetAudioCustomScene=
01-25 23:12:50.718  2086 11812 D aurisys_lib_handler: aurisys_arsi_create_handler(), lib_name mtk_bessound, 0xe43857d0, memory_size 72624, arsi_handler 0xe707c450, retval 0x0
01-25 23:12:50.718  2086 11812 D aurisys_lib_handler: aurisys_arsi_create_handler(), arsi_query_process_unit_bytes, ul 0, dl 4096, retval 0
01-25 23:12:50.718  2086 11812 D aurisys_lib_manager: DL Lib, lib_name mtk_bessound, 0xe43857d0, sample_rate: 48000 => 48000, num_channels: 2 => 2, audio_format: 0x3 => 0x3, interleave: 1 => 1, frame: 0 => 0
01-25 23:12:50.719  2086 11812 D aurisys_lib_manager: DL out, sample_rate: 48000 => 48000, num_channels: 2 => 2, audio_format: 0x3 => 0x4, interleave: 1 => 1, frame: 0 => 0
01-25 23:12:50.719  2086 11812 D AudioALSAHardwareResourceManager: +startOutputDevice(), new_devices = 0x2, mOutputDevices = 0x0, mStartOutputDevicesCount = 0 SampleRate = 48000
01-25 23:12:50.719  2086 11812 D AudioALSADeviceConfigManager: ApplyDeviceTurnonSequenceByName() DeviceName = speaker_output descriptor->DeviceStatusCounte = 0
01-25 23:12:50.721  2086 11812 D AudioALSADeviceConfigManager: ApplyDeviceTurnonSequenceByName() DeviceName = ext_speaker_output descriptor->DeviceStatusCounte = 0
01-25 23:12:50.795  2086 11812 D AudioALSAPlaybackHandlerNormal: -open()
01-25 23:12:50.795  2086 11812 D AudioALSAPlaybackHandlerNormal: setScreenState(), flag = 8, rate = 2048, mInterrupt = 0.042667, mode = 1, sample_rate(target) = 48000, buffer_size = 16384, channel = 2, format = 4, reduceInterruptSize = 1024
01-25 23:12:50.796  2124 22998 E HalHidl : EffectsFactory 0x7b464cca20 dumpEffects: Status(EX_TRANSACTION_FAILED): 'FAILED_TRANSACTION: ' (from rpc)
01-25 23:12:50.800  2124 22998 E HalHidl : Stream 0x7bc64d10a0 dump: Status(EX_TRANSACTION_FAILED): 'FAILED_TRANSACTION: ' (from rpc)
01-25 23:12:50.817  2124 22998 E HalHidl : Stream 0x7bc64cc1e0 dump: Status(EX_TRANSACTION_FAILED): 'FAILED_TRANSACTION: ' (from rpc)
01-25 23:12:50.823  2124 22998 E HalHidl : Device 0x7b464cc3e0 dump: Status(EX_TRANSACTION_FAILED): 'FAILED_TRANSACTION: ' (from rpc)
01-25 23:12:50.824  2124 22998 E HalHidl : Device 0x7b464ce020 dump: Status(EX_TRANSACTION_FAILED): 'FAILED_TRANSACTION: ' (from rpc)
01-25 23:12:50.825  2124 22998 E HalHidl : Device 0x7b464ce0e0 dump: Status(EX_TRANSACTION_FAILED): 'FAILED_TRANSACTION: ' (from rpc)
01-25 23:12:50.859  2124  2280 D AudioFlinger: mixer(0x7db961ca60) throttle end: throttle time(14)
xtkoba commented 1 year ago

Just some random guesses:

SEGV seems to occur when exiting. The backtrace shows libsoxr, but I have no idea what is happening. (Not reproducing for me.)

Does this affect other music players such as mpv? Note that by default mpd calls OpenSL ES APIs directly, while mpv does it via PulseAudio. I wonder if PR #11703 (using PulseAudio) changes anything.

The log includes a fair amount of audio-related messages, while in my environment I see only the following:

### invoking mpd
01-26 21:48:22.497 29405 29405 W ADebug  : Failed to get property persist.sys.media.traces
### playing via ncmpcpp
01-26 21:48:39.622 29407 29419 D         : PlayerBase::PlayerBase()
01-26 21:48:39.623 29407 29419 D         : TrackPlayerBase::TrackPlayerBase()
01-26 21:48:39.623 29407 29419 I libOpenSLES: Emulating old channel mask behavior (ignoring positional mask 0x4, using default mask 0x1 based on channel count of 1)
01-26 21:48:39.637 29407 29419 D AudioTrack: Client defaulted notificationFrames to 1178 for frameCount 3536
01-26 21:48:39.640 29407 29422 D         : PlayerBase::stop() from IPlayer
01-26 21:48:39.640 29407 29422 D AudioTrack: stop() called with 0 frames delivered
### stopping
01-26 21:48:47.045 29407 29422 D         : PlayerBase::stop() from IPlayer
01-26 21:48:47.045 29407 29422 D AudioTrack: stop() called with 327680 frames delivered
01-26 21:48:47.049 29407 29419 D         : PlayerBase::pause() from IPlayer
01-26 21:48:47.049 29407 29419 D         : PlayerBase::stop() from IPlayer
tomty89 commented 1 year ago

Actually mpv was made to use its own OpenSLES driver by default here. But you can easily make it use pulse instead by changing its conf or specifying --ao=pulse. Though neither mpv/ffmpeg or pulse uses libsoxr by default (but both of them can be made so). Not sure about mpd.

11703 really just changed the example conf. To make mpd use pulse you need to change the conf that is actually in use. Also IIRC mpd can have multiple output, so make sure you disable the OpenSLES one explicitly if you want to test or anything.

@dxcvvxd Btw, you might want to share the spec of the audio file you were playing. Also, have you tried files of different specs (mainly sample rate, but perhaps also, sample size).

truboxl commented 11 months ago

apt info libsoxr

Package: libsoxr
Version: 0.1.3-4
Maintainer: @termux
Installed-Size: 1016 kB
Breaks: libsoxr-dev
Replaces: libsoxr-dev
Homepage: https://sourceforge.net/projects/soxr/
Download-Size: 266 kB
APT-Manual-Installed: yes
APT-Sources: https://mirrors.tuna.tsinghua.edu.cn/termux/apt/termux-main stable/main aarch64 Packages
Description: High quality, one-dimensional sample-rate conversion library

objdump -D $PREFIX/lib/libsoxr.so

...
00000000000b6d34 <__kmp_cleanup_indirect_user_locks>:
...
b7728: b9400809      ldr     w9, [x0, #0x8]
...

readelf -s $PREFIX/lib/libomp.a

...
File: /data/data/com.termux/files/usr/lib/libomp.a(kmp_lock.cpp.o)
...
548: 0000000000000000   584 FUNC    GLOBAL DEFAULT   123 __kmp_cleanup_indirect_user_locks
...

Since logcat points to a (threading?) problem that is coming from libomp, I guess there is nothing can be done except for rebuilding libsoxr with latest NDK that hopefully has a fixed libomp.