Podcini automatically resumes playback if sound played through media channel by another app

metronidazole commented 2 months ago

Checklist

[X] I have used the search function for OPEN issues to see if someone else has already submitted the same bug report.
[X] I have also used the search function for CLOSED issues to see if the problem is already solved and just waiting to be released.
[X] I will describe the problem with as much detail as possible.
[X] If the bug only to occurs with a certain podcast, I will include the URL of that podcast.

App version

4.10.0 / 4.9.*

Where did you get the app from

Other

Android version

14 (GrapheneOS)

Device model

No response

First occurred

Month or so ago

Steps to reproduce

Start podcast in Podcini
Pause podcast
Wait for another app to play something with a media stream (e.g. Tasker "Say" with steam set to "media")

Expected behaviour

Podcini stays pasued

Current behaviour

Podcini automatically resumes playback of the last podcast without interaction

Logs

############## LOG 1 ############## --------- beginning of main 05-06 07:08:22.984 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 1(8192 size) used buffers - 54792/54820 (recycle/alloc) - 100/109636 (fetch/transfer) 05-06 07:08:24.634 3755 3755 D TrafficStats: tagSocket(710) with statsTag=0xffffffff, statsUid=-1 05-06 07:08:24.707 3755 3755 D VRI[BugReportActivity]: visibilityChanged oldVisibility=true newVisibility=false 05-06 07:08:24.724 3755 3755 D VRI[BugReportActivity]: Not drawing due to not visible 05-06 07:08:26.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1435611, currentPlaybackSpeed: 1.25 05-06 07:08:26.826 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:08:27.780 3755 3755 D TrafficStats: tagSocket(818) with statsTag=0xffffffff, statsUid=-1 05-06 07:08:28.288 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 1(8192 size) used buffers - 55045/55073 (recycle/alloc) - 100/110142 (fetch/transfer) 05-06 07:08:28.591 3755 3755 D VRI[BugReportActivity]: Start draw after previous draw not visible 05-06 07:08:29.658 3755 3755 D VRI[BugReportActivity]: visibilityChanged oldVisibility=true newVisibility=false 05-06 07:08:29.672 3755 3755 D VRI[BugReportActivity]: Not drawing due to not visible 05-06 07:08:30.983 3755 3755 D TrafficStats: tagSocket(812) with statsTag=0xffffffff, statsUid=-1 05-06 07:08:31.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1441861, currentPlaybackSpeed: 1.25 05-06 07:08:31.826 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:08:33.536 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 1(8192 size) used buffers - 55298/55326 (recycle/alloc) - 100/110648 (fetch/transfer) 05-06 07:08:34.087 3755 3755 D TrafficStats: tagSocket(809) with statsTag=0xffffffff, statsUid=-1 05-06 07:08:36.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1448111, currentPlaybackSpeed: 1.25 05-06 07:08:36.828 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:08:38.883 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 1(8192 size) used buffers - 55553/55581 (recycle/alloc) - 100/111158 (fetch/transfer) 05-06 07:08:41.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1454366, currentPlaybackSpeed: 1.25 05-06 07:08:41.828 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:08:44.220 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 1(8192 size) used buffers - 55809/55837 (recycle/alloc) - 100/111670 (fetch/transfer) 05-06 07:08:46.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1460605, currentPlaybackSpeed: 1.25 05-06 07:08:46.828 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:08:49.506 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 4(32768 size) used buffers - 56064/56092 (recycle/alloc) - 100/112177 (fetch/transfer) 05-06 07:08:51.499 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1466868, currentPlaybackSpeed: 1.25 05-06 07:08:51.830 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:08:54.809 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 4(32768 size) used buffers - 56318/56346 (recycle/alloc) - 100/112683 (fetch/transfer) 05-06 07:08:56.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1473108, currentPlaybackSpeed: 1.25 05-06 07:08:56.830 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:09:00.056 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 1(8192 size) used buffers - 56567/56595 (recycle/alloc) - 100/113186 (fetch/transfer) 05-06 07:09:01.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1479357, currentPlaybackSpeed: 1.25 05-06 07:09:01.831 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:09:05.361 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 1(8192 size) used buffers - 56820/56848 (recycle/alloc) - 100/113692 (fetch/transfer) 05-06 07:09:06.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1485611, currentPlaybackSpeed: 1.25 05-06 07:09:06.832 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:09:10.744 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 1(8192 size) used buffers - 57077/57105 (recycle/alloc) - 100/114206 (fetch/transfer) 05-06 07:09:11.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1491864, currentPlaybackSpeed: 1.25 05-06 07:09:11.832 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:09:16.000 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 1(8192 size) used buffers - 57329/57357 (recycle/alloc) - 100/114710 (fetch/transfer) 05-06 07:09:16.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1498107, currentPlaybackSpeed: 1.25 05-06 07:09:16.834 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:09:21.287 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 4(32768 size) used buffers - 57585/57613 (recycle/alloc) - 100/115217 (fetch/transfer) 05-06 07:09:21.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1504366, currentPlaybackSpeed: 1.25 05-06 07:09:21.835 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:09:26.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1510453, currentPlaybackSpeed: 1.25 05-06 07:09:26.836 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:09:27.624 3755 3755 D TrafficStats: tagSocket(876) with statsTag=0xffffffff, statsUid=-1 05-06 07:09:28.844 3755 3755 D VRI[BugReportActivity]: Start draw after previous draw not visible 05-06 07:09:29.455 3755 3755 D VRI[BugReportActivity]: visibilityChanged oldVisibility=true newVisibility=false 05-06 07:09:29.473 3755 3755 D VRI[BugReportActivity]: Not drawing due to not visible 05-06 07:09:31.113 3755 4028 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 0(0 size) used buffers - 57827/57855 (recycle/alloc) - 100/115708 (fetch/transfer) 05-06 07:09:31.114 3755 4028 D BufferPoolAccessor2.0: evictor expired: 1, evicted: 1 05-06 07:09:31.500 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1510453, currentPlaybackSpeed: 1.25 05-06 07:09:31.837 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:09:36.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1510453, currentPlaybackSpeed: 1.25 05-06 07:09:36.838 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:09:41.500 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1510453, currentPlaybackSpeed: 1.25 05-06 07:09:41.839 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:09:43.379 3755 3755 D TrafficStats: tagSocket(887) with statsTag=0xffffffff, statsUid=-1 05-06 07:09:46.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1510453, currentPlaybackSpeed: 1.25 05-06 07:09:46.840 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:09:49.734 3755 3755 D TrafficStats: tagSocket(894) with statsTag=0xffffffff, statsUid=-1 05-06 07:09:51.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1510453, currentPlaybackSpeed: 1.25 05-06 07:09:51.841 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:09:56.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1510453, currentPlaybackSpeed: 1.25 05-06 07:09:56.841 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called

paused podcini

05-06 07:10:01.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1510453, currentPlaybackSpeed: 1.25 05-06 07:10:01.511 3755 3755 D AudioManager: dispatching onAudioFocusChange(-3) to android.media.AudioManager@ce13899ac.mdiq.podcini.playback.service.LocalMediaPlayer$$ExternalSyntheticLambda0@a79e75e

external media played

05-06 07:10:01.511 3755 3755 D LclPlaybackSvcMPlayer: 05-06 07:10:01.843 3755 3755 D DBWriter: 05-06 07:10:03.364 3755 3755 D AudioManager: 05-06 07:10:03.364 3755 3755 D LclPlaybackSvcMPlayer: 05-06 07:10:03.387 3755 3939 D AudioTrack: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.391 3755 3755 E MSessionService: 05-06 07:10:03.399 3755 4020 D BufferPoolAccessor2.0: 05-06 07:10:05.451 3755 3755 D VRI[BugReportActivity]: 05-06 07:10:06.440 3755 3755 E ac.mdiq.podcini: 05-06 07:10:06.501 3755 3755 D PlaybackService: 05-06 07:10:06.792 3755 3755 W WindowOnBackDispatcher: 05-06 07:10:06.800 3755 3849 D HWUI 05-06 07:10:06.843 3755 3755 D DBWriter: 05-06 07:10:07.134 3755 3755 D UserPreferences: 05-06 07:10:07.151 10185 10185 W libc 05-06 07:10:07.148 10185 10185 W logcat 05-06 07:10:07.167 3755 3755 W WindowOnBackDispatcher: 05-06 07:10:07.172 3755 3849 D HWUI Lost audio focus temporarily. Pausing... setFeedMediaPlaybackInformation called dispatching onAudioFocusChange(1) to android.media.AudioManager@ce13899ac.mdiq.podcini.playback.service.LocalMediaPlayer$$ExternalSyntheticLambda0@a79e75e Gained audio focus getTimestamp_l(42): device stall time corrected using current time 17685852555917 Failed to start foreground android.app.ForegroundServiceStartNotAllowedException: startForegroundService() not allowed due to mAllowStartForeground false: service ac.mdiq.podcini/.playback.service.PlaybackService at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel(ForegroundServiceStartNotAllowedException.java:54) at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel(ForegroundServiceStartNotAllowedException.java:50) at android.os.Parcel.readParcelableInternal(Parcel.java:5035) at android.os.Parcel.readParcelable(Parcel.java:5017) at android.os.Parcel.createExceptionOrNull(Parcel.java:3186) at android.os.Parcel.createException(Parcel.java:3175) at android.os.Parcel.readException(Parcel.java:3151) at android.os.Parcel.readException(Parcel.java:3093) at android.app.IActivityManager$Stub$Proxy.startService(IActivityManager.java:6099) at android.app.ContextImpl.startServiceCommon(ContextImpl.java:1964) at android.app.ContextImpl.startForegroundService(ContextImpl.java:1939) at android.content.ContextWrapper.startForegroundService(ContextWrapper.java:831) at androidx.core.content.ContextCompat$Api26Impl.startForegroundService(SourceFile:1189) at androidx.core.content.ContextCompat.startForegroundService(SourceFile:752) at androidx.media3.session.MediaNotificationManager.startForeground(SourceFile:366) at androidx.media3.session.MediaNotificationManager.updateNotificationInternal(SourceFile:223) at androidx.media3.session.MediaNotificationManager.lambda$updateNotification$6(SourceFile:179) at androidx.media3.session.MediaNotificationManager.$r8$lambda$dHbmLPaEv6xf2OMWoSOXjQMBBhY(SourceFile:0) at androidx.media3.session.MediaNotificationManager$$ExternalSyntheticLambda5.run(SourceFile:0) at androidx.media3.common.util.Util.postOrRun(SourceFile:824) at androidx.media3.session.MediaNotificationManager.lambda$new$0(SourceFile:81) at androidx.media3.session.MediaNotificationManager.$r8$lambda$NYHZ5KZm0zYYXQuqLwbY7Jckyvo(SourceFile:0) at androidx.media3.session.MediaNotificationManager$$ExternalSyntheticLambda2.execute(SourceFile:0) at androidx.media3.session.MediaNotificationManager.lambda$updateNotification$7(SourceFile:177) at androidx.media3.session.MediaNotificationManager.$r8$lambda$DGgWB4sruFYUbTDYRzdf4WiG7kA(SourceFile:0) at androidx.media3.session.MediaNotificationManager$$ExternalSyntheticLambda1.run(SourceFile:0) at androidx.media3.common.util.Util.postOrRun(SourceFile:824) at androidx.media3.session.MediaNotificationManager.updateNotification(SourceFile:171) at androidx.media3.session.MediaSessionService.onUpdateNotification(SourceFile:530) at androidx.media3.session.MediaSessionService.onUpdateNotificationInternal(SourceFile:566) at androidx.media3.session.MediaNotificationManager$MediaControllerListener.onEvents(SourceFile:358) at androidx.media3.session.MediaControllerImplBase.lambda$new$0(SourceFile:159) at androidx.media3.session.MediaControllerImplBase.$r8$lambda$eCzofLTRcUOL6j4CBwglOfDpWms(SourceFile:0) at androidx.media3.session.MediaControllerImplBase$$ExternalSyntheticLambda31.invoke(SourceFile:0) at androidx.media3.common.util.ListenerSet$ListenerHolder.iterationFinished(SourceFile:350) at androidx.media3.common.util.ListenerSet.handleMessage(SourceFile:294) at androidx.media3.common.util.ListenerSet.$r8$lambda$bio3pd12v5B_9b5UeFaPn9XBQ90(SourceFile:0) at androidx.media3.common.util.ListenerSet$$ExternalSyntheticLambda0.handleMessage(SourceFile:0) at android.os.Handler.dispatchMessage(Handler.java:103) at android.os.Looper.loopOnce(Looper.java:232) at android.os.Looper.loop(Looper.java:317) at android.app.ActivityThread.main(ActivityThread.java:8532) at java.lang.reflect.Method.invoke(Native Method) at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:552) at com.android.internal.os.ExecInit.main(ExecInit.java:50) at com.android.internal.os.RuntimeInit.nativeFinishInit(Native Method) at com.android.internal.os.RuntimeInit.main(RuntimeInit.java:359) bufferpool2 0xc8b6458a5e28 : 1(8192 size) total buffers - 1(8192 size) used buffers - 57827/57856 (recycle/alloc) - 100/115708 (fetch/transfer) Start draw after previous draw not visible Invalid resource ID 0x00000000. positionEventTimer currentPosition: 1514591, currentPlaybackSpeed: 1.25 sendCancelIfRunning: isInProgress=falsecallback=android.view.ViewRootImpl$$ExternalSyntheticLambda11@a05cae8 : endAllActiveAnimators on 0xc914e711a800 (MenuPopupWindow$MenuDropDownListView) with handle 0xc7e58932f420 setFeedMediaPlaybackInformation called User data folder not writable or not set. Trying default. : Access denied finding property "ro.debuggable" : type=1400 audit(0.0:31198): avc: denied { read } for name="u:object_r:userdebug_or_eng_prop:s0" dev="tmpfs" ino=435 scontext=u:r:untrusted_app:s0:c136,c256,c512,c768 tcontext=u:object_r:userdebug_or_eng_prop:s0 tclass=file permissive=0 app=ac.mdiq.podcini sendCancelIfRunning: isInProgress=falsecallback=android.view.ViewRootImpl$$ExternalSyntheticLambda11@adbbeea : endAllActiveAnimators on 0xc914e713e800 (RippleDrawable) with handle 0xc7e5892c3ed0

############## LOG 2 ##############

--------- beginning of main 05-06 07:06:21.802 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:06:23.792 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 4(32768 size) total buffers - 1(8192 size) used buffers - 50661/50683 (recycle/alloc) - 90/101362 (fetch/transfer) 05-06 07:06:24.781 3755 3755 D TrafficStats: tagSocket(738) with statsTag=0xffffffff, statsUid=-1 05-06 07:06:25.295 3755 3755 D VRI[BugReportActivity]: visibilityChanged oldVisibility=true newVisibility=false 05-06 07:06:25.313 3755 3755 D VRI[BugReportActivity]: Not drawing due to not visible 05-06 07:06:26.497 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1326541, currentPlaybackSpeed: 1.25 05-06 07:06:26.802 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:06:27.903 3755 3755 D TrafficStats: tagSocket(669) with statsTag=0xffffffff, statsUid=-1 05-06 07:06:29.133 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 4(32768 size) total buffers - 1(8192 size) used buffers - 50916/50938 (recycle/alloc) - 90/101872 (fetch/transfer) 05-06 07:06:30.606 3755 3755 D VRI[BugReportActivity]: Start draw after previous draw not visible 05-06 07:06:30.994 3755 3755 D TrafficStats: tagSocket(681) with statsTag=0xffffffff, statsUid=-1 05-06 07:06:31.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1332786, currentPlaybackSpeed: 1.25 05-06 07:06:31.806 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:06:32.285 3755 3755 D VRI[BugReportActivity]: visibilityChanged oldVisibility=true newVisibility=false 05-06 07:06:32.303 3755 3755 D VRI[BugReportActivity]: Not drawing due to not visible 05-06 07:06:34.288 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 4(32768 size) total buffers - 1(8192 size) used buffers - 51164/51186 (recycle/alloc) - 90/102368 (fetch/transfer) 05-06 07:06:36.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1339052, currentPlaybackSpeed: 1.25 05-06 07:06:36.807 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:06:39.668 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 4(32768 size) total buffers - 1(8192 size) used buffers - 51421/51443 (recycle/alloc) - 90/102882 (fetch/transfer) 05-06 07:06:40.375 3755 3755 D TrafficStats: tagSocket(689) with statsTag=0xffffffff, statsUid=-1 05-06 07:06:41.497 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1345295, currentPlaybackSpeed: 1.25 05-06 07:06:41.807 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:06:45.030 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 4(32768 size) total buffers - 1(8192 size) used buffers - 51677/51699 (recycle/alloc) - 90/103394 (fetch/transfer) 05-06 07:06:46.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1351533, currentPlaybackSpeed: 1.25 05-06 07:06:46.807 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:06:50.369 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 4(32768 size) total buffers - 1(8192 size) used buffers - 51933/51955 (recycle/alloc) - 90/103906 (fetch/transfer) 05-06 07:06:51.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1357784, currentPlaybackSpeed: 1.25 05-06 07:06:51.809 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:06:55.730 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 4(32768 size) total buffers - 1(8192 size) used buffers - 52190/52212 (recycle/alloc) - 90/104420 (fetch/transfer) 05-06 07:06:56.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1364038, currentPlaybackSpeed: 1.25 05-06 07:06:56.809 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:07:00.930 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 4(32768 size) total buffers - 1(8192 size) used buffers - 52438/52460 (recycle/alloc) - 90/104916 (fetch/transfer) 05-06 07:07:01.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1370294, currentPlaybackSpeed: 1.25 05-06 07:07:01.810 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:07:02.315 3755 3755 D TrafficStats: tagSocket(719) with statsTag=0xffffffff, statsUid=-1 05-06 07:07:05.451 3755 3755 D TrafficStats: tagSocket(723) with statsTag=0xffffffff, statsUid=-1 05-06 07:07:06.130 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 4(32768 size) total buffers - 1(8192 size) used buffers - 52687/52709 (recycle/alloc) - 90/105414 (fetch/transfer) 05-06 07:07:06.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1376536, currentPlaybackSpeed: 1.25 05-06 07:07:06.812 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:07:11.286 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 4(32768 size) total buffers - 1(8192 size) used buffers - 52934/52956 (recycle/alloc) - 90/105908 (fetch/transfer) 05-06 07:07:11.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1382783, currentPlaybackSpeed: 1.25 05-06 07:07:11.814 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:07:16.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1389036, currentPlaybackSpeed: 1.25 05-06 07:07:16.596 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 4(32768 size) total buffers - 1(8192 size) used buffers - 53188/53210 (recycle/alloc) - 90/106416 (fetch/transfer) 05-06 07:07:16.815 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:07:21.499 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1395296, currentPlaybackSpeed: 1.25 05-06 07:07:21.815 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:07:21.854 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 1(8192 size) used buffers - 53438/53461 (recycle/alloc) - 91/106918 (fetch/transfer) 05-06 07:07:26.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1401540, currentPlaybackSpeed: 1.25 05-06 07:07:26.815 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:07:27.092 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 1(8192 size) used buffers - 53689/53712 (recycle/alloc) - 91/107420 (fetch/transfer) 05-06 07:07:31.499 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1407796, currentPlaybackSpeed: 1.25 05-06 07:07:31.818 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:07:32.436 3755 4029 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 1(8192 size) used buffers - 53947/53970 (recycle/alloc) - 92/107938 (fetch/transfer) 05-06 07:07:36.499 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1411178, currentPlaybackSpeed: 1.25 05-06 07:07:36.819 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:07:37.744 3755 3755 D VRI[BugReportActivity]: Start draw after previous draw not visible 05-06 07:07:38.348 3755 3755 D VRI[BugReportActivity]: visibilityChanged oldVisibility=true newVisibility=false 05-06 07:07:38.361 3755 3755 D VRI[BugReportActivity]: Not drawing due to not visible 05-06 07:07:40.245 3755 3755 D TrafficStats: tagSocket(766) with statsTag=0xffffffff, statsUid=-1 05-06 07:07:40.759 3755 4028 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 0(0 size) used buffers - 54034/54057 (recycle/alloc) - 95/108112 (fetch/transfer) 05-06 07:07:40.760 3755 4028 D BufferPoolAccessor2.0: evictor expired: 1, evicted: 1 05-06 07:07:41.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1411178, currentPlaybackSpeed: 1.25 05-06 07:07:41.820 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:07:43.422 3755 3755 D TrafficStats: tagSocket(664) with statsTag=0xffffffff, statsUid=-1 05-06 07:07:46.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1411178, currentPlaybackSpeed: 1.25 05-06 07:07:46.821 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:07:51.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1411178, currentPlaybackSpeed: 1.25 05-06 07:07:51.822 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:07:56.499 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1411178, currentPlaybackSpeed: 1.25 05-06 07:07:56.822 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called

paused podcini

05-06 07:08:01.499 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1411178, currentPlaybackSpeed: 1.25 05-06 07:08:01.823 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:08:05.179 3755 3755 D AudioManager: dispatching onAudioFocusChange(-3) to android.media.AudioManager@ce13899ac.mdiq.podcini.playback.service.LocalMediaPlayer$$ExternalSyntheticLambda0@a79e75e

external media played

05-06 07:08:05.179 3755 3755 D LclPlaybackSvcMPlayer: Lost audio focus temporarily. Pausing... 05-06 07:08:06.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1411178, currentPlaybackSpeed: 1.25 05-06 07:08:06.825 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:08:07.023 3755 3755 D AudioManager: dispatching onAudioFocusChange(1) to android.media.AudioManager@ce13899ac.mdiq.podcini.playback.service.LocalMediaPlayer$$ExternalSyntheticLambda0@a79e75e 05-06 07:08:07.023 3755 3755 D LclPlaybackSvcMPlayer: Gained audio focus 05-06 07:08:07.045 3755 3939 D AudioTrack: getTimestamp_l(42): device stall time corrected using current time 17569509731071 05-06 07:08:07.054 3755 3755 D PlaybackService: OnStartCommand flags=0 startId=6 -1 null false null 05-06 07:08:07.054 3755 3755 E PlaybackService: PlaybackService was started with no arguments 05-06 07:08:07.086 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 1(8192 size) total buffers - 1(8192 size) used buffers - 54034/54058 (recycle/alloc) - 95/108112 (fetch/transfer) 05-06 07:08:11.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1416970, currentPlaybackSpeed: 1.25 05-06 07:08:11.825 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:08:12.382 3755 4029 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 2(16384 size) used buffers - 54287/54315 (recycle/alloc) - 100/108628 (fetch/transfer) 05-06 07:08:16.497 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1423217, currentPlaybackSpeed: 1.25 05-06 07:08:16.825 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:08:16.885 3755 3755 D VRI[BugReportActivity]: Start draw after previous draw not visible 05-06 07:08:17.642 3755 4020 D BufferPoolAccessor2.0: bufferpool2 0xc8b6458a5e28 : 5(40960 size) total buffers - 1(8192 size) used buffers - 54537/54565 (recycle/alloc) - 100/109126 (fetch/transfer) 05-06 07:08:19.112 3755 3755 W WindowOnBackDispatcher: sendCancelIfRunning: isInProgress=falsecallback=android.view.ViewRootImpl$$ExternalSyntheticLambda11@55ba7a0 05-06 07:08:19.172 3755 3755 D VRI[PreferenceActivity]: Start draw after previous draw not visible 05-06 07:08:19.699 3755 3755 D VRI[BugReportActivity]: visibilityChanged oldVisibility=true newVisibility=false 05-06 07:08:19.712 3755 3755 D VRI[BugReportActivity]: Not drawing due to not visible 05-06 07:08:19.717 3755 3755 W WindowOnBackDispatcher: sendCancelIfRunning: isInProgress=falsecallback=android.view.ViewRootImpl$$ExternalSyntheticLambda11@148d61e 05-06 07:08:20.358 3755 3755 E ac.mdiq.podcini: Invalid resource ID 0x00000000. 05-06 07:08:20.363 3755 3755 D UserPreferences: User data folder not writable or not set. Trying default. 05-06 07:08:20.364 3755 3755 D BugReportActivity: No crash report recorded 05-06 07:08:20.901 3755 3755 D VRI[PreferenceActivity]: visibilityChanged oldVisibility=true newVisibility=false 05-06 07:08:20.908 3755 3849 D HWUI : endAllActiveAnimators on 0xc914e7063200 (RippleDrawable) with handle 0xc7e588fdbc60 05-06 07:08:20.912 3755 3755 D VRI[PreferenceActivity]: Not drawing due to not visible 05-06 07:08:21.498 3755 3755 D PlaybackService: positionEventTimer currentPosition: 1429366, currentPlaybackSpeed: 1.25 05-06 07:08:21.646 3755 3755 E ac.mdiq.podcini: Invalid resource ID 0x00000000. 05-06 07:08:21.825 3755 3755 D DBWriter: setFeedMediaPlaybackInformation called 05-06 07:08:21.997 3755 3755 W WindowOnBackDispatcher: sendCancelIfRunning: isInProgress=falsecallback=android.view.ViewRootImpl$$ExternalSyntheticLambda11@8d8a555 05-06 07:08:22.004 3755 3849 D HWUI : endAllActiveAnimators on 0xc914e70e8400 (MenuPopupWindow$MenuDropDownListView) with handle 0xc7e5892e1420 05-06 07:08:22.339 3755 3755 D UserPreferences: User data folder not writable or not set. Trying default. 05-06 07:08:22.347 9998 9998 W libc : Access denied finding property "ro.debuggable" 05-06 07:08:22.344 9998 9998 W logcat : type=1400 audit(0.0:31193): avc: denied { read } for name="u:object_r:userdebug_or_eng_prop:s0" dev="tmpfs" ino=435 scontext=u:r:untrusted_app:s0:c136,c256,c512,c768 tcontext=u:object_r:userdebug_or_eng_prop:s0 tclass=file permissive=0 app=ac.mdiq.podcini 05-06 07:08:22.362 3755 3755 W WindowOnBackDispatcher: sendCancelIfRunning: isInProgress=falsecallback=android.view.ViewRootImpl$$ExternalSyntheticLambda11@f627421 05-06 07:08:22.365 3755 3849 D HWUI : endAllActiveAnimators on 0xc914e710c400 (RippleDrawable) with handle 0xc7e589213720

XilinJia commented 2 months ago

Thanks for reporting.

I don't have Tasker for testing, but I suspect this could be the cause:

When Tasker executes the “Say” action, it may simulate media button presses (e.g., play, pause) to handle audio playback. Podcini listens to these simulated media button events, it might interpret them as actual user input and resume playback.

I'm not sure what to do to "solve" it. I'd say it becomes a real issue if other media players are causing the same phenomenon. Tasker is not a normal app, isn't it? It could simply start a media app among other things.

metronidazole commented 2 months ago

When Tasker executes the “Say” action, it may simulate media button presses (e.g., play, pause) to handle audio playback. Podcini listens to these simulated media button events, it might interpret them as actual user input and resume playback.

I don't think so. I had it occur with other sounds/apps as well but it was random and I'm not sure what app was triggering it. Also the changes only started occurring with 4.9.0.

It doesn't occur with symfonium or antennapod.

If you can't fix it it's okay, I've decided to move back to the latter in the interim until things stabilize more as I found other issues (e.g. subscriptions page shows 0 episodes for every sub and crashes on opening one)

XilinJia commented 2 months ago

"subscriptions page shows 0 episodes" is due to the setting of Counter. I explained it here https://github.com/XilinJia/Podcini/issues/33#issuecomment-2050293425. I normally set to "Number of unplayed episodes". I tried setting it to others and didn't get Podcini to crash when opening a feed. Can you send a crash report on it?

metronidazole commented 2 months ago

I see thanks.

See #41

XilinJia commented 2 months ago

Very likely having to do with migrating to media3's MediaSessionService in 4.9.0. This sounds like the cause (from Android document):

Two or more Android apps can play audio to the same output stream simultaneously, and the system mixes everything together. While this is technically impressive, it can be very aggravating to a user. To avoid every music app playing at the same time, Android introduces the idea of audio focus. Only one app can hold audio focus at a time.

When your app needs to output audio, it should request audio focus. When it has focus, it can play sound. However, after you acquire audio focus you may not be able to keep it until you’re done playing. Another app can request focus, which preempts your hold on audio focus. If that happens, your app should pause playing or lower its volume to let users hear the new audio source more easily.

XilinJia commented 1 month ago

This is likely fixed in 5.0.0. Try it and shout back.

metronidazole commented 1 month ago

Seems fixed, thanks!

XilinJia / Podcini