Antennapod: Player stuck intermittently - AntennaPod tried to stream from HTTP source while downloaded media is there

Created on 28 Dec 2018 · 9Comments · Source: AntennaPod/AntennaPod

App version: 1.7.1-based custom build (with a few minor pending pull requests)

Android version: 7.1.1

Current behaviour: The player gets stuck intermittently, usually during the transition from playing one episode to the next one. In such scenario,

Pressing play/pause has no impact.
Sometimes, AntennaPod would become unresponsive for more than a few seconds. It also crashed once or twice.
Sometimes, it could be unstuck by clicking play on an unrelated episode, then back to the original one.
There are a few cases that it got so stuck I resort to reboot the device.
In December '18, it happened to me about 5-10 times.
2019-02-27 Update: the problem stems from that sometimes AntennaPod tried to stream from HTTP source (no network), even though the downloaded media file was available. See the comment on ways to reproduce it.

Environment: Using ExoPlayer seems to increase the likelihood that it got stuck. Since it is intermittent I can't say for sure. An external SD card is also used.

Stacktrace/Logcat:

I got logcat for a few of those cases. They all have the following exception.

[ StackTrace ]
java.lang.NullPointerException: Attempt to read from field 'org.antennapod.audio.AbstractAudioPlayer org.antennapod.audio.MediaPlayer.mpi' on a null object reference
    at de.danoeh.antennapod.core.service.playback.LocalPSMP$$Lambda$7.onError(Unknown Source)
    at de.danoeh.antennapod.core.service.playback.ExoPlayerWrapper$1.onPlayerError$13b2773a(ExoPlayerWrapper.java:85)
    at com.google.android.exoplayer2.ExoPlayerImpl$1.handleMessage(ExoPlayerImpl.java:1555)
    at android.os.Handler.dispatchMessage(Handler.java:102)
    at android.os.Looper.loop(Looper.java:154)
    at android.app.ActivityThread.main(ActivityThread.java:6165)
    at java.lang.reflect.Method.invoke(Native Method)
    at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:888)
    at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:778)

Source

orionlee

👍1

All 9 comments

For the above error shown in crash-report:
ExoPlayerWrapper passes an null MediaPlayer to the underlying LocalPSMP onErrorListener, causing NullPointerException.

  public void onPlayerError(ExoPlaybackException error) {
      if (audioErrorListener != null) {
          audioErrorListener.onError(null, 0, 0); // <- the null causes NullPointerException
      }

Fixing it (either ExoPlayerWrapper side or Listener side) should at least prevent the app from crashing. It doesn't address the underlying issue that causes the player stuck.

orionlee on 1 Jan 2019

This is a screenshot of one instance of player getting stuck at the end of playing an episode. In this specific case,

I can unstuck by pressing play on some other episode, then press play on the one.
the media length shown on UI is somehow screwed up (negative number).

(It's configured to use Sonic Player, so the issue is not specific to ExoPlayer.)

screenshot_2019_01_14_18_04_14

orionlee on 15 Jan 2019

👍1

Here is the log of another stuck incident at the end of an episode:

it was recoverable by pressing play on another episode (then play it again)
the duration of the episode became negative again.

This time I got more detailed logcat traces. The underlying media player returned an error code of -38 from onError callback

Abbreviated logcat:

...
01-16 18:00:45.076 D/LclPlaybackSvcMPlayer(18190): Pausing playback.
01-16 18:00:45.077 D/ReplacementMediaPlayer(18190): this.mpi is not a ServiceBackedMediaPlayer, but we couldn't use it anyway
01-16 18:00:45.077 E/MediaPlayer(18190): pause called in state 0, mPlayer(0x7cb8a860)
01-16 18:00:45.077 E/MediaPlayer(18190): error (-38, 0)
01-16 18:00:45.077 E/MediaPlayer(18190): Error (-38,0)
01-16 18:00:45.078 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:00:45.078 D/PlaybackSvcMediaPlayer(18190): LocalPSMP: Setting player status to PAUSED
01-16 18:00:45.078 D/PlaybackServiceTaskMgr(18190): Cancelled PositionSaver
01-16 18:00:45.078 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0
01-16 18:00:45.078 D/PlaybackService(18190): Saving current position to 0
...
01-16 18:00:46.275 D/PlaybackController(18190): status: PAUSED
01-16 18:00:46.275 D/PlaybackController(18190): PositionObserver cancelled. Result: true
01-16 18:00:46.277 D/PlaybackService(18190): onPostPlayback(): media=Africa’s Drone Experiment
...
01-16 18:00:46.280 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:00:46.280 E/MediaPlayer(18190): Attempt to call getDuration in wrong state: mPlayer=0x7cb8a860, mCurrentState=0
01-16 18:00:46.280 E/MediaPlayer(18190): error (-38, 0)
01-16 18:00:46.281 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:00:46.281 E/MediaPlayer(18190): Attempt to call getDuration in wrong state: mPlayer=0x7cb8a860, mCurrentState=0
01-16 18:00:46.281 E/MediaPlayer(18190): error (-38, 0)
01-16 18:00:46.297 E/MediaPlayer(18190): Error (-38,0)
01-16 18:00:46.297 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0
...
# Press play button on notification control, but to no avail
01-16 18:02:32.754 D/MediaButtonReceiver(18190): Received intent
...
01-16 18:02:32.760 D/LclPlaybackSvcMPlayer(18190): Audiofocus successfully requested
01-16 18:02:32.760 D/LclPlaybackSvcMPlayer(18190): Resuming/Starting playback
01-16 18:02:32.762 D/ReplacementMediaPlayer(18190): start()
01-16 18:02:32.763 D/ReplacementMediaPlayer(18190): this.mpi is not a ServiceBackedMediaPlayer, but we couldn't use it anyway
01-16 18:02:32.765 E/MediaPlayer(18190): start called in state 0, mPlayer(0x7cb8a860)
01-16 18:02:32.765 E/MediaPlayer(18190): error (-38, 0)
01-16 18:02:32.765 E/MediaPlayer(18190): Error (-38,0)
01-16 18:02:32.766 D/PlaybackSvcMediaPlayer(18190): LocalPSMP: Setting player status to PLAYING
01-16 18:02:32.766 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0

Complete logcat

01-16 18:00:44.918 V/chatty  (18190): uid=10365(de.danoeh.antennapod.devR) Thread-3 expire 1 line
01-16 18:00:45.001 V/chatty  (18190): uid=10365(de.danoeh.antennapod.devR) expire 1 line
01-16 18:00:45.044 V/PlaybackService(18190): onPlaybackStateChange(3)
01-16 18:00:45.044 D/PlaybackService(18190): Writing player status playback preferences
01-16 18:00:45.048 D/EventDistributor(18190): Processing event queue. Number of events: 1
01-16 18:00:45.048 D/EventDistributor(18190): Notifying observers. Data: 128
01-16 18:00:45.049 D/PlaybackController(18190): Received statusUpdate Intent.
01-16 18:00:45.049 D/PlaybackService(18190): notificationSetupTask: Starting background work
01-16 18:00:45.069 D/AndroidMediaPlayer(18190): setPlaybackSpeed(1.0)
01-16 18:00:45.070 D/PlaybackController(18190): status: PLAYING
01-16 18:00:45.070 D/PlaybackController(18190): Setting up position observer
01-16 18:00:45.071 V/PlaybackService(18190): notificationSetupTask: playerStatus=PLAYING
01-16 18:00:45.072 D/LclPlaybackSvcMPlayer(18190): Playback speed was set to 1.0
01-16 18:00:45.075 D/LclPlaybackSvcMPlayer(18190): Media player volume was set to 1.0 1.0
01-16 18:00:45.076 D/LclPlaybackSvcMPlayer(18190): Pausing playback.
01-16 18:00:45.077 D/ReplacementMediaPlayer(18190): this.mpi is not a ServiceBackedMediaPlayer, but we couldn't use it anyway
01-16 18:00:45.077 E/MediaPlayer(18190): pause called in state 0, mPlayer(0x7cb8a860)
01-16 18:00:45.077 E/MediaPlayer(18190): error (-38, 0)
01-16 18:00:45.077 E/MediaPlayer(18190): Error (-38,0)
01-16 18:00:45.078 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:00:45.078 D/PlaybackSvcMediaPlayer(18190): LocalPSMP: Setting player status to PAUSED
01-16 18:00:45.078 D/PlaybackServiceTaskMgr(18190): Cancelled PositionSaver
01-16 18:00:45.078 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0
01-16 18:00:45.078 D/PlaybackService(18190): Saving current position to 0
01-16 18:00:45.078 D/PlaybackServiceTaskMgr(18190): Cancelled WidgetUpdater
01-16 18:00:45.078 D/FlattrUtils(18190): Retrieving access token
01-16 18:00:45.078 D/FlattrUtils(18190): No access token found
01-16 18:00:45.084 D/EventDistributor(18190): Processing event queue. Number of events: 1
01-16 18:00:45.084 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:00:45.084 D/EventDistributor(18190): Notifying observers. Data: 128
01-16 18:00:45.104 V/PlaybackService(18190): notificationSetupTask: make service foreground
01-16 18:00:45.108 D/PlaybackService(18190): Notification set up
01-16 18:00:45.153 D/EventDistributor(18190): Processing event queue. Number of events: 1
01-16 18:00:45.153 D/EventDistributor(18190): Notifying observers. Data: 2
01-16 18:00:45.153 D/RxWContentUpdateUiTmplt(18190): arg: 2
01-16 18:00:45.154 D/DBReader(18190): getNavDrawerData() called with: 
01-16 18:00:45.163 I/art     (18190): Background sticky concurrent mark sweep GC freed 100263(14MB) AllocSpace objects, 4(80KB) LOS objects, 18% free, 65MB/81MB, paused 12.930ms total 113.464ms
01-16 18:00:45.185 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@26]
01-16 18:00:45.187 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@29]
01-16 18:00:45.191 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1a]
01-16 18:00:45.215 W/PlayerWidgetJobService(18190): IllegalArgumentException when trying to unbind service
01-16 18:00:45.236 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1]
01-16 18:00:45.254 E/ChapterUtils(18190): javax.net.ssl.SSLPeerUnverifiedException: Hostname play.podtrac.com not verified:
01-16 18:00:45.254 E/ChapterUtils(18190):     certificate: sha1/aFctebkTPpIoyR7j9ig6egDKcSI=
01-16 18:00:45.254 E/ChapterUtils(18190):     DN: CN=securelogin.pccsea.com,O=Puget Consumers Co-op,L=Seattle,ST=Washington,C=US
01-16 18:00:45.254 E/ChapterUtils(18190):     subjectAltNames: [securelogin.pccsea.com]
01-16 18:00:45.254 E/ChapterUtils(18190):   at com.android.okhttp.Connection.connectTls(Connection.java:241)
01-16 18:00:45.254 E/ChapterUtils(18190):   at com.android.okhttp.Connection.connectSocket(Connection.java:199)
01-16 18:00:45.254 E/ChapterUtils(18190):   at com.android.okhttp.Connection.connect(Connection.java:172)
01-16 18:00:45.254 E/ChapterUtils(18190):   at com.android.okhttp.Connection.connectAndSetOwner(Connection.java:367)
01-16 18:00:45.254 E/ChapterUtils(18190):   at com.android.okhttp.OkHttpClient$1.connectAndSetOwner(OkHttpClient.java:130)
01-16 18:00:45.254 E/ChapterUtils(18190):   at com.android.okhttp.internal.http.HttpEngine.connect(HttpEngine.java:329)
01-16 18:00:45.254 E/ChapterUtils(18190):   at com.android.okhttp.internal.http.HttpEngine.sendRequest(HttpEngine.java:246)
01-16 18:00:45.254 E/ChapterUtils(18190):   at com.android.okhttp.internal.huc.HttpURLConnectionImpl.execute(HttpURLConnectionImpl.java:457)
01-16 18:00:45.254 E/ChapterUtils(18190):   at com.android.okhttp.internal.huc.HttpURLConnectionImpl.getResponse(HttpURLConnectionImpl.java:405)
01-16 18:00:45.254 E/ChapterUtils(18190):   at com.android.okhttp.internal.huc.HttpURLConnectionImpl.getInputStream(HttpURLConnectionImpl.java:243)
01-16 18:00:45.254 E/ChapterUtils(18190):   at com.android.okhttp.internal.huc.DelegatingHttpsURLConnection.getInputStream(DelegatingHttpsURLConnection.java:210)
01-16 18:00:45.254 E/ChapterUtils(18190):   at com.android.okhttp.internal.huc.HttpsURLConnectionImpl.getInputStream(HttpsURLConnectionImpl.java)
01-16 18:00:45.254 E/ChapterUtils(18190):   at java.net.URL.openStream(URL.java:1057)
01-16 18:00:45.254 E/ChapterUtils(18190):   at de.danoeh.antennapod.core.util.ChapterUtils.readOggChaptersFromPlayableStreamUrl(ChapterUtils.java:158)
01-16 18:00:45.254 E/ChapterUtils(18190):   at de.danoeh.antennapod.core.util.ChapterUtils.loadChaptersFromStreamUrl(ChapterUtils.java:60)
01-16 18:00:45.254 E/ChapterUtils(18190):   at de.danoeh.antennapod.core.feed.FeedMedia.loadChapterMarks(FeedMedia.java:403)
01-16 18:00:45.254 E/ChapterUtils(18190):   at de.danoeh.antennapod.core.service.playback.PlaybackServiceTaskManager.lambda$startChapterLoader$1(PlaybackServiceTaskManager.java:263)
01-16 18:00:45.254 E/ChapterUtils(18190):   at de.danoeh.antennapod.core.service.playback.-$$Lambda$PlaybackServiceTaskManager$c09cOz04xoeyeRCAarj9igH4RA4.run(lambda)
01-16 18:00:45.254 E/ChapterUtils(18190):   at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:428)
01-16 18:00:45.254 E/ChapterUtils(18190):   at java.util.concurrent.FutureTask.run(FutureTask.java:237)
01-16 18:00:45.254 E/ChapterUtils(18190):   at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:272)
01-16 18:00:45.254 E/ChapterUtils(18190):   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
01-16 18:00:45.254 E/ChapterUtils(18190):   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
01-16 18:00:45.254 E/ChapterUtils(18190):   at java.lang.Thread.run(Thread.java:761)
01-16 18:00:45.254 D/PlaybackServiceTaskMgr(18190): Chapter loader stopped
01-16 18:00:45.281 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@24]
01-16 18:00:45.288 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@28]
01-16 18:00:45.298 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@3]
01-16 18:00:45.318 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@23]
01-16 18:00:45.330 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1c]
01-16 18:00:45.421 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@2a]
01-16 18:00:45.439 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1d]
01-16 18:00:45.450 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@8]
01-16 18:00:45.468 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@7]
01-16 18:00:45.496 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@4]
01-16 18:00:45.517 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@5]
01-16 18:00:45.526 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@6]
01-16 18:00:45.531 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@21]
01-16 18:00:45.536 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@9]
01-16 18:00:45.577 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@a]
01-16 18:00:45.637 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1e]
01-16 18:00:45.641 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@c]
01-16 18:00:45.652 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@f]
01-16 18:00:45.687 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@d]
01-16 18:00:45.745 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@27]
01-16 18:00:45.773 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@b]
01-16 18:00:45.803 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1b]
01-16 18:00:45.808 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@e]
01-16 18:00:45.812 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@11]
01-16 18:00:45.849 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@10]
01-16 18:00:45.858 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@19]
01-16 18:00:45.876 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@12]
01-16 18:00:45.907 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@13]
01-16 18:00:45.986 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@25]
01-16 18:00:45.995 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1f]
01-16 18:00:46.037 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@18]
01-16 18:00:46.041 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@20]
01-16 18:00:46.116 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@15]
01-16 18:00:46.135 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@14]
01-16 18:00:46.149 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@16]
01-16 18:00:46.155 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@17]
01-16 18:00:46.209 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@2b]
01-16 18:00:46.255 D/DBReader(18190): getDownloadedItems() called
01-16 18:00:46.259 V/PlaybackService(18190): onPlaybackStateChange(2)
01-16 18:00:46.260 D/PlaybackService(18190): Writing player status playback preferences
01-16 18:00:46.264 D/DBReader(18190): getFavoriteIDList() called
01-16 18:00:46.266 D/DBReader(18190): getQueueIDList() called
01-16 18:00:46.267 D/DBReader(18190): Extracting Feedlist
01-16 18:00:46.267 D/PlaybackService(18190): notificationSetupTask: Starting background work
01-16 18:00:46.268 D/EventDistributor(18190): Processing event queue. Number of events: 1
01-16 18:00:46.268 D/EventDistributor(18190): Notifying observers. Data: 128
01-16 18:00:46.272 D/PlaybackController(18190): Received statusUpdate Intent.
01-16 18:00:46.275 D/PlaybackController(18190): status: PAUSED
01-16 18:00:46.275 D/PlaybackController(18190): PositionObserver cancelled. Result: true
01-16 18:00:46.277 D/PlaybackService(18190): onPostPlayback(): media=Africa’s Drone Experiment
01-16 18:00:46.277 D/FlattrUtils(18190): Retrieving access token
01-16 18:00:46.278 D/FlattrUtils(18190): No access token found
01-16 18:00:46.280 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:00:46.280 E/MediaPlayer(18190): Attempt to call getDuration in wrong state: mPlayer=0x7cb8a860, mCurrentState=0
01-16 18:00:46.280 E/MediaPlayer(18190): error (-38, 0)
01-16 18:00:46.281 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:00:46.281 E/MediaPlayer(18190): Attempt to call getDuration in wrong state: mPlayer=0x7cb8a860, mCurrentState=0
01-16 18:00:46.281 E/MediaPlayer(18190): error (-38, 0)
01-16 18:00:46.297 E/MediaPlayer(18190): Error (-38,0)
01-16 18:00:46.297 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0
01-16 18:00:46.297 V/PlaybackService(18190): notificationSetupTask: playerStatus=PAUSED
01-16 18:00:46.313 D/PlaybackService(18190): Notification set up
01-16 18:00:46.333 E/MediaPlayer(18190): Error (-38,0)
01-16 18:00:46.333 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0
01-16 18:00:46.335 D/MainActivity(18190): getLastNavFragment() -> 32
01-16 18:00:46.335 D/PlayerWidgetJobService(18190): Connection to service established
01-16 18:00:46.362 D/EventDistributor(18190): Processing event queue. Number of events: 1
01-16 18:00:46.362 D/EventDistributor(18190): Notifying observers. Data: 128
01-16 18:00:46.368 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:00:46.368 E/MediaPlayer(18190): Attempt to call getDuration in wrong state: mPlayer=0x7cb8a860, mCurrentState=0
01-16 18:00:46.368 E/MediaPlayer(18190): error (-38, 0)
01-16 18:00:46.369 E/MediaPlayer(18190): Error (-38,0)
01-16 18:00:46.369 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0
01-16 18:00:46.386 D/EventDistributor(18190): Processing event queue. Number of events: 1
01-16 18:00:46.386 D/EventDistributor(18190): Notifying observers. Data: 2
01-16 18:00:46.386 D/RxWContentUpdateUiTmplt(18190): arg: 2
01-16 18:00:46.387 D/DBReader(18190): getNavDrawerData() called with: 
01-16 18:00:46.396 D/DBReader(18190): getQueue()
01-16 18:00:46.396 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@26]
01-16 18:00:46.404 D/DBReader(18190): getFavoriteIDList() called
01-16 18:00:46.406 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@29]
01-16 18:00:46.411 D/DBReader(18190): getQueueIDList() called
01-16 18:00:46.415 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1a]
01-16 18:00:46.416 D/DBReader(18190): Extracting Feedlist
01-16 18:00:46.480 D/PlaybackServiceTaskMgr(18190): onEvent(QueueEvent QueueEvent[action=REMOVED,item=FeedItem[autoDownload=0,chapters=<null>,contentEncoded=<null>,description=<null>,feed=de.danoeh.antennapod.core.feed.Feed@13,feedId=19,flattrStatus=de.danoeh.antennapod.core.util.flattr.FlattrStatus@228b681,hasChapters=false,imageUrl=http://ichef.bbci.co.uk/images/ic/3000x3000/p03gtk3j.jpg,itemIdentifier=urn:bbc:podcast:p06y5dgy,link=http://www.bbc.co.uk/programmes/p06y5dgy,media=de.danoeh.antennapod.core.feed.FeedMedia@1a77,paymentLink=<null>,pubDate=Wed Jan 16 04:00:00 PST 2019,state=0,tags=[],title=Africa’s Drone Experiment,id=6779],items=<null>,position=-1])
01-16 18:00:46.480 D/Event   (18190): No subscribers registered for event class de.danoeh.antennapod.core.event.FeedItemEvent
01-16 18:00:46.480 D/Event   (18190): No subscribers registered for event class de.greenrobot.event.NoSubscriberEvent
01-16 18:00:46.480 D/DBTasks (18190): autodownloadUndownloadedItems
01-16 18:00:46.481 D/DBWriter(18190): Adding new item to playback history
01-16 18:00:46.481 D/DBReader(18190): getQueue() called
01-16 18:00:46.482 D/DBReader(18190): getQueue()
01-16 18:00:46.483 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1]
01-16 18:00:46.484 D/NetworkUtils(18190): Device is connected to Wi-Fi
01-16 18:00:46.484 D/NetworkUtils(18190): Network for auto-dl is not available
01-16 18:00:46.488 D/EventDistributor(18190): Processing event queue. Number of events: 1
01-16 18:00:46.489 D/EventDistributor(18190): Notifying observers. Data: 16
01-16 18:00:46.510 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@24]
01-16 18:00:46.515 D/DBReader(18190): getFavoriteIDList() called
01-16 18:00:46.517 D/DBReader(18190): getQueueIDList() called
01-16 18:00:46.517 D/DBReader(18190): Extracting Feedlist
01-16 18:00:46.518 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@28]
01-16 18:00:46.533 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@3]
01-16 18:00:46.557 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@23]
01-16 18:00:46.567 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1c]
01-16 18:00:46.686 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@2a]
01-16 18:00:46.721 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1d]
01-16 18:00:46.731 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@8]
01-16 18:00:46.747 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@7]
01-16 18:00:46.775 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@4]
01-16 18:00:46.796 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@5]
01-16 18:00:46.804 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@6]
01-16 18:00:46.809 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@21]
01-16 18:00:46.815 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@9]
01-16 18:00:46.856 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@a]
01-16 18:00:46.919 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1e]
01-16 18:00:46.923 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@c]
01-16 18:00:46.934 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@f]
01-16 18:00:46.970 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@d]
01-16 18:00:47.031 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@27]
01-16 18:00:47.060 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@b]
01-16 18:00:47.090 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1b]
01-16 18:00:47.095 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@e]
01-16 18:00:47.104 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@11]
01-16 18:00:47.167 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@10]
01-16 18:00:47.181 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@19]
01-16 18:00:47.191 I/art     (18190): Background partial concurrent mark sweep GC freed 321375(23MB) AllocSpace objects, 5(212KB) LOS objects, 20% free, 61MB/77MB, paused 5.042ms total 345.070ms
01-16 18:00:47.194 D/ReplacementMediaPlayer(18190): finalize()
01-16 18:00:47.194 D/ReplacementMediaPlayer(18190): Releasing MediaPlayer
01-16 18:00:47.194 D/AndroidMediaPlayer(18190): mp.release()
01-16 18:00:47.194 D/ReplacementMediaPlayer(18190): Setting onSeekCompleteListener to null 871
01-16 18:00:47.206 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@12]
01-16 18:00:47.252 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@13]
01-16 18:00:47.336 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@25]
01-16 18:00:47.344 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1f]
01-16 18:00:47.386 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@18]
01-16 18:00:47.390 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@20]
01-16 18:00:47.464 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@15]
01-16 18:00:47.484 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@14]
01-16 18:00:47.498 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@16]
01-16 18:00:47.505 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@17]
01-16 18:00:47.560 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@2b]
01-16 18:00:47.607 D/DBReader(18190): getDownloadedItems() called
01-16 18:00:47.616 D/DBReader(18190): getFavoriteIDList() called
01-16 18:00:47.617 D/DBReader(18190): getQueueIDList() called
01-16 18:00:47.618 D/DBReader(18190): Extracting Feedlist
01-16 18:00:47.626 D/MainActivity(18190): getLastNavFragment() -> 32
01-16 18:02:32.754 D/MediaButtonReceiver(18190): Received intent
01-16 18:02:32.756 D/PlaybackService(18190): OnStartCommand called
01-16 18:02:32.756 D/PlaybackService(18190): Received media button event
01-16 18:02:32.756 D/PlaybackService(18190): Handling keycode: 85
01-16 18:02:32.760 D/LclPlaybackSvcMPlayer(18190): Audiofocus successfully requested
01-16 18:02:32.760 D/LclPlaybackSvcMPlayer(18190): Resuming/Starting playback
01-16 18:02:32.762 D/ReplacementMediaPlayer(18190): start()
01-16 18:02:32.763 D/ReplacementMediaPlayer(18190): this.mpi is not a ServiceBackedMediaPlayer, but we couldn't use it anyway
01-16 18:02:32.765 E/MediaPlayer(18190): start called in state 0, mPlayer(0x7cb8a860)
01-16 18:02:32.765 E/MediaPlayer(18190): error (-38, 0)
01-16 18:02:32.765 E/MediaPlayer(18190): Error (-38,0)
01-16 18:02:32.766 D/PlaybackSvcMediaPlayer(18190): LocalPSMP: Setting player status to PLAYING
01-16 18:02:32.766 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0
01-16 18:02:32.766 D/PlaybackServiceTaskMgr(18190): Started WidgetUpdater
01-16 18:02:32.766 D/PlaybackServiceTaskMgr(18190): Started PositionSaver
01-16 18:02:32.769 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:02:32.786 D/MediaButtonReceiver(18190): Received intent
01-16 18:02:33.285 V/PlaybackService(18190): onPlaybackStateChange(3)
01-16 18:02:33.285 D/PlaybackService(18190): Writing player status playback preferences
01-16 18:02:33.297 D/PlaybackService(18190): notificationSetupTask: Starting background work
01-16 18:02:33.299 D/ApOkHttpUrlLoader(18190): buildLoadData() called with: model = [https://media.npr.org/assets/img/2019/01/15/75_wide-b4bcad2fc2514233d3259056cacaf456dd310976.jpg?s=1400], width = [128], height = [128]
01-16 18:02:33.306 V/PlaybackService(18190): notificationSetupTask: playerStatus=PLAYING
01-16 18:02:33.312 V/PlaybackService(18190): notificationSetupTask: make service foreground
01-16 18:02:33.324 D/PlaybackService(18190): Notification set up
01-16 18:02:33.382 D/EventDistributor(18190): Processing event queue. Number of events: 1
01-16 18:02:33.382 D/EventDistributor(18190): Notifying observers. Data: 128
01-16 18:02:33.383 D/PlaybackController(18190): Received statusUpdate Intent.
01-16 18:02:33.410 D/PlaybackController(18190): status: PLAYING
01-16 18:02:33.410 D/AndroidMediaPlayer(18190): setPlaybackSpeed(1.0)
01-16 18:02:33.410 D/PlaybackController(18190): Setting up position observer
01-16 18:02:33.416 D/LclPlaybackSvcMPlayer(18190): Playback speed was set to 1.0
01-16 18:02:33.421 D/LclPlaybackSvcMPlayer(18190): Media player volume was set to 1.0 1.0
01-16 18:02:33.422 D/LclPlaybackSvcMPlayer(18190): Pausing playback.
01-16 18:02:33.423 D/ReplacementMediaPlayer(18190): this.mpi is not a ServiceBackedMediaPlayer, but we couldn't use it anyway
01-16 18:02:33.423 E/MediaPlayer(18190): pause called in state 0, mPlayer(0x7cb8a860)
01-16 18:02:33.423 E/MediaPlayer(18190): error (-38, 0)
01-16 18:02:33.424 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:02:33.424 D/PlaybackSvcMediaPlayer(18190): LocalPSMP: Setting player status to PAUSED
01-16 18:02:33.424 D/PlaybackServiceTaskMgr(18190): Cancelled PositionSaver
01-16 18:02:33.424 D/PlaybackService(18190): Saving current position to 0
01-16 18:02:33.425 D/PlaybackServiceTaskMgr(18190): Cancelled WidgetUpdater
01-16 18:02:33.425 D/FlattrUtils(18190): Retrieving access token
01-16 18:02:33.425 D/FlattrUtils(18190): No access token found
01-16 18:02:33.425 E/MediaPlayer(18190): Error (-38,0)
01-16 18:02:33.425 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:02:33.425 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0
01-16 18:02:33.995 D/PlayerWidgetJobService(18190): Connection to service established
01-16 18:02:33.995 D/EventDistributor(18190): Processing event queue. Number of events: 1
01-16 18:02:33.995 D/EventDistributor(18190): Notifying observers. Data: 128
01-16 18:02:34.034 D/EventDistributor(18190): Processing event queue. Number of events: 1
01-16 18:02:34.034 D/EventDistributor(18190): Notifying observers. Data: 2
01-16 18:02:34.034 D/RxWContentUpdateUiTmplt(18190): arg: 2
01-16 18:02:34.036 D/DBReader(18190): getNavDrawerData() called with: 
01-16 18:02:34.050 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@26]
01-16 18:02:34.052 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@29]
01-16 18:02:34.055 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1a]
01-16 18:02:34.076 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1]
01-16 18:02:34.098 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@24]
01-16 18:02:34.102 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@28]
01-16 18:02:34.120 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@3]
01-16 18:02:34.143 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@23]
01-16 18:02:34.155 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1c]
01-16 18:02:34.263 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@2a]
01-16 18:02:34.282 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1d]
01-16 18:02:34.292 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@8]
01-16 18:02:34.309 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@7]
01-16 18:02:34.337 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@4]
01-16 18:02:34.359 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@5]
01-16 18:02:34.367 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@6]
01-16 18:02:34.372 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@21]
01-16 18:02:34.377 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@9]
01-16 18:02:34.417 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@a]
01-16 18:02:34.457 V/PlaybackService(18190): onPlaybackStateChange(2)
01-16 18:02:34.458 D/PlaybackService(18190): Writing player status playback preferences
01-16 18:02:34.460 D/EventDistributor(18190): Processing event queue. Number of events: 1
01-16 18:02:34.461 D/EventDistributor(18190): Notifying observers. Data: 128
01-16 18:02:34.462 D/PlaybackController(18190): Received statusUpdate Intent.
01-16 18:02:34.467 D/PlaybackController(18190): status: PAUSED
01-16 18:02:34.467 D/PlaybackController(18190): PositionObserver cancelled. Result: true
01-16 18:02:34.470 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:02:34.471 E/MediaPlayer(18190): Attempt to call getDuration in wrong state: mPlayer=0x7cb8a860, mCurrentState=0
01-16 18:02:34.471 E/MediaPlayer(18190): error (-38, 0)
01-16 18:02:34.472 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:02:34.472 E/MediaPlayer(18190): Attempt to call getDuration in wrong state: mPlayer=0x7cb8a860, mCurrentState=0
01-16 18:02:34.472 E/MediaPlayer(18190): error (-38, 0)
01-16 18:02:34.473 D/PlaybackService(18190): notificationSetupTask: Starting background work
01-16 18:02:34.475 E/MediaPlayer(18190): Error (-38,0)
01-16 18:02:34.475 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0
01-16 18:02:34.486 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1e]
01-16 18:02:34.490 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@c]
01-16 18:02:34.494 E/MediaPlayer(18190): Error (-38,0)
01-16 18:02:34.494 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0
01-16 18:02:34.496 V/PlaybackService(18190): notificationSetupTask: playerStatus=PAUSED
01-16 18:02:34.496 D/PlayerWidgetJobService(18190): Connection to service established
01-16 18:02:34.496 D/EventDistributor(18190): Processing event queue. Number of events: 1
01-16 18:02:34.496 D/EventDistributor(18190): Notifying observers. Data: 128
01-16 18:02:34.502 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@f]
01-16 18:02:34.510 D/PlaybackService(18190): Notification set up
01-16 18:02:34.529 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:02:34.529 E/MediaPlayer(18190): Attempt to call getDuration in wrong state: mPlayer=0x7cb8a860, mCurrentState=0
01-16 18:02:34.529 E/MediaPlayer(18190): error (-38, 0)
01-16 18:02:34.529 E/MediaPlayer(18190): Error (-38,0)
01-16 18:02:34.529 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0
01-16 18:02:34.552 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@d]
01-16 18:02:34.616 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@27]
01-16 18:02:34.649 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@b]
01-16 18:02:34.679 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1b]
01-16 18:02:34.685 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@e]
01-16 18:02:34.689 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@11]
01-16 18:02:34.737 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@10]
01-16 18:02:34.746 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@19]
01-16 18:02:34.765 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@12]
01-16 18:02:34.798 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@13]
01-16 18:02:34.836 I/art     (18190): Background sticky concurrent mark sweep GC freed 193636(5MB) AllocSpace objects, 5(104KB) LOS objects, 6% free, 72MB/77MB, paused 4.074ms total 104.311ms
01-16 18:02:34.879 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@25]
01-16 18:02:34.887 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1f]
01-16 18:02:34.927 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@18]
01-16 18:02:34.931 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@20]
01-16 18:02:35.004 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@15]
01-16 18:02:35.023 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@14]
01-16 18:02:35.040 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@16]
01-16 18:02:35.047 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@17]
01-16 18:02:35.103 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@2b]
01-16 18:02:35.169 D/DBReader(18190): getDownloadedItems() called
01-16 18:02:35.177 D/DBReader(18190): getFavoriteIDList() called
01-16 18:02:35.179 D/DBReader(18190): getQueueIDList() called
01-16 18:02:35.181 D/DBReader(18190): Extracting Feedlist
01-16 18:02:35.189 D/MainActivity(18190): getLastNavFragment() -> 32
01-16 18:02:35.392 I/art     (18190): Background partial concurrent mark sweep GC freed 322491(22MB) AllocSpace objects, 2(92KB) LOS objects, 22% free, 54MB/70MB, paused 3.668ms total 249.328ms
01-16 18:02:39.841 D/PlaybackService(18190): OnStartCommand called
01-16 18:02:39.841 D/PlaybackService(18190): Received media button event
01-16 18:02:39.841 D/PlaybackService(18190): Handling keycode: 126
01-16 18:02:39.847 D/LclPlaybackSvcMPlayer(18190): Audiofocus successfully requested
01-16 18:02:39.847 D/LclPlaybackSvcMPlayer(18190): Resuming/Starting playback
01-16 18:02:39.849 D/ReplacementMediaPlayer(18190): start()
01-16 18:02:39.849 D/ReplacementMediaPlayer(18190): this.mpi is not a ServiceBackedMediaPlayer, but we couldn't use it anyway
01-16 18:02:39.852 E/MediaPlayer(18190): start called in state 0, mPlayer(0x7cb8a860)
01-16 18:02:39.852 E/MediaPlayer(18190): error (-38, 0)
01-16 18:02:39.852 E/MediaPlayer(18190): Error (-38,0)
01-16 18:02:39.852 D/PlaybackSvcMediaPlayer(18190): LocalPSMP: Setting player status to PLAYING
01-16 18:02:39.852 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0
01-16 18:02:39.852 D/PlaybackServiceTaskMgr(18190): Started WidgetUpdater
01-16 18:02:39.852 D/PlaybackServiceTaskMgr(18190): Started PositionSaver
01-16 18:02:39.856 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:02:40.310 V/PlaybackService(18190): onPlaybackStateChange(3)
01-16 18:02:40.310 D/PlaybackService(18190): Writing player status playback preferences
01-16 18:02:40.319 D/EventDistributor(18190): Processing event queue. Number of events: 1
01-16 18:02:40.319 D/EventDistributor(18190): Notifying observers. Data: 128
01-16 18:02:40.320 D/PlaybackController(18190): Received statusUpdate Intent.
01-16 18:02:40.326 D/PlaybackController(18190): status: PLAYING
01-16 18:02:40.326 D/PlaybackController(18190): Setting up position observer
01-16 18:02:40.329 D/AndroidMediaPlayer(18190): setPlaybackSpeed(1.0)
01-16 18:02:40.333 D/LclPlaybackSvcMPlayer(18190): Playback speed was set to 1.0
01-16 18:02:40.334 D/PlaybackService(18190): notificationSetupTask: Starting background work
01-16 18:02:40.337 D/LclPlaybackSvcMPlayer(18190): Media player volume was set to 1.0 1.0
01-16 18:02:40.338 D/ApOkHttpUrlLoader(18190): buildLoadData() called with: model = [https://media.npr.org/assets/img/2019/01/15/75_wide-b4bcad2fc2514233d3259056cacaf456dd310976.jpg?s=1400], width = [128], height = [128]
01-16 18:02:40.338 D/LclPlaybackSvcMPlayer(18190): Pausing playback.
01-16 18:02:40.338 D/ReplacementMediaPlayer(18190): this.mpi is not a ServiceBackedMediaPlayer, but we couldn't use it anyway
01-16 18:02:40.339 E/MediaPlayer(18190): pause called in state 0, mPlayer(0x7cb8a860)
01-16 18:02:40.339 E/MediaPlayer(18190): error (-38, 0)
01-16 18:02:40.339 E/MediaPlayer(18190): Error (-38,0)
01-16 18:02:40.349 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0
01-16 18:02:40.357 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:02:40.357 D/PlaybackSvcMediaPlayer(18190): LocalPSMP: Setting player status to PAUSED
01-16 18:02:40.357 D/EventDistributor(18190): Processing event queue. Number of events: 1
01-16 18:02:40.357 D/EventDistributor(18190): Notifying observers. Data: 128
01-16 18:02:40.358 D/PlaybackServiceTaskMgr(18190): Cancelled PositionSaver
01-16 18:02:40.358 D/PlaybackService(18190): Saving current position to 0
01-16 18:02:40.358 D/PlaybackServiceTaskMgr(18190): Cancelled WidgetUpdater
01-16 18:02:40.358 D/FlattrUtils(18190): Retrieving access token
01-16 18:02:40.358 D/FlattrUtils(18190): No access token found
01-16 18:02:40.361 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:02:40.364 V/PlaybackService(18190): notificationSetupTask: playerStatus=PAUSED
01-16 18:02:40.388 D/PlayerWidgetJobService(18190): Connection to service established
01-16 18:02:40.393 D/PlaybackService(18190): Notification set up
01-16 18:02:40.399 D/EventDistributor(18190): Processing event queue. Number of events: 1
01-16 18:02:40.399 D/EventDistributor(18190): Notifying observers. Data: 2
01-16 18:02:40.399 D/RxWContentUpdateUiTmplt(18190): arg: 2
01-16 18:02:40.400 D/DBReader(18190): getNavDrawerData() called with: 
01-16 18:02:40.428 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@26]
01-16 18:02:40.430 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@29]
01-16 18:02:40.433 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1a]
01-16 18:02:40.477 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1]
01-16 18:02:40.495 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@24]
01-16 18:02:40.499 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@28]
01-16 18:02:40.510 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@3]
01-16 18:02:40.526 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@23]
01-16 18:02:40.536 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1c]
01-16 18:02:40.606 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@2a]
01-16 18:02:40.624 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1d]
01-16 18:02:40.635 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@8]
01-16 18:02:40.652 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@7]
01-16 18:02:40.680 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@4]
01-16 18:02:40.701 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@5]
01-16 18:02:40.710 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@6]
01-16 18:02:40.714 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@21]
01-16 18:02:40.720 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@9]
01-16 18:02:40.760 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@a]
01-16 18:02:40.822 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1e]
01-16 18:02:40.827 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@c]
01-16 18:02:40.838 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@f]
01-16 18:02:40.874 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@d]
01-16 18:02:40.934 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@27]
01-16 18:02:40.963 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@b]
01-16 18:02:40.993 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1b]
01-16 18:02:40.998 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@e]
01-16 18:02:41.002 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@11]
01-16 18:02:41.040 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@10]
01-16 18:02:41.048 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@19]
01-16 18:02:41.067 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@12]
01-16 18:02:41.099 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@13]
01-16 18:02:41.181 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@25]
01-16 18:02:41.189 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1f]
01-16 18:02:41.231 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@18]
01-16 18:02:41.235 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@20]
01-16 18:02:41.310 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@15]
01-16 18:02:41.330 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@14]
01-16 18:02:41.345 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@16]
01-16 18:02:41.352 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@17]
01-16 18:02:41.409 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@2b]
01-16 18:02:41.457 D/DBReader(18190): getDownloadedItems() called
01-16 18:02:41.465 D/DBReader(18190): getFavoriteIDList() called
01-16 18:02:41.467 D/DBReader(18190): getQueueIDList() called
01-16 18:02:41.468 D/DBReader(18190): Extracting Feedlist
01-16 18:02:41.477 D/MainActivity(18190): getLastNavFragment() -> 32
01-16 18:02:41.485 V/PlaybackService(18190): onPlaybackStateChange(2)
01-16 18:02:41.485 D/PlaybackService(18190): Writing player status playback preferences
01-16 18:02:41.486 D/PlaybackService(18190): notificationSetupTask: Starting background work
01-16 18:02:41.491 V/PlaybackService(18190): notificationSetupTask: playerStatus=PAUSED
01-16 18:02:41.494 D/EventDistributor(18190): Processing event queue. Number of events: 1
01-16 18:02:41.494 D/EventDistributor(18190): Notifying observers. Data: 128
01-16 18:02:41.495 D/PlaybackController(18190): Received statusUpdate Intent.
01-16 18:02:41.501 D/PlaybackController(18190): status: PAUSED
01-16 18:02:41.501 D/PlaybackController(18190): PositionObserver cancelled. Result: true
01-16 18:02:41.503 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:02:41.503 E/MediaPlayer(18190): Attempt to call getDuration in wrong state: mPlayer=0x7cb8a860, mCurrentState=0
01-16 18:02:41.503 E/MediaPlayer(18190): error (-38, 0)
01-16 18:02:41.504 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:02:41.504 E/MediaPlayer(18190): Attempt to call getDuration in wrong state: mPlayer=0x7cb8a860, mCurrentState=0
01-16 18:02:41.504 E/MediaPlayer(18190): error (-38, 0)
01-16 18:02:41.506 E/MediaPlayer(18190): Error (-38,0)
01-16 18:02:41.507 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0
01-16 18:02:41.511 E/MediaPlayer(18190): Error (-38,0)
01-16 18:02:41.511 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0
01-16 18:02:41.511 D/LclPlaybackSvcMPlayer(18190): Ignoring call to pause: Player is in PAUSED state
01-16 18:02:41.517 D/PlayerWidgetJobService(18190): Connection to service established
01-16 18:02:41.527 D/PlaybackService(18190): Notification set up
01-16 18:02:41.528 D/EventDistributor(18190): Processing event queue. Number of events: 1
01-16 18:02:41.528 D/EventDistributor(18190): Notifying observers. Data: 128
01-16 18:02:41.534 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:02:41.534 E/MediaPlayer(18190): Attempt to call getDuration in wrong state: mPlayer=0x7cb8a860, mCurrentState=0
01-16 18:02:41.534 E/MediaPlayer(18190): error (-38, 0)
01-16 18:02:41.534 E/MediaPlayer(18190): Error (-38,0)
01-16 18:02:41.534 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0
01-16 18:02:42.467 D/ApOkHttpUrlLoader(18190): buildLoadData() called with: model = [https://media.npr.org/assets/img/2019/01/15/75_wide-b4bcad2fc2514233d3259056cacaf456dd310976.jpg?s=1400], width = [112], height = [112]
01-16 18:02:42.481 D/MainActivity(18190): getLastNavFragment() -> 32
01-16 18:02:42.495 D/ApOkHttpUrlLoader(18190): buildLoadData() called with: model = [https://kuow-core-prod.s3.us-west-2.amazonaws.com/store/930ac95ee23a3dfe9420ea53115f50c3.png], width = [720], height = [264]
01-16 18:02:42.497 D/FeedMenuHandler(18190): Preparing options menu
01-16 18:02:42.549 D/AutoUpdateManager(18190): last refresh: 9 hours 4 minutes ago
01-16 18:02:42.550 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:02:42.550 E/MediaPlayer(18190): Attempt to call getDuration in wrong state: mPlayer=0x7cb8a860, mCurrentState=0
01-16 18:02:42.550 E/MediaPlayer(18190): error (-38, 0)
01-16 18:02:42.550 D/LclPlaybackSvcMPlayer(18190): getPosition() -> 0
01-16 18:02:42.550 E/MediaPlayer(18190): Attempt to call getDuration in wrong state: mPlayer=0x7cb8a860, mCurrentState=0
01-16 18:02:42.550 E/MediaPlayer(18190): error (-38, 0)
01-16 18:02:42.550 V/PlaybackController(18190): initServiceRunning()
01-16 18:02:42.550 D/ItemlistFragment(18190): onEventMainThread() called with: event = [DownloadEvent{update=DownloaderUpdate{downloaders=[], feedIds=[], mediaIds=[]}}]
01-16 18:02:42.551 D/DBReader(18190): getNavDrawerData() called with: 
01-16 18:02:42.556 D/DBReader(18190): getFeed() called with: feedId = [32]
01-16 18:02:42.559 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@20]
01-16 18:02:42.576 E/MediaPlayer(18190): Error (-38,0)
01-16 18:02:42.576 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@26]
01-16 18:02:42.576 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0
01-16 18:02:42.578 E/MediaPlayer(18190): Error (-38,0)
01-16 18:02:42.579 W/PlaybackSvc.onErrorLtsn(18190): An error has occured: -38 0
01-16 18:02:42.579 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@29]
01-16 18:02:42.592 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1a]
01-16 18:02:42.633 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1]
01-16 18:02:42.648 I/art     (18190): Background sticky concurrent mark sweep GC freed 179234(5MB) AllocSpace objects, 5(104KB) LOS objects, 6% free, 66MB/70MB, paused 4.150ms total 120.543ms
01-16 18:02:42.665 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@24]
01-16 18:02:42.666 D/DBReader(18190): getFavoriteIDList() called
01-16 18:02:42.667 D/DBReader(18190): getQueueIDList() called
01-16 18:02:42.669 D/DBReader(18190): Extracting Feedlist
01-16 18:02:42.670 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@28]
01-16 18:02:42.677 D/DBReader(18190): getQueueIDList() called
01-16 18:02:42.683 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@3]
01-16 18:02:42.683 D/ApOkHttpUrlLoader(18190): buildLoadData() called with: model = [https://kuow-core-prod.s3.us-west-2.amazonaws.com/store/930ac95ee23a3dfe9420ea53115f50c3.png], width = [720], height = [264]
01-16 18:02:42.688 D/MainActivity(18190): getLastNavFragment() -> 32
01-16 18:02:42.700 D/FeedMenuHandler(18190): Preparing options menu
01-16 18:02:42.717 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@23]
01-16 18:02:42.734 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1c]
01-16 18:02:42.834 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@2a]
01-16 18:02:42.860 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1d]
01-16 18:02:42.872 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@8]
01-16 18:02:42.890 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@7]
01-16 18:02:42.922 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@4]
01-16 18:02:42.943 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@5]
01-16 18:02:42.952 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@6]
01-16 18:02:42.957 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@21]
01-16 18:02:42.963 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@9]
01-16 18:02:43.017 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@a]
01-16 18:02:43.133 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1e]
01-16 18:02:43.137 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@c]
01-16 18:02:43.149 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@f]
01-16 18:02:43.193 I/art     (18190): Background partial concurrent mark sweep GC freed 190932(13MB) AllocSpace objects, 1(116KB) LOS objects, 21% free, 59MB/75MB, paused 6.331ms total 220.976ms
01-16 18:02:43.195 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@d]
01-16 18:02:43.259 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@27]
01-16 18:02:43.287 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@b]
01-16 18:02:43.318 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1b]
01-16 18:02:43.323 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@e]
01-16 18:02:43.327 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@11]
01-16 18:02:43.365 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@10]
01-16 18:02:43.373 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@19]
01-16 18:02:43.391 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@12]
01-16 18:02:43.423 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@13]
01-16 18:02:43.503 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@25]
01-16 18:02:43.511 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@1f]
01-16 18:02:43.550 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@18]
01-16 18:02:43.554 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@20]
01-16 18:02:43.627 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@15]
01-16 18:02:43.645 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@14]
01-16 18:02:43.659 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@16]
01-16 18:02:43.665 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@17]
01-16 18:02:43.720 D/DBReader(18190): getFeedItemList() called with: feed = [de.danoeh.antennapod.core.feed.Feed@2b]
01-16 18:02:43.765 D/DBReader(18190): getDownloadedItems() called
01-16 18:02:43.773 D/DBReader(18190): getFavoriteIDList() called
01-16 18:02:43.775 D/DBReader(18190): getQueueIDList() called
01-16 18:02:43.776 D/DBReader(18190): Extracting Feedlist
01-16 18:02:43.784 D/MainActivity(18190): getLastNavFragment() -> 32

orionlee on 17 Jan 2019

The (-38, 0) error seems to indicate some timing issue with prepare and start call on MediaPlayer.

https://stackoverflow.com/questions/18482018/mediaplayer-error-38-0/18482263

In this context, it seems to imply there is some intermittent incorrect sequence of of prepare and start calls when AntennaPod is transitioning from playing one episode to the next one.

orionlee on 17 Jan 2019

Another stuck incident with (-38, 0) error in logcat.

This time is slightly different.

It happened after I pressed pause (hardware button) explicitly and tried to play again (rather than transitioning from one episode to the next one).
the log seems to imply it tries to load the episode from the original http source, rather than the downloaded file. (The file has indeed been downloaded an partially played before it gets stuck).
the player can still be unstuck by pressing play on another episode, then play back to this one.

Logcat Highlights:
(The logcat reflects a custom build roughly based on recent develop + #2954)

# Pause by pressing play/pause
01-18 15:58:30.013 D/PlaybackService(14656): Handling keycode: 85
...
01-18 15:58:30.019 D/LclPlaybackSvcMPlayer(14656): Pausing playback.
...
01-18 15:58:30.882 V/PlaybackService(14656): onPlaybackStateChange(8)
01-18 15:58:30.914 D/PlaybackService(14656): reloadUI callback reached
01-18 15:58:30.916 D/ReplacementMediaPlayer(14656): In setDataSource(context, https://universityofwashington.mc.tritondigital.com/THE_RECORD_P/media/76f79bd73be2185685a50f4c493fc7b1.mp3)
...
# Try to play by pressing play/pause
01-18 16:00:28.242 D/PlaybackService(14656): Handling keycode: 85
01-18 16:00:28.243 D/LclPlaybackSvcMPlayer(14656): Preparing media player
01-18 16:00:28.243 D/PlaybackSvcMediaPlayer(14656): LocalPSMP: Setting player status to PREPARING
...
01-18 16:00:58.718 E/SonicTrack(14656): java.io.IOException: Failed to instantiate extractor.
...
01-18 16:00:59.239 V/PlaybackService(14656): onPlaybackStateChange(4)
01-18 16:00:59.267 D/PlayerWidgetJobService(14656): Connection to service established
01-18 16:00:59.268 E/MediaPlayer(14656): Attempt to perform seekTo in wrong state: mPlayer=0x858af320, mCurrentState=2
01-18 16:00:59.269 E/MediaPlayer(14656): error (-38, 0)
01-18 16:00:59.270 E/MediaPlayer(14656): Error (-38,0)
01-18 16:00:59.275 W/PlaybackSvc.onErrorLtsn(14656): An error has occured: -38 0
01-18 16:01:02.275 D/ReplacementMediaPlayer(14656): start()

Logcat details

01-18 15:58:29.805 D/PlaybackService(14656): Saving current position to 2046641
01-18 15:58:29.961 D/MediaButtonReceiver(14656): Received intent
01-18 15:58:30.013 D/PlaybackService(14656): OnStartCommand called
01-18 15:58:30.013 D/PlaybackService(14656): Received media button event
01-18 15:58:30.013 D/PlaybackService(14656): Handling keycode: 85
01-18 15:58:30.018 D/MediaButtonReceiver(14656): Received intent
01-18 15:58:30.019 D/LclPlaybackSvcMPlayer(14656): Pausing playback.
01-18 15:58:30.028 D/ReplacementMediaPlayer(14656): this.mpi is not a ServiceBackedMediaPlayer, but we couldn't use it anyway
01-18 15:58:30.030 D/SonicAudioPlayer(14656): pause(), current state: STARTED
01-18 15:58:30.030 D/SonicAudioPlayerState(14656): Changed to PAUSED
01-18 15:58:30.030 I/System.out(14656): Decoder changed to PAUSED
01-18 15:58:30.031 D/LclPlaybackSvcMPlayer(14656): getPosition() -> 2046876
01-18 15:58:30.037 D/PlaybackSvcMediaPlayer(14656): LocalPSMP: Setting player status to PAUSED
01-18 15:58:30.037 D/PlaybackServiceTaskMgr(14656): Cancelled PositionSaver
01-18 15:58:30.037 D/PlaybackService(14656): Saving current position to 2046876
01-18 15:58:30.037 D/PlaybackServiceTaskMgr(14656): Cancelled WidgetUpdater
01-18 15:58:30.037 D/FlattrUtils(14656): Retrieving access token
01-18 15:58:30.058 D/FlattrUtils(14656): No access token found
01-18 15:58:30.061 D/LclPlaybackSvcMPlayer(14656): getPosition() -> 2046876
01-18 15:58:30.273 V/PlaybackService(14656): onPlaybackStateChange(2)
01-18 15:58:30.274 D/PlaybackService(14656): Writing player status playback preferences
01-18 15:58:30.278 D/PlaybackService(14656): notificationSetupTask: Starting background work
01-18 15:58:30.350 D/EventDistributor(14656): Processing event queue. Number of events: 1
01-18 15:58:30.350 D/EventDistributor(14656): Notifying observers. Data: 128
01-18 15:58:30.360 D/LclPlaybackSvcMPlayer(14656): reinit()
01-18 15:58:30.361 D/ReplacementMediaPlayer(14656): this.mpi is not a ServiceBackedMediaPlayer, but we couldn't use it anyway
01-18 15:58:30.361 D/SonicAudioPlayerState(14656): Changed to STOPPED
01-18 15:58:30.362 D/PlaybackSvcMediaPlayer(14656): LocalPSMP: Setting player status to INDETERMINATE
01-18 15:58:30.362 D/LclPlaybackSvcMPlayer(14656): getPosition() -> -1
01-18 15:58:30.368 D/PlayerWidgetJobService(14656): Connection to service established
01-18 15:58:30.394 D/ApOkHttpUrlLoader(14656): buildLoadData() called with: model = [https://kuow-core-prod.s3.us-west-2.amazonaws.com/store/1ccc34419db507f8f9e884bc64b68103.jpg], width = [128], height = [128]
01-18 15:58:30.434 V/PlaybackService(14656): notificationSetupTask: playerStatus=INDETERMINATE
01-18 15:58:30.460 D/PlaybackService(14656): Notification set up
01-18 15:58:30.522 V/PlaybackService(14656): onPlaybackStateChange(0)
01-18 15:58:30.588 D/ReplacementMediaPlayer(14656): Releasing MediaPlayer
01-18 15:58:30.589 D/AndroidMediaPlayer(14656): mp.release()
01-18 15:58:30.589 D/ReplacementMediaPlayer(14656): Setting onSeekCompleteListener to null 871
01-18 15:58:30.592 D/AndroidMediaPlayer(14656): Setting prepared listener to this.onPreparedListener
01-18 15:58:30.593 D/ReplacementMediaPlayer(14656): setupMpi
01-18 15:58:30.593 D/ReplacementMediaPlayer(14656): setupMpi
01-18 15:58:30.593 D/ReplacementMediaPlayer(14656): Switching to SonicMediaPlayer
01-18 15:58:30.593 D/MediaPlayer(14656): switchMediaPlayerImpl() called with: from = [org.antennapod.audio.AndroidAudioPlayer@61b309c], to = [org.antennapod.audio.SonicAudioPlayer@70b6aa5]
01-18 15:58:30.593 D/ReplacementMediaPlayer(14656): switchMediaPlayerImpl
01-18 15:58:30.593 D/ReplacementMediaPlayer(14656): switchMediaPlayerImpl(), current state is INITIALIZED
01-18 15:58:30.593 D/SonicAudioPlayerState(14656): Changed to IDLE
01-18 15:58:30.593 D/ReplacementMediaPlayer(14656): Setting playback speed to 1.0
01-18 15:58:30.593 D/ReplacementMediaPlayer(14656): asserting at least one data source is null
01-18 15:58:30.593 D/MediaPlayer(14656): Switched to class org.antennapod.audio.SonicAudioPlayer
01-18 15:58:30.593 D/ReplacementMediaPlayer(14656): onPitchAdjustmentAvailableChangedListener.onPitchAdjustmentAvailableChanged being called
01-18 15:58:30.593 D/ReplacementMediaPlayer(14656): Pitch adjustment state has changed from false to true
01-18 15:58:30.593 D/ReplacementMediaPlayer(14656): onSpeedAdjustmentAvailableChangedListener.onSpeedAdjustmentAvailableChanged being called
01-18 15:58:30.593 D/ReplacementMediaPlayer(14656): Speed adjustment state has changed from false to true
01-18 15:58:30.593 D/ReplacementMediaPlayer(14656): switchMediaPlayerImpl() INITIALIZED
01-18 15:58:30.593 D/PlaybackSvcMediaPlayer(14656): LocalPSMP: Setting player status to INITIALIZING
01-18 15:58:30.594 D/LclPlaybackSvcMPlayer(14656): getPosition() -> 2046876
01-18 15:58:30.680 D/PlayerWidgetJobService(14656): Connection to service established
01-18 15:58:30.882 V/PlaybackService(14656): onPlaybackStateChange(8)
01-18 15:58:30.914 D/PlaybackService(14656): reloadUI callback reached
01-18 15:58:30.916 D/ReplacementMediaPlayer(14656): In setDataSource(context, https://universityofwashington.mc.tritondigital.com/THE_RECORD_P/media/76f79bd73be2185685a50f4c493fc7b1.mp3)
01-18 15:58:30.919 D/PlayerWidgetJobService(14656): Connection to service established
01-18 15:58:30.919 D/ReplacementMediaPlayer(14656): this.mpi is not a ServiceBackedMediaPlayer, but we couldn't use it anyway
01-18 15:58:30.920 D/SonicAudioPlayerState(14656): Changed to INITIALIZED
01-18 15:58:30.921 D/PlaybackSvcMediaPlayer(14656): LocalPSMP: Setting player status to INITIALIZED
01-18 15:58:30.921 D/LclPlaybackSvcMPlayer(14656): getPosition() -> 2046876
01-18 15:58:31.609 V/PlaybackService(14656): onPlaybackStateChange(0)
01-18 15:58:31.609 D/PlaybackService(14656): Writing playback preferences
01-18 15:58:31.627 D/EventDistributor(14656): Processing event queue. Number of events: 1
01-18 15:58:31.627 D/EventDistributor(14656): Notifying observers. Data: 128
01-18 15:58:31.642 D/PlayerWidgetJobService(14656): Connection to service established
01-18 15:58:31.647 D/LclPlaybackSvcMPlayer(14656): getPosition() -> 2046876
01-18 16:00:28.228 D/MediaButtonReceiver(14656): Received intent
01-18 16:00:28.236 D/PlaybackService(14656): OnStartCommand called
01-18 16:00:28.242 D/PlaybackService(14656): Received media button event
01-18 16:00:28.242 D/PlaybackService(14656): Handling keycode: 85
01-18 16:00:28.243 D/LclPlaybackSvcMPlayer(14656): Preparing media player
01-18 16:00:28.243 D/PlaybackSvcMediaPlayer(14656): LocalPSMP: Setting player status to PREPARING
01-18 16:00:28.244 D/LclPlaybackSvcMPlayer(14656): getPosition() -> 2046876
01-18 16:00:28.263 D/MediaButtonReceiver(14656): Received intent
01-18 16:00:28.496 V/PlaybackService(14656): onPlaybackStateChange(8)
01-18 16:00:28.520 D/PlayerWidgetJobService(14656): Connection to service established
01-18 16:00:28.549 D/ReplacementMediaPlayer(14656): prepare() using class org.antennapod.audio.SonicAudioPlayer state INITIALIZED
01-18 16:00:28.550 D/ReplacementMediaPlayer(14656): onPreparedListener is: non-null
01-18 16:00:28.550 D/ReplacementMediaPlayer(14656): preparedListener is: null
01-18 16:00:28.551 D/ReplacementMediaPlayer(14656): this.mpi is not a ServiceBackedMediaPlayer, but we couldn't use it anyway
01-18 16:00:28.575 D/SonicAudioPlayer(14656): prepare(), current state: INITIALIZED
01-18 16:00:28.575 D/SonicAudioPlayerState(14656): Changed to PREPARING
01-18 16:00:28.602 I/MediaHTTPConnection(14656): proxyName: 0.0.0.0 0
01-18 16:00:28.608 E/NuCachedSource2(14656): source returned error -1, 10 retries left
01-18 16:00:31.609 I/MediaHTTPConnection(14656): proxyName: 0.0.0.0 0
01-18 16:00:31.614 E/NuCachedSource2(14656): source returned error -1, 9 retries left
01-18 16:00:34.615 I/MediaHTTPConnection(14656): proxyName: 0.0.0.0 0
01-18 16:00:34.620 E/NuCachedSource2(14656): source returned error -1, 8 retries left
01-18 16:00:37.622 I/MediaHTTPConnection(14656): proxyName: 0.0.0.0 0
01-18 16:00:37.626 E/NuCachedSource2(14656): source returned error -1, 7 retries left
01-18 16:00:40.628 I/MediaHTTPConnection(14656): proxyName: 0.0.0.0 0
01-18 16:00:40.633 E/NuCachedSource2(14656): source returned error -1, 6 retries left
01-18 16:00:43.635 I/MediaHTTPConnection(14656): proxyName: 0.0.0.0 0
01-18 16:00:43.639 E/NuCachedSource2(14656): source returned error -1, 5 retries left
01-18 16:00:46.640 I/MediaHTTPConnection(14656): proxyName: 0.0.0.0 0
01-18 16:00:46.645 E/NuCachedSource2(14656): source returned error -1, 4 retries left
01-18 16:00:49.646 I/MediaHTTPConnection(14656): proxyName: 0.0.0.0 0
01-18 16:00:49.651 E/NuCachedSource2(14656): source returned error -1, 3 retries left
01-18 16:00:52.652 I/MediaHTTPConnection(14656): proxyName: 0.0.0.0 0
01-18 16:00:52.657 E/NuCachedSource2(14656): source returned error -1, 2 retries left
01-18 16:00:55.658 I/MediaHTTPConnection(14656): proxyName: 0.0.0.0 0
01-18 16:00:55.663 E/NuCachedSource2(14656): source returned error -1, 1 retries left
01-18 16:00:58.665 I/MediaHTTPConnection(14656): proxyName: 0.0.0.0 0
01-18 16:00:58.669 E/NuCachedSource2(14656): source returned error -1, 0 retries left
01-18 16:00:58.673 I/MediaHTTPConnection(14656): proxyName: 0.0.0.0 0
01-18 16:00:58.718 E/SonicTrack(14656): Failed setting data source!
01-18 16:00:58.718 E/SonicTrack(14656): java.io.IOException: Failed to instantiate extractor.
01-18 16:00:58.718 E/SonicTrack(14656):     at android.media.MediaExtractor.nativeSetDataSource(Native Method)
01-18 16:00:58.718 E/SonicTrack(14656):     at android.media.MediaExtractor.setDataSource(MediaExtractor.java:186)
01-18 16:00:58.718 E/SonicTrack(14656):     at org.antennapod.audio.SonicAudioPlayer.initStream(SonicAudioPlayer.java:502)
01-18 16:00:58.718 E/SonicTrack(14656):     at org.antennapod.audio.SonicAudioPlayer.doPrepare(SonicAudioPlayer.java:221)
01-18 16:00:58.718 E/SonicTrack(14656):     at org.antennapod.audio.SonicAudioPlayer.prepare(SonicAudioPlayer.java:195)
01-18 16:00:58.718 E/SonicTrack(14656):     at org.antennapod.audio.MediaPlayer.prepare(MediaPlayer.java:864)
01-18 16:00:58.718 E/SonicTrack(14656):     at de.danoeh.antennapod.core.service.playback.LocalPSMP.lambda$prepare$5(LocalPSMP.java:317)
01-18 16:00:58.718 E/SonicTrack(14656):     at de.danoeh.antennapod.core.service.playback.-$$Lambda$LocalPSMP$e2KcqXZ7b0S-kIUaHPZV8_h5hKs.run(lambda)
01-18 16:00:58.718 E/SonicTrack(14656):     at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:428)
01-18 16:00:58.718 E/SonicTrack(14656):     at java.util.concurrent.FutureTask.run(FutureTask.java:237)
01-18 16:00:58.718 E/SonicTrack(14656):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
01-18 16:00:58.718 E/SonicTrack(14656):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
01-18 16:00:58.718 E/SonicTrack(14656):     at java.lang.Thread.run(Thread.java:761)
01-18 16:00:58.718 D/SonicAudioPlayerState(14656): Changed to ERROR
01-18 16:00:58.718 D/ReplacementMediaPlayer(14656): setupMpi
01-18 16:00:58.719 D/MediaPlayer(14656): switchMediaPlayerImpl() called with: from = [org.antennapod.audio.SonicAudioPlayer@70b6aa5], to = [org.antennapod.audio.AndroidAudioPlayer@61b309c]
01-18 16:00:58.719 D/ReplacementMediaPlayer(14656): switchMediaPlayerImpl
01-18 16:00:58.719 D/ReplacementMediaPlayer(14656): switchMediaPlayerImpl(), current state is INITIALIZED
01-18 16:00:58.719 D/ReplacementMediaPlayer(14656): Setting playback speed to 1.0
01-18 16:00:58.720 D/ReplacementMediaPlayer(14656): asserting at least one data source is null
01-18 16:00:58.724 D/ReplacementMediaPlayer(14656): switchMediaPlayerImpl(): stringDataSource != null
01-18 16:00:58.725 D/AndroidMediaPlayer(14656): setDataSource(https://universityofwashington.mc.tritondigital.com/THE_RECORD_P/media/76f79bd73be2185685a50f4c493fc7b1.mp3)
01-18 16:00:58.745 D/AndroidMediaPlayer(14656): setPlaybackSpeed(1.0)
01-18 16:00:58.748 D/MediaPlayer(14656): Switched to class org.antennapod.audio.AndroidAudioPlayer
01-18 16:00:58.748 D/ReplacementMediaPlayer(14656): switchMediaPlayerImpl() INITIALIZED
01-18 16:00:58.748 D/ReplacementMediaPlayer(14656): prepare() finished
01-18 16:00:58.748 D/LclPlaybackSvcMPlayer(14656): Resource prepared
01-18 16:00:58.748 D/PlaybackSvcMediaPlayer(14656): LocalPSMP: Setting player status to PREPARED
01-18 16:00:58.749 D/LclPlaybackSvcMPlayer(14656): getPosition() -> 2046876
01-18 16:00:58.974 V/PlaybackService(14656): onPlaybackStateChange(2)
01-18 16:00:58.977 D/PlaybackService(14656): notificationSetupTask: Starting background work
01-18 16:00:58.977 D/PlaybackServiceTaskMgr(14656): Chapter loader started
01-18 16:00:58.977 D/ChapterUtils(14656): Reading id3 chapters from item The state of the state, from the legislature to the governor's mansion
01-18 16:00:58.983 D/ApOkHttpUrlLoader(14656): buildLoadData() called with: model = [https://kuow-core-prod.s3.us-west-2.amazonaws.com/store/1ccc34419db507f8f9e884bc64b68103.jpg], width = [128], height = [128]
01-18 16:00:58.989 D/LclPlaybackSvcMPlayer(14656): Audiofocus successfully requested
01-18 16:00:58.989 E/ChapterUtils(14656): 
01-18 16:00:58.990 D/LclPlaybackSvcMPlayer(14656): Resuming/Starting playback
01-18 16:00:58.990 E/ChapterUtils(14656): 
01-18 16:00:58.991 D/PlaybackServiceTaskMgr(14656): Chapter loader stopped
01-18 16:00:58.996 V/PlaybackService(14656): notificationSetupTask: playerStatus=PREPARED
01-18 16:00:58.997 D/PlayerWidgetJobService(14656): Connection to service established
01-18 16:00:58.999 D/LclPlaybackSvcMPlayer(14656): getPosition() -> 2046876
01-18 16:00:59.000 D/PlaybackSvcMediaPlayer(14656): LocalPSMP: Setting player status to SEEKING
01-18 16:00:59.001 D/LclPlaybackSvcMPlayer(14656): getPosition() -> 2046876
01-18 16:00:59.010 D/PlaybackService(14656): Notification set up
01-18 16:00:59.239 V/PlaybackService(14656): onPlaybackStateChange(4)
01-18 16:00:59.267 D/PlayerWidgetJobService(14656): Connection to service established
01-18 16:00:59.268 E/MediaPlayer(14656): Attempt to perform seekTo in wrong state: mPlayer=0x858af320, mCurrentState=2
01-18 16:00:59.269 E/MediaPlayer(14656): error (-38, 0)
01-18 16:00:59.270 E/MediaPlayer(14656): Error (-38,0)
01-18 16:00:59.275 W/PlaybackSvc.onErrorLtsn(14656): An error has occured: -38 0
01-18 16:01:02.275 D/ReplacementMediaPlayer(14656): start()
01-18 16:01:02.276 D/ReplacementMediaPlayer(14656): this.mpi is not a ServiceBackedMediaPlayer, but we couldn't use it anyway
01-18 16:01:02.280 E/MediaPlayer(14656): start called in state 0, mPlayer(0x858af320)
01-18 16:01:02.280 E/MediaPlayer(14656): error (-38, 0)
01-18 16:01:02.280 D/PlaybackSvcMediaPlayer(14656): LocalPSMP: Setting player status to PLAYING
01-18 16:01:02.280 E/MediaPlayer(14656): Error (-38,0)
01-18 16:01:02.280 D/PlaybackServiceTaskMgr(14656): Started WidgetUpdater
01-18 16:01:02.280 W/PlaybackSvc.onErrorLtsn(14656): An error has occured: -38 0
01-18 16:01:02.280 D/PlaybackServiceTaskMgr(14656): Started PositionSaver
01-18 16:01:02.283 D/LclPlaybackSvcMPlayer(14656): getPosition() -> 2043876
01-18 16:01:02.531 V/PlaybackService(14656): onPlaybackStateChange(3)
01-18 16:01:02.532 D/PlaybackService(14656): notificationSetupTask: Starting background work
01-18 16:01:02.533 D/PlaybackService(14656): Writing player status playback preferences
01-18 16:01:02.553 V/PlaybackService(14656): notificationSetupTask: playerStatus=PLAYING
01-18 16:01:02.557 D/AndroidMediaPlayer(14656): setPlaybackSpeed(1.0)
01-18 16:01:02.561 V/PlaybackService(14656): notificationSetupTask: make service foreground
01-18 16:01:02.561 D/EventDistributor(14656): Processing event queue. Number of events: 1
01-18 16:01:02.561 D/EventDistributor(14656): Notifying observers. Data: 128
01-18 16:01:02.561 D/LclPlaybackSvcMPlayer(14656): Playback speed was set to 1.0
01-18 16:01:02.565 D/PlayerWidgetJobService(14656): Connection to service established
01-18 16:01:02.566 D/LclPlaybackSvcMPlayer(14656): Media player volume was set to 1.0 1.0
01-18 16:01:02.566 D/LclPlaybackSvcMPlayer(14656): Pausing playback.
01-18 16:01:02.567 D/ReplacementMediaPlayer(14656): this.mpi is not a ServiceBackedMediaPlayer, but we couldn't use it anyway
01-18 16:01:02.567 E/MediaPlayer(14656): pause called in state 0, mPlayer(0x858af320)
01-18 16:01:02.567 E/MediaPlayer(14656): error (-38, 0)
01-18 16:01:02.567 E/MediaPlayer(14656): Error (-38,0)
01-18 16:01:02.568 W/PlaybackSvc.onErrorLtsn(14656): An error has occured: -38 0
01-18 16:01:02.577 D/PlaybackService(14656): Notification set up
01-18 16:01:02.584 D/EventDistributor(14656): Processing event queue. Number of events: 1
01-18 16:01:02.584 D/EventDistributor(14656): Notifying observers. Data: 128
01-18 16:01:02.584 D/LclPlaybackSvcMPlayer(14656): getPosition() -> 2043876
01-18 16:01:02.584 D/PlaybackSvcMediaPlayer(14656): LocalPSMP: Setting player status to PAUSED
01-18 16:01:02.584 D/PlaybackServiceTaskMgr(14656): Cancelled PositionSaver
01-18 16:01:02.584 D/PlaybackService(14656): Saving current position to 2043876
01-18 16:01:02.585 D/PlaybackServiceTaskMgr(14656): Cancelled WidgetUpdater
01-18 16:01:02.585 D/FlattrUtils(14656): Retrieving access token
01-18 16:01:02.585 D/FlattrUtils(14656): No access token found
01-18 16:01:02.586 D/LclPlaybackSvcMPlayer(14656): getPosition() -> 2043876
01-18 16:01:02.782 V/PlaybackService(14656): onPlaybackStateChange(2)
01-18 16:01:02.783 D/PlaybackService(14656): Writing player status playback preferences
01-18 16:01:02.783 D/PlaybackService(14656): notificationSetupTask: Starting background work
01-18 16:01:02.788 D/EventDistributor(14656): Processing event queue. Number of events: 1
01-18 16:01:02.788 D/EventDistributor(14656): Notifying observers. Data: 128
01-18 16:01:02.788 V/PlaybackService(14656): notificationSetupTask: playerStatus=PAUSED
01-18 16:01:02.798 D/LclPlaybackSvcMPlayer(14656): Ignoring call to pause: Player is in PAUSED state
01-18 16:01:02.805 D/PlayerWidgetJobService(14656): Connection to service established
01-18 16:01:02.812 D/LclPlaybackSvcMPlayer(14656): getPosition() -> 2043876
01-18 16:01:02.814 E/MediaPlayer(14656): Attempt to call getDuration in wrong state: mPlayer=0x858af320, mCurrentState=0
01-18 16:01:02.816 E/MediaPlayer(14656): error (-38, 0)
01-18 16:01:02.817 E/MediaPlayer(14656): Error (-38,0)
01-18 16:01:02.818 W/PlaybackSvc.onErrorLtsn(14656): An error has occured: -38 0
01-18 16:01:02.822 D/PlaybackService(14656): Notification set up
01-18 16:01:02.882 D/EventDistributor(14656): Processing event queue. Number of events: 1
01-18 16:01:02.883 D/EventDistributor(14656): Notifying observers. Data: 128

orionlee on 19 Jan 2019

The problem is further narrowed down. In many such cases, somehow AntennaPod tries to stream from the original HTTP source, instead of the downloaded media on the device. (It's verified they have indeed been downloaded). Given there was no network available, the player eventually got stuck with (-38, 0) error.

An abbreviated and annotated logcat illustrating the issue.

# An episode is completed.
01-31 17:57:15.319 D/SonicTrack(18532): Decoding loop exited. Stopping codec and track
...
01-31 17:57:15.730 D/SonicAudioPlayerState(18532): Changed to PLAYBACK_COMPLETED
01-31 17:57:15.732 D/PlaybackSvcMediaPlayer(18532): LocalPSMP: Setting player status to INDETERMINATE
...
01-31 17:57:16.030 D/PlaybackService(18532): getNextInQueue()
01-31 17:57:16.030 D/LclPlaybackSvcMPlayer(18532): Playback of next episode will start immediately.
...
01-31 17:57:16.036 D/PlaybackSvcMediaPlayer(18532): LocalPSMP: Setting player status to INITIALIZING
...
01-31 17:57:16.465 D/PlaybackService(18532): reloadUI callback reached
01-31 17:57:16.465 D/PlaybackController(18532): status: INITIALIZING
# Somehow in trying to play the next episode, it tries to stream from the HTTP source,
# instead of the downloaded mp3 on sdcard
01-31 17:57:16.465 D/ReplacementMediaPlayer(18532): In setDataSource(context, https://universityofwashington.mc.tritondigital.com/THE_RECORD_P/media/88bd644471fab4e659b4ed7be8a257a5.mp3)
...
# It tries to stream from the http source, but there is no network,
# and finally throws an IOException after 30 seconds.
01-31 17:57:18.599 I/MediaHTTPConnection(18532): proxyName: 0.0.0.0 0
01-31 17:57:18.612 E/NuCachedSource2(18532): source returned error -1, 10 retries left
...
01-31 17:57:48.687 E/NuCachedSource2(18532): source returned error -1, 0 retries left
01-31 17:57:48.704 I/MediaHTTPConnection(18532): proxyName: 0.0.0.0 0
01-31 17:57:48.748 D/PlayerWidgetJobService(18532): Connection to service established
01-31 17:57:48.758 E/SonicTrack(18532): Failed setting data source!
01-31 17:57:48.758 E/SonicTrack(18532): java.io.IOException: Failed to instantiate extractor.
01-31 17:57:48.758 E/SonicTrack(18532):     at android.media.MediaExtractor.nativeSetDataSource(Native Method)
01-31 17:57:48.758 E/SonicTrack(18532):     at android.media.MediaExtractor.setDataSource(MediaExtractor.java:186)
01-31 17:57:48.758 E/SonicTrack(18532):     at org.antennapod.audio.SonicAudioPlayer.initStream(SonicAudioPlayer.java:502)
01-31 17:57:48.758 E/SonicTrack(18532):     at org.antennapod.audio.SonicAudioPlayer.doPrepare(SonicAudioPlayer.java:221)
01-31 17:57:48.758 E/SonicTrack(18532):     at org.antennapod.audio.SonicAudioPlayer.prepare(SonicAudioPlayer.java:195)
01-31 17:57:48.758 E/SonicTrack(18532):     at org.antennapod.audio.MediaPlayer.prepare(MediaPlayer.java:864)
01-31 17:57:48.758 E/SonicTrack(18532):     at de.danoeh.antennapod.core.service.playback.LocalPSMP.playMediaObject(LocalPSMP.java:181)
01-31 17:57:48.758 E/SonicTrack(18532):     at de.danoeh.antennapod.core.service.playback.LocalPSMP.lambda$endPlayback$17(LocalPSMP.java:878)
01-31 17:57:48.758 E/SonicTrack(18532):     at de.danoeh.antennapod.core.service.playback.-$$Lambda$LocalPSMP$Cm8NfY9klxUfHGLdJjXUCI5RD9k.run(lambda)
01-31 17:57:48.758 E/SonicTrack(18532):     at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:428)
01-31 17:57:48.758 D/SonicAudioPlayerState(18532): Changed to ERROR
...
# The player continues to try to start playing, leading to a (-38, 0) error
01-31 17:57:49.064 D/ReplacementMediaPlayer(18532): start()
01-31 17:57:49.064 D/ReplacementMediaPlayer(18532): this.mpi is not a ServiceBackedMediaPlayer, but we couldn't use it anyway
01-31 17:57:49.065 E/MediaPlayer(18532): start called in state 2, mPlayer(0x8728ab40)
01-31 17:57:49.065 E/MediaPlayer(18532): error (-38, 0)
01-31 17:57:49.065 D/PlaybackSvcMediaPlayer(18532): LocalPSMP: Setting player status to PLAYING
...
01-31 17:57:49.553 W/PlaybackSvc.onErrorLtsn(18532): An error has occured: -38 0
...

Note the log line

D/ReplacementMediaPlayer(18532): In setDataSource(context, https://universityofwashington.mc.tritondigital.com/THE_RECORD_P/media/88bd644471fab4e659b4ed7be8a257a5.mp3)

It is from AntennaPod-AudioPlayer library .

The data source should have been a local file path, e.g., /storage/9016-4EF8/Android/data/de.danoeh.antennapod.devR/files/media/Hidden Brain/Rewinding Rewriting.mp3, but somehow it wasn't.

Other notes:

I have faced such issues intermittently for quite a while, at least since 1.6.X, so it is unlikely to be a recent regression.
I do use an external SD card, and I wonder if it might be related to some intermittent issues in accessing SD card. The reason is that occasionally, I get download error saying that the directory (for a podcast) does not exist while it actually does, which might indicate some intermittent issues in accessing SD card.

orionlee on 8 Feb 2019

👍1

One issue is located: in some cases, the in-memory Queue object does not have the updated download status of an episode, i.e., an episode is downloaded, but it is not reflected in the in-memory queue. Then AntennaPod will try to stream the episode (and got stuck if there is no network).

One way to reproduce the scenario:

Play some episode
add a non-downloaded episode to the queue, and move it to be the next one to play.
Press download button to download the episode
Once download is complete, turn off network
When the current episode playback is complete, AntennaPod will be stuck trying to play the next one.

I face it more frequently in my custom build that includes PR #2714 . With #2714 and poor network, similar cases happen: an episode is first partially downloaded (and in the queue), and the download is complete subsequently. When AntennaPod tries to play next and encounter such episode, it gets stuck.

Code Analysis
One can see the problem by adding log statements to trace the next FeedMedia object PlaybackSerivce.getNextInQueue()

V/PlaybackService:   getNextInQueue() - nextMedia - localFileAvailable: false, downloaded: false, localURL: null ; streamURL: https://play.podtrac.com/npr-510325/...nal.mp3

The log shows that the FeedMedia object incorrectly has localFileAvailable == false in scenarios described above.

One level down, it means PlaybackServiceTaskManager has supplied an outdated Queue.

Specifically, the queue object is kept up-to-date by PlaybackServiceTaskManager.onEvent(QueueEvent).
When an episode in the queue has been downloaded, such event is not sent to PlaybackServiceTaskManager.

Options for a fix:

ensure the queue object in PlaybackServiceTaskManager is up-to-date (e.g., tracking download complete event by a new onEvent(DownloadEvent) method, or
get the queue from the database directly, removing the caching (the usage is not frequent, typically in going from one episode to the next, so actual impact of giving caching should be negligible.)

orionlee on 25 Feb 2019

👍1

Issues that block the approach of tracking download complete event with onEvent(DownloadEvent) method:
Currently there is no definite DownloadEvent that says so: when an episode download is complete (or cancelled / failed), the DownloadEvent returned is an empty one:

[DownloadEvent{update=DownloaderUpdate{downloaders=[], feedIds=[], mediaIds=[]}}]

The same underlying issue also blocks #2981.

orionlee on 25 Feb 2019

Findings on how to fix the issue by providing proper DownloadEvent to inform receivers a download has been "completed" (success, failure, canceled).

The entry point would be in DownloadService.downloadCompletionThread

Currently, upon download completion,

the service generates a DownloadEvent without the just-completed download , implicitly in the removeDownload(downloader) call,
the event is posted before the download service processes the completed the download (updating the states in the database, etc.)

Changes:
Logically,

include the just completed download in the event
move posting DownloadEvent to the end of cal processing so that the database states reflect the download, e.g., marking the correspond FeedMedia object as downloaded.

At code level,

add the aforementioned logic at the end of the download processing, i.e.,
a. handleCompletedFeedDownload() (asynchronous)
b. handleCompletedFeedMediaDownload() (asynchronous)
c. handleFailedDownload() (asynchronous)
d. case download cancel (currently a block of in a else branch)
adding the logic can be done via a Runnable callback to the above calls.
a. logically, the logic can be invoked in a finally block of the method, were the main logic synchronous. Given the main logic is primarily asynchronous, a callback is needed.
b. To make the logic more readable, one might consider replace the callback, with, say, RxJava-based mechanism, but it adds its own complexity.
c. Using CompletableFuture would have been both relatively easy and readable, but it is only supported for API level >= 24.

Risks: It's not yet clear if some other part of codebase implicitly relies on the current behavior, i.e., when a download is completed, it simply disappears from the DownloadEvent.

orionlee on 26 Feb 2019

Was this page helpful?

0 / 5 - 0 ratings