Raciness in client handle termination leading to hang in Python main thread

[ssokolow]

I'm not in a position to be certain whether this is a python-mpv issue or a libmpv issue, but I thought it'd be better to have you close it than for you to never know.

This code cases the program to just sit there, doing nothing, while commenting out the af argument makes it work:

#!/usr/bin/env python3

import mpv
player = mpv.MPV(af="lavfi=[acompressor]")

player.play("/srv/fservroot/Videos/LGR Plays - Goat Simulator-j4HY_fxwiZo.mp4")
player.wait_for_playback()

The argument has been copy-pasted, verbatim except for the minor af="..." syntax change, from my .mpv/config where it works without issue.

[jaseg]

I tested this exact script on an up-to-date debian sid against python-mpv v0.3.3 and libmpv 0.26.0-3 and it worked without any problems. I'd first try getting an up-to-date ffmpeg/libmpv. If that doesn't help try the following for extended logging and have a close look at the output:

def my_log(loglevel, component, message):
    print('[{}] {}: {}'.format(loglevel, component, message))

player = mpv.MPV(log_handler=my_log, loglevel='debug', af='lavfi=[acompressor]')

If that still doesn't help raise an issue against upstream. Even if wait_for_playback would deadlock for some reason, that thread is not doing anything important and libmpv should still continue playing the file in the background.

Here's what I'm running:

mpv 0.26.0 (C) 2000-2017 mpv/MPlayer/mplayer2 projects
 built on UNKNOWN
ffmpeg library versions:
   libavutil       55.58.100
   libavcodec      57.89.100
   libavformat     57.71.100
   libswscale      4.6.100
   libavfilter     6.82.100
   libswresample   2.7.100
ffmpeg version: 3.3.3-3

[ssokolow]

Bah. The PPA I'm using to get libmpv on *buntu 14.04 LTS doesn't have acompressor and, for reasons unknown to me, providing a log_handler causes it to exit rather than hanging.

(Just log_handler=my_log and def my_log(a, b, c): pass is enough to fix the hang, so I'm guessing that something is blocking on a write which will never complete in the default configuration.)

Do you want to rename this to "Failure to initialize audio filter chain causes hang without a log_handler set" or should I open a new issue?

[jaseg]

Could you tell me your libmpv version and post a script causing the hang?

[ssokolow]

The snippet in the initial post is enough to cause the hang and I'm using the libmpv1 package from this PPA on Kubuntu Trusty. The package metadata claims that it's libmpv 0.22.0.

NOTE: The packager forgot to ensure the bare .so symlink that python-mpv looks for, so I had to add it manually:

sudo ln -s /usr/lib/x86_64-linux-gnu/libmpv.so.1 /usr/lib/x86_64-linux-gnu/libmpv.so

[jaseg]

Ok, I still can't reproduce this. The pure presence of a log_handler should not make a difference but you could try setting loglevel='terminal-default' without setting a log_handler. The loglevel is the only change visible to libmpv a log_handler other than None causes (see here).

This really sounds like a problem with libmpv. libmpv is changing quite rapidly (>1k commits since v0.22.0) so probably I can't reproduce your problem on v0.26.0 since it has already been solved. If you can work around this issue I think its not worth your time investigating it further since it's very likely already fixed in the current libmpv release. If you do wish to trace this further, get your hands on some debug symbols for your libmpv build and then get a close look at where it hangs using gdb (see this comment for some guidance).

[ssokolow]

You're probably right but, since I was curious, here's the state of things when it's hung:

(gdb) info threads
  Id   Target Id         Frame 
  2    Thread 0x7fffde0cd700 (LWP 25485) "mpv/mpv core" pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
* 1    Thread 0x7ffff7fae740 (LWP 25479) "python3" 0x00007ffff7bc565b in pthread_join (threadid=140736918771456, thread_return=thread_return@entry=0x0) at pthread_join.c:92

Thread 0x7ffff7fae740 (LWP 25088) "python3"

#0  0x00007ffff7bc565b in pthread_join (threadid=140736918771456, thread_return=thread_return@entry=0x0) at pthread_join.c:92
        _tid = 25095
        _buffer = {__routine = 0x7ffff7bc5590 <cleanup>, __arg = 0x7fffde0cdd28, __canceltype = 12720080, __prev = 0x0}
        oldtype = 0
        pd = 0x7fffde0cd700
        self = 0x7ffff7fae740
        result = 0
#1  0x00007ffff4f9a433 in mpv_terminate_destroy (ctx=0xc223a0) at ../player/client.c:479
        __PRETTY_FUNCTION__ = "mpv_terminate_destroy"
        playthread = 140736918771456
#2  0x00007ffff5d47adc in ffi_call_unix64 () from /usr/lib/x86_64-linux-gnu/libffi.so.6
No symbol table info available.
#3  0x00007ffff5d4740c in ffi_call () from /usr/lib/x86_64-linux-gnu/libffi.so.6
No symbol table info available.
#4  0x00007ffff5f5912d in _ctypes_callproc () from /usr/lib/python3.4/lib-dynload/_ctypes.cpython-34m-x86_64-linux-gnu.so
No symbol table info available.
#5  0x00007ffff5f596a3 in ?? () from /usr/lib/python3.4/lib-dynload/_ctypes.cpython-34m-x86_64-linux-gnu.so
No symbol table info available.
#6  0x000000000048a487 in PyEval_EvalFrameEx ()
No symbol table info available.
[...a bunch of stuff without symbols that you probably don't care about...]

Thread 0x7fffde0cd700 (LWP 25095) "mpv/mpv core"

#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
No locals.
#1  0x00007ffff4f85404 in mp_dispatch_queue_process (queue=0xba7d10, timeout=<optimized out>) at ../misc/dispatch.c:255
        ts = {tv_sec = 1513398851, tv_nsec = 984203239}
        wait = 9223372036854775807
        frame = {prev = 0x0, thread = 140736918771456, locked_thread = 0, locked = false}
        __PRETTY_FUNCTION__ = "mp_dispatch_queue_process"
#2  0x00007ffff4fb3ea2 in mp_wait_events (mpctx=mpctx@entry=0xb26ed0) at ../player/playloop.c:63
No locals.
#3  0x00007ffff4fac747 in shutdown_clients (mpctx=mpctx@entry=0xb26ed0) at ../player/main.c:155
No locals.
#4  mp_destroy (mpctx=mpctx@entry=0xb26ed0) at ../player/main.c:161
No locals.
#5  0x00007ffff4f985f8 in playback_thread (p=0xb26ed0) at ../player/client.c:497
        mpctx = 0xb26ed0
#6  0x00007ffff7bc4184 in start_thread (arg=0x7fffde0cd700) at pthread_create.c:312
        __res = <optimized out>
        pd = 0x7fffde0cd700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140736918771456, -4939069299421943936, 1, 0, 140736918772160, 140736918771456, 4939141173008328576, 4939052254497924992}, mask_was_saved = 0}}, priv = {pad = {
              0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#7  0x00007ffff78f0ffd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
No locals.

[jaseg]

That's really interesting! That points towards some raciness in the cleanup of mpv handles. I will definitely look into that further when I have some time to spare.

[JonasVautherin]

Just for information: I have the exact same behavior (arch linux, mpv 0.30.0 Copyright © 2000-2019 mpv/MPlayer/mplayer2).

Not a big issue in my case, but I followed this thread, tried the proposed workarounds, and nothing changed, so I thought I might as well mention it :blush:.