Running multiple mpv instances

[smallnetbuilder]

I need to run multiple instances of mpv. Each player will have its own property observer that I would like to log to a separate file.

I think I need to do this by putting the player and its decorated property observer in a separate thread. Is the ability to do this built into python-mpv or does it need to be done in the script that calls your interface?

[jaseg]

You can create multiple MPV instances in the same thread. The observers are called from a per-instance event handling thread that is automatically spawned in the background when you construct the instance. Here's an example of running two at the same time:

#!/usr/bin/env python3
import time
import sys

import mpv

player1 = mpv.MPV(log_handler=print, loglevel='debug', vo='x11')
time.sleep(0.2)
player2 = mpv.MPV(log_handler=print, loglevel='debug', vo='x11')

player1.loop = True
player2.loop = True
player1.play('test.webm')
time.sleep(0.2)
player2.play('test.webm')

def make_observer(player_name):
    def observer(_prop_name, prop_val):
        print(f'{player_name}: {prop_val}')
    return observer
player1.observe_property('time-pos', make_observer('player1'))
player2.observe_property('time-pos', make_observer('player2'))

player1.wait_for_playback()

Testing this I got some crashes in the default opengl vo when launching both players at the same time, but I suspect that is an upstream bug specific to my setup.

[smallnetbuilder]

Thanks again. I'll see if I can get this running.

I'm writing a test application to see if new Wi-Fi 7 APs and routers are really better at handling multiple video streams. I need to run 37 player instances playing RTSP streams. The RTSP streamer easily handles the load. But getting a single system capable of running 37 players, even running 3Mbps steams is going to be a challenge.

[jaseg]

Instead of actually playing these streams you could just dump them to disk using mpv, then analyze variables like momentary throughput and packet latency using tcpdump/wireshark.

[smallnetbuilder]

That's good thought. Could I retrieve video stats too like frame and bit rate and A/V sync?

I've got four players launched so far using your suggested code. I'm working through getting both the player log messages and decorated property observer output also written to a log per player.

Your interface and help have been invaluable! Thank you!

[smallnetbuilder]

I'm trying to write a log file per player. Do I need to define a loghandler per player or is there a way I can pass a logfile name to one handler?

Or is it easier to direct all player logging to a single file, with logging tagged with a player ID?

[jaseg]

I'm trying to write a log file per player. Do I need to define a loghandler per player or is there a way I can pass a logfile name to one handler?

Or is it easier to direct all player logging to a single file, with logging tagged with a player ID?

You could e.g. use functools.partial, that sets the given functions first few arguments and returns a new function:

from functools import partial

def log_handler(logfile, level, prefix, text):
    print(level, prefix, text, file=logfile)

some_logfile = open('some.log', 'w+')
player = mpv.MPV(log_handler=partial(log_handler, some_logfile), loglevel='debug')

[jaseg]

That's good thought. Could I retrieve video stats too like frame and bit rate and A/V sync?

Bitrate should definitely be possible with wireshark's statistics. Does A/V sync depend on the network? I thought you'd transport some container format over RTSP and that would have a fixed A/V sync? If audio and video are separate RTSP streams you might be able to measure that if there are some frame numbers/timestamps in the packet that wireshark can understand.

[smallnetbuilder]

Thanks for both replies. Both are helpful suggestions.

[smallnetbuilder]

Having a problem implementing the partial log_handler. Here's the code

def logtofile(logfile, level, prefix, text):
    # print to terminal
    print(f'{logfile} {datetime.datetime.now():%Y-%m-%d %H:%M:%S} \033[38;5;246m{level:>8} \033[38;5;{col(prefix)}m{prefix}:\033[0m {text}')
    # print to logfile
    print(f'{logfile}{datetime.datetime.now():%Y-%m-%d %H:%M:%S} [{level}] {prefix}: {text}', file=logfile)

# Create players and logfiles
for n in range(numplayers):
    print('>>> Creating player %s logfile' % n)
    logfilename = 'player_'+str(n)+'_vidtest.log'
    logfile = open(logfilename, 'w+')
    atexit.register(logfile.close)
    logfilelist.append(logfile)

    print('>>> Creating player %s' % n)
    playerInstance = mpv.MPV(log_handler=partial(logtofile,logfile), loglevel='warn')
    playerInstance.window_scale = 0.25
    vidplayerlist.append(playerInstance)

    print('>>> Starting player %s' % n)
    playerInstance.play(streamtoplay)
    time.sleep(2)

When I run it, mpv errors all are sent to player_0_vidtest.log. The io.TextIOWrapper name is the same for all the players, i.e. 'player_0vidtest.log'

What did I do wrong?

>>> Creating player 0 logfile
>>> Creating player 0
>>> Starting player 0
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 12:20:11    error ffmpeg/video: h264: co located POCs unavailable
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 12:20:11    error ffmpeg/video: h264: co located POCs unavailable
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 12:20:11    error ffmpeg/video: h264: co located POCs unavailable
>>> Creating player 1 logfile
>>> Creating player 1
>>> Starting player 1
>>> Creating player 2 logfile
>>> Creating player 2
>>> Starting player 2
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 12:20:15    error ffmpeg/video: h264: co located POCs unavailable
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 12:20:15    error ffmpeg/video: h264: co located POCs unavailable
>>> Creating player 3 logfile
>>> Creating player 3
>>> Starting player 3
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 12:20:17    error ffmpeg/video: h264: co located POCs unavailable
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 12:20:17    error ffmpeg/video: h264: co located POCs unavailable
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 12:20:17    error ffmpeg/video: h264: co located POCs unavailable
>>> Creating player 4 logfile
>>> Creating player 4
>>> Starting player 4
>>> Creating player 5 logfile
>>> Creating player 5
>>> Starting player 5
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 12:20:21    error ffmpeg/video: h264: co located POCs unavailable
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 12:20:21    error ffmpeg/video: h264: co located POCs unavailable
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 12:20:21    error ffmpeg/video: h264: co located POCs unavailable
>>> Creating player 6 logfile
>>> Creating player 6
>>> Starting player 6
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 12:20:23    error ffmpeg/video: h264: co located POCs unavailable
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 12:20:23    error ffmpeg/video: h264: co located POCs unavailable
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 12:20:23    error ffmpeg/video: h264: co located POCs unavailable
>>> Creating player 7 logfile
>>> Creating player 7
>>> Starting player 7

>>> Log file list: [<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'>, <_io.TextIOWrapper name='player_1_vidtest.log' mode='w+' encoding='UTF-8'>, <_io.TextIOWrapper name='player_2_vidtest.log' mode='w+' encoding='UTF-8'>, <_io.TextIOWrapper name='player_3_vidtest.log' mode='w+' encoding='UTF-8'>, <_io.TextIOWrapper name='player_4_vidtest.log' mode='w+' encoding='UTF-8'>, <_io.TextIOWrapper name='player_5_vidtest.log' mode='w+' encoding='UTF-8'>, <_io.TextIOWrapper name='player_6_vidtest.log' mode='w+' encoding='UTF-8'>, <_io.TextIOWrapper name='player_7_vidtest.log' mode='w+' encoding='UTF-8'>]

>>> Playerlist: [<mpv.MPV object at 0x7fa673dfac50>, <mpv.MPV object at 0x7fa673e080f0>, <mpv.MPV object at 0x7fa673e084a8>, <mpv.MPV object at 0x7fa673e08860>, <mpv.MPV object at 0x7fa673e08c18>, <mpv.MPV object at 0x7fa673e08fd0>, <mpv.MPV object at 0x7fa673e123c8>, <mpv.MPV object at 0x7fa673e12780>]

[jaseg]

What did I do wrong?

The code you posted is fine! I added the missing parts and got the script below. The output is as expected. I'm guessing you maybe have a global somewhere that's shadowing something? Are you testing this as a script or in an interactive interpreter? If you're testing this in ipython or similar make sure you're actually running the code you posted by restarting the session.

#!/usr/bin/env python3
import mpv
import atexit
import time
import datetime
import functools

nice_cols = [49, 118, 27, 196, 208, 206, 229, 87]
@functools.lru_cache(maxsize=None)
def col(seed):
    global nice_cols
    rv, *nice_cols = nice_cols
    nice_cols = [*nice_cols, rv]
    return rv

def logtofile(logfile, level, prefix, text):
    # print to terminal
    print(f'{logfile} {datetime.datetime.now():%Y-%m-%d %H:%M:%S} \033[38;5;246m{level:>8} \033[38;5;{col(prefix)}m{prefix}:\033[0m {text}')
    # print to logfile
    print(f'{logfile}{datetime.datetime.now():%Y-%m-%d %H:%M:%S} [{level}] {prefix}: {text}', file=logfile)

# Create players and logfiles
logfilelist = []
vidplayerlist = []
for n in range(5):
    print('>>> Creating player %s logfile' % n)
    logfilename = '/tmp/player_'+str(n)+'_vidtest.log'
    logfile = open(logfilename, 'w+')
    atexit.register(logfile.close)
    logfilelist.append(logfile)

    print('>>> Creating player %s' % n)
    playerInstance = mpv.MPV(log_handler=functools.partial(logtofile,logfile), loglevel='warn')
    playerInstance.window_scale = 0.25
    vidplayerlist.append(playerInstance)

    print('>>> Starting player %s' % n)
    playerInstance.play('test.webm')
    time.sleep(2)

Output:

dev-pypi~/python-mpv <3 python3 demo6.py                                                                                                                                                                                              master
>>> Creating player 0 logfile
>>> Creating player 0
>>> Starting player 0
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 18:45:20    error file: Cannot open file 'test.webm': No such file or directory
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 18:45:20    error stream: Failed to open test.webm.
>>> Creating player 1 logfile
>>> Creating player 1
>>> Starting player 1
<_io.TextIOWrapper name='/tmp/player_1_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 18:45:22    error file: Cannot open file 'test.webm': No such file or directory
<_io.TextIOWrapper name='/tmp/player_1_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 18:45:22    error stream: Failed to open test.webm.
>>> Creating player 2 logfile
>>> Creating player 2
>>> Starting player 2
<_io.TextIOWrapper name='/tmp/player_2_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 18:45:24    error file: Cannot open file 'test.webm': No such file or directory
<_io.TextIOWrapper name='/tmp/player_2_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 18:45:24    error stream: Failed to open test.webm.
^CTraceback (most recent call last):
  File "demo6.py", line 40, in <module>
    time.sleep(2)
KeyboardInterrupt
dev-pypi~/python-mpv <3 cat /tmp/player_0_vidtest.log                                                                                                                                                                             (1) master
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>2020-07-21 18:45:20 [error] file: Cannot open file 'test.webm': No such file or directory
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>2020-07-21 18:45:20 [error] stream: Failed to open test.webm.
dev-pypi~/python-mpv <3 cat /tmp/player_1_vidtest.log                                                                                                                                                                                 master
<_io.TextIOWrapper name='/tmp/player_1_vidtest.log' mode='w+' encoding='UTF-8'>2020-07-21 18:45:22 [error] file: Cannot open file 'test.webm': No such file or directory
<_io.TextIOWrapper name='/tmp/player_1_vidtest.log' mode='w+' encoding='UTF-8'>2020-07-21 18:45:22 [error] stream: Failed to open test.webm.

[smallnetbuilder]

I'm testing as a script.

I think I found a problem. When running the script, my streaming source failed. Note the difference in io.TextIOWrapper names for errors from ffmpeg/demuxer and the other sources.

python3 videotestmulti.py
>>> Creating player 0 testlogfile
>>> testlogfilename: player_0_vidtest.log
>>> testlogfile: <_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'>
>>> Creating player 0
>>> Starting player 0
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 15:05:08    error ffmpeg/demuxer: rtsp: method DESCRIBE failed: 404 Not Found
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 15:05:08    error lavf: avformat_open_input() failed
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 15:05:08    error cplayer: Failed to recognize file format.
>>> Creating player 1 testlogfile
>>> testlogfilename: player_1_vidtest.log
>>> testlogfile: <_io.TextIOWrapper name='player_1_vidtest.log' mode='w+' encoding='UTF-8'>
>>> Creating player 1
>>> Starting player 1
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 15:05:10    error ffmpeg/demuxer: rtsp: method DESCRIBE failed: 404 Not Found
<_io.TextIOWrapper name='player_1_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 15:05:10    error lavf: avformat_open_input() failed
<_io.TextIOWrapper name='player_1_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 15:05:10    error cplayer: Failed to recognize file format.
>>> Creating player 2 testlogfile
>>> testlogfilename: player_2_vidtest.log
>>> testlogfile: <_io.TextIOWrapper name='player_2_vidtest.log' mode='w+' encoding='UTF-8'>
>>> Creating player 2
>>> Starting player 2
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 15:05:12    error ffmpeg/demuxer: rtsp: method DESCRIBE failed: 404 Not Found
<_io.TextIOWrapper name='player_2_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 15:05:12    error lavf: avformat_open_input() failed
<_io.TextIOWrapper name='player_2_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 15:05:12    error cplayer: Failed to recognize file format.
>>> Creating player 3 testlogfile
>>> testlogfilename: player_3_vidtest.log
>>> testlogfile: <_io.TextIOWrapper name='player_3_vidtest.log' mode='w+' encoding='UTF-8'>
>>> Creating player 3
>>> Starting player 3
<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 15:05:14    error ffmpeg/demuxer: rtsp: method DESCRIBE failed: 404 Not Found
<_io.TextIOWrapper name='player_3_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 15:05:14    error lavf: avformat_open_input() failed
<_io.TextIOWrapper name='player_3_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-21 15:05:14    error cplayer: Failed to recognize file format.

>>> Log file list: [<_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'>, <_io.TextIOWrapper name='player_1_vidtest.log' mode='w+' encoding='UTF-8'>, <_io.TextIOWrapper name='player_2_vidtest.log' mode='w+' encoding='UTF-8'>, <_io.TextIOWrapper name='player_3_vidtest.log' mode='w+' encoding='UTF-8'>]

>>> Playerlist: [<mpv.MPV object at 0x7f9a084db0f0>, <mpv.MPV object at 0x7f9a084db668>, <mpv.MPV object at 0x7f9a0850a550>, <mpv.MPV object at 0x7f9a08503b70>

[smallnetbuilder]

Were you able to determine why ffmpeg doesn't use the correct io.TextIOWrapper name?

[jaseg]

No, I tried reproducing it using your code but with the script I put it into everything worked. It must have been something outside of the code you posted above.

[smallnetbuilder]

Could it be ffmpeg version and/or python-mpv version? I'm using 0.4.0 due to issue 116

[jaseg]

That should definitely not cause this kind of behavior.

[smallnetbuilder]

Sorry for the long post.

tldr; I suspect log_handler is not properly handling multiple instances. No matter what I try, ffmpeg errors are always logged to the first log_handler instance.

I took your demo6.py script, ran it on my system and got the same result. File 'test.webm' doesn't exist on my system either.

I then changed playerInstance.play to play a valid rtsp stream and saw the same result as before; ffmpeg errors are written to player_0_vidtest.log.

I then modified the script to print logfile value in the for loop and again in logtofile:

#!/usr/bin/env python3
import mpv
import atexit
import time
import datetime
import functools

nice_cols = [49, 118, 27, 196, 208, 206, 229, 87]
@functools.lru_cache(maxsize=None)
def col(seed):
    global nice_cols
    rv, *nice_cols = nice_cols
    nice_cols = [*nice_cols, rv]
    return rv

def logtofile(logfile, level, prefix, text):
    print('>>> logtofile: logfile= ', (logfile)) #<<ADDED THIS PRINT
    # print to terminal
    print(f'{logfile} {datetime.datetime.now():%Y-%m-%d %H:%M:%S} \033[38;5;246m{level:>8} \033[38;5;{col(prefix)}m{prefix}:\033[0m {text}')
    # print to logfile
    #print(f'{logfile}{datetime.datetime.now():%Y-%m-%d %H:%M:%S} [{level}] {prefix}: {text}', file=logfile)

# Create players and logfiles
logfilelist = []
vidplayerlist = []
for n in range(2):
    print('>>> Creating player %s logfile' % n)
    logfilename = '/tmp/player_'+str(n)+'_vidtest.log'
    logfile = open(logfilename, 'w+')
    print('\n>>> Creating player %s logfile: %s' % (n,logfile)) #<<ADDED THIS PRINT
    atexit.register(logfile.close)
    logfilelist.append(logfile)

    print('>>> Creating player %s' % n)
    playerInstance = mpv.MPV(log_handler=functools.partial(logtofile,logfile), loglevel='warn')
    #playerInstance = mpv.MPV(log_handler=print, loglevel='warn')
    playerInstance.window_scale = 0.25
    vidplayerlist.append(playerInstance)

    print('>>> Starting player %s' % n)
    #playerInstance.play('rtsp://172.16.28.101:8554/testfile')
    playerInstance.play('foo.mp4')
    time.sleep(2)

vidplayerlist[0].wait_for_playback()

When I try to play a nonexistent file, the _io.TextIOWrapper name values match in both print statements.

$ python3 samplecode.py
>>> Creating player 0 logfile

>>> Creating player 0 logfile: <_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>
>>> Creating player 0
>>> Starting player 0
>>> logtofile: logfile=  <_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-23 11:50:41    error file: Cannot open file 'foo.mp4': No such file or directory
>>> logtofile: logfile=  <_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-23 11:50:41    error stream: Failed to open foo.mp4.
>>> Creating player 1 logfile

>>> Creating player 1 logfile: <_io.TextIOWrapper name='/tmp/player_1_vidtest.log' mode='w+' encoding='UTF-8'>
>>> Creating player 1
>>> Starting player 1
>>> logtofile: logfile=  <_io.TextIOWrapper name='/tmp/player_1_vidtest.log' mode='w+' encoding='UTF-8'>
<_io.TextIOWrapper name='/tmp/player_1_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-23 11:50:43    error file: Cannot open file 'foo.mp4': No such file or directory
>>> logtofile: logfile=  <_io.TextIOWrapper name='/tmp/player_1_vidtest.log' mode='w+' encoding='UTF-8'>
<_io.TextIOWrapper name='/tmp/player_1_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-23 11:50:43    error stream: Failed to open foo.mp4.

When I play a valid file, they don't. But all errors come from ffmpeg.

$ python3 samplecode.py
>>> Creating player 0 logfile

>>> Creating player 0 logfile: <_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>
>>> Creating player 0
>>> Starting player 0
>>> Creating player 1 logfile

>>> Creating player 1 logfile: <_io.TextIOWrapper name='/tmp/player_1_vidtest.log' mode='w+' encoding='UTF-8'>
>>> Creating player 1
>>> Starting player 1
>>> logtofile: logfile=  <_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-23 12:03:41    error ffmpeg/video: h264: left block unavailable for requested intra4x4 mode -1
>>> logtofile: logfile=  <_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-23 12:03:41    error ffmpeg/video: h264: error while decoding MB 0 61, bytestream 2745
>>> logtofile: logfile=  <_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-23 12:03:41    error ffmpeg/video: h264: left block unavailable for requested intra4x4 mode -1
>>> logtofile: logfile=  <_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-23 12:03:41    error ffmpeg/video: h264: error while decoding MB 0 61, bytestream 2745
>>> logtofile: logfile=  <_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-23 12:03:53    error ffmpeg/video: h264: left block unavailable for requested intra4x4 mode -1
>>> logtofile: logfile=  <_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-23 12:03:53    error ffmpeg/video: h264: error while decoding MB 0 50, bytestream 9543
>>> logtofile: logfile=  <_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-23 12:03:53    error ffmpeg/video: h264: left block unavailable for requested intra4x4 mode -1
>>> logtofile: logfile=  <_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-23 12:03:53    error ffmpeg/video: h264: error while decoding MB 0 50, bytestream 9543
>>> logtofile: logfile=  <_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-23 12:03:54    error ffmpeg/video: h264: left block unavailable for requested intra4x4 mode -1
>>> logtofile: logfile=  <_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-23 12:03:54    error ffmpeg/video: h264: error while decoding MB 0 62, bytestream 2535
>>> logtofile: logfile=  <_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-23 12:03:54    error ffmpeg/video: h264: left block unavailable for requested intra4x4 mode -1
>>> logtofile: logfile=  <_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-23 12:03:54    error ffmpeg/video: h264: error while decoding MB 0 62, bytestream 2535
>>> logtofile: logfile=  <_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'>
<_io.TextIOWrapper name='/tmp/player_0_vidtest.log' mode='w+' encoding='UTF-8'> 2020-07-23 12:04:02    error ffmpeg/video: h264: error while decoding MB 106 66, bytestream -17

I then changed the script to eliminate functools.partial. I created multiple logtofile functions, changing the print statement to include the function name, i.e.

def logtofile0(level, prefix, text):
    print('>>> logtofile0: logfile= ', (logfile))
    # print to terminal
    print(f'logtofile0: {datetime.datetime.now():%Y-%m-%d %H:%M:%S} \033[38;5;246m{level:>8} \033[38;5;{col(prefix)}m{prefix}:\033[0m {text}')

def logtofile1(level, prefix, text):
    print('>>> logtofile1: logfile= ', (logfile))
    # print to terminal
    print(f'logtofile1:{datetime.datetime.now():%Y-%m-%d %H:%M:%S} \033[38;5;246m{level:>8} \033[38;5;{col(prefix)}m{prefix}:\033[0m {text}')

All errors still go to the first logfile.

$ python3 samplecode.py

>>> Creating player 0 logfile
>>> Opened player 0 logfile: <_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'>
>>> Creating player 0 with logfile <_io.TextIOWrapper name='player_0_vidtest.log' mode='w+' encoding='UTF-8'>
>>> Starting player 0

>>> Creating player 1 logfile
>>> Opened player 1 logfile: <_io.TextIOWrapper name='player_1_vidtest.log' mode='w+' encoding='UTF-8'>
>>> Creating player 1 with logfile <_io.TextIOWrapper name='player_1_vidtest.log' mode='w+' encoding='UTF-8'>
>>> Starting player 1
logtofile0: 2020-07-23 13:05:50    error ffmpeg/video: h264: co located POCs unavailable
logtofile0: 2020-07-23 13:05:51    error ffmpeg/video: h264: co located POCs unavailable
logtofile0: 2020-07-23 13:05:56    error ffmpeg/video: h264: left block unavailable for requested intra mode
logtofile0: 2020-07-23 13:05:56    error ffmpeg/video: h264: error while decoding MB 0 51, bytestream 8033
logtofile0: 2020-07-23 13:05:56    error ffmpeg/video: h264: left block unavailable for requested intra mode
logtofile0: 2020-07-23 13:05:56    error ffmpeg/video: h264: error while decoding MB 0 51, bytestream 8033
logtofile0: 2020-07-23 13:05:57    error ffmpeg/video: h264: left block unavailable for requested intra4x4 mode -1
logtofile0: 2020-07-23 13:05:57    error ffmpeg/video: h264: error while decoding MB 0 57, bytestream 3975
logtofile0: 2020-07-23 13:05:57    error ffmpeg/video: h264: left block unavailable for requested intra4x4 mode -1
logtofile0: 2020-07-23 13:05:57    error ffmpeg/video: h264: error while decoding MB 0 57, bytestream 3975

I know both players are getting errors because I see them when I launch multiple mpv players manually.

[smallnetbuilder]

Since you can't reproduce this, it's probably time to close this bug.

[ghost]

ffmpeg has a global log callback, so the first mpv instance or so gets all ffmpeg log messages. This is a problem that needs to be fixed in ffmpeg itself.

[smallnetbuilder]

Thanks wm4. I thought something like that was happening. But I don't know why jaseg wasn't seeing the same behavior. Maybe this has already been addressed in a newer version of ffmpeg than I'm using?

[jaseg]

@smallnetbuilder I probably was not seeing the issue since I did not get any ffmpeg errors. mpv's regular output gets redirected as intended, after all.

You might be interested in what we're doing in the unit tests to silence libmpv/ffmpeg: We /dev/null C stdin/stdout while creating new stdin/stdout handles for python to use. This does not help you disambiguate where a particular ffmpeg log message comes from, but you could use this to just discard all of them. I am fairly sure any serious error will eventually bubble up into mpv's own output anyway.

[smallnetbuilder]

Thanks for the follow up @jaseg