Audio focus not consistently gained/dropped properly

mchowning commented 1 year ago

Description

When the Freeletics app does a workout countdown while Pocket Casts is playing audio, Pocket Casts is inconsistent in giving up audio focus before resuming after the countdown.

Sometimes playback stops for the countdown and resumes after it is done
Sometimes playback continues through the countdown
Sometimes playback continues through the countdown but the Pocket Casts playback scrubber stops updating to reflect that playback is continuing.

Step-by-step reproduction instructions

I tried to reproduce this in a toy app I made for playing different kinds of sounds with different types of focus requests and I wasn't able to find any way to recreate the issue. Even with the Freeletics app the issue does not seem to occur consistently.

Steps:

Download the Freeletics app
While Pocket Casts is playing, begin a workout in the Freeletics app so that there is an audible countdown from 5. I wasn't able to find a way to do this without a Freeletics subscription, so I signed up for a free trial.
Observe that Pocket Casts sometimes stops playing, and sometimes the visual scrubber in the app stops updating.

Screenshots or screen recording

This video shows the different behaviors happening without any interaction with the phone. The screen is split with Pocket Casts on the top and Freeletics on the bottom.

The 3 and 25-second marks are examples of playback stopping as expected
The 15-second mark is an example of playback continuing (and the UI scrubber continuing to update)
The 35-second mark is an example of playback continuing but the UI scrubber not continuing to update.

https://user-images.githubusercontent.com/4656348/218192485-06c66acc-369c-454a-9f9e-3d6da81decca.mov

Did you search for existing bug reports?

[X] I have searched for existing bug reports.

Device, Operating system, and Pocket Casts app version

Samsung A13, Android 12, Pocket Casts 7.32-rc build.

mchowning commented 1 year ago

I encountered this investigating a user was complaint of playback skipping back with the Freeletics app. May be an unrelated issue, but seemed worth mentioning:

Every time Freeletics launches the 5 second countdown, this PocketCast app returns to playback minutes before where it stopped. I tried to turn off Intelligent Playback and use an Unrestricted Battery setting. Nothing prevents this.

I have a Google pixel 7 with the newest Android version.

mchowning commented 1 year ago

Ran across a user report of Freeletics causing Apple music app to lag "like crazy" on Android when the voice coach did the countdown. That seems a big different from what I'm noticing here, but it might be related and might point toward the issue being with the Freeletics app and not with Pocket Casts.

mchowning commented 1 year ago

Digging into some logs, it looks like we're getting a focus gain call just after losing focus in the scenario where playback continues and the scrubber freezes:

17:01:35.592 dispatching onAudioFocusChange(-3) to android.media.AudioManager@ccf2b6fau.com.shiftyjelly.pocketcasts.repositories.playback.FocusManager@a4b807c
17:01:35.593 Playback: Focus lost. AUDIOFOCUS_LOSS: false AUDIOFOCUS_LOSS_TRANSIENT: false AUDIOFOCUS_LOSS_TRANSIENT_CAN_DUCK: true
17:01:35.598 focus lost, mayDuck: false, transientLoss: true, player: au.com.shiftyjelly.pocketcasts.repositories.playback.SimplePlayer@7b15747
17:01:35.598 Playback: Focus lost while playing
17:01:35.600 focusWasPlaying set to Fri Feb 10 17:01:35 EST 2023
17:01:35.608 dispatching onAudioFocusChange(1) to android.media.AudioManager@ccf2b6fau.com.shiftyjelly.pocketcasts.repositories.playback.FocusManager@a4b807c
17:01:35.608 Playback: Focus gained, should resume true. Device removed: false
17:01:35.611 focus gained, shouldResume: true, player: au.com.shiftyjelly.pocketcasts.repositories.playback.SimplePlayer@7b15747
17:01:35.611 Playback: Focus gained, resuming playback
17:01:35.613 focusWasPlaying set to null
17:01:35.662 Playback: Trying to gain audio focus
17:01:35.663 Playback: We already had audio focus
17:01:40.488 dispatching onAudioFocusChange(1) to android.media.AudioManager@ccf2b6fau.com.shiftyjelly.pocketcasts.repositories.playback.FocusManager@a4b807c

We've had bugs before with race conditions between play and pause/stop events happening when the OS sent multiple focus events. Feels like that might be what's happening here, but that's just speculation at this point.

mchowning commented 1 year ago

Did some more digging on this. Noticed that Castbox also has the issue where the audio doesn't respect the focus loss some fo the time with the Freeletics app (although Castbox normally ducks the audio whereas PC normally pauses the playback during normal usage, so the behavior is a bit different).

After some more digging, I found that the problem occurs when another app, like Freeletics, requests focus and then immediately releases focus. I updated my test app, so it now has a button you can press to do exactly that, and it pretty reliably recreates the issue.

I say "pretty reliably" because it appears that this issue is caused by a race condition that occurs because after we receive the focus change events, we use coroutines to switch threads multiple times and this causes the ordering of the two events to become lost. In the case of the UI not updating, the problem is that the focus lost event eventually stops the UI update timer and this frequently ends up happening after the focus gain event starts the timer (even though the focus gain event occurs after the focus loss event). I have some notes about how the events cause calls on different threads in this Google sheet.

We've had issues with this kind of race condition before (I fixed an Android Auto issue that could result in multiple overlapping audio streams a few months ago), so I'd like to find a more robust solution to address the underlying problem instead of band-aiding over this specific issue (particularly since this specific issue isn't that bad). I'm not entirely sure the best way to do this, so I'm going to stop working on this for a bit and think about it.

At a high level, I'm thinking that we may need to try to reorganize some of the logic in the PlaybackManager, FocusManager, and Player classes, so that they do all the work they can on a specific dispatcher (that enforces sequential handling by being limited to one thread or, probably even better, using a mutex).

The problem is that these classes have some of the most fragile code in the app (and there are soo many edge cases), and they're not covered by many tests, so I'm thinking that the first step is probably to do some safe refactorings to extract out some logic from these classes and get that logic tested, so that then I can start making larger changes with some test protection. That's just my thinking at this point though, like I said earlier, I want to give this some more thought before I start making changes.

mchowning commented 1 year ago

I've got some work in progress on this on the fix/async-focus-events branch. My plan is to finish that and get a PR up when I get some available time.

Automattic / pocket-casts-android