[Question] How to log all the output info of crf-search

[iPaulis]

Hi, first of all, thank you for this awesome tool.

I've written a small powershell script to batch process a folder with multiple video files and run crf-search with all of them for a given target vmaf. It is probably poorly written, but it is simple, works well and I'm happy with it.
Now I'm having some trouble trying to log all the information shown in the powershell terminal when I run crf-search, maybe because I'm not sure how to do it correctly.

I find extremely useful the information of the several attempts ab-av1 makes to find the most suitable crf for the target vmaf and their estimated filesize. I think it is very helpful info to make a final decision on what settings to finally choose, as I might have incorrectly assessed my initial target and the filesize difference with a bit lower/higher vmaf might be or not be worth it for a certain video file, so I could benefit more from a crf in between the tested ones to get a more quality/size efficient result.

This is the script I'm running:

$default_target = 92
if (!($target = Read-Host "Target VMAF [$default_target]")) { $target = $default_target }
$default_preset = 5
if (!($preset = Read-Host "Preset [$default_preset]")) { $preset = $default_preset }

$logfile = "./crf-search_vmaf" + $target + "p" + $preset + ".txt"
$videotype=@("*.mp4","*.mkv")
$filter=@("*sample*","*x265*")

$filelist = Get-ChildItem -Path '.\' -Include $videotype -Exclude $filter -File -Name -Recurse
# Clean
Remove-Item ./*.ivf
Remove-Item ./*sample*

foreach ($value in $filelist) {
$referencedir = '.\' + $value
Write-Host "--------------------------------------------------------------------------------------------------" *>&1 | Tee-Object -FilePath $logfile -Append
Write-Host $referencedir *>&1 | Tee-Object -FilePath $logfile -Append

ab-av1 crf-search --min-crf 18 --min-vmaf $target --vmaf n_threads=16 --vmaf n_subsample=4 -i $referencedir --preset $preset *>&1 | Tee-Object -FilePath $logfile -Append

Write-Host "--------------------------------------------------------------------------------------------------" *>&1 | Tee-Object -FilePath $logfile -Append

# Clean
Remove-Item ./*.ivf
Remove-Item ./*sample*
}

cmd /c pause | out-null

When I run it like this, with *>&1 to redirect all streams into my logfile, I don't see the usual progress bar and multiple crf-search attempts in my terminal, nor it logs them into the logfile, which is what I'm interested in. Instead, I get the following result:

.\testfile1.mp4
crf 49 VMAF 90.49 predicted full encode size 41.26 MiB (5%) taking 3 minutes
ab-av1 :
En M:\test\vmaf_target.ps1: 21 Carácter: 1

• ab-av1 crf-search --min-crf 18 --min-vmaf $target --vmaf n_threads=16 ...

•   + CategoryInfo          : NotSpecified: (:String) [], RemoteException
    + FullyQualifiedErrorId : NativeCommandError
  
  

Encode with: ab-av1 encode -i .\testfile1.mp4 --crf 49 --preset 10

---

---

.\testfile2.mp4
ab-av1 :
En M:\test\vmaf_target.ps1: 21 Carácter: 1

• ab-av1 crf-search --min-crf 18 --min-vmaf $target --vmaf n_threads=16 ...

•   + CategoryInfo          : NotSpecified: (:String) [], RemoteException
    + FullyQualifiedErrorId : NativeCommandError
  
  

Encode with: ab-av1 encode -i .\testfile2.mp4 --crf 47 --preset 10

crf 47 VMAF 90.02 predicted full encode size 79.59 MiB (7%) taking 5 minutes

I don't know why that error appears, but it does not bother me much. The problem is that it does not log the other crf tests, only the final one for my target vmaf. Exactly the same happens when the error stream is redirected with 2>&1.
Then, if I change the redirect *>&1 option to, let say, verbose 4>&1, as well as any other redirect, this is what I get:

.\testfile1.mp4
crf 49 VMAF 90.06 predicted full encode size 42.66 MiB (5%) taking 2 minutes

---

.\testfile2.mp4
crf 46 VMAF 90.35 predicted full encode size 87.05 MiB (7%) taking 3 minutes

As you can see, the error disappears, but again, only the final result of the crf-search command is logged. I tried with the other redirects as explained by microsoft's documentation (https://learn.microsoft.com/en-us/powershell/module/microsoft.powershell.core/about/about_redirection?view=powershell-7.2) with the same result.

So it seems I am unable to save the whole process shown in the terminal into a file, including the results of the binary search to find the best crf value. This is what I would expect to save into the log (copy pasted from my terminal):

---

.\testfile1.mp4

• crf 36 VMAF 95.57 (12%)
• crf 45 VMAF 92.14 (6%)
• crf 55 VMAF 86.18 (3%)
  00:00:41 ################################################################################### (sampling crf 49, eta 0s)
  Encode with: ab-av1 encode -i .\testfile1.mp4 --crf 49 --preset 11

crf 49 VMAF 90.06 predicted full encode size 42.66 MiB (5%) taking 2 minutes

---

.\testfile2.mp4

• crf 36 VMAF 94.89 (15%)
• crf 45 VMAF 90.95 (8%)
• crf 55 VMAF 83.72 (4%)
  00:01:31 ################################################################################### (sampling crf 46, eta 0s)
  Encode with: ab-av1 encode -i .\testfile2.mp4 --crf 46 --preset 11

crf 46 VMAF 90.35 predicted full encode size 87.05 MiB (7%) taking 3 minutes

What am I doing wrong? could you help me save all the information into a text file?

Thank you in advance.

[alexheretic]

It doesn't work as you expect currently because we print using the progress bar library. Progress bar stuff avoids output to not-terminals.

However, it's possible to suspend the bar and use eprintln! which will work more like as you expect. I don't see a problem doing this, so lets do it.

[alexheretic]

Ah I just gave suspend a try suggested by the progress bar lib in docs, but it doesn't really work very well with the progress bar. So no easy fix there.

I guess the real issue is the current stderr output is designed for humans to read on a terminal as the bin is running, rather than as a log. Perhaps the better course of action is to introduce proper logging that can be enabled and used in these cases.

[iPaulis]

So these results are also printed by the progress bar library?

crf 36 VMAF 94.89 (15%)
crf 45 VMAF 90.95 (8%)
crf 55 VMAF 83.72 (4%)

I was hoping they could be saved in a variable and then printed through another stream or something similar.
Well, I don't know how, but if there was a simple way where then I could capture that stream with powershell and save it myself, that would be enough for me.

If that is not as simple or possible, then I would appreciate if ab-av1 itself was able of logging, I guess by adding a parameter to the command line or something like that.

Sorry for bothering with this request, although I'm not a programmer, I was hoping I could solve it myself.
As encoding with av1 takes so much time, this tool is really helpful and lets me know beforehand what encoding settings I would like to use. That is why I was trying to get a head start by logging the crf-search results first, and then queue those encodes later or in another day when I have time to spend in actually deciding which final crf suits more for that specific file.

Thank you for your help.

[alexheretic]

I've made a simple change that will print the crf-search attempts also when stderr is not a terminal (#61). This approach won't generally work for printing sample-encode logs etc, so adding a logging option is still perhaps the way to go for a full verbose output. But perhaps this change will work for you for now?

[iPaulis]

It kinda works? I mean, the results are output through stderr now, but they are messy to read, as they are mixed with other stderr error messages, like this:

---

.\testfile1.mp4
ab-av1 : - crf 36 VMAF 95.13 (12%)
En M:\test\vmaf_target.ps1: 21 Carácter: 1

• ab-av1 crf-search --min-crf 18 --min-vmaf $target --vmaf n_threads=16 ...

•   + CategoryInfo          : NotSpecified: (- crf 36 VMAF 95.13 (12%):String) [], RemoteException
    + FullyQualifiedErrorId : NativeCommandError
  
  

• crf 45 VMAF 91.56 (6%)
• crf 55 VMAF 85.15 (3%)

crf 47 VMAF 90.54 predicted full encode size 49.18 MiB (6%) taking 2 minutes
Encode with: ab-av1 encode -i .\testfile1.mp4 --crf 47 --preset 12

---

---

.\testfile2.mp4
ab-av1 : - crf 36 VMAF 94.63 (15%)
En M:\test\vmaf_target.ps1: 21 Carácter: 1

• ab-av1 crf-search --min-crf 18 --min-vmaf $target --vmaf n_threads=16 ...

•   + CategoryInfo          : NotSpecified: (- crf 36 VMAF 94.63 (15%):String) [], RemoteException
    + FullyQualifiedErrorId : NativeCommandError
  
  

• crf 45 VMAF 90.49 (8%)
• crf 55 VMAF 82.83 (4%)
• crf 46 VMAF 89.85 (7%)

Encode with: ab-av1 encode -i .\testfile2.mp4 --crf 45 --preset 12

crf 45 VMAF 90.49 predicted full encode size 93.51 MiB (8%) taking 4 minutes

I don't know why that error appears, if it wasn't there it wouldn't be so messy.

Alternatively, is it possible to output it through any other stream? just not stderr, to not mix it with the error logs, maybe the warning or debug stream?
Or just through the main stdout itself? or would that double the output in the terminal by showing the same info twice from the progress bar and from this?

[alexheretic]

The idea is stdout is the program result only, which in this case is the human readable output of the successful crf search.

Stderr is used for progress bars, updates/logs & errors. It isn't usual to use more than the two standard streams so I'd prefer not to.

I don't know why that error appears, if it wasn't there it wouldn't be so messy.

Nor me, I don't recognise the error at all. A Windows/powershell thing presumably?

[iPaulis]

I understand. However, the attempts could be considered part of the result, as they provide very useful context to understand how the program achieved the final result, and crf 46 VMAF 89.85 (7%) seems quite human readable to me.

Anyway, I'm trying to get rid of the powershell error message, but it seems to be a default error streamed through stderr everytime powershell runs a non native executable, such as ab-av1. I was able to make the message smaller by adding %{ "$_" } into the pipeline:

ab-av1.exe crf-search --min-crf 18 --min-vmaf $target --vmaf n_threads=16 --vmaf n_subsample=4 -i $referencedir --preset $preset *>&1 | %{ "$_" } | Tee-Object -FilePath $logfile -Append

So now I get:

---

.\testfile1.mp4

• crf 36 VMAF 95.13 (12%)
• crf 45 VMAF 91.56 (6%)
• crf 41 VMAF 93.47 (9%)
  crf 42 VMAF 93.09 predicted full encode size 69.46 MiB (8%) taking 2 minutes
  System.Management.Automation.RemoteException
  Encode with: ab-av1 encode -i .\testfile1.mp4 --crf 42 --preset 12
  System.Management.Automation.RemoteException

---

---

.\testfile2.mp4

• crf 36 VMAF 94.63 (15%)
• crf 45 VMAF 90.49 (8%)
  crf 40 VMAF 93.14 predicted full encode size 135.53 MiB (11%) taking 4 minutes
  System.Management.Automation.RemoteException
  Encode with: ab-av1 encode -i .\testfile2.mp4 --crf 40 --preset 12
  System.Management.Automation.RemoteException

---

I'll try to completely get rid of it if it is even possible.

[iPaulis]

Trying to get rid of that powershell error message was giving me a headache, I made some advancement using the Start-Process powershell command to run ab-av1, it got rid of the error message but then had other problems trying to log, so nevermind.

I took a simpler approach. Thanks to your latest commit to help me with this issue I learnt what lines affect these options. In the end I found it a lot easier to download the repo and change your code to output the crf-search samples in the stdout, and compile that modified ab-av1 version.
Now the terminal output is not as pretty as yours, but I get to finally log the whole crf-search process including the context; exactly what I wanted. It results in a log like this:

---

.\testfile1.mp4

• crf 36 VMAF 95.13 (12%)
• crf 45 VMAF 91.56 (6%)
• crf 55 VMAF 85.15 (3%)
  crf 47 VMAF 90.54 predicted full encode size 49.18 MiB (6%) taking 2 minutes

---

---

.\testfile2.mp4

• crf 36 VMAF 94.63 (15%)
• crf 45 VMAF 90.49 (8%)
• crf 55 VMAF 82.83 (4%)
• crf 46 VMAF 89.85 (7%)
  crf 45 VMAF 90.49 predicted full encode size 93.51 MiB (8%) taking 3 minutes

---

This solution will work for me perfectly fine, but I would not like to get stuck in this version if you make other improvements to the program. So I would be very grateful if you could eventually add a proper logging natively supported option as you initially suggested in the future.

Sorry for bothering you with this and thank you for all your help and support.
Great tool!

[alexheretic]

I've merged #209 log support. Let me know if that is enough to resolve this.