v20 background playback stops and doesn't recover

[aand18]

Checklist

• I am using the latest version.
• I checked, but didn't find any duplicates of this issue in the repo.
• I have read the contribution guidelines given at https://github.com/TeamNewPipe/NewPipe/blob/HEAD/.github/CONTRIBUTING.md.
• This issue contains only one bug. I will open one issue for every bug report I want to file.

Steps to reproduce the bug

1. Add a few long videos to background queue
2. Maybe lose connectivity after a few minutes (I'm not sure it's the cause)

Actual behaviour

I was playing a long video in background and it stopped after a few minutes. I think it was buffering (notification showed the hourglass instead of the play button).
It never recovered.

I tried jumping to next in queue, but it still stayed on buffering (I don't remember if it switched to next video or ignored the "next video" command).

This could be a different bug - on v19 you could press next when the current video was stuck and it would play the next queued video.

Finally, I exited with the X notification button.

Expected behavior

Background playback should recover from connectivity issues.

Screenshots/Screen recordings

Logs

Device info

• Android version/Custom ROM version: stock Android 9
• Device model: Samsung S8

Just installed v20 and this hasn't happened with v19 so I think it's a bug.

Immediately after, I reinstalled v19 and it played back the same videos with no problems.

If you need more info, please advise on a way that I can contribute further.

[opusforlife2]

Do you know how to capture a log?

[aand18]

@opusforlife2 I'll try to reproduce and have a log

[aand18]

Do you know how to capture a log?

@opusforlife2 No idea :D

I thought there was an option in the menu, somewhere, but I guess not.

[opusforlife2]

Do you have root?

[aand18]

@opusforlife2 no root.

I've reinstalled v20 yesterday and it was impossible to listen to anything of long duration in the background. I'd be really surprised if it wasn't a widespread issue.

[opusforlife2]

https://www.xda-developers.com/guide-sending-a-logcat-to-help-debug-your-favorite-app/

[Medard22]

I have encountered this issue several times as well. Mostly on my tablet - Teclast T30, stock Android 9.

[UserX404]

@aand18
Same here
Sonx Xperia XZ2c, Android 10

[opusforlife2]

I tried logging via logcat, but there seems to be no logs from newpipe

Wat in tarnation!?

[wb9688]

@ventilaar: Does your phone have some battery saving thingy? If so, could you try turning that off?

[floral-qua-floral]

Getting a very similar problem. If I have more than one video in my background queue, Newpipe will immediately stop loading audio for the background player. It will keep playing anything that's in the cache, but as soon as it runs out it will start buffering and never resume playback. This doesn't seem to be 100% consistent, but I'm having a really hard time identifying what specific set of circumstances cause it to occur or not occur.

Playback won't recover even if I remove all items from the queue except 1. The only way to get the background player going again is to completely empty the queue and then add a singular item back to it.

I can try to obtain a log myself as well, if it'd be useful.

[opusforlife2]

I can try to obtain a log myself as well, if it'd be useful.

Please do. We really need to pin this down.

[Idiotten]

Also have this issue. A majority of the time it stops at 1:04 time, but I've had it in the 2 minutes area before as well. Hopefully I did the log thing correctly. It happened at 9:37.

logcat.txt

I think the 'exact' log where it broke is: "10-16 09:37:59.988"

It shows as a red error and then after that error are a bunch of messages saying "Newpipe tried to update with no new data"

[Stypox]

I tried to extract some infromation from that logcat, here is what I have found.

Up until 09:37:27 there was no activity for more than 30s, so I guess that data before that is pretty much useless. Then some notification updates can be seen:

10-16 09:37:31.171 I/[-5]oneconnect[1.7.51.42_01][MDE](11012): MediaSessionImpl.onPlaybackStateChanged - [org.schabi.newpipe] got state -> PlaybackState {state=3, position=36, buffered position=64644, speed=1.0, updated=211404410, actions=2364287, custom actions=[], active item id=1, error=null}
10-16 09:37:31.171 I/[-5]oneconnect[1.7.51.42_01][MDE](11012): MediaSessionMonitor.onMediaSessionChanged - org.schabi.newpipe Session is changed to Playing. checking audio state.
10-16 09:37:31.172 V/AvrcpMediaPlayerWrapper( 2001): onPlaybackStateChanged(): org.schabi.newpipe : PlaybackState {state=3, position=36, buffered position=64644, speed=1.0, updated=211404410, actions=2364287, custom actions=[], active item id=1, error=null}
10-16 09:37:31.174 D/FaceWidgetMusicController_LOCK( 2015): saveCurrentDataToDB() instantly, pkg = org.schabi.newpipe, title = Two Neighbors - Back Then, artist = Nightblue Music[-2]
10-16 09:37:31.184 D/ApplicationPolicy( 1342): isStatusBarNotificationAllowedAsUser: packageName = org.schabi.newpipe,userId = 0
10-16 09:37:31.186 V/AvrcpMediaPlayerWrapper( 2001): sendMediaUpdate(): Metadata has been updated for org.schabi.newpipe
10-16 09:37:31.197 I/[-5]oneconnect[1.7.51.42_01][MDE](11012): MediaSessionImpl.onPlaybackStateChanged - [org.schabi.newpipe] got state -> PlaybackState {state=3, position=66, buffered position=64644, speed=1.0, updated=211404437, actions=2364287, custom actions=[], active item id=1, error=null}
10-16 09:37:31.197 I/[-5]oneconnect[1.7.51.42_01][MDE](11012): MediaSessionMonitor.onMediaSessionChanged - org.schabi.newpipe Session is changed to Playing. checking audio state.
10-16 09:37:31.200 V/AvrcpMediaPlayerWrapper( 2001): onQueueChanged(): org.schabi.newpipe
10-16 09:37:31.202 V/AvrcpMediaPlayerWrapper( 2001): onPlaybackStateChanged(): org.schabi.newpipe : PlaybackState {state=3, position=66, buffered position=64644, speed=1.0, updated=211404437, actions=2364287, custom actions=[], active item id=1, error=null}
10-16 09:37:31.212 D/ApplicationPolicy( 1342): isStatusBarNotificationAllowedAsUser: packageName = org.schabi.newpipe,userId = 0
10-16 09:37:31.289 D/EdgeLightingManager( 1342): showForNotification : isInteractive=true, isHeadUp=false, color=0, sbn = StatusBarNotification(pkg=org.schabi.newpipe user=UserHandle{0} id=123789 tag=null key=0|org.schabi.newpipe|123789|null|10503: Notification(channel=newpipe pri=1 contentView=null vibrate=null sound=null tick defaults=0x0 flags=0x62 color=0xff616161 category=transport actions=5 vis=PUBLIC semFlags=0x0 semPriority=0 semMissedCount=0))
10-16 09:37:31.305 D/Friday_SysNotificationListener( 4817): onNotificationPosted()::sbn.getPackageName() = org.schabi.newpipe
10-16 09:37:31.305 D/Friday_SysNotificationListener( 4817): This Notification is On-Going, let's skip it [ org.schabi.newpipe]
10-16 09:37:31.310 D/Launcher.NotificationListener( 2263): onNotificationPosted : org.schabi.newpipe number : 0 listener : null
10-16 09:37:31.310 D/Launcher.NotificationListener( 2263): shouldBeFilteredOut : org.schabi.newpipe missingTitleAndText : false isGroupHeader : false
10-16 09:37:31.317 D/EdgeLightingManager( 1342): showForNotification : isInteractive=true, isHeadUp=false, color=0, sbn = StatusBarNotification(pkg=org.schabi.newpipe user=UserHandle{0} id=123789 tag=null key=0|org.schabi.newpipe|123789|null|10503: Notification(channel=newpipe pri=1 contentView=null vibrate=null sound=null tick defaults=0x0 flags=0x62 color=0xff616161 category=transport actions=5 vis=PUBLIC semFlags=0x0 semPriority=0 semMissedCount=0))
10-16 09:37:32.204 I/[-5]oneconnect[1.7.51.42_01][MDE](11012): MediaSessionMonitor.audioOutputState - org.schabi.newpipe is active controller.
10-16 09:37:32.204 I/[-5]oneconnect[1.7.51.42_01][MDE](11012): MediaSessionMonitor.onMediaSessionChanged - Audio is working. org.schabi.newpipe Session is changed to Playing.

Then the app goes to foreground (why wasn't it already foreground before?!?)

10-16 09:37:32.204 I/[-5]oneconnect[1.7.51.42_01][MDE](11012): MediaPlayerMonitor.onSessionPlaybackStateChanged - org.schabi.newpipe is not active session.
10-16 09:37:32.560 I/Pageboost( 1342): moveTaskToFront : org.schabi.newpipe
10-16 09:37:32.607 D/PkgPredictorService( 1342): org.schabi.newpipe go to foreground!
10-16 09:37:32.608 I/PerfSDKService( 1342): Current foregroundpackage name : org.schabi.newpipe
10-16 09:37:32.633 D/GameManagerService( 1342): handleForegroundChange(). pkgName: org.schabi.newpipe, clsName: org.schabi.newpipe.MainActivity,FgActivityName:org.schabi.newpipe/.MainActivity,userID:0
10-16 09:37:32.633 D/GameManagerService( 1342):   handleForegroundChange(). set mFgApp: org.schabi.newpipe
10-16 09:37:32.633 D/GameManagerService( 1342): notifyResumePause(). pkg: org.schabi.newpipe, type: 4, isMinimized: false, isTunableApp: false

Then everything seems to still be fine, since playback and notification updates are sent.

10-16 09:37:32.807 W/WifiTransportLayerUtils( 1342): getApplicationCategory - IOException org.schabi.newpipe
10-16 09:37:32.825 V/AvrcpMediaPlayerWrapper( 2001): onQueueChanged(): org.schabi.newpipe
10-16 09:37:32.826 W/AvrcpMediaPlayerWrapper( 2001): onQueueChanged(): org.schabi.newpipe tried to update with no new data
10-16 09:37:32.827 I/[-5]oneconnect[1.7.51.42_01][MDE](11012): MediaSessionImpl.onPlaybackStateChanged - [org.schabi.newpipe] got state -> PlaybackState {state=3, position=1689, buffered position=64644, speed=1.0, updated=211406065, actions=2364287, custom actions=[], active item id=1, error=null}
10-16 09:37:32.827 I/[-5]oneconnect[1.7.51.42_01][MDE](11012): MediaSessionMonitor.onMediaSessionChanged - org.schabi.newpipe Session is changed to Playing. checking audio state.
10-16 09:37:32.828 V/AvrcpMediaPlayerWrapper( 2001): onPlaybackStateChanged(): org.schabi.newpipe : PlaybackState {state=3, position=1689, buffered position=64644, speed=1.0, updated=211406065, actions=2364287, custom actions=[], active item id=1, error=null}
10-16 09:37:32.830 V/AvrcpMediaPlayerWrapper( 2001): sendMediaUpdate(): Metadata has been updated for org.schabi.newpipe
10-16 09:37:32.926 D/EdgeLightingManager( 1342): showForNotification : isInteractive=true, isHeadUp=false, color=0, sbn = StatusBarNotification(pkg=org.schabi.newpipe user=UserHandle{0} id=123789 tag=null key=0|org.schabi.newpipe|123789|null|10503: Notification(channel=newpipe pri=1 contentView=null vibrate=null sound=null tick defaults=0x0 flags=0x62 color=0xff616161 category=transport actions=5 vis=PUBLIC semFlags=0x0 semPriority=0 semMissedCount=0))
10-16 09:37:32.939 D/Friday_SysNotificationListener( 4817): onNotificationPosted()::sbn.getPackageName() = org.schabi.newpipe
10-16 09:37:32.939 D/Friday_SysNotificationListener( 4817): This Notification is On-Going, let's skip it [ org.schabi.newpipe]
10-16 09:37:32.940 D/MdnieScenarioControlService( 1342):  packageName : org.schabi.newpipe    className : org.schabi.newpipe.MainActivity
10-16 09:37:32.945 D/Launcher.NotificationListener( 2263): onNotificationPosted : org.schabi.newpipe number : 0 listener : null
10-16 09:37:32.945 D/Launcher.NotificationListener( 2263): shouldBeFilteredOut : org.schabi.newpipe missingTitleAndText : false isGroupHeader : false
10-16 09:37:33.136 D/FaceWidgetMusicController_LOCK( 2015): saveCurrentDataToDB() handler, pkg = org.schabi.newpipe, title = Layto x Neoni - Ghost Town, artist = Nightblue Music[-2]
10-16 09:37:33.300 V/AvrcpMediaPlayerWrapper( 2001): sendMediaUpdate(): Metadata has been updated for org.schabi.newpipe

Then for some reason the MediaSession disconnects from NewPipe and is destroyed, and from then on the playback isn't updated correctly anymore (see PlaybackState {state=0, position=7954, buffered position=7954, speed=0.0, updated=211412333, actions=2364287, custom actions=[], active item id=1, error=null} compared to PlaybackState {state=3, position=1689, buffered position=64644, speed=1.0, updated=211406065, actions=2364287, custom actions=[], active item id=1, error=null} above)

10-16 09:37:33.835 I/[-5]oneconnect[1.7.51.42_01][MDE](11012): MediaSessionMonitor.audioOutputState - org.schabi.newpipe is active controller.
10-16 09:37:33.835 I/[-5]oneconnect[1.7.51.42_01][MDE](11012): MediaSessionMonitor.onMediaSessionChanged - Audio is working. org.schabi.newpipe Session is changed to Playing.
10-16 09:37:33.835 I/[-5]oneconnect[1.7.51.42_01][MDE](11012): MediaPlayerMonitor.onSessionPlaybackStateChanged - org.schabi.newpipe is not active session.
10-16 09:37:39.094 I/[-5]oneconnect[1.7.51.42_01][MDE](11012): MediaSessionImpl.onPlaybackStateChanged - [org.schabi.newpipe] got state -> PlaybackState {state=0, position=7954, buffered position=7954, speed=0.0, updated=211412333, actions=2364287, custom actions=[], active item id=1, error=null}
10-16 09:37:39.094 I/[-5]oneconnect[1.7.51.42_01][MDE](11012): MediaSessionMonitor.onMediaSessionChanged - org.schabi.newpipe Session is changed to None
10-16 09:37:39.095 I/[-5]oneconnect[1.7.51.42_01][MDE](11012): MediaSessionMonitor.removeSession - Session of org.schabi.newpipe is removed.
10-16 09:37:39.095 I/[-5]oneconnect[1.7.51.42_01][MDE](11012): MediaPlayerMonitor.onSessionStopped - org.schabi.newpipe is not active session.
10-16 09:37:39.104 I/MediaFocusControl( 1342): abandonAudioFocus() from uid/pid 10503/13444 clientId=android.media.AudioManager@a5295b4org.schabi.newpipe.player.helper.AudioReactor@76ae10e
10-16 09:37:39.106 D/MediaSessionService( 1342): Destroying org.schabi.newpipe/MediaSessionManager (userId=0)
10-16 09:37:39.106 I/AvrcpMediaPlayerList( 2001): onAddressedPlayerChanged: component=org.schabi.newpipe
10-16 09:37:39.106 W/AvrcpMediaPlayerList( 2001): org.schabi.newpipe is already the active player
10-16 09:37:39.106 D/FaceWidgetMusicController_LOCK( 2015): onSessionDestroyed() sessionPackage = org.schabi.newpipe, mLastPackageName = org.schabi.newpipe
10-16 09:37:39.107 I/FaceWidgetMusicController_LOCK( 2015): loadLastInformation() [org.schabi.newpipe, org.schabi.newpipe, Layto x Neoni - Ghost Town, Nightblue Music]
10-16 09:37:39.107 W/AvrcpMediaPlayerWrapper( 2001): The session was destroyed org.schabi.newpipe
10-16 09:37:39.108 D/FaceWidgetMusicController_LOCK( 2015): isNoMusic returns false / false org.schabi.newpipe NewPipe
10-16 09:37:39.110 D/FaceWidgetPlaybackStateMonitor_LOCK( 2015): updateController: , current controller =  Package: org.schabi.newpipe Flags: 3 State: PlaybackState {state=0, position=0, buffered position=0, speed=0.0, updated=211412345, actions=0, custom actions=[], active item id=-1, error=null} Metadata: null, null, null ButtonReceiver: PendingIntent{f29b965: android.os.BinderProxy@5831ac5}
10-16 09:37:39.111 D/FaceWidgetMusicController_LOCK( 2015): onSessionDestroyed() sessionPackage = org.schabi.newpipe, mLastPackageName = org.schabi.newpipe
10-16 09:37:39.112 I/FaceWidgetMusicController_LOCK( 2015): loadLastInformation() [org.schabi.newpipe, org.schabi.newpipe, Layto x Neoni - Ghost Town, Nightblue Music]
10-16 09:37:39.112 D/FaceWidgetMusicController_LOCK( 2015): isNoMusic returns true / true null NewPipe

Then the media session is recreated and reattached to NewPipe, but playback updates are still not sent correctly by NewPipe.

10-16 09:37:39.115 D/MediaSessionService( 1342): Media button session is changed to org.schabi.newpipe/MediaSessionManager (userId=0)
10-16 09:37:39.115 D/MediaSessionService( 1342): Created session for org.schabi.newpipe with tag MediaSessionManager
10-16 09:37:39.119 I/AvrcpMediaPlayerList( 2001): onAddressedPlayerChanged: token=org.schabi.newpipe
10-16 09:37:39.119 W/AvrcpMediaPlayerList( 2001): org.schabi.newpipe is already the active player
10-16 09:37:39.120 D/FaceWidgetMusicController_LOCK( 2015): isNoMusic returns true / true null NewPipe
10-16 09:37:39.120 D/FaceWidgetMusicController_LOCK( 2015): onSessionEnabled() enabled = true, mEnabled = true, lastSession = org.schabi.newpipe, activeSession = null
10-16 09:37:39.126 I/SurfaceFlinger(  870):      DEVICE | 0x7882e7d4a0 | 0000 | RGBA_8888 |   0.0    0.0 1080.0 2280.0 |    0    0 1080 2280 | org.schabi.newpipe/org.schabi.newpipe.MainActivity$_13444#0
10-16 09:37:39.129 D/ApplicationPolicy( 1342): isStatusBarNotificationAllowedAsUser: packageName = org.schabi.newpipe,userId = 0
10-16 09:37:39.129 D/ApplicationPolicy( 1342): isStatusBarNotificationAllowedAsUser: packageName = org.schabi.newpipe,userId = 0
10-16 09:37:39.132 D/AvrcpMediaPlayerList( 2001): onActiveSessionsChanged: controller: org.schabi.newpipe
10-16 09:37:39.132 I/AvrcpMediaPlayerList( 2001): addMediaPlayer() : org.schabi.newpipe
10-16 09:37:39.133 V/AvrcpMediaPlayerWrapper( 2001): Controller for org.schabi.newpipe was updated. false
10-16 09:37:39.133 D/FaceWidgetPlaybackStateMonitor_LOCK( 2015): onActiveSessionsChanged() controllers: Size: 1 Package: org.schabi.newpipe Flags: 3 State: PlaybackState {state=0, position=0, buffered position=0, speed=0.0, updated=211412360, actions=2363959, custom actions=[], active item id=1, error=null} Metadata: null, null, null ButtonReceiver: PendingIntent{45ee63a: android.os.BinderProxy@5831ac5}
10-16 09:37:39.133 D/FaceWidgetPlaybackStateMonitor_LOCK( 2015): org.schabi.newpipe is same as lastSessionPkgName
10-16 09:37:39.140 V/AvrcpMediaPlayerWrapper( 2001): sendMediaUpdate(): Metadata has been updated for org.schabi.newpipe
10-16 09:37:39.140 D/CacheFactory(13444): initExoPlayerCache: cacheDir = /storage/emulated/0/Android/data/org.schabi.newpipe/cache/exoplayer
10-16 09:37:39.145 I/FaceWidgetPlaybackStateMonitor_LOCK( 2015): onActiveSessionsChanged() catch top session  Package: org.schabi.newpipe Flags: 3 State: PlaybackState {state=0, position=0, buffered position=0, speed=0.0, updated=211412360, actions=2363959, custom actions=[], active item id=1, error=null} Metadata: null, null, null ButtonReceiver: PendingIntent{9fb6848: android.os.BinderProxy@5831ac5}
10-16 09:37:39.145 D/FaceWidgetPlaybackStateMonitor_LOCK( 2015): updateController:  Package: org.schabi.newpipe Flags: 3 State: PlaybackState {state=0, position=0, buffered position=0, speed=0.0, updated=211412360, actions=2363959, custom actions=[], active item id=1, error=null} Metadata: null, null, null ButtonReceiver: PendingIntent{98186e1: android.os.BinderProxy@5831ac5}, current controller = 

After a while PlaybackState {state=0, ... turns to PlaybackState {state=6, ...:

10-16 09:37:39.193 V/AvrcpMediaPlayerWrapper( 2001): onPlaybackStateChanged(): org.schabi.newpipe : PlaybackState {state=6, position=0, buffered position=0, speed=0.0, updated=211412411, actions=2363959, custom actions=[], active item id=0, error=null}

[Stypox]

@Idiotten thank you for collecting a logcat. Unfortunately I could only understand roughly what happened, since there is no debug information from NewPipe itself but only from the system. Could you try installing a debug apk and collect a logcat with that? E.g. the one in #4549

[Idiotten]

@Stypox Assuming you mean just do the same thing with that apk, and I don't have to do anything different within settings of that version or something then:

logcat 22-49.txt
On this one playback stopped at 22:49.

logcat 22-53.txt
This one stopped at 22:53.

If I have to do something in the app to capture the log and the above are just the same as the previous one then lmk.

[Stypox]

Thank you! Did you manually open the app at 22:49:21? I assume you didn't. So what happens is basically that Android resumes NewPipe's MainActivity completely at random in the background. The player receives the ACTION_VIDEO_FRAGMENT_RESUMED intent and after a brief second the ACTION_VIDEO_FRAGMENT_STOPPED intent. Probably during this transition something bad happens inside the player, making it not work anymore. @avently do you have some time to look into this? I am unable to work with Android services, service connections and exoplayer ;-)

[Denofalltrades]

I'm having this problem only since the phone upgraded itself to android 10, and one comment up there made me look at the battery optimization, I think that new pipe is being throttled by the battery manager. In my phone it is placing a buffering newpipe into the notification area. When tapping that it opens to the Trending screen and happily plays anything I tap. Maybe put a timeout on the buffering module to completely flush and close?