search

XilinJia / Podcini

Open source podcast instrument for Android in Kotlin with media3, supporting channels, playlists, podcasts and single media from YouTube and YT Music as well as normal podcasts.
GNU General Public License v3.0
158 stars 7 forks source link

Podcini.R randomly restart playback while in background #71

Closed metronidazole closed 3 weeks ago

metronidazole commented 2 months ago

Checklist

App version

6.0.13

Where did you get the app from

Other

Android version

14

Device model

No response

First occurred

Last few days

Steps to reproduce

  1. Open podicini.R and start a podcast
  2. Pause podcast and go back homescreen
  3. Do anything else on your phone

I'm not sure what triggers this exactly. It seems to be random thus far.

Expected behaviour

Podcini should remain paused in background

Current behaviour

Podcini randomly restarts playback. Nothing is shown in the mediabar in notifications (unlike when you actually start playback)

I don't think this is related to similar issue #40 - playing sound manually doesn't trigger this.

Logs

--------- beginning of main 07-17 19:53:14.313 28445 29279 I IPCThreadState: oneway function results for code 2 on binder at 0xd32c59d02820 will be dropped but finished with status UNKNOWN_TRANSACTION 07-17 19:54:14.380 28445 28445 D TrafficStats: tagSocket(106) with statsTag=0xffffffff, statsUid=-1 07-17 19:54:14.449 28445 28445 I ExoPlayerImpl: Release 24cc32 [AndroidXMedia3/1.3.1] [husky, Pixel 8 Pro, Google, 34] [media3.common, media3.exoplayer, media3.decoder, media3.session, media3.datasource, media3.extractor] 07-17 19:54:14.498 28445 28714 D CCodecBuffers: [c2.android.mp3.decoder#170:1D-Output.Impl[N]] Client returned a buffer it does not own according to our record: 0 07-17 19:54:14.498 28445 28714 D CCodecBuffers: [c2.android.mp3.decoder#170:1D-Output.Impl[N]] Client returned a buffer it does not own according to our record: 1 07-17 19:54:14.499 28445 28714 D CCodecBuffers: [c2.android.mp3.decoder#170:1D-Output.Impl[N]] Client returned a buffer it does not own according to our record: 2 07-17 19:54:14.501 28445 28509 D MediaCodec: keep callback message for reclaim 07-17 19:54:14.503 28445 28714 I CCodecConfig: query failed after returning 7 values (BAD_INDEX) 07-17 19:54:14.504 28445 28714 D BufferPoolAccessor2.0: bufferpool2 0xd40f9ab16828 : 1(8192 size) total buffers - 1(8192 size) used buffers - 370/389 (recycle/alloc) - 18/774 (fetch/transfer) 07-17 19:54:14.508 28445 28714 W Codec2Client: query -- param skipped: index = 1342179345. 07-17 19:54:14.509 28445 28714 W Codec2Client: query -- param skipped: index = 2415921170. 07-17 19:54:14.555 28445 28714 D CCodecBufferChannel: [c2.android.mp3.decoder#170] MediaCodec discarded an unknown buffer 07-17 19:54:14.556 28445 28714 D CCodecBufferChannel: [c2.android.mp3.decoder#170] MediaCodec discarded an unknown buffer 07-17 19:54:14.556 28445 28714 D CCodecBufferChannel: [c2.android.mp3.decoder#170] MediaCodec discarded an unknown buffer 07-17 19:54:14.556 28445 28714 D CCodecBufferChannel: [c2.android.mp3.decoder#170] MediaCodec discarded an unknown buffer 07-17 19:54:14.573 28445 28714 I hw-BpHwBinder: onLastStrongRef automatically unlinking death recipients 07-17 19:54:14.685 28445 28445 D TrafficStats: tagSocket(96) with statsTag=0xffffffff, statsUid=-1 07-17 19:54:14.690 28445 28445 D TrafficStats: tagSocket(96) with statsTag=0xffffffff, statsUid=-1 07-17 19:54:14.696 28445 28445 D TrafficStats: tagSocket(96) with statsTag=0xffffffff, statsUid=-1 07-17 19:54:14.747 28445 28445 I ExoPlayerImpl: Init 6093805 [AndroidXMedia3/1.3.1] [husky, Pixel 8 Pro, Google, 34] 07-17 19:54:15.306 28445 11288 I DMCodecAdapterFactory: Creating an asynchronous MediaCodec adapter for track type audio 07-17 19:54:15.316 28445 11294 D CCodec : allocate(c2.android.mp3.decoder) 07-17 19:54:15.332 28445 11294 I CCodec : setting up 'default' as default (vendor) store 07-17 19:54:15.353 28445 11294 I CCodec : Created component [c2.android.mp3.decoder] 07-17 19:54:15.354 28445 11294 D CCodecConfig: read media type: audio/mpeg 07-17 19:54:15.365 28445 11294 D ReflectedParamUpdater: extent() != 1 for single value type: algo.buffers.max-count.values 07-17 19:54:15.367 28445 11294 D ReflectedParamUpdater: extent() != 1 for single value type: output.subscribed-indices.values 07-17 19:54:15.367 28445 11294 D ReflectedParamUpdater: extent() != 1 for single value type: input.buffers.allocator-ids.values 07-17 19:54:15.368 28445 11294 D ReflectedParamUpdater: extent() != 1 for single value type: output.buffers.allocator-ids.values 07-17 19:54:15.369 28445 11294 D ReflectedParamUpdater: extent() != 1 for single value type: algo.buffers.allocator-ids.values 07-17 19:54:15.369 28445 11294 D ReflectedParamUpdater: extent() != 1 for single value type: output.buffers.pool-ids.values 07-17 19:54:15.371 28445 11294 D ReflectedParamUpdater: extent() != 1 for single value type: algo.buffers.pool-ids.values 07-17 19:54:15.380 28445 11294 I CCodecConfig: query failed after returning 7 values (BAD_INDEX) 07-17 19:54:15.381 28445 11294 D CCodecConfig: c2 config diff is Dict { 07-17 19:54:15.381 28445 11294 D CCodecConfig: c2::u32 coded.bitrate.value = 64000 07-17 19:54:15.381 28445 11294 D CCodecConfig: c2::u32 input.buffers.max-size.value = 8192 07-17 19:54:15.381 28445 11294 D CCodecConfig: c2::u32 input.delay.value = 0 07-17 19:54:15.381 28445 11294 D CCodecConfig: string input.media-type.value = "audio/mpeg" 07-17 19:54:15.381 28445 11294 D CCodecConfig: string output.media-type.value = "audio/raw" 07-17 19:54:15.381 28445 11294 D CCodecConfig: c2::u32 raw.channel-count.value = 2 07-17 19:54:15.381 28445 11294 D CCodecConfig: c2::u32 raw.sample-rate.value = 44100 07-17 19:54:15.381 28445 11294 D CCodecConfig: } 07-17 19:54:15.392 28445 11294 I MediaCodec: MediaCodec will operate in async mode 07-17 19:54:15.397 28445 11294 D CCodec : [c2.android.mp3.decoder] buffers are bound to CCodec for this session 07-17 19:54:15.397 28445 11294 D CCodecConfig: no c2 equivalents for log-session-id 07-17 19:54:15.397 28445 11294 D CCodecConfig: no c2 equivalents for flags 07-17 19:54:15.399 28445 11294 D CCodecConfig: config failed => CORRUPTED 07-17 19:54:15.400 28445 11294 D CCodecConfig: c2 config diff is c2::u32 raw.channel-count.value = 1 07-17 19:54:15.402 28445 11294 W Codec2Client: query -- param skipped: index = 1107298332. 07-17 19:54:15.403 28445 11294 D CCodec : client requested max input size 4096, which is smaller than what component recommended (8192); overriding with component recommendation. 07-17 19:54:15.403 28445 11294 W CCodec : This behavior is subject to change. It is recommended that app developers double check whether the requested max input size is in reasonable range. 07-17 19:54:15.403 28445 11294 D CCodec : encoding statistics level = 0 07-17 19:54:15.403 28445 11294 D CCodec : setup formats input: AMessage(what = 0x00000000) = { 07-17 19:54:15.403 28445 11294 D CCodec : int32_t bitrate = 64000 07-17 19:54:15.403 28445 11294 D CCodec : int32_t channel-count = 1 07-17 19:54:15.403 28445 11294 D CCodec : int32_t max-input-size = 8192 07-17 19:54:15.403 28445 11294 D CCodec : string mime = "audio/mpeg" 07-17 19:54:15.403 28445 11294 D CCodec : int32_t sample-rate = 44100 07-17 19:54:15.403 28445 11294 D CCodec : } 07-17 19:54:15.403 28445 11294 D CCodec : setup formats output: AMessage(what = 0x00000000) = { 07-17 19:54:15.403 28445 11294 D CCodec : int32_t channel-count = 1 07-17 19:54:15.403 28445 11294 D CCodec : string mime = "audio/raw" 07-17 19:54:15.403 28445 11294 D CCodec : int32_t sample-rate = 44100 07-17 19:54:15.403 28445 11294 D CCodec : int32_t android._config-pcm-encoding = 2 07-17 19:54:15.403 28445 11294 D CCodec : } 07-17 19:54:15.403 28445 11294 I CCodecConfig: query failed after returning 7 values (BAD_INDEX) 07-17 19:54:15.407 28445 11288 D MediaCodec: keep callback message for reclaim 07-17 19:54:15.411 28445 11294 W Codec2Client: query -- param skipped: index = 1342179345. 07-17 19:54:15.411 28445 11294 W Codec2Client: query -- param skipped: index = 2415921170. 07-17 19:54:15.418 28445 11294 D CCodecBufferChannel: [c2.android.mp3.decoder#159] Created input block pool with allocatorID 16 => poolID 19 - OK (0) 07-17 19:54:15.428 28445 28662 D BufferPoolAccessor2.0: Destruction - bufferpool2 0xd40f9ab16828 cached: 0/0M, 0/0% in use; allocs: 393, 94% recycled; transfers: 774, 98% unfetched 07-17 19:54:15.431 28445 11294 I CCodecBufferChannel: [c2.android.mp3.decoder#159] Created output block pool with allocatorID 16 => poolID 201 - OK 07-17 19:54:15.431 28445 11294 D CCodecBufferChannel: [c2.android.mp3.decoder#159] Configured output block pool ids 201 => OK 07-17 19:54:15.465 28445 11288 D MediaCodec: keep callback message for reclaim 07-17 19:54:15.466 28445 11294 I CCodecConfig: query failed after returning 7 values (BAD_INDEX) 07-17 19:54:15.467 28445 11294 W Codec2Client: query -- param skipped: index = 1342179345. 07-17 19:54:15.467 28445 11294 W Codec2Client: query -- param skipped: index = 2415921170. 07-17 19:54:15.473 28445 11294 D CCodecBufferChannel: [c2.android.mp3.decoder#159] MediaCodec discarded an unknown buffer 07-17 19:54:15.473 28445 11294 D CCodecBufferChannel: [c2.android.mp3.decoder#159] MediaCodec discarded an unknown buffer 07-17 19:54:15.473 28445 11294 D CCodecBufferChannel: [c2.android.mp3.decoder#159] MediaCodec discarded an unknown buffer 07-17 19:54:15.473 28445 11294 D CCodecBufferChannel: [c2.android.mp3.decoder#159] MediaCodec discarded an unknown buffer 07-17 19:54:15.474 28445 11294 I hw-BpHwBinder: onLastStrongRef automatically unlinking death recipients 07-17 19:54:15.619 28445 11288 I DMCodecAdapterFactory: Creating an asynchronous MediaCodec adapter for track type audio 07-17 19:54:15.629 28445 11301 D CCodec : allocate(c2.android.mp3.decoder) 07-17 19:54:15.636 28445 11301 I CCodec : setting up 'default' as default (vendor) store 07-17 19:54:15.645 28445 11301 I CCodec : Created component [c2.android.mp3.decoder] 07-17 19:54:15.647 28445 11301 D CCodecConfig: read media type: audio/mpeg 07-17 19:54:15.657 28445 11301 D ReflectedParamUpdater: extent() != 1 for single value type: algo.buffers.max-count.values 07-17 19:54:15.659 28445 11301 D ReflectedParamUpdater: extent() != 1 for single value type: output.subscribed-indices.values 07-17 19:54:15.660 28445 11301 D ReflectedParamUpdater: extent() != 1 for single value type: input.buffers.allocator-ids.values 07-17 19:54:15.660 28445 11301 D ReflectedParamUpdater: extent() != 1 for single value type: output.buffers.allocator-ids.values 07-17 19:54:15.661 28445 11301 D ReflectedParamUpdater: extent() != 1 for single value type: algo.buffers.allocator-ids.values 07-17 19:54:15.661 28445 11301 D ReflectedParamUpdater: extent() != 1 for single value type: output.buffers.pool-ids.values 07-17 19:54:15.662 28445 11301 D ReflectedParamUpdater: extent() != 1 for single value type: algo.buffers.pool-ids.values 07-17 19:54:15.669 28445 11301 I CCodecConfig: query failed after returning 7 values (BAD_INDEX) 07-17 19:54:15.670 28445 11301 D CCodecConfig: c2 config diff is Dict { 07-17 19:54:15.670 28445 11301 D CCodecConfig: c2::u32 coded.bitrate.value = 64000 07-17 19:54:15.670 28445 11301 D CCodecConfig: c2::u32 input.buffers.max-size.value = 8192 07-17 19:54:15.670 28445 11301 D CCodecConfig: c2::u32 input.delay.value = 0 07-17 19:54:15.670 28445 11301 D CCodecConfig: string input.media-type.value = "audio/mpeg" 07-17 19:54:15.670 28445 11301 D CCodecConfig: string output.media-type.value = "audio/raw" 07-17 19:54:15.670 28445 11301 D CCodecConfig: c2::u32 raw.channel-count.value = 2 07-17 19:54:15.670 28445 11301 D CCodecConfig: c2::u32 raw.sample-rate.value = 44100 07-17 19:54:15.670 28445 11301 D CCodecConfig: } 07-17 19:54:15.677 28445 11301 I MediaCodec: MediaCodec will operate in async mode 07-17 19:54:15.679 28445 11301 D CCodec : [c2.android.mp3.decoder] buffers are bound to CCodec for this session 07-17 19:54:15.679 28445 11301 D CCodecConfig: no c2 equivalents for log-session-id 07-17 19:54:15.679 28445 11301 D CCodecConfig: no c2 equivalents for flags 07-17 19:54:15.681 28445 11301 D CCodecConfig: config failed => CORRUPTED 07-17 19:54:15.682 28445 11301 D CCodecConfig: c2 config diff is c2::u32 raw.channel-count.value = 1 07-17 19:54:15.684 28445 11301 W Codec2Client: query -- param skipped: index = 1107298332. 07-17 19:54:15.685 28445 11301 D CCodec : client requested max input size 4096, which is smaller than what component recommended (8192); overriding with component recommendation. 07-17 19:54:15.685 28445 11301 W CCodec : This behavior is subject to change. It is recommended that app developers double check whether the requested max input size is in reasonable range. 07-17 19:54:15.685 28445 11301 D CCodec : encoding statistics level = 0 07-17 19:54:15.685 28445 11301 D CCodec : setup formats input: AMessage(what = 0x00000000) = { 07-17 19:54:15.685 28445 11301 D CCodec : int32_t bitrate = 64000 07-17 19:54:15.685 28445 11301 D CCodec : int32_t channel-count = 1 07-17 19:54:15.685 28445 11301 D CCodec : int32_t max-input-size = 8192 07-17 19:54:15.685 28445 11301 D CCodec : string mime = "audio/mpeg" 07-17 19:54:15.685 28445 11301 D CCodec : int32_t sample-rate = 44100 07-17 19:54:15.685 28445 11301 D CCodec : } 07-17 19:54:15.685 28445 11301 D CCodec : setup formats output: AMessage(what = 0x00000000) = { 07-17 19:54:15.685 28445 11301 D CCodec : int32_t channel-count = 1 07-17 19:54:15.685 28445 11301 D CCodec : string mime = "audio/raw" 07-17 19:54:15.685 28445 11301 D CCodec : int32_t sample-rate = 44100 07-17 19:54:15.685 28445 11301 D CCodec : int32_t android._config-pcm-encoding = 2 07-17 19:54:15.685 28445 11301 D CCodec : } 07-17 19:54:15.687 28445 11301 I CCodecConfig: query failed after returning 7 values (BAD_INDEX) 07-17 19:54:15.688 28445 11288 D MediaCodec: keep callback message for reclaim 07-17 19:54:15.691 28445 11301 W Codec2Client: query -- param skipped: index = 1342179345. 07-17 19:54:15.691 28445 11301 W Codec2Client: query -- param skipped: index = 2415921170. 07-17 19:54:15.694 28445 11301 D CCodecBufferChannel: [c2.android.mp3.decoder#678] Created input block pool with allocatorID 16 => poolID 20 - OK (0) 07-17 19:54:15.698 28445 11301 I CCodecBufferChannel: [c2.android.mp3.decoder#678] Created output block pool with allocatorID 16 => poolID 202 - OK 07-17 19:54:15.698 28445 11301 D CCodecBufferChannel: [c2.android.mp3.decoder#678] Configured output block pool ids 202 => OK 07-17 19:54:16.435 28445 28445 D PlaybackController: handleStatus() called status: PLAYING 07-17 19:54:16.455 28445 28445 D PlaybackController: handleStatus() called status: PLAYING 07-17 19:54:19.507 28445 28661 D BufferPoolAccessor2.0: evictor expired: 1, evicted: 0 07-17 19:54:20.508 28445 28661 D BufferPoolAccessor2.0: bufferpool2 0xd40f9aac2e28 : 0(0 size) total buffers - 0(0 size) used buffers - 8/13 (recycle/alloc) - 4/8 (fetch/transfer) 07-17 19:54:20.508 28445 28661 D BufferPoolAccessor2.0: evictor expired: 1, evicted: 1 07-17 19:54:21.007 28445 11301 D BufferPoolAccessor2.0: bufferpool2 0xd40f9aac8028 : 5(40960 size) total buffers - 4(32768 size) used buffers - 253/258 (recycle/alloc) - 5/507 (fetch/transfer) 07-17 19:54:26.297 28445 11301 D BufferPoolAccessor2.0: bufferpool2 0xd40f9aac8028 : 5(40960 size) total buffers - 1(8192 size) used buffers - 504/509 (recycle/alloc) - 5/1014 (fetch/transfer) 07-17 19:54:28.233 28445 28445 D TrafficStats: tagSocket(208) with statsTag=0xffffffff, statsUid=-1 07-17 19:54:28.589 28445 28494 I IPCThreadState: oneway function results for code 1 on binder at 0xd32c59f66200 will be dropped but finished with status UNKNOWN_TRANSACTION 07-17 19:54:29.082 28445 28445 D PlaybackController: handleStatus() called status: PAUSED 07-17 19:54:31.369 28445 28445 D TrafficStats: tagSocket(206) with statsTag=0xffffffff, statsUid=-1 07-17 19:54:33.512 28445 28661 D BufferPoolAccessor2.0: bufferpool2 0xd40f9aac8028 : 5(40960 size) total buffers - 0(0 size) used buffers - 634/639 (recycle/alloc) - 5/1276 (fetch/transfer) 07-17 19:54:33.513 28445 28661 D BufferPoolAccessor2.0: evictor expired: 1, evicted: 1 07-17 19:54:34.446 28445 28445 D TrafficStats: tagSocket(122) with statsTag=0xffffffff, statsUid=-1 07-17 19:54:36.508 28445 28445 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 07-17 19:54:36.535 28445 28445 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 07-17 19:54:36.541 28445 28445 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 07-17 19:54:36.542 28445 28445 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 07-17 19:54:36.543 28445 28445 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 07-17 19:54:36.544 28445 28445 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 07-17 19:54:36.546 28445 28445 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 07-17 19:54:36.547 28445 28445 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 07-17 19:54:36.548 28445 28445 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 07-17 19:54:36.555 28445 28445 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 07-17 19:54:36.556 28445 28445 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 07-17 19:54:36.557 28445 28445 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 07-17 19:54:36.557 28445 28445 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 07-17 19:54:36.558 28445 28445 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 07-17 19:54:37.091 28445 28445 D VRI[MainActivity]: visibilityChanged oldVisibility=true newVisibility=false 07-17 19:54:37.106 28445 28512 D HWUI : endAllActiveAnimators on 0xd470ccbe9a00 (RippleDrawable) with handle 0xd34006f6e570 07-17 19:54:37.515 28445 28445 D TrafficStats: tagSocket(193) with statsTag=0xffffffff, statsUid=-1 07-17 19:54:37.725 28445 28445 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 07-17 19:54:38.590 28445 28445 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 07-17 19:54:39.134 28445 28445 D VRI[PreferenceActivity]: visibilityChanged oldVisibility=true newVisibility=false 07-17 19:54:39.148 28445 28512 D HWUI : endAllActiveAnimators on 0xd470ccec7200 (RippleDrawable) with handle 0xd34006dfaba0 07-17 19:54:42.159 28445 28445 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 07-17 19:54:42.498 28445 28445 W WindowOnBackDispatcher: sendCancelIfRunning: isInProgress=falsecallback=android.view.ViewRootImpl$$ExternalSyntheticLambda11@d3c6037 07-17 19:54:42.501 28445 28512 D HWUI : endAllActiveAnimators on 0xd470cd0cb200 (MenuPopupWindow$MenuDropDownListView) with handle 0xd34006e00420 07-17 19:54:43.295 11696 11696 W libc : Access denied finding property "ro.debuggable" 07-17 19:54:43.290 11696 11696 W logcat : type=1400 audit(0.0:181721): avc: denied { read } for name="u:object_r:userdebug_or_eng_prop:s0" dev="tmpfs" ino=445 scontext=u:r:untrusted_app:s0:c101,c257,c512,c768 tcontext=u:object_r:userdebug_or_eng_prop:s0 tclass=file permissive=0 app=ac.mdiq.podcini.R 07-17 19:54:43.301 28445 28445 W WindowOnBackDispatcher: sendCancelIfRunning: isInProgress=falsecallback=android.view.ViewRootImpl$$ExternalSyntheticLambda11@44a8815 07-17 19:54:43.304 28445 28512 D HWUI : endAllActiveAnimators on 0xd470cd08d400 (RippleDrawable) with handle 0xd34006e58030

XilinJia commented 2 months ago

not quite reproducible

metronidazole commented 2 months ago

I'll let you know if I can find way to reproduce it. It occurs randomly and rarely.

metronidazole commented 2 months ago

It's happened again a few times since. Today I just was listening to a youtube video with Tubular and in the middle of it (didn't touch the screen at all) Podicini just started randomly playing and taking over phone output. I hadn't opened the app for >15 hours. I then opened it to get this log which may be helpful.

--------- beginning of main
08-03 09:02:40.409 19895 19895 D AudioManager: dispatching onAudioFocusChange(-3) to android.media.AudioManager@e3625c5androidx.media3.exoplayer.AudioFocusManager$AudioFocusListener@7ee4b1a
08-03 09:02:42.900 19895 19895 D AudioManager: dispatching onAudioFocusChange(1) to android.media.AudioManager@e3625c5androidx.media3.exoplayer.AudioFocusManager$AudioFocusListener@7ee4b1a
08-03 09:03:03.479 19895 22491 I IPCThreadState: oneway function results for code 2 on binder at 0xc6b70ad14640 will be dropped but finished with status UNKNOWN_TRANSACTION
08-03 09:03:03.776 19895 19895 D AudioManager: dispatching onAudioFocusChange(-1) to android.media.AudioManager@e3625c5androidx.media3.exoplayer.AudioFocusManager$AudioFocusListener@7ee4b1a
(see log file for more)

podicini.log

metronidazole commented 2 months ago

It happened again. This time I started playback of media on my second phone (both phones run kdeconnect and share media playback status in notification area), and as soon as I started, Podicini on my main phone started playing

log2.txt

XilinJia commented 2 months ago

These unfortunately don't show much hint.

In 6.3.3, I added some Log.d messages, so hopefully, the next log you can provide will be more helpful

XilinJia commented 2 months ago

I caught this happening once in 6.3.4. I opened Podcini, without doing anything, switched to other app, then I hear Podcini playing. From the log I have, it appears Podcini's PlaybackService has received a "android.intent.action.MEDIA_BUTTON" action for some reason. I'm sure I did not pressed the play button.

metronidazole commented 2 months ago

That's odd. So it's android sending phantom intents then? I don't have any media keys on my phone.

I haven't had another instance yet so no further logs.

deadcombo commented 1 month ago

Also experiencing this, I can reliably trigger it by using the button in the notification drawer to clear all notifications.

        ## Environment

Android version: 14 OS version: 5.10.222-android13-4-g9b0143d7dce9 Podcini version: 6.3.5 Model: Pixel 7 Pro Device: cheetah Product: cheetah

        ## Crash info

Time: 08-08-2024 17:08:09 Podcini version: 6.3.5

StackTrace

java.lang.NullPointerException
    at ac.mdiq.podcini.ui.fragment.AudioPlayerFragment$PlayerUIFragment.getBinding(SourceFile:506)
    at ac.mdiq.podcini.ui.fragment.AudioPlayerFragment$PlayerUIFragment.updateUi(SourceFile:702)
    at ac.mdiq.podcini.ui.fragment.AudioPlayerFragment.onCollaped(SourceFile:189)
    at ac.mdiq.podcini.ui.fragment.AudioPlayerFragment.onCreateView(SourceFile:147)
    at androidx.fragment.app.Fragment.performCreateView(SourceFile:3119)
    at androidx.fragment.app.FragmentStateManager.createView(SourceFile:577)
    at androidx.fragment.app.FragmentStateManager.moveToExpectedState(SourceFile:286)
    at androidx.fragment.app.FragmentStore.moveToExpectedState(SourceFile:114)
    at androidx.fragment.app.FragmentManager.moveToState(SourceFile:1675)
    at androidx.fragment.app.FragmentManager.dispatchStateChange(SourceFile:3259)
    at androidx.fragment.app.FragmentManager.dispatchActivityCreated(SourceFile:3177)
    at androidx.fragment.app.FragmentController.dispatchActivityCreated(SourceFile:263)
    at androidx.fragment.app.FragmentActivity.onStart(SourceFile:350)
    at androidx.appcompat.app.AppCompatActivity.onStart(SourceFile:251)
    at ac.mdiq.podcini.ui.activity.MainActivity.onStart(SourceFile:528)
    at android.app.Instrumentation.callActivityOnStart(Instrumentation.java:1706)
    at android.app.Activity.performStart(Activity.java:9056)
    at android.app.ActivityThread.handleStartActivity(ActivityThread.java:4029)
    at android.app.servertransaction.TransactionExecutor.performLifecycleSequence(TransactionExecutor.java:327)
    at android.app.servertransaction.TransactionExecutor.cycleToPath(TransactionExecutor.java:307)
    at android.app.servertransaction.TransactionExecutor.executeLifecycleItem(TransactionExecutor.java:279)
    at android.app.servertransaction.TransactionExecutor.executeTransactionItems(TransactionExecutor.java:150)
    at android.app.servertransaction.TransactionExecutor.execute(TransactionExecutor.java:93)
    at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2602)
    at android.os.Handler.dispatchMessage(Handler.java:107)
    at android.os.Looper.loopOnce(Looper.java:232)
    at android.os.Looper.loop(Looper.java:317)
    at android.app.ActivityThread.main(ActivityThread.java:8623)
    at java.lang.reflect.Method.invoke(Native Method)
    at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:580)
    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:369)
XilinJia commented 1 month ago

Also experiencing this, I can reliably trigger it by using the button in the notification drawer to clear all notifications.

Thanks for the info. Can you give more detail? how do you trigger it?

Also the stacktrace included is not about start playing. To get the log when the random playing happens, go to Settings -> Report bug, then press the 3 dots on the top right corner and press "Export detailed logs". Please attach that here.

metronidazole commented 1 month ago

Thanks for the info. Can you give more detail? how do you trigger it?

I was able to confirm their reproduction. On the notification panel, there should be a button that clears all notifications. You must have at least one notification present for it to show on my device. When I press that, that will also trigger this bug. I have attached a log of this:

log.txt

metronidazole commented 1 month ago

clear

deadcombo commented 1 month ago

On August 11, 2024 9:01:12 AM UTC, Xilin Jia @.***> wrote:

Also experiencing this, I can reliably trigger it by using the button in the notification drawer to clear all notifications.

Thanks for the info. Can you give more detail? how do you trigger it?

Also the stacktrace included is not about start playing. To get the log when the random playing happens, go to Settings -> Report bug, then press the 3 dots on the top right corner and press "Export detailed logs". Please attach that here.

-- Reply to this email directly or view it on GitHub: https://github.com/XilinJia/Podcini/issues/71#issuecomment-2282683581 You are receiving this because you commented.

Message ID: @.*> --------- beginning of crash 08-07 14:30:35.035 29948 29948 E AndroidRuntime: FATAL EXCEPTION: main 08-07 14:30:35.035 29948 29948 E AndroidRuntime: Process: ac.mdiq.podcini.R, PID: 29948 08-07 14:30:35.035 29948 29948 E AndroidRuntime: java.lang.IllegalArgumentException 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at androidx.media3.common.util.Assertions.checkArgument(SourceFile:40) 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at androidx.media3.common.PlaybackParameters.(SourceFile:61) 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at ac.mdiq.podcini.playback.service.LocalMediaPlayer.setPlaybackParams(SourceFile:430) 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at ac.mdiq.podcini.playback.service.LocalMediaPlayer.resume(SourceFile:311) 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at ac.mdiq.podcini.playback.service.PlaybackService.handleKeycode(SourceFile:821) 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at ac.mdiq.podcini.playback.service.PlaybackService.access$handleKeycode(SourceFile:95) 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at ac.mdiq.podcini.playback.service.PlaybackService$MyCallback.onMediaButtonEvent$lambda$1(SourceFile:685) 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at ac.mdiq.podcini.playback.service.PlaybackService$MyCallback.$r8$lambda$PFduI31KP_b8OsFYyfGnjToyI1E(SourceFile:0) 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at ac.mdiq.podcini.playback.service.PlaybackService$MyCallback$$ExternalSyntheticLambda1.run(SourceFile:0) 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at android.os.Handler.handleCallback(Handler.java:959) 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at android.os.Handler.dispatchMessage(Handler.java:100) 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at android.os.Looper.loopOnce(Looper.java:232) 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at android.os.Looper.loop(Looper.java:317) 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at android.app.ActivityThread.main(ActivityThread.java:8623) 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at java.lang.reflect.Method.invoke(Native Method) 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:580) 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at com.android.internal.os.ExecInit.main(ExecInit.java:50) 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at com.android.internal.os.RuntimeInit.nativeFinishInit(Native Method) 08-07 14:30:35.035 29948 29948 E AndroidRuntime: at com.android.internal.os.RuntimeInit.main(RuntimeInit.java:369) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: FATAL EXCEPTION: main 08-07 14:31:05.898 2476 2476 E AndroidRuntime: Process: ac.mdiq.podcini.R, PID: 2476 08-07 14:31:05.898 2476 2476 E AndroidRuntime: android.app.RemoteServiceException$ForegroundServiceDidNotStartInTimeException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{52cc685 u0 ac.mdiq.podcini.R/ac.mdiq.podcini.playback.service.PlaybackService c:ac.mdiq.podcini.R} 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at android.app.ActivityThread.generateForegroundServiceDidNotStartInTimeException(ActivityThread.java:2250) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at android.app.ActivityThread.throwRemoteServiceException(ActivityThread.java:2221) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at android.app.ActivityThread.-$$Nest$mthrowRemoteServiceException(Unknown Source:0) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2527) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at android.os.Handler.dispatchMessage(Handler.java:107) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at android.os.Looper.loopOnce(Looper.java:232) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at android.os.Looper.loop(Looper.java:317) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at android.app.ActivityThread.main(ActivityThread.java:8623) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at java.lang.reflect.Method.invoke(Native Method) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:580) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at com.android.internal.os.ExecInit.main(ExecInit.java:50) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at com.android.internal.os.RuntimeInit.nativeFinishInit(Native Method) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at com.android.internal.os.RuntimeInit.main(RuntimeInit.java:369) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: Caused by: android.app.StackTrace: Last startServiceCommon() call for this service was made here 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at android.app.ContextImpl.startServiceCommon(ContextImpl.java:1985) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at android.app.ContextImpl.startForegroundService(ContextImpl.java:1939) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at android.content.ContextWrapper.startForegroundService(ContextWrapper.java:832) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at android.content.ContextWrapper.startForegroundService(ContextWrapper.java:832) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at androidx.core.content.ContextCompat$Api26Impl.startForegroundService(SourceFile:1128) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at androidx.core.content.ContextCompat.startForegroundService(SourceFile:700) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at ac.mdiq.podcini.receiver.MediaButtonReceiver.onReceive(SourceFile:33) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at android.app.ActivityThread.handleReceiver(ActivityThread.java:4718) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at android.app.ActivityThread.-$$Nest$mhandleReceiver(Unknown Source:0) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2406) 08-07 14:31:05.898 2476 2476 E AndroidRuntime: ... 9 more 08-08 17:08:09.693 29094 29094 E AndroidRuntime: FATAL EXCEPTION: main 08-08 17:08:09.693 29094 29094 E AndroidRuntime: Process: ac.mdiq.podcini.R, PID: 29094 08-08 17:08:09.693 29094 29094 E AndroidRuntime: java.lang.NullPointerException 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at ac.mdiq.podcini.ui.fragment.AudioPlayerFragment$PlayerUIFragment.getBinding(SourceFile:506) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at ac.mdiq.podcini.ui.fragment.AudioPlayerFragment$PlayerUIFragment.updateUi(SourceFile:702) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at ac.mdiq.podcini.ui.fragment.AudioPlayerFragment.onCollaped(SourceFile:189) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at ac.mdiq.podcini.ui.fragment.AudioPlayerFragment.onCreateView(SourceFile:147) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at androidx.fragment.app.Fragment.performCreateView(SourceFile:3119) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at androidx.fragment.app.FragmentStateManager.createView(SourceFile:577) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at androidx.fragment.app.FragmentStateManager.moveToExpectedState(SourceFile:286) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at androidx.fragment.app.FragmentStore.moveToExpectedState(SourceFile:114) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at androidx.fragment.app.FragmentManager.moveToState(SourceFile:1675) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at androidx.fragment.app.FragmentManager.dispatchStateChange(SourceFile:3259) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at androidx.fragment.app.FragmentManager.dispatchActivityCreated(SourceFile:3177) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at androidx.fragment.app.FragmentController.dispatchActivityCreated(SourceFile:263) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at androidx.fragment.app.FragmentActivity.onStart(SourceFile:350) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at androidx.appcompat.app.AppCompatActivity.onStart(SourceFile:251) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at ac.mdiq.podcini.ui.activity.MainActivity.onStart(SourceFile:528) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at android.app.Instrumentation.callActivityOnStart(Instrumentation.java:1706) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at android.app.Activity.performStart(Activity.java:9056) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at android.app.ActivityThread.handleStartActivity(ActivityThread.java:4029) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at android.app.servertransaction.TransactionExecutor.performLifecycleSequence(TransactionExecutor.java:327) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at android.app.servertransaction.TransactionExecutor.cycleToPath(TransactionExecutor.java:307) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at android.app.servertransaction.TransactionExecutor.executeLifecycleItem(TransactionExecutor.java:279) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at android.app.servertransaction.TransactionExecutor.executeTransactionItems(TransactionExecutor.java:150) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at android.app.servertransaction.TransactionExecutor.execute(TransactionExecutor.java:93) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2602) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at android.os.Handler.dispatchMessage(Handler.java:107) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at android.os.Looper.loopOnce(Looper.java:232) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at android.os.Looper.loop(Looper.java:317) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at android.app.ActivityThread.main(ActivityThread.java:8623) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at java.lang.reflect.Method.invoke(Native Method) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:580) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at com.android.internal.os.ExecInit.main(ExecInit.java:50) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at com.android.internal.os.RuntimeInit.nativeFinishInit(Native Method) 08-08 17:08:09.693 29094 29094 E AndroidRuntime: at com.android.internal.os.RuntimeInit.main(RuntimeInit.java:369) --------- beginning of main 08-11 11:25:22.617 16929 30642 W AudioTrack: restoreTrack_l(2217): dead IAudioTrack, PCM, creating a new one from getPosition() 08-11 11:25:22.618 16929 30642 I BpBinder: onLastStrongRef automatically unlinking death recipients: 08-11 11:25:22.620 16929 17114 I BpBinder: onLastStrongRef automatically unlinking death recipients: 08-11 11:25:22.655 16929 30652 D BufferPoolAccessor2.0: bufferpool2 0xb400c32365e4f028 : 1(8192 size) total buffers - 1(8192 size) used buffers - 54437/54443 (recycle/alloc) - 18/108872 (fetch/transfer) 08-11 11:25:22.886 16929 16929 D headsetDisconnected: headsetDisconnected onReceive called with action: android.intent.action.HEADSET_PLUG 08-11 11:25:22.889 16929 16929 D headsetDisconnected: headsetDisconnected onReceive called with action: android.intent.action.HEADSET_PLUG 08-11 11:25:29.661 16929 17135 D BufferPoolAccessor2.0: bufferpool2 0xb400c32365e4f028 : 4(32768 size) total buffers - 0(0 size) used buffers - 54445/54454 (recycle/alloc) - 24/108896 (fetch/transfer) 08-11 11:25:29.663 16929 17135 D BufferPoolAccessor2.0: evictor expired: 1, evicted: 1 08-11 11:25:38.592 16929 16929 D TrafficStats: tagSocket(113) with statsTag=0xffffffff, statsUid=-1 08-11 11:25:41.747 16929 16929 D TrafficStats: tagSocket(113) with statsTag=0xffffffff, statsUid=-1 08-11 11:25:44.906 16929 16929 D TrafficStats: tagSocket(113) with statsTag=0xffffffff, statsUid=-1 08-11 11:25:48.063 16929 16929 D TrafficStats: tagSocket(113) with statsTag=0xffffffff, statsUid=-1 08-11 11:25:51.187 16929 16929 D TrafficStats: tagSocket(113) with statsTag=0xffffffff, statsUid=-1 08-11 11:25:56.858 16929 16929 D PlaybackService: onStartCommand flags=0 startId=3 keycode=-1 customAction=null hardwareButton=false action=android.intent.action.MEDIA_BUTTON Episode 15 - Amerikan Tabloid pt 2: Yankees and Cowboys 08-11 11:25:56.891 16929 30652 D CCodecBuffers: [c2.android.mp3.decoder#0:1D-Output.Impl[N]] Client returned a buffer it does not own according to our record: 0 08-11 11:25:56.891 16929 30652 D CCodecBuffers: [c2.android.mp3.decoder#0:1D-Output.Impl[N]] Client returned a buffer it does not own according to our record: 1 08-11 11:25:56.891 16929 30652 D CCodecBuffers: [c2.android.mp3.decoder#0:1D-Output.Impl[N]] Client returned a buffer it does not own according to our record: 2 08-11 11:25:56.891 16929 30642 D MediaCodec: keep callback message for reclaim 08-11 11:25:56.894 16929 30652 I CCodecConfig: query failed after returning 7 values (BAD_INDEX) 08-11 11:25:56.894 16929 30652 D BufferPoolAccessor2.0: bufferpool2 0xb400c32365e4f028 : 1(8192 size) total buffers - 1(8192 size) used buffers - 54445/54455 (recycle/alloc) - 24/108896 (fetch/transfer) 08-11 11:25:56.895 16929 30652 W Codec2Client: query -- param skipped: index = 1342179345. 08-11 11:25:56.895 16929 30652 W Codec2Client: query -- param skipped: index = 2415921170. 08-11 11:25:56.899 16929 16929 D PlaybackService: statusChanged called INDETERMINATE 08-11 11:25:56.910 16929 30652 W MessageQueue: Handler (android.media.MediaCodec$EventHandler) {7150640} sending message to a Handler on a dead thread 08-11 11:25:56.910 16929 30652 W MessageQueue: java.lang.IllegalStateException: Handler (android.media.MediaCodec$EventHandler) {7150640} sending message to a Handler on a dead thread 08-11 11:25:56.910 16929 30652 W MessageQueue: at android.os.MessageQueue.enqueueMessage(MessageQueue.java:603) 08-11 11:25:56.910 16929 30652 W MessageQueue: at android.os.Handler.enqueueMessage(Handler.java:787) 08-11 11:25:56.910 16929 30652 W MessageQueue: at android.os.Handler.sendMessageAtTime(Handler.java:736) 08-11 11:25:56.910 16929 30652 W MessageQueue: at android.os.Handler.sendMessageDelayed(Handler.java:706) 08-11 11:25:56.910 16929 30652 W MessageQueue: at android.os.Handler.sendMessage(Handler.java:644) 08-11 11:25:56.910 16929 30652 W MessageQueue: at android.media.MediaCodec.postEventFromNative(MediaCodec.java:5622) 08-11 11:25:56.910 16929 30652 W MessageQueue: Handler (android.media.MediaCodec$EventHandler) {7150640} sending message to a Handler on a dead thread 08-11 11:25:56.910 16929 30652 W MessageQueue: java.lang.IllegalStateException: Handler (android.media.MediaCodec$EventHandler) {7150640} sending message to a Handler on a dead thread 08-11 11:25:56.910 16929 30652 W MessageQueue: at android.os.MessageQueue.enqueueMessage(MessageQueue.java:603) 08-11 11:25:56.910 16929 30652 W MessageQueue: at android.os.Handler.enqueueMessage(Handler.java:787) 08-11 11:25:56.910 16929 30652 W MessageQueue: at android.os.Handler.sendMessageAtTime(Handler.java:736) 08-11 11:25:56.910 16929 30652 W MessageQueue: at android.os.Handler.sendMessageDelayed(Handler.java:706) 08-11 11:25:56.910 16929 30652 W MessageQueue: at android.os.Handler.sendMessage(Handler.java:644) 08-11 11:25:56.910 16929 30652 W MessageQueue: at android.media.MediaCodec.postEventFromNative(MediaCodec.java:5622) 08-11 11:25:56.910 16929 30652 W MessageQueue: Handler (android.media.MediaCodec$EventHandler) {7150640} sending message to a Handler on a dead thread 08-11 11:25:56.910 16929 30652 W MessageQueue: java.lang.IllegalStateException: Handler (android.media.MediaCodec$EventHandler) {7150640} sending message to a Handler on a dead thread 08-11 11:25:56.910 16929 30652 W MessageQueue: at android.os.MessageQueue.enqueueMessage(MessageQueue.java:603) 08-11 11:25:56.910 16929 30652 W MessageQueue: at android.os.Handler.enqueueMessage(Handler.java:787) 08-11 11:25:56.910 16929 30652 W MessageQueue: at android.os.Handler.sendMessageAtTime(Handler.java:736) 08-11 11:25:56.910 16929 30652 W MessageQueue: at android.os.Handler.sendMessageDelayed(Handler.java:706) 08-11 11:25:56.910 16929 30652 W MessageQueue: at android.os.Handler.sendMessage(Handler.java:644) 08-11 11:25:56.910 16929 30652 W MessageQueue: at android.media.MediaCodec.postEventFromNative(MediaCodec.java:5622) 08-11 11:25:56.911 16929 30652 D CCodecBufferChannel: [c2.android.mp3.decoder#0] MediaCodec discarded an unknown buffer 08-11 11:25:56.911 16929 30652 D CCodecBufferChannel: [c2.android.mp3.decoder#0] MediaCodec discarded an unknown buffer 08-11 11:25:56.911 16929 30652 D CCodecBufferChannel: [c2.android.mp3.decoder#0] MediaCodec discarded an unknown buffer 08-11 11:25:56.911 16929 30652 D CCodecBufferChannel: [c2.android.mp3.decoder#0] MediaCodec discarded an unknown buffer 08-11 11:25:56.915 16929 30652 I hw-BpHwBinder: onLastStrongRef automatically unlinking death recipients 08-11 11:25:56.946 16929 16929 D PlaybackService: statusChanged called INITIALIZING 08-11 11:25:56.952 16929 16929 D PlaybackService: statusChanged called INITIALIZED 08-11 11:25:57.043 16929 16929 D PlaybackService: statusChanged called PREPARING 08-11 11:25:57.057 16929 16929 D PlaybackService: statusChanged called PREPARED 08-11 11:25:57.072 16929 30642 I DMCodecAdapterFactory: Creating an asynchronous MediaCodec adapter for track type audio 08-11 11:25:57.076 16929 2642 D CCodec : allocate(c2.android.mp3.decoder) 08-11 11:25:57.081 16929 2642 I CCodec : setting up 'default' as default (vendor) store 08-11 11:25:57.083 16929 16929 D PlaybackService: statusChanged called SEEKING 08-11 11:25:57.086 16929 16929 D PlaybackService: statusChanged called PREPARED 08-11 11:25:57.091 16929 2642 I CCodec : Created component [c2.android.mp3.decoder] 08-11 11:25:57.099 16929 2642 D CCodecConfig: read media type: audio/mpeg 08-11 11:25:57.102 16929 2642 D ReflectedParamUpdater: extent() != 1 for single value type: algo.buffers.max-count.values 08-11 11:25:57.102 16929 2642 D ReflectedParamUpdater: extent() != 1 for single value type: output.subscribed-indices.values 08-11 11:25:57.102 16929 2642 D ReflectedParamUpdater: extent() != 1 for single value type: input.buffers.allocator-ids.values 08-11 11:25:57.102 16929 2642 D ReflectedParamUpdater: extent() != 1 for single value type: output.buffers.allocator-ids.values 08-11 11:25:57.103 16929 2642 D ReflectedParamUpdater: extent() != 1 for single value type: algo.buffers.allocator-ids.values 08-11 11:25:57.103 16929 2642 D ReflectedParamUpdater: extent() != 1 for single value type: output.buffers.pool-ids.values 08-11 11:25:57.103 16929 2642 D ReflectedParamUpdater: extent() != 1 for single value type: algo.buffers.pool-ids.values 08-11 11:25:57.106 16929 2642 I CCodecConfig: query failed after returning 7 values (BAD_INDEX) 08-11 11:25:57.106 16929 2642 D CCodecConfig: c2 config diff is Dict { 08-11 11:25:57.106 16929 2642 D CCodecConfig: c2::u32 coded.bitrate.value = 64000 08-11 11:25:57.106 16929 2642 D CCodecConfig: c2::u32 input.buffers.max-size.value = 8192 08-11 11:25:57.106 16929 2642 D CCodecConfig: c2::u32 input.delay.value = 0 08-11 11:25:57.106 16929 2642 D CCodecConfig: string input.media-type.value = "audio/mpeg" 08-11 11:25:57.106 16929 2642 D CCodecConfig: string output.media-type.value = "audio/raw" 08-11 11:25:57.106 16929 2642 D CCodecConfig: c2::u32 raw.channel-count.value = 2 08-11 11:25:57.106 16929 2642 D CCodecConfig: c2::u32 raw.sample-rate.value = 44100 08-11 11:25:57.106 16929 2642 D CCodecConfig: } 08-11 11:25:57.110 16929 2642 I MediaCodec: MediaCodec will operate in async mode 08-11 11:25:57.110 16929 2642 D CCodec : [c2.android.mp3.decoder] buffers are bound to CCodec for this session 08-11 11:25:57.110 16929 2642 D CCodecConfig: no c2 equivalents for log-session-id 08-11 11:25:57.110 16929 2642 D CCodecConfig: no c2 equivalents for flags 08-11 11:25:57.111 16929 2642 D CCodecConfig: config failed => CORRUPTED 08-11 11:25:57.111 16929 2642 W Codec2Client: query -- param skipped: index = 1107298332. 08-11 11:25:57.111 16929 2642 D CCodec : client requested max input size 4096, which is smaller than what component recommended (8192); overriding with component recommendation. 08-11 11:25:57.111 16929 2642 W CCodec : This behavior is subject to change. It is recommended that app developers double check whether the requested max input size is in reasonable range. 08-11 11:25:57.111 16929 2642 D CCodec : encoding statistics level = 0 08-11 11:25:57.111 16929 2642 D CCodec : setup formats input: AMessage(what = 0x00000000) = { 08-11 11:25:57.111 16929 2642 D CCodec : int32_t bitrate = 64000 08-11 11:25:57.111 16929 2642 D CCodec : int32_t channel-count = 2 08-11 11:25:57.111 16929 2642 D CCodec : int32_t max-input-size = 8192 08-11 11:25:57.111 16929 2642 D CCodec : string mime = "audio/mpeg" 08-11 11:25:57.111 16929 2642 D CCodec : int32_t sample-rate = 44100 08-11 11:25:57.111 16929 2642 D CCodec : } 08-11 11:25:57.111 16929 2642 D CCodec : setup formats output: AMessage(what = 0x00000000) = { 08-11 11:25:57.111 16929 2642 D CCodec : int32_t channel-count = 2 08-11 11:25:57.111 16929 2642 D CCodec : string mime = "audio/raw" 08-11 11:25:57.111 16929 2642 D CCodec : int32_t sample-rate = 44100 08-11 11:25:57.111 16929 2642 D CCodec : int32_t android._config-pcm-encoding = 2 08-11 11:25:57.111 16929 2642 D CCodec : } 08-11 11:25:57.111 16929 2642 I CCodecConfig: query failed after returning 7 values (BAD_INDEX) 08-11 11:25:57.113 16929 30642 D MediaCodec: keep callback message for reclaim 08-11 11:25:57.118 16929 16929 D PlaybackService: statusChanged called PLAYING 08-11 11:25:57.119 16929 2642 W Codec2Client: query -- param skipped: index = 1342179345. 08-11 11:25:57.119 16929 2642 W Codec2Client: query -- param skipped: index = 2415921170. 08-11 11:25:57.120 16929 2642 D CCodecBufferChannel: [c2.android.mp3.decoder#892] Created input block pool with allocatorID 16 => poolID 25 - OK (0) 08-11 11:25:57.124 16929 2642 I CCodecBufferChannel: [c2.android.mp3.decoder#892] Created output block pool with allocatorID 16 => poolID 703 - OK 08-11 11:25:57.124 16929 2642 D CCodecBufferChannel: [c2.android.mp3.decoder#892] Configured output block pool ids 703 => OK 08-11 11:25:57.133 16929 30642 D MediaCodec: keep callback message for reclaim 08-11 11:25:57.134 16929 2642 I CCodecConfig: query failed after returning 7 values (BAD_INDEX) 08-11 11:25:57.134 16929 2642 W Codec2Client: query -- param skipped: index = 1342179345. 08-11 11:25:57.134 16929 2642 W Codec2Client: query -- param skipped: index = 2415921170. 08-11 11:25:57.143 16929 2642 D CCodecBufferChannel: [c2.android.mp3.decoder#892] flushed work; ignored. 08-11 11:25:57.143 16929 2642 D CCodecBufferChannel: [c2.android.mp3.decoder#892] Discard frames from previous generation. 08-11 11:25:57.231 16929 16929 D PlaybackService: statusChanged called PLAYING 08-11 11:25:57.273 16929 16929 D PlaybackService: onStartCommand flags=0 startId=4 keycode=-1 customAction=null hardwareButton=false action=null Episode 15 - Amerikan Tabloid pt 2: Yankees and Cowboys 08-11 11:25:57.288 16929 16929 D PlaybackService: onStartCommand flags=0 startId=5 keycode=-1 customAction=null hardwareButton=false action=null Episode 15 - Amerikan Tabloid pt 2: Yankees and Cowboys 08-11 11:25:57.365 16929 16929 D PlaybackController: notificationReceiver onReceive called with action: action.ac.mdiq.podcini.service.playerNotification 08-11 11:25:57.365 16929 16929 D PlaybackController: handleStatus() called status: PLAYING 08-11 11:25:57.372 16929 16929 D PlaybackController: statusUpdate onReceive called with action: action.ac.mdiq.podcini.service.playerStatusChanged 08-11 11:25:57.372 16929 16929 D PlaybackController: handleStatus() called status: PLAYING 08-11 11:25:57.373 16929 16929 D PlaybackController: statusUpdate onReceive called with action: action.ac.mdiq.podcini.service.playerStatusChanged 08-11 11:25:57.373 16929 16929 D PlaybackController: statusUpdate onReceive called with action: action.ac.mdiq.podcini.service.playerStatusChanged 08-11 11:25:57.373 16929 16929 D PlaybackController: statusUpdate onReceive called with action: action.ac.mdiq.podcini.service.playerStatusChanged 08-11 11:25:57.373 16929 16929 D PlaybackController: statusUpdate onReceive called with action: action.ac.mdiq.podcini.service.playerStatusChanged 08-11 11:25:57.373 16929 16929 D PlaybackController: statusUpdate onReceive called with action: action.ac.mdiq.podcini.service.playerStatusChanged 08-11 11:25:57.373 16929 16929 D PlaybackController: statusUpdate onReceive called with action: action.ac.mdiq.podcini.service.playerStatusChanged 08-11 11:25:57.373 16929 16929 D PlaybackController: statusUpdate onReceive called with action: action.ac.mdiq.podcini.service.playerStatusChanged 08-11 11:25:57.373 16929 16929 D PlaybackController: statusUpdate onReceive called with action: action.ac.mdiq.podcini.service.playerStatusChanged 08-11 11:25:57.553 16929 24102 I IPCThreadState: oneway function results for code 2 on binder at 0xb400c23da67554a0 will be dropped but finished with status UNKNOWN_TRANSACTION 08-11 11:25:57.579 16929 24102 I IPCThreadState: oneway function results for code 1 on binder at 0xb400c23da67554a0 will be dropped but finished with status UNKNOWN_TRANSACTION 08-11 11:26:01.897 16929 17135 D BufferPoolAccessor2.0: bufferpool2 0xb400c32365e4f028 : 0(0 size) total buffers - 0(0 size) used buffers - 54445/54459 (recycle/alloc) - 24/108896 (fetch/transfer) 08-11 11:26:01.897 16929 17135 D BufferPoolAccessor2.0: evictor expired: 1, evicted: 1 08-11 11:26:02.374 16929 2642 D BufferPoolAccessor2.0: bufferpool2 0xb400c32365e74228 : 6(49152 size) total buffers - 1(8192 size) used buffers - 214/220 (recycle/alloc) - 6/428 (fetch/transfer) 08-11 11:26:04.917 16929 16929 W WindowOnBackDispatcher: sendCancelIfRunning: *@. 08-11 11:26:04.936 16929 16929 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 08-11 11:26:04.991 16929 16929 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 08-11 11:26:05.004 16929 16929 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 08-11 11:26:05.006 16929 16929 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 08-11 11:26:05.009 16929 16929 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 08-11 11:26:05.011 16929 16929 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 08-11 11:26:05.013 16929 16929 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 08-11 11:26:05.016 16929 16929 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 08-11 11:26:05.018 16929 16929 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 08-11 11:26:05.031 16929 16929 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 08-11 11:26:05.033 16929 16929 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 08-11 11:26:05.036 16929 16929 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 08-11 11:26:05.136 16929 16929 D VRI[BugReportActivity]: visibilityChanged oldVisibility=true newVisibility=false 08-11 11:26:05.158 16929 16929 W WindowOnBackDispatcher: sendCancelIfRunning: @. 08-11 11:26:05.905 16929 16929 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 08-11 11:26:05.912 16929 16929 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 08-11 11:26:05.955 16929 16929 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 08-11 11:26:06.738 16929 16929 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 08-11 11:26:06.897 16929 16929 D VRI[PreferenceActivity]: visibilityChanged oldVisibility=true newVisibility=false 08-11 11:26:07.729 16929 2642 D BufferPoolAccessor2.0: bufferpool2 0xb400c32365e74228 : 6(49152 size) total buffers - 2(16384 size) used buffers - 420/426 (recycle/alloc) - 6/838 (fetch/transfer) 08-11 11:26:09.074 16929 16929 E ac.mdiq.podcini.R: Invalid resource ID 0x00000000. 08-11 11:26:09.132 16929 16929 W WindowOnBackDispatcher: sendCancelIfRunning: @. 08-11 11:26:09.874 16929 16929 D TrafficStats: tagSocket(208) with statsTag=0xffffffff, statsUid=-1 08-11 11:26:10.338 16929 16929 W WindowOnBackDispatcher: sendCancelIfRunning: @.***

XilinJia commented 1 month ago

So again, it's due to the fact that onStartCommand in PlaybackService is called with: flags=0 startId=1 keycode=-1 customAction=null hardwareButton=false action=android.intent.action.MEDIA_BUTTON Can't get anything deeper than that.

@metronidazole, you could trigger the play everytime you clear the notification? I had a couple chances but didn't get that to happen.

deadcombo commented 1 month ago

I can trigger it every time I press it.

On Sun, Aug 11, 2024 at 1:56 PM Xilin Jia @.***> wrote:

So again, it's due to the fact that onStartCommand in PlaybackService is called with: flags=0 startId=1 keycode=-1 customAction=null hardwareButton=false action=android.intent.action.MEDIA_BUTTON Can't get anything deeper than that.

@metronidazole https://github.com/metronidazole, you could trigger the play everytime you clear the notification? I had a couple chances but didn't get that to happen.

— Reply to this email directly, view it on GitHub https://github.com/XilinJia/Podcini/issues/71#issuecomment-2282769496, or unsubscribe https://github.com/notifications/unsubscribe-auth/AI3XAQQHDY3DQABLMEOQ4WTZQ5UP7AVCNFSM6AAAAABLAPJEZWVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDEOBSG43DSNBZGY . You are receiving this because you commented.Message ID: @.***>

metronidazole commented 1 month ago

@metronidazole, you could trigger the play everytime you clear the notification? I had a couple chances but didn't get that to happen.

I tried it a few times and as long as Podcini had been opened recently it would work.

The only time it didnt was when I went to sleep and then tried it in the morning.

metronidazole commented 1 month ago

Another log with the additional logging full-logs (1).txt

deadcombo commented 1 month ago

Here is mine:

full-logs.txt

Apologies for the previous dump, I did not know that an email reply would dump the file rather than attach it.

XilinJia commented 1 month ago

Got some hint. It appears the following event from the system causes the play:

PlaybackService: onStartCommand flags=0 startId=1 keycode=-1 keyEvent=KeyEvent { action=ACTION_DOWN, keyCode=KEYCODE_MEDIA_STOP, scanCode=0, metaState=0, flags=0x0, repeatCount=0, eventTime=0, downTime=0, deviceId=-1, source=0x0, displayId=-1 } customAction=null hardwareButton=false action=android.intent.action.MEDIA_BUTTON

Normally when keycode=-1, keyEvent=null so Podcini skips further checking it, but apparently, during this type of situations, keyEvent is not null. Will observe a bit further.

XilinJia commented 1 month ago

Hopefully, 6.4.0 resolved this issue.

deadcombo commented 4 weeks ago

Hopefully, 6.4.0 resolved this issue.

Having tested ever since, it seems that way. I have not had a single instance of this bug.

Thank you for your efforts.

XilinJia commented 3 weeks ago

great. Let's close this for now.