踩坑之路:MediaPlayer播放完成偶现onCompletion不执行问题

背景

前段时间再做一个需求

  1. 是一个过渡页面，
  2. 过渡页面播放音频(播放"终回"音频)
  3. 音频播放完毕，跳转到下一个页面

需求其实挺简单的，然后很快就把代码写完了。跑了两遍也都是正常执行，于是二话不说就提测了。后来某天测试提出过渡页面会卡住，不会跳转到下一个页面。如下所示，一直卡在终回页面上面


不会跳转.gif
  1. 于是我第一时间想到就是难道是我忘记设置结束的回调方法了?特意去查看了下代码:
                val voicePlayer = VoicePlayerUnMute()
                voicePlayer.play(mRoundVoiceRes)
                voicePlayer.setOnCompletionListener {
                    LogHelper.i(TAG, "onNextPage tag = $tag")
                    onNextPage()
                }

这里的VoicePlayerUnMute是封装的MediaPlayer，然后播放指定的音频文件，设置了setOnCompletionListener ，代码好像没什么问题，于是跑过去问了下情况，了解到这个是个偶现的bug。

  1. 既然代码上面看上去没啥问题，会不会是MediaPlayer在播放的时候出现了Error，导致onCompletion回调没有执行？于是我又加了一点代码:
                val voicePlayer = VoicePlayerUnMute()
                voicePlayer.play(mRoundVoiceRes)
                voicePlayer.setOnCompletionListener {
                    LogHelper.i(TAG, "onNextPage tag = $tag")
                    onNextPage()
                }
                voicePlayer.setOnErrorListener { _: MediaPlayer, _: Int, _: Int ->
                    LogHelper.i(TAG,"播放出现了错误")
                    false
                }

由于是偶现的问题，所以我多试了几次，确实是会出现几次页面卡住跳转不过去的现象，但是onError里面并没有打印出相应的Log。这下有点懵圈了，没有出现播放错误，那到底是出了什么问题？

  1. 粗略的看了下onCompletion回调的执行，搜索了一下发现有两处:
            case MEDIA_PLAYBACK_COMPLETE:
                {
                    mOnCompletionInternalListener.onCompletion(mMediaPlayer);
                    OnCompletionListener onCompletionListener = mOnCompletionListener;
                    if (onCompletionListener != null)
                        onCompletionListener.onCompletion(mMediaPlayer);
                }
                stayAwake(false);
                return;

            case MEDIA_ERROR:
                Log.e(TAG, "Error (" + msg.arg1 + "," + msg.arg2 + ")");
                boolean error_was_handled = false;
                OnErrorListener onErrorListener = mOnErrorListener;
                if (onErrorListener != null) {
                    error_was_handled = onErrorListener.onError(mMediaPlayer, msg.arg1, msg.arg2);
                }
                {
                    mOnCompletionInternalListener.onCompletion(mMediaPlayer);
                    OnCompletionListener onCompletionListener = mOnCompletionListener;
                    if (onCompletionListener != null && ! error_was_handled) {
                        onCompletionListener.onCompletion(mMediaPlayer);
                    }
                }
                stayAwake(false);
                return;

一处是播放完成的时候回调，一处是播放出现错误的时候出现了回调。这个时候才发现刚才的猜想完全就是错误的。所以现在为止还是没有找到原因所在。

  1. 我又重新操作了几次，发现这几次不跳转的情况中，有播放完的，也有播放到一半停住的。所以是什么地方调用MediaPlayer的stop或者pause了？后来想想又感觉不可能，自己的player对象是个局部变量，用的地方就这么一处，怎么可能会调用这几个方法。这下就更加疑惑了，MediaPlayer内部实现逻辑太复杂，一次性想要吃透太困难了，现在bug又必须得尽早改掉，这事看上去越来越棘手了。
  1. 没办法，只能暂时比对一下正常情况下和异常情况下的MediaPlayer的log吧:
2020-10-20 19:44:26.425 21860-21860/com.youdao.youdaomath D/MediaPlayer: handleMessage msg:(1, 0, 0)
2020-10-20 19:44:26.425 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: getCurrentPosition
2020-10-20 19:44:26.426 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: isPlaying: 0
2020-10-20 19:44:26.429 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: invoke 72
2020-10-20 19:44:26.432 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: isPlaying: 0
2020-10-20 19:44:26.432 21860-21860/com.youdao.youdaomath I/VoicePlayerUnMute2: [VoicePlayerUnMute2] start
2020-10-20 19:44:26.432 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: getDuration_l
2020-10-20 19:44:26.435 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: start
2020-10-20 19:44:26.437 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: MediaPlayer::setVolume(1.000000, 1.000000)
2020-10-20 19:44:26.507 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: message received msg=6, ext1=0, ext2=0
2020-10-20 19:44:26.507 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: unrecognized message: (6, 0, 0)
2020-10-20 19:44:26.508 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: callback application
2020-10-20 19:44:26.508 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: back from callback
2020-10-20 19:44:26.509 21860-21860/com.youdao.youdaomath D/MediaPlayer: handleMessage msg:(6, 0, 0)
2020-10-20 19:44:26.509 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: getCurrentPosition
2020-10-20 19:44:26.510 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: isPlaying: 1
2020-10-20 19:44:26.791 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: message received msg=211, ext1=0, ext2=0
2020-10-20 19:44:26.791 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: unrecognized message: (211, 0, 0)
2020-10-20 19:44:26.791 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: callback application
2020-10-20 19:44:26.791 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: back from callback
2020-10-20 19:44:26.792 21860-21860/com.youdao.youdaomath D/MediaPlayer: handleMessage msg:(211, 0, 0)
2020-10-20 19:44:27.834 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: message received msg=2, ext1=0, ext2=0
2020-10-20 19:44:27.834 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: playback complete
2020-10-20 19:44:27.834 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: callback application
2020-10-20 19:44:27.835 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: back from callback
2020-10-20 19:44:27.835 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: message received msg=211, ext1=0, ext2=0
2020-10-20 19:44:27.835 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: unrecognized message: (211, 0, 0)
2020-10-20 19:44:27.835 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: callback application
2020-10-20 19:44:27.835 21860-21860/com.youdao.youdaomath D/MediaPlayer: handleMessage msg:(2, 0, 0)
2020-10-20 19:44:27.836 21860-22561/com.youdao.youdaomath V/MediaPlayerNative: back from callback

上面这个是正常情况下的log

2020-10-20 19:58:26.416 21860-21860/com.youdao.youdaomath D/MediaPlayer: handleMessage msg:(1, 0, 0)
2020-10-20 19:58:26.416 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: getCurrentPosition
2020-10-20 19:58:26.417 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: isPlaying: 0
2020-10-20 19:58:26.420 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: invoke 72
2020-10-20 19:58:26.424 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: isPlaying: 0
2020-10-20 19:58:26.424 21860-21860/com.youdao.youdaomath I/VoicePlayerUnMute2: [VoicePlayerUnMute2] start
2020-10-20 19:58:26.425 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: getDuration_l
2020-10-20 19:58:26.428 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: start
2020-10-20 19:58:26.431 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: MediaPlayer::setVolume(1.000000, 1.000000)
2020-10-20 19:58:26.488 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: message received msg=6, ext1=0, ext2=0
2020-10-20 19:58:26.488 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: unrecognized message: (6, 0, 0)
2020-10-20 19:58:26.488 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: callback application
2020-10-20 19:58:26.488 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: back from callback
2020-10-20 19:58:26.489 21860-21860/com.youdao.youdaomath D/MediaPlayer: handleMessage msg:(6, 0, 0)
2020-10-20 19:58:26.490 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: getCurrentPosition
2020-10-20 19:58:26.490 21860-21860/com.youdao.youdaomath V/MediaPlayerNative: isPlaying: 1
2020-10-20 19:58:26.763 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: message received msg=211, ext1=0, ext2=0
2020-10-20 19:58:26.763 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: unrecognized message: (211, 0, 0)
2020-10-20 19:58:26.763 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: callback application
2020-10-20 19:58:26.763 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: back from callback
2020-10-20 19:58:26.763 21860-21860/com.youdao.youdaomath D/MediaPlayer: handleMessage msg:(211, 0, 0)
2020-10-20 19:58:27.232 21860-21875/com.youdao.youdaomath D/MediaPlayer: finalize native_finalize called
2020-10-20 19:58:27.232 21860-21875/com.youdao.youdaomath W/MediaPlayer-JNI: MediaPlayer finalized without being released
2020-10-20 19:58:27.232 21860-21875/com.youdao.youdaomath V/MediaPlayerNative: setListener
2020-10-20 19:58:27.232 21860-21875/com.youdao.youdaomath V/MediaPlayerNative: disconnect
2020-10-20 19:58:27.260 21860-21875/com.youdao.youdaomath V/MediaPlayerNative: destructor
2020-10-20 19:58:27.261 21860-21875/com.youdao.youdaomath V/MediaPlayerNative: disconnect
2020-10-20 19:58:27.261 21860-21875/com.youdao.youdaomath D/MediaPlayer: finalize native_finalize finished
2020-10-20 19:58:28.256 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: message received msg=2, ext1=0, ext2=0
2020-10-20 19:58:28.256 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: playback complete
2020-10-20 19:58:28.256 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: callback application
2020-10-20 19:58:28.256 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: back from callback
2020-10-20 19:58:28.257 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: message received msg=211, ext1=0, ext2=0
2020-10-20 19:58:28.257 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: unrecognized message: (211, 0, 0)
2020-10-20 19:58:28.257 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: callback application
2020-10-20 19:58:28.257 21860-21860/com.youdao.youdaomath D/MediaPlayer: handleMessage msg:(2, 0, 0)
2020-10-20 19:58:28.257 21860-21884/com.youdao.youdaomath V/MediaPlayerNative: back from callback
2020-10-20 19:58:28.263 21860-21860/com.youdao.youdaomath D/MediaPlayer: handleMessage msg:(211, 0, 0)

上面这个是异常情况的log

这一看还真看出点名堂来,仔细发现异常情况下多了下面这段log:

2020-10-20 19:58:27.232 21860-21875/com.youdao.youdaomath D/MediaPlayer: finalize native_finalize called
2020-10-20 19:58:27.232 21860-21875/com.youdao.youdaomath W/MediaPlayer-JNI: MediaPlayer finalized without being released
2020-10-20 19:58:27.232 21860-21875/com.youdao.youdaomath V/MediaPlayerNative: setListener
2020-10-20 19:58:27.232 21860-21875/com.youdao.youdaomath V/MediaPlayerNative: disconnect
2020-10-20 19:58:27.260 21860-21875/com.youdao.youdaomath V/MediaPlayerNative: destructor
2020-10-20 19:58:27.261 21860-21875/com.youdao.youdaomath V/MediaPlayerNative: disconnect
2020-10-20 19:58:27.261 21860-21875/com.youdao.youdaomath D/MediaPlayer: finalize native_finalize finished

看样子似乎是被release调了？
根据第二行log：

2020-10-20 19:58:27.232 21860-21875/com.youdao.youdaomath W/MediaPlayer-JNI: MediaPlayer finalized without being released

认定应该是JNI里面打出来的log，MediaPlayer是android.media包下面的类文件，那么JNI名字应该是android_media_MediaPlayer.cpp，于是在源码社区搜索了一下这个文件:


image.png

确实是有相应的文件，那么就打开文件搜索下"MediaPlayer finalized without being released"这个log:

static void
android_media_MediaPlayer_native_finalize(JNIEnv *env, jobject thiz)
{
    ALOGV("native_finalize");
    sp<MediaPlayer> mp = getMediaPlayer(env, thiz);
    if (mp != NULL) {
        ALOGW("MediaPlayer finalized without being released");
    }
    android_media_MediaPlayer_release(env, thiz);
}

以此反推，MediaPlayer.java里面应该是调用了native_finalize方法，继续往下搜索:

private native final void native_finalize();

果然有这么一个方法，在查看下调用的地方:

    @Override
    protected void finalize() {
        baseRelease();
        native_finalize();
    }

finalize方法调用，看到这里，我直接裂开了有没有。finalize方法是虚拟机在GC的时候调用的，具体可以看下这篇Java虚拟机内存管理机制。我的Player对象就直接被GC了么？目前暂时也没有去证明，既然找到了原因，那就改以下代码，直接将player对象设置成类的成员变量：

    /**
     * 播放回合的音频播放器
     */
    private var mRoundVoicePlayer = VoicePlayerUnMute()

                mRoundVoicePlayer.play(mRoundVoiceRes)
                mRoundVoicePlayer.setOnCompletionListener {
                    LogHelper.i(TAG, "onNextPage tag = $tag")
                    onNextPage()
                }

然后再试效果:


修改后.gif

的确应该是改好了(原来试验10次大概会出现3次卡主不动，改完之后就试了十几次都没再出现过了)

真是一个让人胃疼的Bug。。。

©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 206,214评论 6赞 481
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 88,307评论 2赞 382
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 152,543评论 0赞 341
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 55,221评论 1赞 279
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 64,224评论 5赞 371
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 49,007评论 1赞 284
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 38,313评论 3赞 399
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 36,956评论 0赞 259
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 43,441评论 1赞 300
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,925评论 2赞 323
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,018评论 1赞 333
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 33,685评论 4赞 322
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 39,234评论 3赞 307
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,240评论 0赞 19
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,464评论 1赞 261
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 45,467评论 2赞 352
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 42,762评论 2赞 345