Handbrake: Regression: Change to CLI progress behavior corrupts piped output when using `tee` and other tools

[donmelton]

The change by @bradleysepos to test/test.c on March 10 described as "cli: Avoid carriage return in progress output when piping.":

https://github.com/HandBrake/HandBrake/commit/7c438ad5ae81c31c660fc9a208dacd7177f54a24

... actually corrupts progress output when piping that output to tee and other tools, making progress seem to stutter and emit a significant number of unnecessary line feeds. This makes it very difficult to capture the output of HandBrakeCLI to a log file, something that is simple and easy to do with the release version of HandBrake or similar programs like ffmpeg.

Here's how to reproduce the problem behavior with latest source version on macOS:

echo -n >output.mkv.log
HandBrakeCLI -i input.mkv -o output.mkv | tee -ai output.mkv.log

This will produce progress output to the console and log file something like this:

[14:19:27] sync: first pts audio 0x1 is 0

Encoding: task 1 of 1, 0.13 %
Encoding: task 1 of 1, 0.21 %
Encoding: task 1 of 1, 0.30 % (49.87 fps, avg 62.48 fps, ETA 00h33m34s)
Encoding: task 1 of 1, 0.41 % (55.61 fps, avg 61.14 fps, ETA 00h34m16s)
Encoding: task 1 of 1, 0.52 % (58.92 fps, avg 61.15 fps, ETA 00h34m13s)
Encoding: task 1 of 1, 0.56 % (48.82 fps, avg 57.98 fps, ETA 00h36m04s)
Encoding: task 1 of 1, 0.63 % (32.46 fps, avg 55.16 fps, ETA 00h37m53s)[14:19:43] sync: "Chapter 2" (2) at frame 835 time 3130627

Encoding: task 1 of 1, 0.69 % (35.88 fps, avg 52.78 fps, ETA 00h39m34s)
Encoding: task 1 of 1, 0.75 % (37.06 fps, avg 50.83 fps, ETA 00h41m04s)
Encoding: task 1 of 1, 0.79 % (29.09 fps, avg 48.17 fps, ETA 00h43m19s)

Obviously that doesn't look like progress output which is not piped.

This not only affects using tee, which is a common idiom, but it also breaks the output of my transcode-video tool.

Can this change be rolled back or modified so this behavior doesn't happen?

Thanks. And my apologies for not opening this issue sooner. This is what I get for not testing nightly builds on a regular basis. :)

[bradleysepos]

Hi Don,

That change was made to solve issues with the carriage return not being treated properly when piping. It wasn’t working at all in most cases where the output wasn’t a terminal, for instance most of the time when redirecting to a file, the carriage return was essentially an ignored byte. The output you’re seeing is what is intended by that patch and I believe a subsequent one throttles the output so it’s not spamming.

What would you like to see? Perhaps there’s a compromise I haven’t thought of, or we could make the separator configurable. Note that HandBrake prints different output to stdout vs. stderr.

[donmelton]

@bradleysepos Thanks for the quick response! Well, the behavior I want is simple. I want this:

HandBrakeCLI -i input.mkv -o output.mkv

... to behave exactly like this:

echo -n >output.mkv.log
HandBrakeCLI -i input.mkv -o output.mkv | tee -ai output.mkv.log

... when characters are sent to the console.

And that's how the release version of HandBrakeCLI, ffmpeg and just about every other tool I can think of behaves when their progress output is piped.

I'm honestly not sure what you're trying to fix with the original change. And the subsequent changes you made to test.c don't make it spam or stutter any less. Did you try the commands I included to see the behavior I'm writing about?

[donmelton]

@bradleysepos BTW, just to be clear, I can reproduce the stutter and spewing behavior when piping on macOS using a build from source just after your change and with the latest source.

[bradleysepos]

I’m mobile at the moment, but will take a look later.

For grins, try redirecting to a file instead of using tee, and compare release against nightly. E.g., command > foo.log 2>&1. If I recall correctly, the nightly should behave better there.

[donmelton]

@bradleysepos What you suggest is actually worse. :) And I tried with the latest nightly build. Not only is the log content still corrupted with useless linefeeds , but I don't get any output that way, progress or otherwise, to the console.

Seriously, HandBrakeCLI really needs to handle piping like other command line tools.

[bradleysepos]

Indeed, it wasn't a suggestion for use as much as a hint regarding why the change was made. When redirecting to a file, printing a CR doesn't overwrite the line, it prints a CR character. So one would achieve output with seemingly messed up line endings.

I'll certainly look at improving the behavior, and I'm peeking at other tools. Patches always welcome (hint, hint 😸).

[donmelton]

@bradleysepos Sorry I took so long to respond! We have family over for the holidays and it's a bit hectic.

Thanks for the explanation. But the problem you're trying to solve isn't a problem. And your change violates the unwritten (but as nearly as I can tell universal) contract for command line tools that console output is the same as redirected or, more importantly, piped output.

Why is the original behavior _not_ a problem? Because if I do this with HandBrakeCL version 1.0.7:

HandBrakeCLI -i input.mkv -o output.mkv >output.log

... I can easily get the effect you're trying to achieve with this:

cat output.log | tr '\r' '\n' >new-output.log

Or, I can shortcut the whole process by doing this with HandBrakeCL version 1.0.7:

HandBrakeCLI -i input.mkv -o output.mkv | tr '\r' '\n' >output.log

That's not the only way to achieve those results, but it's probably the shortest. :)

You mentioned looking at other tools. I'll help. Let's examine ffmpeg and rsync, two tools which I use every day.

Here's how to do the same thing with ffmpeg (which chooses to send progress output to stderr):

ffmpeg -i input.mkv output.mkv 2>output.log

If you inspect that output.log file you'll see the progress portion contains only carriage returns and no line endings. And, of course, it can be deconstructed with the same tr '\r' '\n' command.

While rsync isn't a transcoding tool, a command like this:

rsync -a /path/to/source /path/to/destination/ >output.log

... will yield the same kind of progress text, only carriage returns and no line endings. Which, once again, can be deconstructed by redirecting to tr '\r' '\n'.

And piping the output of both ffmpeg and rsync to tee -ai output.log will yield the same behavior as HandBrakeCL version 1.0.7, i.e. console output will look normal and the log file will be identical.

Please back out your change. As you can see, it's unnecessary and it's breaking more piping behavior than it's fixing. It should be the responsibility of the caller to deal with line endings.

So, since you requested it, here's a patch to back out the change:

restore-progress-piping-behavior.patch.txt

My apologies, but I can't test it since the current tree does not build on macOS Sierra. (Older versions build fine.) But I'm sure the patch works. Both of your changes were quite small.

If you want, I can turn the patch into a pull request. Just let me know.

BTW, I noticed you milestoned this for the 1.2.0 release. Wouldn't you consider this for 1.1.0?

Thanks for you time and Happy Holidays!

[bradleysepos]

Done. I committed a slightly simpler patch, but thanks for putting that together. Let me know if this works for you.

Aside, what issue are you having building on with Sierra? What Xcode version?

[donmelton]

@bradleysepos Thanks for responding so quickly!

I know it's odd since I used to work for so long in system software at the Fruit Company, but I very rarely upgrade to the new macOS until after the first of the year. :)

All I'm trying to do is build HandBrakeCLI via:

./configure --launch-jobs=$(sysctl -n hw.ncpu) --launch --disable-xcode

Which normally works fine. Here's the error I'm seeing with the current tree:

  : /usr/bin/gcc -std=gnu99 -pipe -fmessage-length=0 -Wall -arch x86_64 -g0 -O3 -mfpmath=sse -msse2 -DUSE_X265 -I./libhb/ -I./contrib/include -I./contrib/include/libxml2 -c ../test/test.c -o test/test.o
  : In file included from ../test/parsecsv.c:11:
  : In file included from ./libhb/hb.h:17:
  : ./libhb/common.h:471:13: warning: duplicate 'const' declaration specifier [-Wduplicate-decl-specifier]
  :     PRIVATE const char  * json;   // JSON encoded job string
  :             ^
  : In file included from ../test/test.c:33:
  : In file included from ./libhb/hb.h:17:
  : ./libhb/common.h:471:13: warning: duplicate 'const' declaration specifier [-Wduplicate-decl-specifier]
  :     PRIVATE const char  * json;   // JSON encoded job string
  :             ^
  : 1 warning generated.
  : ../test/test.c:254:27: error: token is not a valid binary operator in a preprocessor subexpression
  :     #if (stdout_tty == 1) stdout_sep = "\r";
  :         ~~~~~~~~~~~~~~~~~ ^
  : ../test/test.c:255:6: error: unterminated conditional directive
  :     #if (stderr_tty == 1) stderr_sep = "\r";
  :      ^
  : ../test/test.c:254:6: error: unterminated conditional directive
  :     #if (stdout_tty == 1) stdout_sep = "\r";
  :      ^
  : ../test/test.c:5052:23: error: expected '}'
  : #endif // __APPLE_CC__
  :                       ^
  : ../test/test.c:230:1: note: to match this '{'
  : {
  : ^
  : 1 warning and 4 errors generated.
  : make: *** [test/test.o] Error 1
-------------------------------------------------------------------------------
time end: Sun Dec 24 14:32:29 2017
duration: 5 minutes, 48 seconds (348.82s)
result: FAILURE (code 2)

It's conceivable this is also a problem on High Sierra, but I don't have it installed. :)

As soon as I can build, I'll test your change and let you know if it works.

[bradleysepos]

I know it's odd since I used to work for so long in system software at the Fruit Company, but I very rarely upgrade to the new macOS until after the first of the year. :)

Completely understandable. I actually do that on purpose, usually upgrading around December and then only every other year for even releases. This year was an exception. If you saw the 3813-line text file I call system documentation, you might think I'm slightly mad. 😸 Stability++

Here's the error I'm seeing with the current tree

Oof, I... uh... just caused that. Fixed.

If you're still getting an unrelated error, the output again please.

[donmelton]

@bradleysepos "Stability" is the word. :)

That was fast! But still failing for me after a git pull and complete rebuild:

/ -I./contrib/include -I./contrib/include/libxml2 -c ../test/test.c -o test/test.o
  : In file included from ../test/parsecsv.c:11:
  : In file included from ./libhb/hb.h:17:
  : ./libhb/common.h:471:13: warning: duplicate 'const' declaration specifier [-Wduplicate-decl-specifier]
  :     PRIVATE const char  * json;   // JSON encoded job string
  :             ^
  : In file included from ../test/test.c:33:
  : In file included from ./libhb/hb.h:17:
  : ./libhb/common.h:471:13: warning: duplicate 'const' declaration specifier [-Wduplicate-decl-specifier]
  :     PRIVATE const char  * json;   // JSON encoded job string
  :             ^
  : 1 warning generated.
  : ../test/test.c:4900:11: warning: 'FSPathMakeRef' is deprecated: first deprecated in macOS 10.8 [-Wdeprecated-declarations]
  :     err = FSPathMakeRef( (const UInt8 *) input, &ref, NULL );
  :           ^
  : /System/Library/Frameworks/CoreServices.framework/Frameworks/CarbonCore.framework/Headers/Files.h:4115:18: note: 'FSPathMakeRef' has been explicitly marked deprecated here
  : extern OSStatus  FSPathMakeRef(const UInt8 *path, FSRef *ref, Boolean *isDirectory)        __OSX_AVAILABLE_BUT_DEPRECATED(__MAC_10_0, __MAC_10_8, __IPHONE_NA, __IPHONE_NA);
  :                  ^
  : ../test/test.c:4908:11: warning: 'FSGetCatalogInfo' is deprecated: first deprecated in macOS 10.8 [-Wdeprecated-declarations]
  :     err = FSGetCatalogInfo( &ref, kFSCatInfoVolume, &catalogInfo, NULL, NULL,
  :           ^
  : /System/Library/Frameworks/CoreServices.framework/Frameworks/CarbonCore.framework/Headers/Files.h:2620:15: note: 'FSGetCatalogInfo' has been explicitly marked deprecated here
  : extern OSErr  FSGetCatalogInfo(const FSRef *ref, FSCatalogInfoBitmap whichInfo, FSCatalogInfo *catalogInfo, HFSUniStr255 *outName, FSSpecPtr fsSpec, FSRef *parentRef) __OSX_AVAILABLE_BUT_DEPRECATED(__MAC_10_0, __MAC_10_8, __IPHONE_NA, __IPHONE_NA);
  :               ^
  : ../test/test.c:4918:11: warning: 'FSGetVolumeParms' is deprecated: first deprecated in macOS 10.8 [-Wdeprecated-declarations]
  :     err = FSGetVolumeParms( volRefNum, &volumeParms, sizeof( volumeParms ) );
  :           ^
  : /System/Library/Frameworks/CoreServices.framework/Frameworks/CarbonCore.framework/Headers/Files.h:7247:18: note: 'FSGetVolumeParms' has been explicitly marked deprecated here
  : extern OSStatus  FSGetVolumeParms(FSVolumeRefNum volume, GetVolParmsInfoBuffer *buffer, ByteCount bufferSize) __OSX_AVAILABLE_BUT_DEPRECATED(__MAC_10_5, __MAC_10_8, __IPHONE_NA, __IPHONE_NA);
  :                  ^
  : 4 warnings generated.
  : /usr/bin/g++ -pipe -Wl,-S -fmessage-length=0 -Wall -arch x86_64 -g0 -O3 -mfpmath=sse -msse2 -DUSE_X265 -I./libhb/ -I./contrib/include -I./contrib/include/libxml2 -o HandBrakeCLI test/parsecsv.o test/test.o ./libhb/libhandbrake.a -framework IOKit -framework CoreServices -framework CoreText -framework CoreGraphics -framework AudioToolbox -framework Foundation -L./contrib/lib -lass -lavresample -lavformat -lavcodec -lavfilter -lavutil -lmp3lame -ldvdnav -ldvdread -lfribidi -lsamplerate -lswscale -lvpx -ltheoraenc -ltheoradec -lvorbis -lvorbisenc -logg -lx264 -lbluray -lfreetype -lxml2 -lbz2 -lz -ljansson -lharfbuzz -lopus -lx265 -liconv
  : ld: warning: text-based stub file /System/Library/Frameworks//AudioToolbox.framework/AudioToolbox.tbd and library file /System/Library/Frameworks//AudioToolbox.framework/AudioToolbox are out of sync. Falling back to library file for linking.
  : Undefined symbols for architecture x86_64:
  :   "_lzma_auto_decoder", referenced from:
  :       _xz_head in libxml2.a(xzlib.o)
  :   "_lzma_code", referenced from:
  :       _xz_decomp in libxml2.a(xzlib.o)
  :   "_lzma_end", referenced from:
  :       ___libxml2_xzclose in libxml2.a(xzlib.o)
  :   "_lzma_properties_decode", referenced from:
  :       _is_format_lzma in libxml2.a(xzlib.o)
  : ld: symbol(s) not found for architecture x86_64
  : clang: error: linker command failed with exit code 1 (use -v to see invocation)
  : make: *** [HandBrakeCLI] Error 1
-------------------------------------------------------------------------------
time end: Sun Dec 24 14:52:00 2017
duration: 5 minutes, 7 seconds (307.85s)
result: FAILURE (code 2)

It looks like a linker error? There are no other clang errors in the spew. Shall I attach a log for you?

[bradleysepos]

Nope, that gives me something to go on. Opened a new issue here: https://github.com/HandBrake/HandBrake/issues/1075

[donmelton]

@bradleysepos To reiterate my comment from #1075:

Thanks for the special build!

OK, that's much improved as far handling line endings goes. But it still stutters when piped. By that I mean, I'm getting less than half the same number of progress lines in the pipe as I would if HandBrakeCLI is not piped.

Honestly, I thought it was hung at first. So something is still broken here.

But I can't re-open the bug the bug I originally filed to report that the regression is not (quite) fixed yet.

[donmelton]

@bradleysepos As I just mentioned in your commit, that should fix it. Thanks!

I'll verify as soon as I can build and let you know.

Happy Holidays!

[bradleysepos]

https://www.dropbox.com/sh/hchz3l4b8usbw6y/AAB5XDa-ulO0WWnych9iTEQba?dl=0&lst=

[donmelton]

@bradleysepos Woo hoo! Yeah, I can confirm that fixed it. Thanks so much for doing this on Christmas Eve. :)

Again, Happy Holidays, sir!

[bradleysepos]

No problem. ;) Best to you and yours.