Is it possible to decrease redundant logging info on Windows?
supremestarhawk opened this issue · 36 comments
I don't remember this being an issue on Mac, but on Windows, handbrake will print hundreds of lines of Encoding: task 1 of 1 to the log. Is there a way to prevent this? The only option I can find in HandbrakeCLI is -H verbose= which doesn't appear to change this behavior.
Lastly, If there's a solution, I think it would make sense to set this as a default behavior for transcode-video.
@cameronks Good question. Unfortunately, I don't know for sure but I think @samhutchins answered this question in #128 the other day. And I think the trick might be to use a batch file with @echo off at the top.
BTW, does the increased verbosity only plague you when using transcode-video or do you see the same problem when using HandBrakeCLI standalone and redirecting its output to a file?
Do you mean these lines?
I don't know a way to stop those, what's the problem with them though?
@donmelton @echo off in a batch file stops every single command being printed to the screen before it's executed, it doesn't change the output of anything though
@samhutchins Yep! That's what I'm talking about.
The problem is a lot of key data in a log is at the beginning and the end. Manually reviewing a log you have to scroll through so much if you want to review the data at the end.
Also, the logs are super bloated in size. I just took a log file down from 956KB to 15KB just removing those lines, and the length of this video was only 38 minutes. The longer the video/slower the encode, the more it prints.
First world problems for sure, but if I had the option to mute that, I would.
If you call transcode-video with --dry-run you'll get the HandBrakeCLI command that will get called. If you copy that command and append 2> encode.log I think you'll get what you want. For example:
HandBrakeCLI --input=The_Force_Awakens_-_BLU-RAY_t00.mkv --output=The_Force_Awakens_-_BLU-RAY_t00.mp4 --markers --encoder=x264 --crop=0:0:0:0 --auto-anamorphic --rate=30 --pfr --encoder-preset=medium --encoder-profile=high --encoder-level=4.0 --quality=1 --audio=1,1 --aencoder=fdk_aac,ac3 --encopts=vbv-maxrate=6000:vbv-bufsize=12000:crf-max=25:qpmax=34 2> encode.log
encode.log will contain only the stuff at the beginning and the end, but none of the progress stuff. I don't think Don's query-handbrake-log will parse that file though
If that's what you want I can probably think of a few tricks to make that the default behaviour
@samhutchins Actually, I believe query-handbrake-log will parse that. Worth trying anyway.
Thanks @samhutchins . I will give this a shot later this evening.
I've done some direct comparisons of behaviour between macOS and Windows today
The difference in behaviour is around how the progress output from Handbrake is handled (by which I mean lines that look like this: Encoding: task 1 of 1, 95.69 % (110.95 fps, avg 118.42 fps, ETA 00h00m18s))
macOS
In the terminal window, this line is updated/overwritten regularly, and doesn't scroll
In the log file produced by transcode-video each of those updates is on a new line
Windows
In the terminal window, each of those updates is on a new line
In the log file produced by transcode-video each of those updates is on a new line
Regardless of platform, the logfile will be very long and mainly full of the progress updates, but on a mac the terminal window isn't flooded with these updates, which makes it very easy to scroll up only a handful of lines to see the logging at the beginning. On Windows though, the terminal is flooded with updates, often making it so you can't scroll back to the beginning.
When calling Handbrake directly (ie, not through transcode-video) on Windows, the output is the same as on macOS, the progress line gets updated/overwritten, it doesn't start scrolling. Something about 'piping' the output through Ruby is causing each update to be on its own line on Windows; I don't know if something different could be done in the IO::popen call to change this, but if it can it would be a lovely quality of life improvement for Windows users.
I hope this post makes sense
@samhutchins That was perfect. HandbrakeCLI just overwrites the "Encoding: task 1 of 1" in the command prompt/terminal window, which is how I remember it on my Mac, and it doesn't print any of that to the log.
@donmelton It looks like the above is HandbrakeCLI's default behavior? I simply copied out the command --dry-run gave me into HandbrakeCLI, and it doesn't print the extra lines.
Edit: Just saw your post above which mirrors what I found!
@samhutchins That's some great investigative work. Thanks!
It sounds like there may be some kind of bug in Ruby on Windows then because this is all I'm doing in the loop which processes the output of HandBrakeCLI:
begin
IO.popen(handbrake_command, :err=>[:child, :out]) do |io|
Signal.trap 'INT' do
Process.kill 'INT', io.pid
end
io.each_char do |char|
print char
log_file.print char unless log_file.nil?
end
end
rescue SystemCallError => e
raise "transcoding failed: #{e}"
end
As you can see, that's a call to print char for both console output and log file output. And print char doesn't add carriage returns, linefeeds or anything else to those streams.
Unless I'm doing something wrong there, I'm not sure what I can fix.
@samhutchins I wonder if this multiple-line behavior also happens when using the Windows Subsystem for Linux? Maybe @JMoVS could tell us?
@donmelton changing the popen call to include mode='rb' fixes this on Windows for me, does this affect the Mac at all? I'm back from work so I won't have access to a Mac until tomorrow
IO.popen('HandBrakeCLI.exe -i title00.mkv -o foo.mp4', mode="rb", :err=>[:child, :out]) do |io|
Edit: although it does now do double newlines in the log file... Hmm...
So what's happening is that, by default, Ruby is 'clever' and converts line endings between EOL and CRLF. Changing the mode to rb stops this, but it messes up the log file that's written. Ideally it wouldn't do the line ending conversion when printing to the console, but would do line ending conversion when printing to the log file. Without buffering the output a little I don't know how (or if) this can be done
http://ruby-doc.org/core-2.2.3/IO.html#method-c-new-label-IO+Open+Mode
@samhutchins Interesting! I'll try it on macOS later today when I'm back at my computer just to see what happens.
There's a line just above that section I pasted in before which opens the log file:
log_file = @log ? File.new(handbrake_options['output'] + '.log', 'w') : nil
What happens if you make the change you did before and also change the 'w' there to 'wb'? Would that fix the log file on Windows, too?
Awesome, that fixes it :-D
Hopefully this makes no difference on other platforms, in which case this would be a really welcome change for Windows users
@samhutchins Wow! Thanks for testing so quickly. :)
Yeah, I'll definitely try this on macOS later today and see what happens then. If it doesn't change anything, I'll check it in right away so someone can try this on Linux, too, just in case.
@samhutchins OK, I'm back from my long lunch. :)
Cursory testing on macOS seems to work. Here's a git diff of the change I have in my local tree:
diff --git a/bin/transcode-video b/bin/transcode-video
index e17c26c..63aacb0 100755
--- a/bin/transcode-video
+++ b/bin/transcode-video
@@ -1267,11 +1267,11 @@ HERE
end
Console.debug handbrake_command
- log_file = @log ? File.new(handbrake_options['output'] + '.log', 'w') : nil
+ log_file = @log ? File.new(handbrake_options['output'] + '.log', 'wb') : nil
Console.info 'Transcoding with HandBrakeCLI...'
begin
- IO.popen(handbrake_command, :err=>[:child, :out]) do |io|
+ IO.popen(handbrake_command, 'rb', :err=>[:child, :out]) do |io|
Signal.trap 'INT' do
Process.kill 'INT', io.pid
end
Notice that I didn't prepend 'rb' with a mode= when calling IO.popen. Ruby flags that as unnecessary when I did it.
Anyway, using binary mode seems to work on macOS. My only concern is that reading the Ruby documentation closer, it says:
"b" Binary file mode
Suppresses EOL <-> CRLF conversion on Windows. And
sets external encoding to ASCII-8BIT unless explicitly
specified.
That whole "sets external encoding to ASCII-8BIT unless explicitly specified" thing has me worried since I don't know what the default encoding is supposed to be. But maybe that doesn't matter since the Unix file command says that some of the log files are UTF-8 Unicode text, with CR, LF line terminators.
Can you try that patch on your Mac tonight and let me know what you think? Thanks!
It doesn't appear to break anything for me on macOS, and the log files produced before and after the change appear to be the same, in so far as 2 log files can be the same.
@samhutchins Excellent! And thanks for testing.
OK, I'll check this in and release it as 0.17.1 later today.
Awesome. The logging, both to the log file and to the terminal window, will be identical between platforms! :-D
@donmelton @samhutchins Much appreciated!
@cameronks You are very welcome, sir! Thanks for opening this issue. And many thanks to @samhutchins for figuring out what was really wrong.
The fix has been released. Just gem update video_transcoding to get it.
Just a heads up, the Command Prompt window is perfect and mimics the performance on Mac by overwriting/refreshing the line.
It is still writing all of the lines to the log though, but without carriage returns between the lines. I've attached a log as an example.
Not sure if anything can be done with it, or why my results are different from Sam's, but I'm happy with the progress made on this regardless.
@cameronks Well, at least the console spew is fixed. But, damn, I thought this would fix the log file, too.
@samhutchins Can you reproduce the behavior that @cameronks is seeing? Or do your logs come out fine now?
Dang it!
I use VS Code as my default text editor, and it all looks fine there. It looks messed up in Notepad though:
I have no idea what to do about that without adding some kind of buffering and post-processing to the log writing stuff in transcode-video :-\
I guess code sees a \r and treats it as a new line, but Notepad is expecting a \r\n for the new line.
Sorry for not catching this guys, I should've tried notepad earlier
Edit:
Bit more info, for fun:
\r is a carriage return, which sends the cursor to the start of the line
\n is a linefeed, and moves the cursor down a line
On Unix-y systems, like macOS, ending a line with \n is enough to start a new line at the beginning of the line, but Windows being the way it is requires both the 'put the cursor at the beginning' and the 'go to a new line' characters. It's weird an annoying
I guess most of the Handbrake output on Windows ends each line with \r\n, but only does the \r when it's doing the progress updates. This is what causes the line to be overwritten in the terminal. transcode-video is just putting the raw characters in the log file, and a \r on it's own isn't enough to make Notepad render newlines.
@samhutchins These things happen. Don't worry about it. After all, I'm releasing without testing on Windows myself. :)
Hmmmm, I suppose I could turn off binary mode for the log file? But, then again, modern editors should understand that it's a Unix-style text file now?
@donmelton I edited my above comment a bit
Yeah, 'modern' editors handle this just fine. As you can see, VS code works well. Notepad only mangles the progress update lines though, and I wouldn't expect anyone to be reading those in any detail anyway, it just looks a bit weird. All the important stuff is rendered correctly in Notepad as well as VS Code
@donmelton and if you turn off the binary mode for the log file you get lots of weird double carriage return issues in the log file. In notepad that would render every progress update on a new line, and all the preamble at the beginning of the log with double line-spacing
@samhutchins Then I think we're OK as is. And we can just recommend that people use Unix-aware editors if they want to view their log files. Hopefully, query-handbrake-log works correctly with these new files. Please tell me that it does. :)
C:\Users\Sam\Desktop>query-handbrake-log t The.Melting.Face.mp4.log
00:01:43 The.Melting.Face.mp4
C:\Users\Sam\Desktop>query-handbrake-log s The.Melting.Face.mp4.log
152.975922 fps The.Melting.Face.mp4
C:\Users\Sam\Desktop>query-handbrake-log b The.Melting.Face.mp4.log
1491.46 kbps The.Melting.Face.mp4
C:\Users\Sam\Desktop>query-handbrake-log r The.Melting.Face.mp4.log
20.36 The.Melting.Face.mp4
Works just fine
It's also worth noting that even in Notepad all the important stuff is still absolutely fine:
It's only all those Encoding: task 1 of 1, 95.69 % (110.95 fps, avg 118.42 fps, ETA 00h00m18s) lines that don't get the newlines, and I don't imagine anyone wants to read all those anyway
Sidenote to @cameronks, I'm jealous of your CPU :-P
@samhutchins Sweet! :)
Yeah, that's some major CPU horsepower there, @cameronks. :)
Planning to build a new PC soon. Hopefully gonna get one of those new 8 core 16 thread CPUs AMD just announced
@samhutchins That would be some awesome transcoding box then. Of course, it's probably adequate for other tasks. :)
It's only all those Encoding: task 1 of 1, 95.69 % (110.95 fps, avg 118.42 fps, ETA 00h00m18s) lines that don't get the newlines, and I don't imagine anyone wants to read all those anyway
Absolutely. Just to clarify, I was wondering if it was possible to create the log without those lines at all. No carriage returns actually helps truncate all of that needless data a bit compared to before.
Sidenote to @cameronks, I'm jealous of your CPU :-P
Thanks! I built that last summer almost exclusively as a transcoding and Plex box.
@cameronks Unfortunately, I can't easily filter those lines out since query-handbrake-log depends on some of them.
@donmelton Ah, thanks for that. I was thinking the Mac version didn't write those lines to the log at all, so that's why I was confused when Sam said the logs were identical between the two. It's been awhile since I used transcode-video on Mac!