Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Playback stops, won't restart after multiple forward jumps via Bluetooth #3264

Closed
dlemire60 opened this issue Jul 12, 2019 · 35 comments
Closed
Labels
Type: Possible bug Issues that seem to be a bug, but haven't been confirmed yet

Comments

@dlemire60
Copy link

App version: AntennaPod 1.7.2b, Commit b892713, from Google Play store

Android version: Android 8.1.0, security patch level 1 April 2019, no custom ROMs, not rooted

Device model: Moto G5S Plus phone

Expected behaviour: execute multiple 30 second forward jumps to skip over advertising and have playback continue without any other interaction with phone.

Current behaviour: While listening in the car or with Bluetooth headphones, multiple presses of forward jump button often cause AntennaPod to stop playback, and playback can only be resumed by unlocking the phone and restarting in the AntennaPod app. If Android Auto is active, I have to exit Android Auto; hitting the play button within Android Auto does nothing. This is reproducible, but not 100% consistent. Situation is better if I wait between presses of the forward jump button but playback sometimes still stops.

I encounter this most often listening to Security Now, as it typically has several long sponsor breaks per 2h podcast. http://feeds.twit.tv/sn.xml

First occurred: Uncertain, last few months?

Steps to reproduce: Start podcast playback via Bluetooth device. Press forward jump button on listening device several times (typically at least 3, often 5 or more)

@ByteHamster
Copy link
Member

Hi! I can not reproduce this issue on my device. Skipping forward and backward multiple times on my Bluetooth headset works fine. If you could reproduce the error and then grab a logcat output, it will be much easier to fix.

@dlemire60
Copy link
Author

OK. I'll try to find some time to do that. First time I'll have worked with logcat, so that'll be a (small) learning curve. This looks like a good guide (https://android.gadgethacks.com/how-to/android-basics-capture-logcat-for-detailed-bug-reports-0167774/), but if you know of a better one please provide a link. My phone isn't rooted, so I'll have to go the ADB route.

@ByteHamster
Copy link
Member

Thanks a lot. The article suggests to use adb logcat > logcat.txt but I would instead use adb logcat -d > logcat.txt. That -d parameter makes the command stop after it has written everything to the file instead of waiting for more logs to be generated.

@dlemire60
Copy link
Author

Good tip. Thanks. I've worked with ADB a tiny bit to load CyanogenMod on an old tablet. But I'm no developer, so these things never get past the crawl stage of crawl / walk / run. :-) I'll pos when I have something.

@dlemire60
Copy link
Author

dlemire60 commented Oct 1, 2019

I'm delinquent on getting a logcat for this, but I was still have a problem just before the latest update. Now running 1.7.3b -- any chance there's a fix in there?

EDIT: Never mind, problem still occurs with the new version.

@dugite-code
Copy link

dugite-code commented Oct 23, 2019

I believe experiencing the same issue when using the Android Auto app even without bluetooth.

Reproduction is a bit hit and miss, in this instance I had to hit the skip button several times to reproduce, however quite often I've had it occur after only skipping twice. Once playback stops I have to clear AntennaPod from recent apps and re-open otherwise playback will not re-start (I pressed the play button twice to demonstrate this)

Logcat
searchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}, ComponentInfo{org.videolan.vlc/org.videolan.vlc.PlaybackService}]
10-23 10:00:15.089  2968  3395 V Avrcp   : old state = PlaybackState {state=1, position=-1, buffered position=0, speed=1.0, updated=650972650, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}, new state= PlaybackState {state=0, position=-1, buffered position=0, speed=1.0, updated=650972660, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}
10-23 10:00:15.089  2968  3395 I Avrcp   : updatePlayStatusForDevice: device: null
10-23 10:00:15.089  2968  3395 V Avrcp   : updatePlaybackState (1): old=PlaybackState {state=1, position=-1, buffered position=0, speed=1.0, updated=650972650, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}(0), new=PlaybackState {state=0, position=-1, buffered position=0, speed=1.0, updated=650972660, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}(0)
10-23 10:00:15.089  2968  3395 D Avrcp   : sendPlayPosNotificationRsp: Not registered or requesting.
10-23 10:00:15.089  2968  3395 D Avrcp   : Exit onPlaybackStateChanged()
10-23 10:00:15.089  5910  5910 I ExoPlayerImpl: Release 3b498e3 [ExoPlayerLib/2.9.3] [kinzie, XT1580, motorola, 24] [goog.exo.core]
10-23 10:00:15.092  5910  5910 I ExoPlayerImpl: Init d0c72e0 [ExoPlayerLib/2.9.3] [kinzie, XT1580, motorola, 24]
10-23 10:00:15.094  1145  5736 I MediaFocusControl:  AudioFocus  abandonAudioFocus() from uid/pid 10109/5910 clientId=android.media.AudioManager@1717094de.danoeh.antennapod.core.service.playback.LocalPSMP$1@412373d
10-23 10:00:15.094  5910  5910 D PlaybackService: Playback ended
10-23 10:00:15.095  5910  5910 D PlaybackSvcMediaPlayer: LocalPSMP: Setting player status to STOPPED
10-23 10:00:15.095  5910  5910 D LclPlaybackSvcMPlayer: getPosition() -> -1
10-23 10:00:15.097  2968  3395 V Avrcp   : MediaController playback changed: PlaybackState {state=1, position=-1, buffered position=0, speed=1.0, updated=650972674, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}
10-23 10:00:15.098  2968  3395 V Avrcp   : updatePlayPauseState, state: PlaybackState {state=1, position=-1, buffered position=0, speed=1.0, updated=650972674, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null} device: null
10-23 10:00:15.098  2968  3395 V Avrcp   : Device: no name:
10-23 10:00:15.098  2968  3395 V Avrcp   : updatePlayerPlayPauseState, old=PlaybackState {state=0, position=-1, buffered position=0, speed=1.0, updated=650972660, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}, state=PlaybackState {state=1, position=-1, buffered position=0, speed=1.0, updated=650972674, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}
10-23 10:00:15.098  2968  3395 V Avrcp   : old state = PlaybackState {state=0, position=-1, buffered position=0, speed=1.0, updated=650972660, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}, new state= PlaybackState {state=1, position=-1, buffered position=0, speed=1.0, updated=650972674, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}
10-23 10:00:15.098  2968  3395 I Avrcp   : updatePlayStatusForDevice: device: null
10-23 10:00:15.098  2968  3395 V Avrcp   : updatePlaybackState (1): old=PlaybackState {state=0, position=-1, buffered position=0, speed=1.0, updated=650972660, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}(0), new=PlaybackState {state=1, position=-1, buffered position=0, speed=1.0, updated=650972674, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}(0)
10-23 10:00:15.098  2968  3395 D Avrcp   : sendPlayPosNotificationRsp: Not registered or requesting.
10-23 10:00:15.098  2968  3395 D Avrcp   : Exit onPlaybackStateChanged()
10-23 10:00:15.102   527   527 D GH.NotifListenCNameMgr: No set listener, returning default: com.google.android.gearhead.notifications.SharedNotificationListenerManager$ListenerService
10-23 10:00:15.102   527   527 D GH.AvailableAppFinder: Found available apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}, ComponentInfo{org.videolan.vlc/org.videolan.vlc.PlaybackService}]
10-23 10:00:15.102   527   527 D GH.AvailableAppFinder: Filtered apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}, ComponentInfo{org.videolan.vlc/org.videolan.vlc.PlaybackService}]
10-23 10:00:15.103   527   527 D GH.AvailableAppFinder: Found available apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}, ComponentInfo{org.videolan.vlc/org.videolan.vlc.PlaybackService}]
10-23 10:00:15.103   527   527 D GH.AvailableAppFinder: Filtered apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}, ComponentInfo{org.videolan.vlc/org.videolan.vlc.PlaybackService}]
10-23 10:00:15.104  5910  5910 E PlaybackService: Cannot do post-playback processing: media was null
10-23 10:00:15.105   527   527 D GH.MediaPlaybackMonitor: onPlaybackStateChanged 1
10-23 10:00:15.106   527   527 D GH.StreamItemManager: postInternal: Posting buy{type=MEDIA, id=-4151775864118476492, contentId=-1159914893}. #items 1 -> 1
10-23 10:00:15.106   527   527 D GH.SimToNSAdapter: processing SI: buy{type=MEDIA, id=-4151775864118476492, contentId=-1159914893}
10-23 10:00:15.106   527   527 D GH.MPAdapter: getAsNotificationWorker for buy{type=MEDIA, id=-4151775864118476492, contentId=-1159914893} component=ComponentInfo{de.danoeh.antennapod/}
10-23 10:00:15.106  5910  5910 D EventDistributor: Processing event queue. Number of events: 2
10-23 10:00:15.106  5910  5910 D EventDistributor: Notifying observers. Data: 128
10-23 10:00:15.107   527   527 D GH.MPAdapter: getLeftAction forceDefault=false prevIsAvailable=false customActions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]]
10-23 10:00:15.107  1145  1202 I PowerManagerService: setInteractiveWhileDozingInternal - false
10-23 10:00:15.108   527   527 D GH.MPAdapter: getRightAction forceDefault=false prevIsAvailable=true customActions=[Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]]
10-23 10:00:15.109  1145  1202 I PowerManagerService: setInteractiveWhileDozingInternal - false
10-23 10:00:15.109  5910  5910 D MediaSessionCompat: onPause()
10-23 10:00:15.109  5910  5910 D MediaSessionCompat: onStop()
10-23 10:00:15.109  5910  5910 D PlaybackSvcMediaPlayer: LocalPSMP: Setting player status to INDETERMINATE
10-23 10:00:15.109  5910  5910 D LclPlaybackSvcMPlayer: getPosition() -> -1
10-23 10:00:15.109   527   527 D GH.NotificationStore: on notify: Notification(id=-1415076299, package=de.danoeh.antennapod priority=DEFAULT, alertOnlyOnce=false, primaryIcon=Action[icon=Icon(typ=APP_ICON componentName=ComponentInfo{de.danoeh.antennapod/}), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], secondaryIcon=null, firstAction=Action[icon=Icon(typ=RESOURCE pkg=android id=0x01080026), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], secondAction=Action[icon=Icon(typ=RESOURCE pkg=com.google.android.projection.gearhead id=0x7f080328), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], thirdAction=Action[icon=Icon(typ=RESOURCE pkg=com.google.android.projection.gearhead id=0x7f080340), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], style=MEDIA
10-23 10:00:15.111  2968  3395 V Avrcp   : MediaController playback changed: PlaybackState {state=0, position=-1, buffered position=0, speed=1.0, updated=650972687, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}
10-23 10:00:15.112  2968  3395 V Avrcp   : updatePlayPauseState, state: PlaybackState {state=0, position=-1, buffered position=0, speed=1.0, updated=650972687, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null} device: null
10-23 10:00:15.112  2968  3395 V Avrcp   : Device: no name:
10-23 10:00:15.112  2968  3395 V Avrcp   : updatePlayerPlayPauseState, old=PlaybackState {state=1, position=-1, buffered position=0, speed=1.0, updated=650972674, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}, state=PlaybackState {state=0, position=-1, buffered position=0, speed=1.0, updated=650972687, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}
10-23 10:00:15.112  2968  3395 V Avrcp   : old state = PlaybackState {state=1, position=-1, buffered position=0, speed=1.0, updated=650972674, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}, new state= PlaybackState {state=0, position=-1, buffered position=0, speed=1.0, updated=650972687, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}
10-23 10:00:15.112  2968  3395 I Avrcp   : updatePlayStatusForDevice: device: null
10-23 10:00:15.112  2968  3395 V Avrcp   : updatePlaybackState (1): old=PlaybackState {state=1, position=-1, buffered position=0, speed=1.0, updated=650972674, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}(0), new=PlaybackState {state=0, position=-1, buffered position=0, speed=1.0, updated=650972687, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}(0)
10-23 10:00:15.112  2968  3395 D Avrcp   : sendPlayPosNotificationRsp: Not registered or requesting.
10-23 10:00:15.112  2968  3395 D Avrcp   : Exit onPlaybackStateChanged()
10-23 10:00:15.113  5910  5910 I ExoPlayerImpl: Release d0c72e0 [ExoPlayerLib/2.9.3] [kinzie, XT1580, motorola, 24] [goog.exo.core]
10-23 10:00:15.114   527   527 D GH.NotifListenCNameMgr: No set listener, returning default: com.google.android.gearhead.notifications.SharedNotificationListenerManager$ListenerService
10-23 10:00:15.116  5910  5910 I ExoPlayerImpl: Init 275dd0c [ExoPlayerLib/2.9.3] [kinzie, XT1580, motorola, 24]
10-23 10:00:15.116   527   527 D GH.AvailableAppFinder: Found available apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}, ComponentInfo{org.videolan.vlc/org.videolan.vlc.PlaybackService}]
10-23 10:00:15.117   527   527 D GH.AvailableAppFinder: Filtered apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}, ComponentInfo{org.videolan.vlc/org.videolan.vlc.PlaybackService}]
10-23 10:00:15.117   527   527 D GH.AvailableAppFinder: Found available apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}, ComponentInfo{org.videolan.vlc/org.videolan.vlc.PlaybackService}]
10-23 10:00:15.118   527   527 D GH.AvailableAppFinder: Filtered apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}, ComponentInfo{org.videolan.vlc/org.videolan.vlc.PlaybackService}]
10-23 10:00:15.119  1145  2491 I MediaFocusControl:  AudioFocus  abandonAudioFocus() from uid/pid 10109/5910 clientId=android.media.AudioManager@1717094de.danoeh.antennapod.core.service.playback.LocalPSMP$1@412373d
10-23 10:00:15.119  5910  5910 D PlaybackService: Playback ended
10-23 10:00:15.121  5910  5910 D PlaybackSvcMediaPlayer: LocalPSMP: Setting player status to STOPPED
10-23 10:00:15.121  5910  5910 D LclPlaybackSvcMPlayer: getPosition() -> -1
10-23 10:00:15.124   527   527 W GH.ColorChecker: Tint color does not meet contrast requirements. Using black.
10-23 10:00:15.124  2968  3395 V Avrcp   : MediaController playback changed: PlaybackState {state=1, position=-1, buffered position=0, speed=1.0, updated=650972700, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}
10-23 10:00:15.124  2968  3395 V Avrcp   : updatePlayPauseState, state: PlaybackState {state=1, position=-1, buffered position=0, speed=1.0, updated=650972700, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null} device: null
10-23 10:00:15.124  2968  3395 V Avrcp   : Device: no name:
10-23 10:00:15.124  5910  5910 E PlaybackService: Cannot do post-playback processing: media was null
10-23 10:00:15.125  2968  3395 V Avrcp   : updatePlayerPlayPauseState, old=PlaybackState {state=0, position=-1, buffered position=0, speed=1.0, updated=650972687, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}, state=PlaybackState {state=1, position=-1, buffered position=0, speed=1.0, updated=650972700, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}
10-23 10:00:15.125  5910  5910 D PlaybackService: Received onUnbind event
10-23 10:00:15.125  2968  3395 V Avrcp   : old state = PlaybackState {state=0, position=-1, buffered position=0, speed=1.0, updated=650972687, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}, new state= PlaybackState {state=1, position=-1, buffered position=0, speed=1.0, updated=650972700, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}
10-23 10:00:15.125  2968  3395 I Avrcp   : updatePlayStatusForDevice: device: null
10-23 10:00:15.125  2968  3395 V Avrcp   : updatePlaybackState (1): old=PlaybackState {state=0, position=-1, buffered position=0, speed=1.0, updated=650972687, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}(0), new=PlaybackState {state=1, position=-1, buffered position=0, speed=1.0, updated=650972700, actions=616, custom actions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]], active item id=-1, error=null}(0)
10-23 10:00:15.125  2968  3395 D Avrcp   : sendPlayPosNotificationRsp: Not registered or requesting.
10-23 10:00:15.125  2968  3395 D Avrcp   : Exit onPlaybackStateChanged()
10-23 10:00:15.125  5910  5910 D MediaSessionCompat: onSkipToNext()
10-23 10:00:15.125  5910  5910 D LclPlaybackSvcMPlayer: getPosition() -> -1
10-23 10:00:15.125  5910  5910 E LclPlaybackSvcMPlayer: getPosition() returned INVALID_TIME in seekDelta
10-23 10:00:15.125  5910  5910 D EventDistributor: Processing event queue. Number of events: 0
10-23 10:00:15.127  5910  5910 D EventDistributor: Event queue didn't contain any new events. Observers will not be notified.
10-23 10:00:15.133   527   527 D GH.MediaPlaybackMonitor: onPlaybackStateChanged 0
10-23 10:00:15.133   527   527 D GH.StreamItemManager: postInternal: Posting buy{type=MEDIA, id=-4151775864118476492, contentId=-1159914893}. #items 1 -> 1
10-23 10:00:15.134   527   527 D GH.SimToNSAdapter: processing SI: buy{type=MEDIA, id=-4151775864118476492, contentId=-1159914893}
10-23 10:00:15.134   527   527 D GH.MPAdapter: getAsNotificationWorker for buy{type=MEDIA, id=-4151775864118476492, contentId=-1159914893} component=ComponentInfo{de.danoeh.antennapod/}
10-23 10:00:15.135   527   527 D GH.MPAdapter: getLeftAction forceDefault=false prevIsAvailable=false customActions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]]
10-23 10:00:15.136   527   527 D GH.MPAdapter: getRightAction forceDefault=false prevIsAvailable=true customActions=[Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]]
10-23 10:00:15.137  1145  1202 I PowerManagerService: setInteractiveWhileDozingInternal - false
10-23 10:00:15.137   527   527 D GH.NotificationStore: on notify: Notification(id=-1415076299, package=de.danoeh.antennapod priority=DEFAULT, alertOnlyOnce=false, primaryIcon=Action[icon=Icon(typ=APP_ICON componentName=ComponentInfo{de.danoeh.antennapod/}), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], secondaryIcon=null, firstAction=Action[icon=Icon(typ=RESOURCE pkg=android id=0x01080026), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], secondAction=Action[icon=Icon(typ=RESOURCE pkg=com.google.android.projection.gearhead id=0x7f080328), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], thirdAction=Action[icon=Icon(typ=RESOURCE pkg=com.google.android.projection.gearhead id=0x7f080340), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], style=MEDIA
10-23 10:00:15.140   527   527 D GH.NotifListenCNameMgr: No set listener, returning default: com.google.android.gearhead.notifications.SharedNotificationListenerManager$ListenerService
10-23 10:00:15.141   527   527 D GH.AvailableAppFinder: Found available apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}, ComponentInfo{org.videolan.vlc/org.videolan.vlc.PlaybackService}]
10-23 10:00:15.142   527   527 D GH.AvailableAppFinder: Filtered apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}, ComponentInfo{org.videolan.vlc/org.videolan.vlc.PlaybackService}]
10-23 10:00:15.142   527   527 D GH.AvailableAppFinder: Found available apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}, ComponentInfo{org.videolan.vlc/org.videolan.vlc.PlaybackService}]
10-23 10:00:15.142   527   527 D GH.AvailableAppFinder: Filtered apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}, ComponentInfo{org.videolan.vlc/org.videolan.vlc.PlaybackService}]
10-23 10:00:15.146  5910  5910 D MediaSessionCompat: onSkipToNext()
10-23 10:00:15.146  5910  5910 D LclPlaybackSvcMPlayer: getPosition() -> -1
10-23 10:00:15.146  5910  5910 E LclPlaybackSvcMPlayer: getPosition() returned INVALID_TIME in seekDelta
10-23 10:00:15.147   527   527 D GH.MediaPlaybackMonitor: onPlaybackStateChanged 1
10-23 10:00:15.147   527   527 D GH.StreamItemManager: postInternal: Posting buy{type=MEDIA, id=-4151775864118476492, contentId=-1159914893}. #items 1 -> 1
10-23 10:00:15.147   527   527 D GH.SimToNSAdapter: processing SI: buy{type=MEDIA, id=-4151775864118476492, contentId=-1159914893}
10-23 10:00:15.147   527   527 D GH.MPAdapter: getAsNotificationWorker for buy{type=MEDIA, id=-4151775864118476492, contentId=-1159914893} component=ComponentInfo{de.danoeh.antennapod/}
10-23 10:00:15.148   527   527 D GH.MPAdapter: getLeftAction forceDefault=false prevIsAvailable=false customActions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]]
10-23 10:00:15.150  1145  2192 D WifiNative-HAL: Failing getSupportedFeatureset because HAL isn't started
10-23 10:00:15.151  7682  5002 W GAv4    : Excessive tracking detected; call ignored.
10-23 10:00:15.151  7682  5002 W GAv4    : Discarding hit. Too many hits sent too quickly, rate limiting invoked: sr=1440x2368,cd=OVERVIEW_FACET,sf=100.0,ec=OVERVIEW_MEDIA_CARD,cid=593aeb6b-6d0e-49e6-a724-fd34f99902ed,cd3=PhoneOnly_PhoneOnly,_v=ma19.5.15,av=4.7.593824-release,v=1,a=624112705,an=Android Auto,cd1=PHONE,ul=en-au,t=event,cd2=PhoneOnly,tid=UA-73098246-1,aiid=com.android.vending,ea=MEDIA_SKIP_TO_NEXT,cd4=PLUGGED,aid=com.google.android.projection.gearhead,cd5=PORTRAIT
10-23 10:00:15.152   527   527 D GH.MPAdapter: getRightAction forceDefault=false prevIsAvailable=true customActions=[Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]]
10-23 10:00:15.153   527   527 D GH.NotificationStore: on notify: Notification(id=-1415076299, package=de.danoeh.antennapod priority=DEFAULT, alertOnlyOnce=false, primaryIcon=Action[icon=Icon(typ=APP_ICON componentName=ComponentInfo{de.danoeh.antennapod/}), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], secondaryIcon=null, firstAction=Action[icon=Icon(typ=RESOURCE pkg=android id=0x01080026), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], secondAction=Action[icon=Icon(typ=RESOURCE pkg=com.google.android.projection.gearhead id=0x7f080328), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], thirdAction=Action[icon=Icon(typ=RESOURCE pkg=com.google.android.projection.gearhead id=0x7f080340), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], style=MEDIA
10-23 10:00:15.155   527   527 D GH.NotifListenCNameMgr: No set listener, returning default: com.google.android.gearhead.notifications.SharedNotificationListenerManager$ListenerService
10-23 10:00:15.155   527   527 D GH.AvailableAppFinder: Found available apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}, ComponentInfo{org.videolan.vlc/org.videolan.vlc.PlaybackService}]
10-23 10:00:15.156   527   527 D GH.AvailableAppFinder: Filtered apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}, ComponentInfo{org.videolan.vlc/org.videolan.vlc.PlaybackService}]
10-23 10:00:15.156   527   527 D GH.AvailableAppFinder: Found available apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}, ComponentInfo{org.videolan.vlc/org.videolan.vlc.PlaybackService}]
10-23 10:00:15.156   527   527 D GH.AvailableAppFinder: Filtered apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}, ComponentInfo{org.videolan.vlc/org.videolan.vlc.PlaybackService}]
10-23 10:00:15.159   527   527 W GH.ColorChecker: Tint color does not meet contrast requirements. Using black.
10-23 10:00:15.161  1145  2192 D WifiNative-HAL: Failing getSupportedFeatureset because HAL isn't started
10-23 10:00:15.162  7682  5002 W GAv4    : Excessive tracking detected; call ignored.
10-23 10:00:15.163  7682  5002 W GAv4    : Discarding hit. Too many hits sent too quickly, rate limiting invoked: sr=1440x2368,cd=OVERVIEW_FACET,sf=100.0,ec=MEDIA,cid=593aeb6b-6d0e-49e6-a724-fd34f99902ed,cd3=PhoneOnly_PhoneOnly,_v=ma19.5.15,av=4.7.593824-release,v=1,a=624112705,an=Android Auto,cd1=PHONE,ul=en-au,t=event,cd2=PhoneOnly,tid=UA-73098246-1,aiid=com.android.vending,ea=SKIP_TO_NEXT,cd4=PLUGGED,aid=com.google.android.projection.gearhead,cd5=PORTRAIT,el=de.danoeh.antennapod
10-23 10:00:15.166   527   527 D GH.MediaPlaybackMonitor: onPlaybackStateChanged 0
10-23 10:00:15.166   527   527 D GH.StreamItemManager: postInternal: Posting buy{type=MEDIA, id=-4151775864118476492, contentId=-1159914893}. #items 1 -> 1
10-23 10:00:15.166   527   527 D GH.SimToNSAdapter: processing SI: buy{type=MEDIA, id=-4151775864118476492, contentId=-1159914893}
10-23 10:00:15.166   527   527 D GH.MPAdapter: getAsNotificationWorker for buy{type=MEDIA, id=-4151775864118476492, contentId=-1159914893} component=ComponentInfo{de.danoeh.antennapod/}
10-23 10:00:15.168   527   527 D GH.MPAdapter: getLeftAction forceDefault=false prevIsAvailable=false customActions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]]
10-23 10:00:15.169   527   527 D GH.MPAdapter: getRightAction forceDefault=false prevIsAvailable=true customActions=[Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]]
10-23 10:00:15.170   527   527 D GH.NotificationStore: on notify: Notification(id=-1415076299, package=de.danoeh.antennapod priority=DEFAULT, alertOnlyOnce=false, primaryIcon=Action[icon=Icon(typ=APP_ICON componentName=ComponentInfo{de.danoeh.antennapod/}), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], secondaryIcon=null, firstAction=Action[icon=Icon(typ=RESOURCE pkg=android id=0x01080026), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], secondAction=Action[icon=Icon(typ=RESOURCE pkg=com.google.android.projection.gearhead id=0x7f080328), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], thirdAction=Action[icon=Icon(typ=RESOURCE pkg=com.google.android.projection.gearhead id=0x7f080340), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], style=MEDIA
10-23 10:00:15.172   527   527 D GH.MediaPlaybackMonitor: onPlaybackStateChanged 1
10-23 10:00:15.172   527   527 D GH.StreamItemManager: postInternal: Posting buy{type=MEDIA, id=-4151775864118476492, contentId=-1159914893}. #items 1 -> 1
10-23 10:00:15.172   527   527 D GH.SimToNSAdapter: processing SI: buy{type=MEDIA, id=-4151775864118476492, contentId=-1159914893}
10-23 10:00:15.172   527   527 D GH.MPAdapter: getAsNotificationWorker for buy{type=MEDIA, id=-4151775864118476492, contentId=-1159914893} component=ComponentInfo{de.danoeh.antennapod/}
10-23 10:00:15.173   527   527 D GH.MPAdapter: getLeftAction forceDefault=false prevIsAvailable=false customActions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]]
10-23 10:00:15.174   527   527 D GH.MPAdapter: getRightAction forceDefault=false prevIsAvailable=true customActions=[Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]]
10-23 10:00:15.174   527   527 D GH.NotificationStore: on notify: Notification(id=-1415076299, package=de.danoeh.antennapod priority=DEFAULT, alertOnlyOnce=false, primaryIcon=Action[icon=Icon(typ=APP_ICON componentName=ComponentInfo{de.danoeh.antennapod/}), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], secondaryIcon=null, firstAction=Action[icon=Icon(typ=RESOURCE pkg=android id=0x01080026), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], secondAction=Action[icon=Icon(typ=RESOURCE pkg=com.google.android.projection.gearhead id=0x7f080328), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], thirdAction=Action[icon=Icon(typ=RESOURCE pkg=com.google.android.projection.gearhead id=0x7f080340), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], style=MEDIA
10-23 10:00:15.178   527   527 W GH.ColorChecker: Tint color does not meet contrast requirements. Using black.
10-23 10:00:15.182   483   738 W AudioFlinger::EffectModule: EffectModule 0xf227c180 destructor called with unreleased interface
10-23 10:00:15.182   483   738 W AudioFlinger::EffectHandle: disconnect Effect handle 0xf1be0d40 disconnected after thread destruction
10-23 10:00:15.184   483   738 D APM_AudioPolicyManager: stopOutput() output 21, stream 3, session 10785
10-23 10:00:15.278   684   684 I MSM-irqbalance: Decided to move IRQ304 from CPU2 to CPU1
10-23 10:00:15.298  5910  5910 D MediaSessionCompat: onSkipToNext()
10-23 10:00:15.298  5910  5910 D LclPlaybackSvcMPlayer: getPosition() -> -1
10-23 10:00:15.298  5910  5910 E LclPlaybackSvcMPlayer: getPosition() returned INVALID_TIME in seekDelta
10-23 10:00:15.312  1145  2192 D WifiNative-HAL: Failing getSupportedFeatureset because HAL isn't started
10-23 10:00:15.314  7682  5002 W GAv4    : Excessive tracking detected; call ignored.
10-23 10:00:15.314  7682  5002 W GAv4    : Discarding hit. Too many hits sent too quickly, rate limiting invoked: sr=1440x2368,cd=OVERVIEW_FACET,sf=100.0,ec=OVERVIEW_MEDIA_CARD,cid=593aeb6b-6d0e-49e6-a724-fd34f99902ed,cd3=PhoneOnly_PhoneOnly,_v=ma19.5.15,av=4.7.593824-release,v=1,a=624112705,an=Android Auto,cd1=PHONE,ul=en-au,t=event,cd2=PhoneOnly,tid=UA-73098246-1,aiid=com.android.vending,ea=MEDIA_SKIP_TO_NEXT,cd4=PLUGGED,aid=com.google.android.projection.gearhead,cd5=PORTRAIT
10-23 10:00:15.329  1145  2192 D WifiNative-HAL: Failing getSupportedFeatureset because HAL isn't started
10-23 10:00:15.331  7682  5002 W GAv4    : Excessive tracking detected; call ignored.
10-23 10:00:15.332  7682  5002 W GAv4    : Discarding hit. Too many hits sent too quickly, rate limiting invoked: sr=1440x2368,cd=OVERVIEW_FACET,sf=100.0,ec=MEDIA,cid=593aeb6b-6d0e-49e6-a724-fd34f99902ed,cd3=PhoneOnly_PhoneOnly,_v=ma19.5.15,av=4.7.593824-release,v=1,a=624112705,an=Android Auto,cd1=PHONE,ul=en-au,t=event,cd2=PhoneOnly,tid=UA-73098246-1,aiid=com.android.vending,ea=SKIP_TO_NEXT,cd4=PLUGGED,aid=com.google.android.projection.gearhead,cd5=PORTRAIT,el=de.danoeh.antennapod
10-23 10:00:15.583  1145  1202 I PowerManagerService: setInteractiveWhileDozingInternal - false
10-23 10:00:15.586   527   527 D GH.CallManager: getting Active calls
10-23 10:00:15.586   527   527 I GH.CallManager: getCalls
10-23 10:00:15.586   527   527 D GH.CallAdapterImpl: getCalls()
10-23 10:00:15.592   527   527 I GH.CallManager: getCalls
10-23 10:00:15.592   527   527 D GH.CallAdapterImpl: getCalls()
10-23 10:00:15.597   527   527 D GH.CallManager: got Active calls: []
10-23 10:00:15.605  5910  5910 D MediaSessionCompat: onPlay()
10-23 10:00:15.612  1145  2192 D WifiNative-HAL: Failing getSupportedFeatureset because HAL isn't started
10-23 10:00:15.613  7682  5002 W GAv4    : Excessive tracking detected; call ignored.
10-23 10:00:15.613  7682  5002 W GAv4    : Discarding hit. Too many hits sent too quickly, rate limiting invoked: sr=1440x2368,cd=OVERVIEW_FACET,sf=100.0,ec=OVERVIEW_MEDIA_CARD,cid=593aeb6b-6d0e-49e6-a724-fd34f99902ed,cd3=PhoneOnly_PhoneOnly,_v=ma19.5.15,av=4.7.593824-release,v=1,a=624112705,an=Android Auto,cd1=PHONE,ul=en-au,t=event,cd2=PhoneOnly,tid=UA-73098246-1,aiid=com.android.vending,ea=MEDIA_PLAY,cd4=PLUGGED,aid=com.google.android.projection.gearhead,cd5=PORTRAIT
10-23 10:00:15.623  1145  2192 D WifiNative-HAL: Failing getSupportedFeatureset because HAL isn't started
10-23 10:00:15.625  7682  5002 W GAv4    : Excessive tracking detected; call ignored.
10-23 10:00:15.626  7682  5002 W GAv4    : Discarding hit. Too many hits sent too quickly, rate limiting invoked: sr=1440x2368,cd=OVERVIEW_FACET,sf=100.0,ec=MEDIA,cid=593aeb6b-6d0e-49e6-a724-fd34f99902ed,cd3=PhoneOnly_PhoneOnly,_v=ma19.5.15,av=4.7.593824-release,v=1,a=624112705,an=Android Auto,cd1=PHONE,ul=en-au,t=event,cd2=PhoneOnly,tid=UA-73098246-1,aiid=com.android.vending,ea=PLAY,cd4=PLUGGED,aid=com.google.android.projection.gearhead,cd5=PORTRAIT,el=de.danoeh.antennapod
10-23 10:00:15.780  1145  1145 V NotificationService: pkg=com.google.android.apps.maps canInterrupt=false intercept=true
10-23 10:00:15.805   527   527 D GH.NavigationConverter: not extended
10-23 10:00:15.942  8599  8622 D WireGuard/GoBackend/Home: peer(u7qK/X24) - Sending keepalive packet
10-23 10:00:16.025  1145  2435 E LocSvc_eng: E/Calling gnss_sv_status_cb
10-23 10:00:16.032  1145  1202 I PowerManagerService: setInteractiveWhileDozingInternal - false
10-23 10:00:16.036  1145  1202 I PowerManagerService: setInteractiveWhileDozingInternal - false
10-23 10:00:16.096  1145  1202 I PowerManagerService: setInteractiveWhileDozingInternal - false
10-23 10:00:16.104   527   527 D GH.CallManager: getting Active calls
10-23 10:00:16.104   527   527 I GH.CallManager: getCalls
10-23 10:00:16.104   527   527 D GH.CallAdapterImpl: getCalls()
10-23 10:00:16.108   527   527 I GH.CallManager: getCalls
10-23 10:00:16.108   527   527 D GH.CallAdapterImpl: getCalls()
10-23 10:00:16.114   527   527 D GH.CallManager: got Active calls: []
10-23 10:00:16.117  5910  5910 D MediaSessionCompat: onPlay()
10-23 10:00:16.124  1145  2192 D WifiNative-HAL: Failing getSupportedFeatureset because HAL isn't started
10-23 10:00:16.125  7682  5002 W GAv4    : Excessive tracking detected; call ignored.
10-23 10:00:16.125  7682  5002 W GAv4    : Discarding hit. Too many hits sent too quickly, rate limiting invoked: sr=1440x2368,cd=OVERVIEW_FACET,sf=100.0,ec=OVERVIEW_MEDIA_CARD,cid=593aeb6b-6d0e-49e6-a724-fd34f99902ed,cd3=PhoneOnly_PhoneOnly,_v=ma19.5.15,av=4.7.593824-release,v=1,a=624112705,an=Android Auto,cd1=PHONE,ul=en-au,t=event,cd2=PhoneOnly,tid=UA-73098246-1,aiid=com.android.vending,ea=MEDIA_PLAY,cd4=PLUGGED,aid=com.google.android.projection.gearhead,cd5=PORTRAIT
10-23 10:00:16.141  1145  2192 D WifiNative-HAL: Failing getSupportedFeatureset because HAL isn't started
10-23 10:00:16.143  7682  5002 W GAv4    : Excessive tracking detected; call ignored.
10-23 10:00:16.144  7682  5002 W GAv4    : Discarding hit. Too many hits sent too quickly, rate limiting invoked: sr=1440x2368,cd=OVERVIEW_FACET,sf=100.0,ec=MEDIA,cid=593aeb6b-6d0e-49e6-a724-fd34f99902ed,cd3=PhoneOnly_PhoneOnly,_v=ma19.5.15,av=4.7.593824-release,v=1,a=624112705,an=Android Auto,cd1=PHONE,ul=en-au,t=event,cd2=PhoneOnly,tid=UA-73098246-1,aiid=com.android.vending,ea=PLAY,cd4=PLUGGED,aid=com.google.android.projection.gearhead,cd5=PORTRAIT,el=de.danoeh.antennapod
10-23 10:00:16.291   527   527 D GH.CallManager: getting Active calls
10-23 10:00:16.291   527   527 I GH.CallManager: getCalls
10-23 10:00:16.291   527   527 D GH.CallAdapterImpl: getCalls()
10-23 10:00:16.296   527   527 I GH.CallManager: getCalls
10-23 10:00:16.297   527   527 D GH.CallAdapterImpl: getCalls()
10-23 10:00:16.304   527   527 D GH.CallManager: got Active calls: []
10-23 10:00:16.308  5910  5910 D MediaSessionCompat: onPlay()
10-23 10:00:16.316  1145  2192 D WifiNative-HAL: Failing getSupportedFeatureset because HAL isn't started
10-23 10:00:16.328  1145  2192 D WifiNative-HAL: Failing getSupportedFeatureset because HAL isn't started
10-23 10:00:16.331  7682  5002 W GAv4    : Excessive tracking detected; call ignored.
10-23 10:00:16.331  7682  5002 W GAv4    : Discarding hit. Too many hits sent too quickly, rate limiting invoked: sr=1440x2368,cd=OVERVIEW_FACET,sf=100.0,ec=MEDIA,cid=593aeb6b-6d0e-49e6-a724-fd34f99902ed,cd3=PhoneOnly_PhoneOnly,_v=ma19.5.15,av=4.7.593824-release,v=1,a=624112705,an=Android Auto,cd1=PHONE,ul=en-au,t=event,cd2=PhoneOnly,tid=UA-73098246-1,aiid=com.android.vending,ea=PLAY,cd4=PLUGGED,aid=com.google.android.projection.gearhead,cd5=PORTRAIT,el=de.danoeh.antennapod
10-23 10:00:17.025  1145  2435 E LocSvc_eng: E/Calling gnss_sv_status_cb
10-23 10:00:17.032  1145  1202 I PowerManagerService: setInteractiveWhileDozingInternal - false
10-23 10:00:17.039  1145  1202 I PowerManagerService: setInteractiveWhileDozingInternal - false
10-23 10:00:17.131  1145  1145 V NotificationService: pkg=com.google.android.apps.maps canInterrupt=false intercept=true
10-23 10:00:17.149   527   527 D GH.NavigationConverter: not extended
10-23 10:00:17.154   445   693 I SFPerfTracer:      triggers: (rate: 3:473) (1143864 sw vsyncs) (0 skipped) (86:3686787 vsyncs) (88:5192097)

Device: Motorola X Force
Android Version: 7.0
AntennaPod Version: 1.7.3b

@dlemire60
Copy link
Author

@dugite-code is describing very much what I've experienced. Thanks to dugite-code for posting their logcat, I'm not really set up to do that, which is why I'm super-delinquent doing so. Updating my original post:

App version: AntennaPod 1.7.3b, Commit f9e7e9a, from Google Play store

Android version: Android 8.1.0, security patch level 1 August 2019, no custom ROMs, not rooted

@dugite-code
Copy link

As I recently purchased a new Phone I thought I would test this again, Please see my logcat output below. This time it was triggered after a couple of rewinds.

Logcat
11-08 11:37:13.029  8197  8197 D PlaybackService: Received onUnbind event
11-08 11:37:13.029  9360  9360 D GH.NotifListenCNameMgr: No set listener, returning default: com.google.android.gearhead.notifications.SharedNotificationListenerManager$ListenerService
11-08 11:37:13.030  8197  8197 D EventDistributor: Processing event queue. Number of events: 0
11-08 11:37:13.030  8197  8197 D EventDistributor: Event queue didn't contain any new events. Observers will not be notified.
11-08 11:37:13.030  9360  9360 D GH.AvailableAppFinder: Found available apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}]
11-08 11:37:13.030  9360  9360 D GH.AvailableAppFinder: Filtered apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}]
11-08 11:37:13.030  9360  9360 D GH.AvailableAppFinder: Found available apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}]
11-08 11:37:13.030  9360  9360 D GH.AvailableAppFinder: Filtered apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}]
11-08 11:37:13.033  9360  9360 D GH.NotifListenCNameMgr: No set listener, returning default: com.google.android.gearhead.notifications.SharedNotificationListenerManager$ListenerService
11-08 11:37:13.033  9360  9360 D GH.AvailableAppFinder: Found available apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}]
11-08 11:37:13.033  9360  9360 D GH.AvailableAppFinder: Filtered apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}]
11-08 11:37:13.034  9360  9360 D GH.AvailableAppFinder: Found available apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}]
11-08 11:37:13.034  9360  9360 D GH.AvailableAppFinder: Filtered apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}]
11-08 11:37:13.038  9360  9360 D GH.NotifListenCNameMgr: No set listener, returning default: com.google.android.gearhead.notifications.SharedNotificationListenerManager$ListenerService
11-08 11:37:13.038  9360  9360 D GH.AvailableAppFinder: Found available apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}]
11-08 11:37:13.039  9360  9360 D GH.AvailableAppFinder: Filtered apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}]
11-08 11:37:13.039  9360  9360 D GH.AvailableAppFinder: Found available apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}]
11-08 11:37:13.039  9360  9360 D GH.AvailableAppFinder: Filtered apps [ComponentInfo{de.danoeh.antennapod/de.danoeh.antennapod.core.service.playback.PlaybackService}, ComponentInfo{com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.mediabrowser.PodcastsMediaBrowserService}]
11-08 11:37:13.041  9360  9360 W GH.ColorChecker: Tint color does not meet contrast requirements. Using black.
11-08 11:37:13.042  9360  9360 W StaticLayout: maxLineHeight should not be -1.  maxLines:1 lineCount:1
11-08 11:37:13.042  9360  9360 I chatty  : uid=10177 com.google.android.projection.gearhead:vanagon identical 4 lines
11-08 11:37:13.042  9360  9360 W StaticLayout: maxLineHeight should not be -1.  maxLines:1 lineCount:1
11-08 11:37:13.045  9360  9360 D GH.MediaPlaybackMonitor: onPlaybackStateChanged 1
11-08 11:37:13.045  9360  9360 D GH.StreamItemManager: postInternal: Posting buy{type=MEDIA, id=-4151775864118476492, contentId=-1973773564}. #items 1 -> 1
11-08 11:37:13.045  9360  9360 D GH.SimToNSAdapter: processing SI: buy{type=MEDIA, id=-4151775864118476492, contentId=-1973773564}
11-08 11:37:13.045  9360  9360 D GH.MPAdapter: getAsNotificationWorker for buy{type=MEDIA, id=-4151775864118476492, contentId=-1973773564} component=ComponentInfo{de.danoeh.antennapod/}
11-08 11:37:13.046  9360  9360 D GH.MPAdapter: getLeftAction forceDefault=false prevIsAvailable=false customActions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]]
11-08 11:37:13.046  9360  9360 D GH.MPAdapter: getRightAction forceDefault=false prevIsAvailable=true customActions=[Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]]
11-08 11:37:13.046  9360  9360 D GH.NotificationStore: on notify: Notification(id=-1257683909, package=de.danoeh.antennapod priority=DEFAULT, alertOnlyOnce=false, primaryIcon=Action[icon=Icon(typ=APP_ICON componentName=ComponentInfo{de.danoeh.antennapod/}), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], secondaryIcon=null, firstAction=Action[icon=Icon(typ=RESOURCE pkg=android id=0x01080026), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], secondAction=Action[icon=Icon(typ=RESOURCE pkg=com.google.android.projection.gearhead id=0x7f080328), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], thirdAction=Action[icon=Icon(typ=RESOURCE pkg=com.google.android.projection.gearhead id=0x7f080340), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], style=MEDIA
11-08 11:37:13.047  9360  9360 D GH.MediaPlaybackMonitor: onPlaybackStateChanged 0
11-08 11:37:13.048  9360  9360 D GH.StreamItemManager: postInternal: Posting buy{type=MEDIA, id=-4151775864118476492, contentId=-1973773564}. #items 1 -> 1
11-08 11:37:13.048  9360  9360 D GH.SimToNSAdapter: processing SI: buy{type=MEDIA, id=-4151775864118476492, contentId=-1973773564}
11-08 11:37:13.048  9360  9360 D GH.MPAdapter: getAsNotificationWorker for buy{type=MEDIA, id=-4151775864118476492, contentId=-1973773564} component=ComponentInfo{de.danoeh.antennapod/}
11-08 11:37:13.048  9360  9360 D GH.MPAdapter: getLeftAction forceDefault=false prevIsAvailable=false customActions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]]
11-08 11:37:13.049  9360  9360 D GH.MPAdapter: getRightAction forceDefault=false prevIsAvailable=true customActions=[Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]]
11-08 11:37:13.049  9360  9360 D GH.NotificationStore: on notify: Notification(id=-1257683909, package=de.danoeh.antennapod priority=DEFAULT, alertOnlyOnce=false, primaryIcon=Action[icon=Icon(typ=APP_ICON componentName=ComponentInfo{de.danoeh.antennapod/}), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], secondaryIcon=null, firstAction=Action[icon=Icon(typ=RESOURCE pkg=android id=0x01080026), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], secondAction=Action[icon=Icon(typ=RESOURCE pkg=com.google.android.projection.gearhead id=0x7f080328), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], thirdAction=Action[icon=Icon(typ=RESOURCE pkg=com.google.android.projection.gearhead id=0x7f080340), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], style=MEDIA
11-08 11:37:13.050  9360  9360 D GH.MediaPlaybackMonitor: onPlaybackStateChanged 1
11-08 11:37:13.050  9360  9360 D GH.StreamItemManager: postInternal: Posting buy{type=MEDIA, id=-4151775864118476492, contentId=-1973773564}. #items 1 -> 1
11-08 11:37:13.050  9360  9360 D GH.SimToNSAdapter: processing SI: buy{type=MEDIA, id=-4151775864118476492, contentId=-1973773564}
11-08 11:37:13.050  9360  9360 D GH.MPAdapter: getAsNotificationWorker for buy{type=MEDIA, id=-4151775864118476492, contentId=-1973773564} component=ComponentInfo{de.danoeh.antennapod/}
11-08 11:37:13.051  9360  9360 D GH.MPAdapter: getLeftAction forceDefault=false prevIsAvailable=false customActions=[Action:mName='Rewind, mIcon=17301542, mExtras=Bundle[mParcelledData.dataSize=144], Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]]
11-08 11:37:13.052  9360  9360 D GH.MPAdapter: getRightAction forceDefault=false prevIsAvailable=true customActions=[Action:mName='Fast forward, mIcon=17301537, mExtras=Bundle[mParcelledData.dataSize=144]]
11-08 11:37:13.052  9360  9360 D GH.NotificationStore: on notify: Notification(id=-1257683909, package=de.danoeh.antennapod priority=DEFAULT, alertOnlyOnce=false, primaryIcon=Action[icon=Icon(typ=APP_ICON componentName=ComponentInfo{de.danoeh.antennapod/}), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], secondaryIcon=null, firstAction=Action[icon=Icon(typ=RESOURCE pkg=android id=0x01080026), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], secondAction=Action[icon=Icon(typ=RESOURCE pkg=com.google.android.projection.gearhead id=0x7f080328), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], thirdAction=Action[icon=Icon(typ=RESOURCE pkg=com.google.android.projection.gearhead id=0x7f080340), label=null, intent=Intent { act=com.google.android.gearhead.ACTION_HANDLE_NOTIFICATION_INTENT pkg=com.google.android.projection.gearhead (has extras) }], style=MEDIA
11-08 11:37:13.055  9360  9360 W GH.ColorChecker: Tint color does not meet contrast requirements. Using black.
11-08 11:37:13.055 12410 12431 D NewAvrcpTargetJni: getCurrentPlayStatus
11-08 11:37:13.055 12410 12431 D NewAvrcpNativeInterface: getPlayStatus
11-08 11:37:13.056  9360  9360 W StaticLayout: maxLineHeight should not be -1.  maxLines:1 lineCount:1
11-08 11:37:13.056  9360  9360 I chatty  : uid=10177 com.google.android.projection.gearhead:vanagon identical 4 lines
11-08 11:37:13.056  9360  9360 W StaticLayout: maxLineHeight should not be -1.  maxLines:1 lineCount:1
11-08 11:37:13.105 12048  8158 W StreamHalLocal: Local streams can not have effects
11-08 11:37:13.105 12048  8158 E AudioFlinger::EffectModule: Error when removing effect: -38
11-08 11:37:13.105 12048 12058 W StreamHalLocal: Local streams can not have effects
11-08 11:37:13.105 12048 12058 E AudioFlinger::EffectModule: Error when removing effect: -38
11-08 11:37:13.106 12048 12058 D APM_AudioPolicyManager: stopOutput() output 757, stream 3, session 1977
11-08 11:37:13.430  4451  4451 V MediaRouterService: restoreBluetoothA2dp(true)
11-08 11:37:13.203 12048 12058 D APM_AudioPolicyManager: stopOutput() output 757, stream 3, session 1977
11-08 11:37:13.958  4129  4163 V echo-service: [ExynosThermal] Sensor [tmu_little] temp(40000)
11-08 11:37:13.958  4129  4163 V echo-service: [ExynosThermal] Sensor [tmu_big] temp(41000)
11-08 11:37:13.958  4129  4163 V echo-service: [ExynosThermal] Sensor [tmu_gpu] temp(41000)
11-08 11:37:13.958  4129  4163 V echo-service: [ExynosThermal] Sensor [tmu_isp] temp(40000)
11-08 11:37:13.959  4129  4163 V echo-service: [ExynosThermal] Sensor [therm_soc] temp(33982)
11-08 11:37:13.960  4129  4163 V echo-service: [ExynosThermal] Sensor [therm_bat] temp(30465)
11-08 11:37:13.960  4129  4163 V echo-service: [ExynosThermal] Sensor [therm_pa] temp(32444)
11-08 11:37:13.961  4129  4163 V echo-service: [ExynosThermal] Sensor [therm_board] temp(31418)
11-08 11:37:13.961  4129  4163 V echo-service: [ExynosThermal] Sensor [therm_usb_con] temp(29438)
11-08 11:37:13.961  4129  4163 V echo-service: [ExynosThermal] Sensor [therm_chg] temp(32900)

Device: Motorola One Vision
Android Version: 9 Security Patch 1st October 2019
AntennaPod Version: 1.7.3b

@ByteHamster
Copy link
Member

Thanks for the logcat @dugite-code. Are you sure that it is the full logcat of the time when you pressed play? There is no logging from within AntennaPod, it just logged the fact that AntennaPod shows a notification. Either AntennaPod is not called at all or the logcat is from a wrong time.

@dugite-code
Copy link

Sorry, looks like I accidentally trimmed too much in an effort to narrow things down. Here is a complete logcat dump.

android.log

@ByteHamster
Copy link
Member

Thanks for the full log. There is still nothing interesting about AntennaPod in it, so I guess that the system actually does not call AntennaPod at all. I am currently not sure why it does not do it, though.

@dlemire60
Copy link
Author

So this behavior remains a mystery?

@ByteHamster
Copy link
Member

From a first look, I do not know why this happens. This needs more investigations. I am not sure when/if I will be able to do that, though. Contributions welcome :)

@dugite-code
Copy link

I've done a bit more testing, it appears to only occur if you have ExoPlayer selected in Media Playback.

With or without skip silence and playback speed independent

@dlemire60 what player are you using? I've not been able to re-produce the bug with the Built-in Android player or with Sonic Media Player. Note: looks like you have to close Antenna pod for the player change to take place

@dlemire60
Copy link
Author

dlemire60 commented Nov 19, 2019

I am indeed running ExoPlayer. I don't recall ever making a selection of that. I've got the three options you listed: Built-In, Sonic, ExoPlayer. Do you have a recommendation between the other two? Is the problem with ExoPlayer fix-able?

@ByteHamster
Copy link
Member

ByteHamster commented Nov 19, 2019

I've done a bit more testing, it appears to only occur if you have ExoPlayer selected in Media Playback.

Good find! 👍

I am indeed running ExoPlayer. I don't recall ever making a selection of that.

We changed the default to ExoPlayer recently because it supports more formats and is under active development (as opposed to the other two). We should try to find out why this happens and fix it instead of reverting to the old players.

@dlemire60
Copy link
Author

dlemire60 commented Dec 5, 2019

Just noticed #3574 , any chance these might be related?

@dlemire60
Copy link
Author

I've had this recur again several times recently, particularly in the car (where it's extra annoying). I notice my player is back to ExoPlayer and I honestly don't recall whether or not I did that. So:

  1. Guidance on choosing between Sonic and Android media players?
  2. Any chance this glitch with ExoPlayer will be fixed?
  3. Is the selected media player being changed back to the default on update? If so, please reconsider this decision: if someone isn't using the default player, there's probably a reason.

Thanks.

@dlemire60
Copy link
Author

dlemire60 commented Jun 3, 2020

I experienced this again today. Sonic media player. AntennaPod version 1.8.1 (6e6a64f). All other details same as previous reports. New issue #4203 appears to be related / same.

First reported July 2019 and since confirmed by multiple users. It would be nice if this got some attention.

@dlemire60
Copy link
Author

I have experienced this issue multiple times recently. As previously noted, #4203 appears related / same. I'm on the verge of abandoning this podcatcher over this issue, as losing playback during my driving commute is infuriating. There are multiple user complaints over the course of a year+ with no apparent response at all.

@tonytamsf
Copy link
Member

I am able to reproduce this with hitting the rewind button very quickly

https://gist.github.com/tonytamsf/6b3fe74462da38c7a6d1431c6b654819

@tonytamsf
Copy link
Member

I tested this in a car, while playing just hit forward or rewind very quickly and it will crash with the ExoPlayer. With the default android player, it will not crash

@ByteHamster I have a test build with doing actual locking when using the Exoplayer and I can make this crash go away. Is there any reason why we should not do locking with ExoPlayer?

28f424e#diff-75c6bb9019824923f353e71fb0838b9b923f41bfc7ed926f7b0b97cbf73cf11dR101

@ByteHamster
Copy link
Member

Sorry, I don't really understand what you mean. Should ExoPlayer be locked or not? From the code, I guess it should not be locked. So is the reason for this issue a deadlock?

Comment here:

I have a test build with doing actual locking when using the Exoplayer and I can make this crash go away.

Code comment:

A lock is not needed if everything is called on the same thread.

@tonytamsf
Copy link
Member

tonytamsf commented Jan 14, 2021

Sorry, I don't really understand what you mean. Should ExoPlayer be locked or not? From the code, I guess it should not be locked. So is the reason for this issue a deadlock?

Right now the code does not lock for ExoPlayer here, PlayerLock

If I actually do lock, then this issue goes away with hitting 'many' consecutive fast forward / rewinds.

@tonytamsf
Copy link
Member

@keunes please assign to me

@ByteHamster
Copy link
Member

#3574 (comment)
What would be the downsize of doing locking for ExoPlayer?

If we actually execute everything on the main thread like it should be done, locking shouldn't make a difference. If it does, we are doing something wrong elsewhere. I fear that what we do wrong elsewhere could cause deadlocks or make the situation worse in other locations when adding locking. If you know where we do something wrong elsewhere, it would be a more "clean" fix. We can also lock and then do a long beta test if you don't know.

@tonytamsf
Copy link
Member

tonytamsf commented Jan 27, 2021

I originally thought locking happens for the other 2 players, so there was not going to be a problem with locking on ExoPlayer as well.

It seems like you suspect there are other threads running. Which I could learn how to find. Happy to dig some more to find the root cause, it will take me a while. Is it possible ExoPlayer is not thread safe?

Not sure what this issue from ExoPlayer is telling us google/ExoPlayer#4463

@dlemire60
Copy link
Author

I had this issue again this morning. Media player is set to Sonic. Locked up on a single forward jump on Bluetooth.

  • AntennaPod v2.1.2 (a87cec5)
  • Moto G5s+ phone
  • Android 8.1.0, version OPS28.65-36-14
  • Bluetooth in my Chevy Bolt EV

Have to exit Android Auto, close AntennaPod and relaunch it to resume playback. This remains super-frustrating, as AntennaPod otherwise suits my podcast playing needs pretty much perfectly.

@tonytamsf
Copy link
Member

@dlemire60 does it happen with ExoPlayer? I am guessing yes. Does it happen if you slow down a bit when you skip, waiting for 3 seconds between each skip?

@dlemire60
Copy link
Author

@tonytamsf I'm fairly sure I've seen it happen with ExoPlayer. I won't claim to carefully track what player is selected.

Generally slowing down multiple skips does seem to reduce the likelihood of this crash. But this morning it happened on the very first skip. And this only ever happens when the skips are triggered via Bluetooth. I've never had it happen from skipping forward using the phone UI.

@tonytamsf
Copy link
Member

Got it, that is a good clue the media handling might be an issue. It happens to me when I use Android Auto screen in my car

@dlemire60
Copy link
Author

Glad to hear it's useful, since I'm not really in a position to capture / supply logs to help debug. The Bolt EV has channel forward / back buttons on the steering while that trigger the jump as well as on the infotainment screen. I've locked up AntennaPod with both. The common denominator in all of this for me is initiating the skip forward / back command via Bluetooth.

I just reread my original post on this issue and all of that still holds. And I'm confident I've seen it happen with at least two of the three available media players. I'm a little fuzzy on whether the media player preference setting is sticky across program updates; I have a gut feel it isn't but I've switched phone app updates to fully automatic so I'm not really paying attention at that level.

@shbach
Copy link

shbach commented Jan 28, 2021

I'm also getting this bug. ExoPlayer selected and skips triggered via bluetooth.

@ByteHamster
Copy link
Member

Is it possible ExoPlayer is not thread safe?

ExoPlayer is not thread safe, no. Currently, it only prints error messages to logcat when accessing it on the wrong thread. I tried upgrading the library and discovered that more recent versions will just crash the whole app in that case. I already made sure that most calls to ExoPlayer happen on the main thread but both the crashes when upgrading and the fact that locking fixes an issue show that I forgot some cases. If you would be up for digging into that, it would be pretty great :)

@keunes keunes added the Type: Possible bug Issues that seem to be a bug, but haven't been confirmed yet label May 11, 2023
@ByteHamster
Copy link
Member

This issue is more than 2 years old and we had several changes to the ExoPlayer code since then. I assume this went away at some point. If it didn't , feel free to comment and we can re-open the issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Type: Possible bug Issues that seem to be a bug, but haven't been confirmed yet
Projects
None yet
Development

No branches or pull requests

6 participants