1090919 - Audio is lost when mediaserver restarts (AudioPolicyService death callback problem?).

Status: RESOLVED FIXED

(Firefox OS Graveyard :: General, defect)

Description

[Peter Mörck]

Attachment: flame_mediaserver_kill_fail_restart.txt

If the mediaserver is manually killed (or dies) it will automatically restart.
When it dies, binder death callbacks are made to b2g and b2g/plugin-container for AudioFlinger and AudioPolicyService.

However, it seems that the callback for AudioPolicyService to b2g sometimes doesn’t occur until b2g is trying to register a new callback when the mediaserver is starting up.
This seems to happen about 1-2 seconds after the mediaserver was killed.
Enabling more debugprints in AudioSystem shows this call with PID of the new mediaserver making AudioFlinger: registerClient() call to the b2g PID.
Right after that, the AudioPolicyService server dies and audio is lost in the phone.

Log example:
12-31 20:01:47.049  1763  1763 V AudioFlinger: registerClient() client 0xb7c51da0, pid 211
12-31 20:01:47.049   211  1272 W AudioSystem: AudioPolicyService server died!
1763 is the new mediaserver. 211 is b2g.

This isn’t 100% reproducible. Sometimes we’ve reproduced it every time we’ve tried. Other times we’ve had to kill the mediaserver 20-30 times before it happens.
Once it does happen, killing the mediaserver again brings everything back up and audio is working again.

We have noticed that when it does work, the callback prints for both AudioFlinger and AudioPolicyService seem to arrive at the same time, right efter the mediaserver was killed.
Also, we experimented by adding a 2 second delay before executing NS_DispatchToMainThread() in BinderDeadCallback() in AudioManager.cpp, which seems to avoid the problem.
This indicates there seems to be some race condition when trying to restart, but just adding a wait there is not a nice solution.

There have been previous problems with this in Android and patches have been provided by Google. Please see:
https://android.googlesource.com/platform/frameworks/av/+/4629161%5E!/
https://android.googlesource.com/platform/frameworks/base/+/ca35e4823459189dd57ec5472caf3a617d03b568%5E!/#F0

However these patches seem to fix problems with JNI, but this looks like a similar issue concerning b2g.
I will attach a log taken from a Flame device running 2.0.0.0-prerelease.
Could you please see if this can be fixed?

Comment 1

[[:fabrice] Fabrice Desré]

Can you check if that happens also on 2.1?

Comment 2

[Daniel Bonnevier]

Attachment: 2.1.0.0-prerelease

Comment 3

[Peter Mörck]

We added a new log using 2.1.0.0-prelease (platform version 34.0a2).
When trying engineering build and killing mediaserver, there was a delay of about 10 seconds or so and then the screen went blank and I think b2g restarted. It took a long time but audio playback was resumed (or possibly song restarted).
When using production build and killing mediaserver, audio was lost (this is what is in the attached 2.1.0.0-prerelease log).
Sometimes got some b2g crash preceeded by the message:
GeckoDump: XXX FIXME : Got a mozContentEvent: inputmethod-update-layouts
Occasionally killing mediaserver would work instantly and resume audio with only a small delay, and sometimes audio was lost.
Sometimes we lost adb connection and the device wouldn't show up in "adb devices".
So it's a bit erratic behavior, but the problem seems to exist in 2.1 as well.

Comment 4

[Daniel Bonnevier]

Attachment: Fix-audio-problem-when-mediaserver-is-restarted.patch

Comment 5

[Michael Wu [:mwu]]

Comment on attachment 8518901 [details] [diff] [review]
Fix-audio-problem-when-mediaserver-is-restarted.patch

Review of attachment 8518901 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks for the patch!

Just one thing - can you limit the number of retries? If something horrible happens, it would be a bit better to keep going rather than get stuck in an infinite loop.

Comment 6

[Daniel Bonnevier]

Attachment: Fix-audio-problem-when-mediaserver-is-restarted.patch

New patch.

Comment 7

[Michael Wu [:mwu]]

Comment on attachment 8519903 [details] [diff] [review]
Fix-audio-problem-when-mediaserver-is-restarted.patch

Review of attachment 8519903 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/system/gonk/AudioManager.cpp
@@ +62,5 @@
>  #define HEADPHONES_STATUS_CHANGED     "headphones-status-changed"
>  #define MOZ_SETTINGS_CHANGE_ID        "mozsettings-changed"
>  #define AUDIO_CHANNEL_PROCESS_CHANGED "audio-channel-process-changed"
> +#define AUDIO_POLICY_SERVICE_NAME     "media.audio_policy"
> +#define AUDIO_POLICY_SERVICE_MAX_RETRY 100

100 retries means.. 20 seconds, which seems a bit much. Something is probably really broken if we have to wait more than 10 seconds.

Also I don't think there's much value in making this a const at the top of the file when the actual delay isn't. Just inline the max retry value.

@@ +67,3 @@
>  
>  #define MOZ_XLOUD_KEY               "audio.sony.effect.xloud_enabled"
>  #define MOZ_CLEARPHASE_KEY          "audio.sony.effect.clearphase_enabled"

This isn't in our version of this file - can you submit a patch against the upstream version of gecko?

@@ +146,5 @@
>      AudioManager *am = static_cast<AudioManager *>(amService.get());
> +
> +    int attempt = 0;
> +    while (attempt < AUDIO_POLICY_SERVICE_MAX_RETRY &&
> +        defaultServiceManager()->checkService(String16(AUDIO_POLICY_SERVICE_NAME)) == 0) {

nit: I recommend a for loop here with an explicit if statement to check if the audio policy is available. Counting down instead of up may let you simplify the check after the loop when we can't get the audio policy service.

@@ +152,5 @@
> +      usleep(1000 * 200);
> +      attempt++;
> +    }
> +
> +    if (attempt >= AUDIO_POLICY_SERVICE_MAX_RETRY) {

MOZ_ASSERT or MOZ_RELEASE_ASSERT is a bit more idiomatic. I'm not sure that this should crash on release builds, but maybe that'll ensure audio policy service startup issues are fixed.

Comment 8

[Daniel Bonnevier]

Attachment: Fix-audio-problem-when-mediaserver-is-restarted.patch

This patch is based on 2.1.

Comment 9

[Michael Wu [:mwu]]

Comment on attachment 8520634 [details] [diff] [review]
Fix-audio-problem-when-mediaserver-is-restarted.patch

Review of attachment 8520634 [details] [diff] [review]:
-----------------------------------------------------------------

Looks like 2.1 is close enough to m-c for this to apply.

::: dom/system/gonk/AudioManager.cpp
@@ +94,5 @@
>      NS_ENSURE_TRUE(amService, NS_OK);
>      AudioManager *am = static_cast<AudioManager *>(amService.get());
> +
> +    int attempt = 0;
> +    while (attempt < 50) {

A for loop is a bit more idiomatic here.

@@ +95,5 @@
>      AudioManager *am = static_cast<AudioManager *>(amService.get());
> +
> +    int attempt = 0;
> +    while (attempt < 50) {
> +      LOG("AudioPolicyService is dead! attempt=%d", attempt);

This code will say that the AudioPolicyService is dead at least once on startup, even if it isn't.

@@ +97,5 @@
> +    int attempt = 0;
> +    while (attempt < 50) {
> +      LOG("AudioPolicyService is dead! attempt=%d", attempt);
> +      usleep(1000 * 200);
> +      

Trailing whitespace

Comment 10

[Daniel Bonnevier]

Attachment: Fix-audio-problem-when-mediaserver-is-restarted.patch

Comment 11

[Michael Wu [:mwu]]

Comment on attachment 8522235 [details] [diff] [review]
Fix-audio-problem-when-mediaserver-is-restarted.patch

Review of attachment 8522235 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/system/gonk/AudioManager.cpp
@@ +95,5 @@
>      AudioManager *am = static_cast<AudioManager *>(amService.get());
> +
> +    int attempt;
> +    for (attempt = 0; attempt < 50; attempt++) {
> +      usleep(1000 * 200);

This waits for the policy to start even before checking if it's available, which seems inefficient.

Comment 12

[Daniel Bonnevier]

Attachment: Fix-audio-problem-when-mediaserver-is-restarted.patch

Comment 13

[Michael Wu [:mwu]]

Comment on attachment 8522965 [details] [diff] [review]
Fix-audio-problem-when-mediaserver-is-restarted.patch

Looks good, thanks!

Comment 14

[Michael Wu [:mwu]]

https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=8af6cd77f84e

Comment 15

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/48a024873cbc