CLI not completing, but says it is.

HandBrake for Mac support
Forum rules
An Activity Log is required for support requests. Please read How-to get an activity log? for details on how and why this should be provided.
Post Reply
mikejandreau
Posts: 6
Joined: Sun Sep 09, 2018 1:27 pm

CLI not completing, but says it is.

Post by mikejandreau » Sun Sep 09, 2018 1:32 pm

Description of problem or question:
I'm trying to link up the CLI with some folder automation, to automatically run on files when I move them to a directory. The CLI runs for a while, and thinks it's completed, but the resulting file is only 48bytes (or around that size. It varies based on source file)

Steps to reproduce the problem (If Applicable):
Whether I run a custom script, or run the CLI right from Terminal, the result is the same.
For example, I'm testing with the film Tag:

Code: Select all

/Applications/HandBrakeCLI -i Tag (2018).mkv -o Tag (2018).m4v --preset="Normal" -v
The result, after Handbrake's CLI says it's done is my original file and one that's 48 bytes, like so: http://take.ms/knvUH

If I run that same file through the GUI, it works perfectly. What's noteworthy here is that while the GUI is running, the output file is also 48 bytes, until the GUI reports it's done. Then it's the proper size and the file works.

HandBrake version (e.g., 1.0.0):
CLI.

Operating system and version (e.g., Ubuntu 16.04 LTS, macOS 10.13 High Sierra, Windows 10 Creators Update):
Mac OS X 10.13.6

HandBrake Activity Log ***required*** (see How-to get an activity log)

Code: Select all

Pennyworth:TBP Alfred$ /Applications/HandBrakeCLI -i Tag (2018).mkv -o Tag (2018).m4v --preset="Normal" -v
-bash: syntax error near unexpected token `('
Pennyworth:TBP Alfred$ /Applications/HandBrakeCLI -i "Tag (2018).mkv" -o "Tag (2018).m4v" --preset="Normal" -v
[08:27:14] hb_init: starting libhb thread
[08:27:14] thread 700000d6f000 started ("libhb")
HandBrake 1.1.1 (2018061800) - Darwin x86_64 - https://handbrake.fr
12 CPUs detected
Opening Tag (2018).mkv...
[08:27:14] CPU: Intel(R) Xeon(R) CPU E5-1650 v2 @ 3.50GHz
[08:27:14]  - Intel microarchitecture Ivy Bridge
[08:27:14]  - logical processor count: 12
[08:27:14] hb_scan: path=Tag (2018).mkv, title_index=1
udfread ERROR: ECMA 167 Volume Recognition failed
disc.c:323: failed opening UDF image Tag (2018).mkv
disc.c:424: error opening file BDMV/index.bdmv
disc.c:424: error opening file BDMV/BACKUP/index.bdmv
[08:27:14] bd: not a bd - trying as a stream/file instead
libdvdnav: Using dvdnav version 5.0.3
libdvdread: Encrypted DVD support unavailable.
libdvdread:DVDOpenFileUDF:UDFFindFile /VIDEO_TS/VIDEO_TS.IFO failed
libdvdread:DVDOpenFileUDF:UDFFindFile /VIDEO_TS/VIDEO_TS.BUP failed
libdvdread: Can't open file VIDEO_TS.IFO.
libdvdnav: vm: failed to read VIDEO_TS.IFO
[08:27:14] dvd: not a dvd - trying as a stream/file instead
Input #0, matroska,webm, from 'Tag (2018).mkv':
  Duration: 01:40:33.91, start: 0.000000, bitrate: N/A
    Stream #0:0(eng): Video: h264 (High)
      yuv420p, 1920x808, PAR 1:1 DAR 240:101
      23.98 fps, 1k tbn (default)
    Metadata:
      BPS-eng         : 9379199
      DURATION-eng    : 01:40:33.903000000
      NUMBER_OF_FRAMES-eng: 144669
      NUMBER_OF_BYTES-eng: 7074147683
      _STATISTICS_WRITING_APP-eng: mkvmerge v25.0.0 ('Prog Noir') 64-bit
      _STATISTICS_WRITING_DATE_UTC-eng: 2018-08-11 08:43:02
      _STATISTICS_TAGS-eng: BPS DURATION NUMBER_OF_FRAMES NUMBER_OF_BYTES
    Stream #0:1(eng): Audio: dts (DTS)
      48000 Hz, 5.1, fltp, 1536 kb/s (default)
    Metadata:
      BPS-eng         : 1508999
      DURATION-eng    : 01:40:33.910000000
      NUMBER_OF_FRAMES-eng: 565679
      NUMBER_OF_BYTES-eng: 1138146148
      _STATISTICS_WRITING_APP-eng: mkvmerge v25.0.0 ('Prog Noir') 64-bit
      _STATISTICS_WRITING_DATE_UTC-eng: 2018-08-11 08:43:02
      _STATISTICS_TAGS-eng: BPS DURATION NUMBER_OF_FRAMES NUMBER_OF_BYTES
[08:27:14] scan: decoding previews for title 1
[08:27:14] scan: audio 0x1: dca, rate=48000Hz, bitrate=1536000 English (DTS) (5.1 ch)
Scanning title 1 of 1, preview 8, 80.00 %[08:27:14] scan: 10 previews, 1920x808, 23.976 fps, autocrop = 2/2/0/0, aspect 2.38:1, PAR 1:1
[08:27:14] libhb: scan thread found 1 valid title(s)
+ Using preset: Normal
+ title 1:
  + stream: Tag (2018).mkv
  + duration: 01:40:33
  + size: 1920x808, pixel aspect: 1/1, display aspect: 2.38, 23.976 fps
  + autocrop: 2/2/0/0
  + chapters:
    + 1: cells 0->0, 0 blocks, duration 01:40:33
  + audio tracks:
    + 1, English (DTS) (5.1 ch) (iso639-2: eng), 48000Hz, 1536000bps
  + subtitle tracks:
[08:27:15] 1 job(s) to process
[08:27:15] json job:
{
    "Audio": {
        "AudioList": [
            {
                "Bitrate": 160,
                "CompressionLevel": -1.0,
                "DRC": 0.0,
                "DitherMethod": "auto",
                "Encoder": "ca_aac",
                "Gain": 0.0,
                "Mixdown": "dpl2",
                "NormalizeMixLevel": false,
                "PresetEncoder": "ca_aac",
                "Quality": -3.0,
                "Samplerate": 0,
                "Track": 0
            }
        ],
        "CopyMask": [
            "copy:aac",
            "copy:ac3",
            "copy:dts",
            "copy:dtshd",
            "copy:eac3",
            "copy:flac",
            "copy:mp3",
            "copy:truehd"
        ],
        "FallbackEncoder": "ac3"
    },
    "Destination": {
        "AlignAVStart": false,
        "ChapterList": [
            {
                "Name": ""
            }
        ],
        "ChapterMarkers": false,
        "File": "Tag (2018).m4v",
        "InlineParameterSets": false,
        "Mp4Options": {
            "IpodAtom": false,
            "Mp4Optimize": false
        },
        "Mux": "m4v"
    },
    "Filters": {
        "FilterList": [
            {
                "ID": 6,
                "Settings": {
                    "mode": 0
                }
            },
            {
                "ID": 11,
                "Settings": {
                    "crop-bottom": 2,
                    "crop-left": 0,
                    "crop-right": 0,
                    "crop-top": 2,
                    "height": 804,
                    "width": 1920
                }
            }
        ]
    },
    "Metadata": {},
    "PAR": {
        "Den": 1,
        "Num": 1
    },
    "SequenceID": 0,
    "Source": {
        "Angle": 0,
        "Path": "Tag (2018).mkv",
        "Range": {
            "End": 1,
            "Start": 1,
            "Type": "chapter"
        },
        "Title": 1
    },
    "Subtitle": {
        "Search": {
            "Burn": true,
            "Default": false,
            "Enable": false,
            "Forced": false
        },
        "SubtitleList": []
    },
    "Video": {
        "ColorMatrixCode": 0,
        "Encoder": "x264",
        "Level": "4.0",
        "Options": "",
        "Preset": "veryfast",
        "Profile": "main",
        "QSV": {
            "AsyncDepth": 4,
            "Decode": false
        },
        "Quality": 20.0,
        "Tune": "",
        "Turbo": false,
        "TwoPass": false
    }
}
[08:27:15] starting job
[08:27:15] job configuration:
[08:27:15]  * source
[08:27:15]    + Tag (2018).mkv
[08:27:15]    + title 1, chapter(s) 1 to 1
[08:27:15]    + container: matroska,webm
[08:27:15]  * destination
[08:27:15]    + Tag (2018).m4v
[08:27:15]    + container: MPEG-4 (libavformat)
[08:27:15]  * video track
[08:27:15]    + decoder: h264
[08:27:15]    + filters
[08:27:15]      + Framerate Shaper (mode=0)
[08:27:15]        + frame rate: same as source (around 23.976 fps)
[08:27:15]      + Crop and Scale (width=1920:height=804:crop-top=2:crop-bottom=2:crop-left=0:crop-right=0)
[08:27:15]        + source: 1920 * 808, crop (2/2/0/0): 1920 * 804, scale: 1920 * 804
[08:27:15]    + Output geometry
[08:27:15]      + storage dimensions: 1920 x 804
[08:27:15]      + pixel aspect ratio: 1 : 1
[08:27:15]      + display dimensions: 1920 x 804
[08:27:15]    + encoder: H.264 (libx264)
[08:27:15]      + preset:  veryfast
[08:27:15]      + profile: main
[08:27:15]      + level:   4.0
[08:27:15]      + quality: 20.00 (RF)
[08:27:15]  * audio track 1
[08:27:15]    + decoder: English (DTS) (5.1 ch) (track 1, id 0x1)
[08:27:15]      + bitrate: 1536 kbps, samplerate: 48000 Hz
[08:27:15]    + mixdown: Dolby Pro Logic II
[08:27:15]    + encoder: AAC (Apple AudioToolbox)
[08:27:15]      + bitrate: 160 kbps, samplerate: 48000 Hz
[08:27:15] sync: expecting 144669 video frames
[08:27:15] encx264: min-keyint: 24, keyint: 240
[08:27:15] encx264: encoding at constant RF 20.000000
[08:27:15] encx264: unparsed options: level=4.0:ref=1:8x8dct=0:weightp=1:subme=2:mixed-refs=0:trellis=0:vbv-bufsize=25000:vbv-maxrate=20000:rc-lookahead=10
x264 [info]: using SAR=1/1
x264 [info]: using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX
x264 [info]: profile Main, level 4.0
[08:27:15] sync: first pts video is 0
[08:27:15] sync: Chapter 1 at frame 1 time 0
[08:27:15] sync: first pts audio 0x1 is 0
Encoding: task 1 of 1, 99.91 % (237.67 fps, avg 112.05 fps, ETA 00h00m01s)[08:48:45] reader: done. 1 scr changes
Encoding: task 1 of 1, 99.97 % (237.67 fps, avg 112.05 fps, ETA 00h00m01s)[08:48:45] work: average encoding speed for job is 112.047203 fps
Encoding: task 1 of 1, 99.97 % (237.67 fps, avg 112.05 fps, ETA 00h00m01s)[08:48:45] vfr: lost time: 0 (0 frames)
[08:48:45] vfr: gained time: 0 (0 frames) (0 not accounted for)
[08:48:45] dca-decoder done: 565679 frames, 0 decoder errors
[08:48:45] h264-decoder done: 144669 frames, 0 decoder errors
[08:48:45] sync: got 144669 frames, 144669 expected
[08:48:45] sync: framerate min 23.981 fps, max 23.981 fps, avg 23.976 fps
x264 [info]: frame I:2547  Avg QP:16.72  size:116464
x264 [info]: frame P:42276 Avg QP:19.67  size: 27948
x264 [info]: frame B:99846 Avg QP:20.78  size:  8096
x264 [info]: consecutive B-frames:  6.1%  4.1%  4.7% 85.1%
x264 [info]: mb I  I16..4: 45.2%  0.0% 54.8%
x264 [info]: mb P  I16..4: 21.1%  0.0%  8.4%  P16..4: 28.8% 11.1%  5.1%  0.0%  0.0%    skip:25.6%
x264 [info]: mb B  I16..4:  3.3%  0.0%  0.8%  B16..8: 17.6%  4.7%  0.4%  direct:10.9%  skip:62.4%  L0:38.4% L1:48.1% BI:13.5%
x264 [info]: coded y,uvDC,uvAC intra: 40.9% 61.9% 22.8% inter: 6.9% 16.3% 0.4%
x264 [info]: i16 v,h,dc,p: 42% 23% 19% 16%
x264 [info]: i4 v,h,dc,ddl,ddr,vr,hd,vl,hu: 26% 18% 16%  7%  8%  7%  7%  6%  5%
x264 [info]: i8c dc,h,v,p: 51% 20% 25%  5%
x264 [info]: Weighted P-Frames: Y:0.9% UV:0.4%
x264 [info]: kb/s:3031.60
[08:48:45] mux: track 0, 144669 frames, 2286459970 bytes, 3031.46 kbps, fifo 2048
[08:48:45] mux: track 1, 282842 frames, 122203485 bytes, 162.02 kbps, fifo 4096
[08:48:45] libhb: work result = 0

Encode done!

HandBrake has exited.
I'd appreciate any help anyone can give me. I'd love to get this automation working properly!

rollin_eng
Veteran User
Posts: 2905
Joined: Wed May 04, 2011 11:06 pm

Re: CLI not completing, but says it is.

Post by rollin_eng » Sun Sep 09, 2018 2:28 pm

HB has run successfully, your screenshot shows a time of 9:18 but HB finished at 8:48, is something running after HB?

Woodstock
Veteran User
Posts: 2818
Joined: Tue Aug 27, 2013 6:39 am

Re: CLI not completing, but says it is.

Post by Woodstock » Sun Sep 09, 2018 3:29 pm

Did you try playing the m4v file?

I've read that Finder has one of the same "features" as Windows Explorer, that it caches file information in weird ways. It notices that a file has been created, but it sometimes does not update that information willingly as the file changes size. File size can change with no change in Finder/Explorer, and even new files can be created, with no change in Finder/Explorer.

mikejandreau
Posts: 6
Joined: Sun Sep 09, 2018 1:27 pm

Re: CLI not completing, but says it is.

Post by mikejandreau » Sun Sep 09, 2018 3:34 pm

Nothing is running after. Edit: that’s not true. Hazel is running to change the color of the tag, so it doesn’t run the CLI again.

I’ll try just the CLI script when I get back home. I’ll also try some other files, just in case. Maybe I’ll find a file that’s a few mega so I can test faster than waiting an hour.

I tried playing the file and it was 2 seconds long.

mikejandreau
Posts: 6
Joined: Sun Sep 09, 2018 1:27 pm

Re: CLI not completing, but says it is.

Post by mikejandreau » Mon Sep 10, 2018 8:55 pm

It must have been something with the few files I was testing. It's working a treat now and tied in nicely with Hazel and Filebot to fully automate all of the work I'd been doing manually.

Post Reply