Playing video scope preview followed by playing video from mediaplayer-app causes media-hub to crash

Bug #1598885 reported by Jim Hodapp on 2016-07-04
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Canonical System Image
High
Unassigned
media-hub (Ubuntu)
High
Unassigned
media-hub (Ubuntu RTM)
High
Unassigned

Bug Description

media-hub crashes, steps to reproduce:

1. Preview a video from the newer video scope (inline video playback in the scope)
2. Before the preview video finishes, from the scope, press play to play the same video in mediaplayer-app
3. Let the video play for a couple of seconds in mediaplayer-app
4. Press the 'X' to close mediaplayer-app and go back to the scope
5. Press '<' to navigate away from this video in the video scope
6. Observe that media-hub crashes

Jim Hodapp (jhodapp) on 2016-07-04
summary: - Playing video scope preview followed by from mediaplayer-app causes
- media-hub to crash
+ Playing video scope preview followed by playing video from mediaplayer-
+ app causes media-hub to crash
Dave Morley (davmor2) wrote :

Confirming this can be triggered but only occasionally doesn't happen all the time.

Changed in media-hub (Ubuntu):
status: New → Confirmed
Changed in media-hub (Ubuntu RTM):
status: New → Confirmed
Jim Hodapp (jhodapp) wrote :

This happens every time for me on turbo on this image:

phablet@ubuntu-phablet:~$ system-image-cli -i
current build number: 117
device name: turbo
channel: ubuntu-touch/rc-proposed/ubuntu
last update: 2016-07-04 08:50:53
version version: 117
version ubuntu: 20160702
version device: 20160617-82a5c0d
version custom: 20160702

Jim Hodapp (jhodapp) on 2016-07-04
Changed in canonical-devices-system-image:
assignee: nobody → John McAleely (john.mcaleely)
status: New → Triaged
importance: Undecided → High
Changed in media-hub (Ubuntu):
importance: Undecided → High
Changed in media-hub (Ubuntu RTM):
importance: Undecided → High
Víctor R. Ruiz (vrruiz) wrote :

Just saw this. I thought it wasn't a known problem. Good to know it's already reported :)

Víctor R. Ruiz (vrruiz) wrote :
Víctor R. Ruiz (vrruiz) wrote :

It happens to me every time in turbo.

current build number: 130
device name: turbo
channel: ubuntu-touch/rc-proposed/meizu-pd.en

Jim Hodapp (jhodapp) wrote :

Yeah same for me on turbo. It's less pronounced on other devices, meaning it's a timing issue.

Lorn Potter (lorn-potter) wrote :

Happens on my turbo (rc-proposed #169) but not on my nexus 4 (rc-proposed #519)

Both have same version of media-hub (Version: 4.6.0+15.04.20160823-0ubuntu1)

Comparing both media-hub logs, on turbo it never gets to:

[TT 2016-09-01 01:42:19.191777] [player_implementation.cpp:230@clear_wakelock]

Jim Hodapp (jhodapp) wrote :

@Lorn: have you been able to get your own backtrace of the crash? It's not happening for me in the latest build for krillin (rc-proposed #420). So it's possible that this is a video driver-specific issue on turbo.

Lorn Potter (lorn-potter) wrote :

Sorry, it is turbo that goes to clear_wakelock and then crashes

Lorn Potter (lorn-potter) wrote :
Download full text (4.9 KiB)

This is what I can get:

[TT 2016-09-02 00:59:54.136978] [player_implementation.cpp:230@clear_wakelock]
[II 2016-09-02 00:59:54.137228] [player_implementation.cpp:249@clear_wakelock] Clearing display wakelock.
[DD 2016-09-02 00:59:56.535177] [ubuntu.cpp:111@Context] apparmor profile name: unconfined
[DD 2016-09-02 00:59:56.535388] [ubuntu.cpp:112@Context] is_unconfined(): true
[DD 2016-09-02 00:59:56.535526] [ubuntu.cpp:113@Context] has_package_name(): false
[DD 2016-09-02 00:59:56.535764] [service_skeleton.cpp:301@operator()] -- Destroying app_name='unconfined', info='unconfined', ':1.191'
[II 2016-09-02 00:59:56.535928] [playbin.cpp:186@reset] Client died, resetting pipeline
[TT 2016-09-02 00:59:56.536049] [playbin.cpp:201@reset_pipeline]
PulseAudio event for sink with index 0 received.
[II 2016-09-02 00:59:56.539585] [engine.cpp:73@on_playbin_state_changed] State changed on playbin: PAUSED
[II 2016-09-02 00:59:56.539776] [player_implementation.cpp:193@operator()] Emiting playback_status_changed signal: PlaybackStatus::paused
[II 2016-09-02 00:59:56.576683] [pulse_audio_output_observer.cpp:323@on_query_for_primary_sink_finished] Checking if port is available -> 0
PulseAudio sink details for sink.primary with index 0 is available:
  Output to wired headphone: false
  Output to wired headset: false
[II 2016-09-02 00:59:56.606302] [engine.cpp:73@on_playbin_state_changed] State changed on playbin: READY
[II 2016-09-02 00:59:56.606943] [player_implementation.cpp:193@operator()] Emiting playback_status_changed signal: PlaybackStatus::ready
[TT 2016-09-02 00:59:56.608157] [player_implementation.cpp:230@clear_wakelock]
[II 2016-09-02 00:59:56.608436] [player_implementation.cpp:249@clear_wakelock] Clearing display wakelock.
[TT 2016-09-02 00:59:56.608610] [track_list_implementation.cpp:378@reset]
[II 2016-09-02 00:59:56.608748] [player_implementation.cpp:679@operator()] End of tracklist reached, stopping playback
[DD 2016-09-02 00:59:56.608943] [playbin.cpp:560@set_state_and_wait] Requested state change in main thread context.
[TT 2016-09-02 00:59:56.609020] [playbin.cpp:534@set_state_in_main_thread]
[DD 2016-09-02 00:59:56.609130] [player_implementation.cpp:129@operator()] Setting state for parent: 0x61875c
[TT 2016-09-02 00:59:56.610142] [engine.cpp:481@stop]
[II 2016-09-02 00:59:56.610338] [player_implementation.cpp:193@operator()] Emiting playback_status_changed signal: PlaybackStatus::stopped
[II 2016-09-02 00:59:56.610619] [player_implementation.cpp:328@update_mpris_properties] Updating MPRIS TrackList properties:
[II 2016-09-02 00:59:56.610768] [player_implementation.cpp:329@update_mpris_properties] Tracks: 0
[II 2016-09-02 00:59:56.610953] [player_implementation.cpp:330@update_mpris_properties] has_previous: 0
[II 2016-09-02 00:59:56.611208] [player_implementation.cpp:331@update_mpris_properties] has_next: 0
[DD 2016-09-02 00:59:56.611955] [player_implementation.cpp:640@operator()] ==== Resetting current player
[TT 2016-09-02 00:59:56.612122] [service_skeleton.cpp:919@reset_current_player]
[TT 2016-09-02 00:59:56.612276] [service_skeleton.cpp:770@reset_current_player]
[II 2016-09-02 00:59:58.143019] [player_imple...

Read more...

Lorn Potter (lorn-potter) wrote :

I cannot seem to get a debug build, debug symbols installed or any good backtrace

Jim Hodapp (jhodapp) wrote :

@Lorn: Have you installed libc6-dbg?

Lorn Potter (lorn-potter) wrote :

Not much better:

[II 2016-09-04 23:43:23.063275] [player_implementation.cpp:89@operator()] Released display state: DisplayState::on
[DD 2016-09-04 23:43:23.580995] [ubuntu.cpp:111@Context] apparmor profile name: unity8-dash
[DD 2016-09-04 23:43:23.581189] [ubuntu.cpp:112@Context] is_unconfined(): false
[DD 2016-09-04 23:43:23.581321] [ubuntu.cpp:113@Context] has_package_name(): true
[DD 2016-09-04 23:43:23.581470] [service_skeleton.cpp:301@operator()] -- Destroying app_name='unity8-dash', info='unity8-dash', ':1.416'
[II 2016-09-04 23:43:23.581630] [playbin.cpp:186@reset] Client died, resetting pipeline
[TT 2016-09-04 23:43:23.581740] [playbin.cpp:201@reset_pipeline]
[New Thread 0xe5447360 (LWP 17405)]
[New Thread 0xdb822360 (LWP 17638)]
[New Thread 0xd50aa360 (LWP 17625)]
[New Thread 0xdf6ca360 (LWP 17457)]
[New Thread 0xdfefc360 (LWP 17442)]
[New Thread 0xe2f15360 (LWP 17423)]
[New Thread 0xe4c47360 (LWP 17406)]
[New Thread 0xe5cf8360 (LWP 17322)]
[New Thread 0xed6fc360 (LWP 16501)]
[New Thread 0xedefc360 (LWP 16500)]
[New Thread 0xf30fd360 (LWP 16498)]
[New Thread 0xf3ac0360 (LWP 16497)]

Program received signal SIGABRT, Aborted.
[Switching to Thread 0xe5447360 (LWP 17405)]
__libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:47
47 ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S: No such file or directory.
(gdb) bt
#0 __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:47
#1 0xf693162e in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:55
#2 0xf6932332 in __GI_abort () at abort.c:89
#3 0xf4699930 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) bt full
#0 __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:47
No locals.
#1 0xf693162e in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:55
        _a1 = 0
        _a3tmp = 6
        _a1tmp = 0
        _a3 = 6
        _nametmp = 268
        _a2tmp = 17405
        _a2 = 17405
        _name = 268
        _sys_result = <optimized out>
        pd = 0xe5447360
        pid = 0
        selftid = 17405
#2 0xf6932332 in __GI_abort () at abort.c:89
        save_stage = 2
        act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {3846465476, 2, 4, 4, 3846465476, 4137270779, 4100559909, 4100559877,
              4100579404, 139, 0, 4100560477, 0, 7, 8, 3846465468, 1, 4092696661, 7, 3846465564, 139, 29189, 3, 4099495415, 0, 68, 0, 4099482529, 3846465564, 0,
              3846465564, 4092696661}}, sa_flags = -448500672, sa_restorer = 0x0}
        sigs = {__val = {32, 0 <repeats 31 times>}}
#3 0xf4699930 in ?? ()
No symbol table info available.
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Lorn Potter (lorn-potter) wrote :

Program received signal SIGABRT, Aborted.
[Switching to Thread 0xe4b1e360 (LWP 30451)]
__libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:47
47 ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S: No such file or directory.
(gdb) info thread
  Id Target Id Frame
  20 Thread 0xf3ac0360 (LWP 29577) "Binder_1" 0xf46d9ee0 in ?? ()
  19 Thread 0xf30fd360 (LWP 29578) "Binder_2" 0xf46d9ee0 in ?? ()
  18 Thread 0xedefc360 (LWP 29580) "threaded-ml" 0xf699a4e0 in poll () at ../sysdeps/unix/syscall-template.S:81
  17 Thread 0xed4fd360 (LWP 29581) "media-hub-serve" 0xf699a4e0 in poll () at ../sysdeps/unix/syscall-template.S:81
  16 Thread 0xe539c360 (LWP 30368) "ALooper" __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  15 Thread 0xe431e360 (LWP 30452) "CodecLooper" 0xf46b23f8 in ?? ()
  14 Thread 0xe22cb360 (LWP 30455) "amcvideodec-omx" syscall () at ../sysdeps/unix/sysv/linux/arm/syscall.S:37
  13 Thread 0xdf1ed360 (LWP 30460) "vqueue:src" syscall () at ../sysdeps/unix/sysv/linux/arm/syscall.S:37
  12 Thread 0xde9a6360 (LWP 30461) "aqueue:src" syscall () at ../sysdeps/unix/sysv/linux/arm/syscall.S:37
  11 Thread 0xd4bfd360 (LWP 30532) "pool" syscall () at ../sysdeps/unix/sysv/linux/arm/syscall.S:37
  10 Thread 0xdb304360 (LWP 30542) "media-hub-serve" 0xf6c8851e in nanosleep () at ../sysdeps/unix/syscall-template.S:81
  9 Thread 0xdbb04360 (LWP 30543) "Binder_3" 0xf46d9ee0 in ?? ()
* 8 Thread 0xe4b1e360 (LWP 30451) "CodecLooper" __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:47
  7 Thread 0xe66fd360 (LWP 30366) "multiqueue0:src" syscall () at ../sysdeps/unix/sysv/linux/arm/syscall.S:37
  6 Thread 0xe5cfd360 (LWP 30367) "multiqueue0:src" syscall () at ../sysdeps/unix/sysv/linux/arm/syscall.S:37
  5 Thread 0xe7096360 (LWP 30365) "qtdemux0:sink" syscall () at ../sysdeps/unix/sysv/linux/arm/syscall.S:37
  4 Thread 0xe78fc360 (LWP 30359) "typefind:sink" syscall () at ../sysdeps/unix/sysv/linux/arm/syscall.S:37
  3 Thread 0xf26fd360 (LWP 29579) "media-hub-serve" __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  2 Thread 0xecafd360 (LWP 29582) "media-hub-serve" 0xf69a1132 in epoll_wait () at ../sysdeps/unix/syscall-template.S:81
  1 Thread 0xf484b000 (LWP 29560) "media-hub-serve" 0xf699a4e0 in poll () at ../sysdeps/unix/syscall-template.S:81

Jim Hodapp (jhodapp) wrote :

@Lorn: take a look at these instructions to get further debug symbols across hybris. From the looks of the backtrace, it looks like it's crashing on the Android side.

Changed in media-hub (Ubuntu):
assignee: nobody → Lorn Potter (lorn-potter)
Changed in media-hub (Ubuntu RTM):
assignee: nobody → Lorn Potter (lorn-potter)
Changed in media-hub (Ubuntu):
status: Confirmed → In Progress
Changed in media-hub (Ubuntu RTM):
status: Confirmed → In Progress
Changed in canonical-devices-system-image:
status: Triaged → In Progress
Lorn Potter (lorn-potter) wrote :

Finally got something a tiny bit more descriptive.

47 ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S: No such file or directory.
(gdb) bt full
#0 __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:47
No locals.
#1 0xf693162e in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:55
        _a1 = 0
        _a3tmp = 6
        _a1tmp = 0
        _a3 = 6
        _nametmp = 268
        _a2tmp = 10919
        _a2 = 10919
        _name = 268
        _sys_result = <optimized out>
        pd = 0xe4b4f360
        pid = 0
        selftid = 10919
#2 0xf6932332 in __GI_abort () at abort.c:89
        save_stage = 2
        act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {3837061060, 2, 4, 4, 3837061060, 4137270779, 4100559909, 4100559877, 4100579404, 139, 0,
              4100560477, 0, 7, 8, 3837061052, 1, 4092696661, 7, 3837061148, 139, 29189, 3, 4099495415, 0, 68, 0, 4099482529, 3837061148, 0, 3837061148, 4092696661}},
          sa_flags = -457905088, sa_restorer = 0x0}
        sigs = {__val = {32, 0 <repeats 31 times>}}
#3 0xf4699930 in __android_log_assert (cond=<optimized out>, tag=0xe4b4f360 "\001", fmt=0xf3f19acb "%s") at system/core/liblog/logd_write_kern.c:288
        buf = "frameworks/av/media/libstagefright/ACodec.cpp:5041 CHECK_EQ( mCodec->mOMX->freeNode(mCodec->mNode),(status_t)OK) failed: -2147483648 vs. 0\000\000\002", '\000' <repeats 19 times>, ":\000\000\000\000\000\000\000n\000\000\000\000p\237\366\001\000\000\000\000p\237\366\001\000\000\000\000\243:\000\020\000\200\343\000\000\000\000"...
#4 0xf3e87f08 in ?? ()
No symbol table info available.
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Lorn Potter (lorn-potter) wrote :
Download full text (4.3 KiB)

Loaded more android symbols:

(gdb) bt full
#0 __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:47
No locals.
#1 0xf693162e in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:55
        _a1 = 0
        _a3tmp = 6
        _a1tmp = 0
        _a3 = 6
        _nametmp = 268
        _a2tmp = 15930
        _a2 = 15930
        _name = 268
        _sys_result = <optimized out>
        pd = 0xe4b4f360
        pid = 0
        selftid = 15930
#2 0xf6932332 in __GI_abort () at abort.c:89
        save_stage = 2
        act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {3837061060, 2, 4, 4, 3837061060, 4137270779,
              4100559909, 4100559877, 4100579404, 139, 0, 4100560477, 0, 7, 8, 3837061052, 1, 4092696661, 7, 3837061148, 139, 29189, 3, 4099495415,
              0, 68, 0, 4099482529, 3837061148, 0, 3837061148, 4092696661}}, sa_flags = -457905088, sa_restorer = 0x0}
        sigs = {__val = {32, 0 <repeats 31 times>}}
#3 0xf4699930 in __android_log_assert (cond=<optimized out>, tag=0xe4b4f360 "\001", fmt=0xf3f19acb "%s")
    at system/core/liblog/logd_write_kern.c:288
        buf = "frameworks/av/media/libstagefright/ACodec.cpp:5041 CHECK_EQ( mCodec->mOMX->freeNode(mCodec->mNode),(status_t)OK) failed: -2147483648 vs. 0\000\000\002", '\000' <repeats 19 times>, ":\000\000\000\000\000\000\000n\000\000\000\000p\237\366\001\000\000\000\000p\237\366\001\000\000\000\000\243:\000\020\000\200\343\000\000\000\000"...
#4 0xf3e87f08 in android::ACodec::LoadedState::onShutdown (this=0xe5d209c0, keepComponentAllocated=keepComponentAllocated@entry=false)
    at frameworks/av/media/libstagefright/ACodec.cpp:5041
        _(float, long __restrict, long) = {static kEmptyString = 0x0,
          mData = 0xe381e320 "frameworks/av/media/libstagefright/ACodec.cpp:5041 CHECK_EQ( mCodec->mOMX->freeNode(mCodec->mNode),(status_t)OK) failed: -2147483648 vs. 0", mSize = 138, mAllocSize = 160}
        _(long double,...)(short) = {static kEmptyString = 0x0, mData = 0xe38052e0 "-2147483648 vs. 0", mSize = 17, mAllocSize = 32}
#5 0xf3e8c55e in android::ACodec::LoadedState::onMessageReceived (this=<optimized out>, msg=...)
    at frameworks/av/media/libstagefright/ACodec.cpp:5086
        keepComponentAllocated = 0
        handled = false
#6 0xf410273e in android::AHierarchicalStateMachine::handleMessage (this=0x1, msg=...)
    at frameworks/av/media/libstagefright/foundation/AHierarchicalStateMachine.cpp:58
        save = {m_ptr = 0xe5d209c0}
        cur = {m_ptr = 0xe5d209c0}
#7 0xf3e839e8 in android::ACodec::onMessageReceived (this=<optimized out>, msg=...) at frameworks/av/include/media/stagefright/ACodec.h:59
No locals.
#8 0xf41034c4 in android::ALooperRoster::deliverMessage (this=0xf410d02c, msg=...)
    at frameworks/av/media/libstagefright/foundation/ALooperRoster.cpp:138
        handler = {m_ptr = 0xe5d20868}
#9 0xf4102e48 in android::ALooper::loop (this=<optimized out>) at frameworks/av/media/libstagefright/foundation/ALooper.cpp:213
        event = {mWhenUs = 110223249075, mMessage = {m_ptr = 0xe3a14000}}
#10 0xf46324d6 in android::Thread::_threadLoop (user=0xe5d45438) at system/...

Read more...

Jim Hodapp (jhodapp) wrote :

@Lorn: Have you been able to enable the debug messages in ACodec.cpp by uncommenting N_DEBUG (or something close to that) at the top of the .cpp file? I'd also recommend adding some of your own ALOGD messages and such around the area to start debugging why this crash is happening. Comparing a good start of playback via the mediaplayer-app from the scope vs the one that crashes is what I'd suggest looking at next.

Lorn Potter (lorn-potter) wrote :

Here is the procedure without playing in media player (just preview and then back out of the video scope - no crash)
https://pastebin.canonical.com/165831
android logcat:
https://pastebin.canonical.com/165833

I also got some more debug output from android side during the crash:
android logcat:
https://pastebin.canonical.com/165828/

Lorn Potter (lorn-potter) wrote :

that should be:
https://pastebin.canonical.com/165832/
 for the second link in comment #20

Jim Hodapp (jhodapp) wrote :

Line #56 of the logcat output from comment #21 is definitely key. So it's the cleanup of the MediaCodecDelegate that is having an issue. So now to figure out the root cause of why this case is different when previewing and then watching in mediaplayer-app, and why only on Turbo.

Jim Hodapp (jhodapp) wrote :

Another thing to consider is why is watching a video in the scope followed by the mediaplayer-app different than watching a video in the mediaplayer-app two times in a row? That might also be something to figure out what the difference is.

Lorn Potter (lorn-potter) wrote :

commented out frameworks/av/media/libstagefright/ACodec.cpp:5041, which is:

  CHECK_EQ(mCodec->mOMX->freeNode(mCodec->mNode), (status_t)OK);

and it did not crash.

Jim Hodapp (jhodapp) wrote :

Yeah, I'd start debugging the freeNode() function to see what it expects and exactly why it's not coming back with a status of OK.

Lorn Potter (lorn-potter) wrote :

logcat output when running mediaplayer-app only, without the preview scope:

https://pastebin.canonical.com/166479/

Changed in media-hub (Ubuntu):
assignee: Lorn Potter (lorn-potter) → nobody
Changed in media-hub (Ubuntu RTM):
assignee: Lorn Potter (lorn-potter) → nobody
Changed in canonical-devices-system-image:
assignee: John McAleely (john.mcaleely) → nobody
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers