Sometimes MediaPlayer prepareAsyc() doesn't call onPrepared() until POWER pressed

Question

I've been trying to reproduce what my QA team calls the "Random Pausing Bug" for some time. Today, I reproduced it three times while debugging with logcat on. It appears intermittently and only in poor network.

The user experiences audio pause, until they go touch their phone (press the power or trackball) and it immediately starts playing again. This is because I call start in the onPrepared callback, and start is never called in these cases. This is our most severe bug.

What I Know:

1) This happens intermittently on the Nexus One with 2.2.1 (not sure if it's on other devices)

2) I call prepareAsyc() from a PlaybackService while the device screen is off. Sometimes, onPrepared() is never called, so my subsequent mediaplayer.start() call is never fired. I can see with network sniffers and the buffering callback that buffering is happening.

3) If I touch the devices power or trackball to wake it up, onPrepared() is immediately called (already buffered) and my callback starts playback.

Here are logs with time stamps showing the issue three times:

FIRST EXAMPLE (no callback for 20s until I hit power button):

11-10 16:10:55.966 I/AwesomePlayer(   59): calling prefetcher->prepare()
11-10 16:11:15.511 D/KeyguardViewMediator(   94): wakeWhenReadyLocked(26)
11-10 16:11:15.511 D/KeyguardViewMediator(   94): handleWakeWhenReady(26)
11-10 16:11:15.511 D/KeyguardViewMediator(   94): pokeWakelock(5000)
11-10 16:11:15.511 I/power   (   94): *** set_screen_state 1
11-10 16:11:15.561 D/SurfaceFlinger(   94): Screen about to return, flinger = 0x1fe300
11-10 16:11:15.701 D/AK8973  (   64): Compass Start
11-10 16:11:15.701 D/WifiService(   94): ACTION_SCREEN_ON
11-10 16:11:15.711 I/Prefetcher(   59): [0x602d80] cache below low water mark, filling cache.
11-10 16:11:15.821 I/AwesomePlayer(   59): prefetcher is done preparing
11-10 16:11:15.831 W/MogMediaPlayer.onPreparedListener( 2968): onPrepared, calling notifyPrepared()

TWO MORE EXAMPLES (the first time 3s before I hit power, the next was 8s):

11-10 16:14:54.649 I/AwesomePlayer(   59): calling prefetcher->prepare()
11-10 16:14:57.500 D/KeyguardViewMediator(   94): wakeWhenReadyLocked(26)
11-10 16:14:57.500 D/KeyguardViewMediator(   94): handleWakeWhenReady(26)
11-10 16:14:57.500 D/KeyguardViewMediator(   94): pokeWakelock(5000)
11-10 16:14:57.500 I/power   (   94): *** set_screen_state 1
11-10 16:14:57.560 D/SurfaceFlinger(   94): Screen about to return, flinger = 0x1fe300
11-10 16:14:57.580 D/WifiStateTracker(   94): Reset connections and stopping DHCP
11-10 16:14:57.580 D/WifiService(   94): ACTION_SCREEN_ON
11-10 16:14:57.670 I/Prefetcher(   59): [0xa990] cache below low water mark, filling cache.
11-10 16:14:57.700 D/AK8973  (   64): Compass Start
11-10 16:14:57.800 I/AwesomePlayer(   59): prefetcher is done preparing
11-10 16:14:57.800 W/MogMediaPlayer.onPreparedListener( 2968): onPrepared, calling notifyPrepared()



11-10 16:39:03.608 I/AwesomePlayer(   59): calling prefetcher->prepare()
11-10 16:39:11.506 D/KeyguardViewMediator(   94): wakeWhenReadyLocked(26)
11-10 16:39:11.506 D/KeyguardViewMediator(   94): handleWakeWhenReady(26)
11-10 16:39:11.506 D/KeyguardViewMediator(   94): pokeWakelock(5000)
11-10 16:39:11.506 I/power   (   94): *** set_screen_state 1
11-10 16:39:11.566 D/SurfaceFlinger(   94): Screen about to return, flinger = 0x1fe300
11-10 16:39:11.586 D/WifiStateTracker(   94): Reset connections and stopping DHCP
11-10 16:39:11.586 D/WifiService(   94): ACTION_SCREEN_ON
11-10 16:39:11.716 D/AK8973  (   64): Compass Start
11-10 16:39:11.766 I/Prefetcher(   59): [0x59ac18] cache below low water mark, filling cache.
11-10 16:39:11.856 I/AwesomePlayer(   59): prefetcher is done preparing
11-10 16:39:11.946 W/MogMediaPlayer.onPreparedListener( 2968): onPrepared, calling notifyPrepared()

Does anyone know anything about this bug or how to work around it?

Thanks in advance, Ben

Answer 1

I am experiencing something very similar on Android 2.3.3, 2.3.7 and 4.1.2. For me, after working just fine for some time, MediaPlayer randomly refuses to load. The difference is that for me the power button doesn't help either - nothing does, onPrepared is simply never called. I'm playing files from the SD-card and not the network, so buffering is not a problem. It happens more when files are loaded frequently, but in general the bug happens easily often enough to affect all my users.

Your issue seems to be related to mine, but sadly I don't have an answer for you either. I'm posting this here to amass more information on the problem. I tried using setDataSource, prepare, prepareAsync as well as the MediaPlayer.create() method which starts loading the specified file immediately. I tried reusing the same mediaplyer (using mp.reset()) as well as creating a brand new one for each new file to be loaded (I stop and call release() on the previous player beforehand), but nothing makes a difference: if the user starts switching through files faster (but nothing excessive - I would expect any media app to handle this), close to 1 out of every 5 files fails to indicate failure, or load.