mpv-player / mpv

🎥 Command line video player
https://mpv.io
Other
26.89k stars 2.84k forks source link

Changes in mpv output log #14133

Closed 422658476 closed 2 months ago

422658476 commented 2 months ago

Previously, the mpv process would automatically output logs to two different pipes, one was Standard Output and the other was error.

Information about [current video playback progress] can be captured in error, such as:

AV: 00:00:15 / 00:40:45 (0%) A-V: 0.000 Cache: 471s/150MB
AV: 00:00:16 / 00:40:45 (0%) A-V: 0.000 Cache: 471s/150MB
AV: 00:00:17 / 00:40:45 (0%) A-V: 0.000 Cache: 471s/150MB

Standard Output can capture [video information], such as:

(+) Video --vid=1 (*) (f) 'video-title' (h264 1280x720 23.976fps)
(+) Audio --aid=1 (*) (f) 'English' (ac3 6ch 48000Hz)
      Audio --aid=2 'chinese' (ac3 3ch 48000Hz)
(+) Subs --sid=1 (*) (f) 'chinese' (ass)
       Subs --sid=2 'English' (ass)

But in the latest mpv (20240512), the information of these two pipes seems to be merged, and all information is output through Standard Output (this also makes the error pipe abandoned, because no information will be captured).

The merging of information will cause serious problems when debugging the player front-end, because the [current video playback progress] information is constantly updated, so [video information] can easily appear at the top of a very long log information, or even The log information will be deleted because it is too long, and it will be difficult for people to see this information (because [video information] does not change very well). When [Video Information] changes, this information will even be mixed with [Current Video Playback Progress], which is also difficult to read, such as

AV: 00:00:15 / 00:40:45 (0%) A-V: 0.000 Cache: 471s/150MB
  (+) Video --vid=1 (*) (f) 'video-title' (h264 1280x720 23.976fps)
AV: 00:00:16/ 00:40:45 (0%) A-V: 0.000 Cache: 471s/150MB
(+) Audio --aid=1 (*) (f) 'English' (ac3 6ch 48000Hz)
AV: 00:00:17 / 00:40:45 (0%) A-V: 0.000 Cache: 471s/150MB
  Audio --aid=2 'chinese' (ac3 3ch 48000Hz)
AV: 00:00:18 / 00:40:45 (0%) A-V: 0.000 Cache: 471s/150MB
  (+) Subs --sid=1 (*) (f) 'chinese' (ass)

My question is:

  1. Is it a bug that the information in the two pipelines is merged, or is it a change in the latest code?

I didn't see the change log in DOCS/client-api-changes.rst. Of course, this change is quite new, so the log may not have been written yet.

  1. Will this change be maintained in the future? I personally feel very bad about this, and it has caused problems for my player front-end.
Dudemanguy commented 2 months ago

The change to collapse all streams to stdout is completely intentional. Regardless of this change, your frontend relying on this seems rather strange. The API has log levels for a reason. Use them.

kasper93 commented 2 months ago

I didn't see the change log in DOCS/client-api-changes.rst.

Console output is not an API. You should not rely on it for any parsing activities. The API exists to access mpv log grouped by log level . Use them.

422658476 commented 2 months ago

Of course, the front end relies on these log information. I must use the changes in these logs to determine whether the current command transmitted to mpv is correct. This information is also the most comprehensive, correct, and intuitive. This is why I read these.

The log needs to consider practicality and why it was previously divided into two pipeline outputs. At least the two pipeline outputs are very easy to read.

You may only use these log information after generating the .log, but in fact you are not the only one looking at this information. The front end reads these log information when it changes. This may also be the reason why the output was previously split into 2 pipes.

When I first debugged the merged debug log, I even thought that the log output of the Standard Output pipeline was faulty, because there was only playback progress information in the Standard Output at this time. why is it like this? Because the video information will only be captured when the file starts playing, when I look at these logs a few seconds later, the video information has already disappeared without a trace, as if this information has never been captured, because They are already at the top of the long log message and will most likely be deleted. The two logs mixed together are also difficult to read.

You may think that it is natural to use observe_property to monitor changes in mpv. I also use observe_property to monitor changes in most parameters, but observe_property has some unavoidable shortcomings in actual use:

  1. Not everyone is an expert in mpv. I only used observe_property after reading these log information, because as a beginner, I didn’t know which parameter changes needed to be tracked. There were too many parameters. When I was a beginner, I didn't know that there was such a good thing as observe_property. The log gave me a good reference. Now it is much more difficult for beginners.

  2. Using observe_property to batch monitor parameter changes will cause the pipe to be blocked (at least in Qt). I usually send 5 parameters in batches and then pause them so that mpv has time to read them. This is usually no problem, but multiple pauses will extend the command execution time and waste the front-end startup time.

  3. Parameters are captured in the log faster, especially the width, height and duration of the video. This allows the front-end to prioritize these parameters and make the interface display faster. If you use observe_property, you must first create a pipeline and then use multiple questions and answers to obtain this information. I know this is not the correct way to use logging, but in practice it works very well.

I respect the changes you have made. I only need to modify three lines of code to solve the bug caused by this change. It will not even slow down the front-end startup speed, but it will become much more difficult for me to read these real-time log changes in the future. I may need to add new code to separate them again (from the front end, at least I don't expect that change).

You can close this issue, I have determined that this is not a bug.

Thank you very much, thank you for all your contributions to mpv, I also like mpv very much.

ruihe774 commented 2 months ago

Using observe_property to batch monitor parameter changes will cause the pipe to be blocked (at least in Qt). If you use observe_property, you must first create a pipeline and then use multiple questions and answers to obtain this information.

Are you using the JSON IPC? Why "batch monitor parameter changes will cause the pipe to be blocked"? Can you provide information on how your code interact with mpv?

422658476 commented 2 months ago

I can only give you a rough description, because this problem was solved several years ago, so I can only give the following information from the description and memories added to the relevant code

2 possible phenomena: Add the following code as text to the strlist [strlist_observe_property_1], and then send this strlist to mpv. If the text is too long, it may exceed the maximum value that mpv can read, which will cause some commands mpv to fail to obtain successfully.

Or for each line of code below, use a for loop to quickly pass it to mpv in batches. Then the transfer speed will be too fast, causing mpv to not even run normally.

This should be a problem with my code, not mpv.

    strlist_observe_property_1 << "{ \"command\": [\"observe_property\", 100 , \"filename\"]}";
    strlist_observe_property_1 << "{ \"command\": [\"observe_property\", 111 , \"volume\"]}";
    strlist_observe_property_1 << "{ \"command\": [\"observe_property\", 122 , \"chapters\"]}";
    strlist_observe_property_1 << "{ \"command\": [\"observe_property\", 133 , \"playlist-count\"]}";
    strlist_observe_property_1 << "{ \"command\": [\"observe_property\", 144 , \"playlist-pos\"]}";
    strlist_observe_property_1 << "{ \"command\": [\"observe_property\", 155 , \"loop-playlist\"]}";
    strlist_observe_property_1 << "{ \"command\": [\"observe_property\", 166 , \"osd-bar\"]}";
    strlist_observe_property_1 << "{ \"command\": [\"observe_property\", 177 , \"audio-params/channel-count\"]}";
    strlist_observe_property_1 << "{ \"command\": [\"observe_property\", 188 , \"container-fps\"]}";
    strlist_observe_property_1 << "{ \"command\": [\"observe_property\", 199 , \"hwdec-current\"]}";
ruihe774 commented 2 months ago

Add the following code as text to the strlist [strlist_observe_property_1], and then send this strlist to mpv. If the text is too long, it may exceed the maximum value that mpv can read, which will cause some commands mpv to fail to obtain successfully.

You need to add \n to separate each command. See the documentation:

Every message must be terminated with \n. Additionally, \n must not appear anywhere inside the message. In practice this means that messages should be minified before being sent to mpv.

422658476 commented 2 months ago

This is not the reason. Only the command that is too long and the interval between multiple transmissions is too short will cause problems. If this is the problem, then each command sent to mpv will not take effect, and in the end I will not be able to control mpv.