Permutor CLI erroring out when trying to parse VMAF score

[Zekfoo]

Hey there, thanks for the tools!

I'm running into an error when running permuter-cli with -c to calculate VMAF scores, for example:

permutor-cli.exe -e hevc_nvenc -s 1080-120.y4m -b 30 -m 100 -c

Options:
  -calculating vmaf score
[ETR: Unknown until first permutation is done]
[Permutation:   1/315]
[Resolution:    1920x1080]
[Encoder:       hevc_nvenc]
[FPS:           120]
[Bitrate:       30Mb/s]
[-preset p1 -tune hq -profile:v main -rc cbr -cbr true -gpu 0]
  [00:00:03] [#############################################################################] 2383/2383 frames (00:00:00)
  Average FPS:  737
  1%'ile:       550
  90%'ile:      818

Calculating vmaf score; might take longer than original encode depending on your CPU...
  [00:00:26] [#############################################################################] 2383/2383 frames (00:00:00)
VMAF calculation finishing up...
thread 'main' panicked at 'Could not parse score from line: [in#1/yuv4mpegpipe @ 000001cc4db22080]   Input stream #1:0 (video): 2383 packets read (7412083200 bytes); 2383 frames decoded; 0 decode errors; : ParseFloatError { kind: Empty }', engine\src\permutation_engine.rs:230:45

The last several lines of my ffmpeg log:

[out#0/null @ 000001cc4e0d5280] All streams finished
[out#0/null @ 000001cc4e0d5280] Terminating muxer thread
[out#0/null @ 000001cc4e0d5280] Output file #0 (pipe:):
[out#0/null @ 000001cc4e0d5280]   Output stream #0:0 (video): 2383 frames encoded; 2383 packets muxed (1143840 bytes); 
[out#0/null @ 000001cc4e0d5280]   Total: 2383 packets (1143840 bytes) muxed
[out#0/null @ 000001cc4e0d5280] video:1117kB audio:0kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: unknown
frame= 2383 fps= 90 q=-0.0 Lsize=N/A time=00:00:19.85 bitrate=N/A speed=0.747x    
[Parsed_libvmaf_0 @ 000001cc4f0aef40] VMAF score: 93.807331
[in#0/hevc @ 000001cc4db21440] Input file #0 (tcp://localhost:2000?listen&listen_timeout=3000&timeout=1000000):
[in#0/hevc @ 000001cc4db21440]   Input stream #0:0 (video): 2383 packets read (75186948 bytes); 2383 frames decoded; 0 decode errors; 
[in#0/hevc @ 000001cc4db21440]   Total: 2383 packets (75186948 bytes) demuxed
[AVIOContext @ 000001cc4db20900] Statistics: 75186948 bytes read, 0 seeks
[in#1/yuv4mpegpipe @ 000001cc4db22080] Input file #1 (1080-120.y4m):
[in#1/yuv4mpegpipe @ 000001cc4db22080]   Input stream #1:0 (video): 2383 packets read (7412083200 bytes); 2383 frames decoded; 0 decode errors; 
[in#1/yuv4mpegpipe @ 000001cc4db22080]   Total: 2383 packets (7412083200 bytes) demuxed
[AVIOContext @ 000001cc4db27940] Statistics: 7412097579 bytes read, 0 seeks

Digging into the rust code and the ffmpeg log file, my guess is that the log file parsing is simply looking at the wrong line.

I am running Windows 11 with ffmpeg-release-full from gyan.dev, as instructed by the README.

[Zekfoo]

Testing with different ffmpeg releases, this bug is only present with fmpeg 6.1 and 6.1.1, not present with 6.0 or 5.1.2. I guess there must have been some change in log file format/ordering between 6.0 and 6.1.

[mat-gritz]

I'm also having the same issue with ffmpeg 6.1 and above.

[ ATTEMPT 1/3 ] Calculating vmaf score; might take longer than original encode depending on your CPU...
V: Vmaf args calculating quality: -y -report -r 60 -i tcp://localhost:2000?listen&listen_timeout=3000&timeout=1000000 -r 60 -i .\2k-60.y4m -filter_complex libvmaf='n_threads=16:n_subsample=5' -f null -
V: ffmpeg args: [-y -report -r 60 -i tcp://localhost:2000?listen&listen_timeout=3000&timeout=1000000 -r 60 -i .\2k-60.y4m -filter_complex libvmaf='n_threads=16:n_subsample=5' -f null -]
V: ffmpeg args no network calls (copy this and run locally, minus the quotes): [-y -report -r 60 -i tcp://localhost:2000?listen&listen_timeout=3000&timeout=1000000 -r 60 -i .\2k-60.y4m -filter_complex libvmaf='n_threads=16:n_subsample=5' -f null -]
V: Encoder fmmpeg args sending to vmaf: -progress tcp://localhost:1234 -stats_period 0.5 -y -i .\2k-60.y4m -b:v 10M -c:v hevc_amf -usage transcoding -quality balanced -profile:v main -profile_tier main -rc cbr -cbr true -gpu 0 -f hevc tcp://localhost:2000
V: ffmpeg args: [-progress tcp://localhost:1234 -stats_period 0.5 -y -i .\2k-60.y4m -b:v 10M -c:v hevc_amf -usage transcoding -quality balanced -profile:v main -profile_tier main -rc cbr -cbr true -gpu 0 -f hevc tcp://localhost:2000]
V: ffmpeg args no network calls (copy this and run locally, minus the quotes): [-y -i .\2k-60.y4m -b:v 10M -c:v hevc_amf -usage transcoding -quality balanced -profile:v main -profile_tier main -rc cbr -cbr true -gpu 0 -f null -]
  [00:00:52] [#############################################################################################################################################################################################################################################] 1800/1800 frames (00:00:00)
VMAF calculation finishing up...
thread 'main' panicked at 'Could not parse score from line: [in#1/yuv4mpegpipe @ 000001f2793a0140]   Input stream #1:0 (video): 1800 packets read (9953280000 bytes); 1800 frames decoded; 0 decode errors; : ParseFloatError { kind: Empty }', engine\src\permutation_engine.rs:230:45
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

From my ffmpeg log:

[out#0/null @ 000001f191869b00] All streams finished
[out#0/null @ 000001f191869b00] Terminating thread with return code 0 (success)
[Parsed_libvmaf_0 @ 000001f1900c6480] VMAF score: 76.238144
[fc#0 @ 000001f1900aa480] Terminating thread with return code 0 (success)
[out#0/null @ 000001f191869b00] Output file #0 (pipe:):
[out#0/null @ 000001f191869b00]   Output stream #0:0 (video): 1800 frames encoded; 1800 packets muxed (864000 bytes); 
[out#0/null @ 000001f191869b00]   Total: 1800 packets (864000 bytes) muxed
[out#0/null @ 000001f191869b00] video:844kB audio:0kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: unknown
frame= 1800 fps= 31 q=-0.0 Lsize=N/A time=00:00:30.00 bitrate=N/A speed=0.511x    
[in#0/hevc @ 000001f1900c2e00] Input file #0 (tcp://localhost:2000?listen&listen_timeout=3000&timeout=1000000):
[in#0/hevc @ 000001f1900c2e00]   Input stream #0:0 (video): 1800 packets read (37524036 bytes); 1800 frames decoded; 0 decode errors; 
[in#0/hevc @ 000001f1900c2e00]   Total: 1800 packets (37524036 bytes) demuxed
[AVIOContext @ 000001f1900c6680] Statistics: 37524036 bytes read, 0 seeks
[in#1/yuv4mpegpipe @ 000001f1900ed940] Input file #1 (.\2k-60.y4m):
[in#1/yuv4mpegpipe @ 000001f1900ed940]   Input stream #1:0 (video): 1800 packets read (9953280000 bytes); 1800 frames decoded; 0 decode errors; 
[in#1/yuv4mpegpipe @ 000001f1900ed940]   Total: 1800 packets (9953280000 bytes) demuxed
[AVIOContext @ 000001f1906aed40] Statistics: 9953290880 bytes read, 0 seeks

[Proryanator]

Hey there! Thanks for opening this issue. I can take a look and see about adding compatibility support for newer versions of ffmpeg!

I think I tested 6.0 excusively but well worth making sure it parses better.

Glad ya'll enjoy the tool! @masgritz @Zekfoo

[e-dong]

Hi @Proryanator ! I wanted to let you know I did some experimentation. I posted more info in the discord, but in short I think it would be better to parse standard out than reading the log file. The last line has the VMAF score.