AMC script skips video files in subfolders

[korzynski]

The AMC script appears to silently skip movie files when they are more than 1 level deep.

When I run the AMC script directly on a folder that contains movie files, it processes the movie files and ignores the video extras, as expected.

However, if I instead run the script against the parent folder that contains subfolders with movie files, then the script appears to processes the subfolders and reports ignoring the video extras within, but it does not process the movie files and the logs contain no indication that they even exist. This occurs whether the script is run with the test or the move action.

I don't know if it's related, but when I run the script against the parent folder with the move action, the log also contains numerous errors stating "Failed to read media characteristics: DateTimeParseException: Text 'UTC 2017-05-03 02:52:50 / UTC 2017-04-30 18:00:28' could not be parsed, unparsed text found at index 23". These errors don't occur when the script runs with the move action against a subfolder, or with the test action against the parent or subfolder.

I am running the FileBot docker container rednoah/filebot under CentOS 7
The media source and destination are located on an NFS share hosted on a Synology NAS and mounted at /mnt/Media

An excerpt of the folder tree at /mnt/Media/Library/

Code: Select all

.
└── CouchPotato
    ├── 100\ Bloody\ Acres\ (2012)
    │   ├── 100\ Bloody\ AcresBR-Rip-fanart.jpg
    │   ├── 100\ Bloody\ AcresBR-Rip.mkv
    │   ├── 100\ Bloody\ AcresBR-Rip.nfo
    │   ├── 100\ Bloody\ AcresBR-Rip.tbn
    │   └── 100\ Bloody\ AcresBR-Rip-trailer.mp4
    ├── 10x10\ (2018)\ [tt6210996]
    │   ├── 10x10\ (2018)
    │   └── 10x10\ (2018)\ -\ HD\ 720p\ H264\ AC3\ 6ch.mkv
    ├── 12\ Angry\ Men.1957.HD(tt0050083)
    │   └── 12\ Angry\ Men.1957.1080p.AC3.H264.mkv
    ├── 12\ Years\ a\ Slave\ (2013)
    │   ├── 12\ Years\ a\ SlaveBR-Rip-fanart.jpg
    │   ├── 12\ Years\ a\ SlaveBR-Rip.mkv
    │   ├── 12\ Years\ a\ SlaveBR-Rip.nfo
    │   ├── 12\ Years\ a\ SlaveBR-Rip.srt
    │   └── 12\ Years\ a\ SlaveBR-Rip.tbn
    └── 13\ Assassins\ (2010)
        ├── 13\ Assassins.2010.720p.6.XVID.avi
        ├── 13\ Assassins.2010.720p.6.XVID-trailer.mov
        └── 13\ Assassins\ (2010).sfv

Heres my command line for scanning a subfolder

Code: Select all

docker run --rm -it -v /mnt/Media:/volume1 -v data:/data rednoah/filebot -script 'fn:amc' '/volume1/Library/CouchPotato/100 Bloody Acres (2012)' --output '/volume1/Library' --action test --conflict auto --lang en --def 'ut_label=Movie' 'artwork=y' 'skipExtract=y' 'clean=n' 'unsorted=y' 'movieFormat={plex.derive{" [$vs-$vf][$ac][$channels][$vc]"}}' excludeList='/volume1/filebot/excludes.txt' --apply refresh --log all --log-file '/volume1/filebot/filebot.log'

And the log result:

Code: Select all

[2020-06-19 03:29:22.599] Using persistent disk cache: /data/.filebot/cache/0
[2020-06-19 03:29:28.497] Run script [fn:amc] at [Fri Jun 19 03:29:28 GMT 2020]
[2020-06-19 03:29:28.531] Parameter: ut_label = Movie
[2020-06-19 03:29:28.532] Parameter: artwork = y
[2020-06-19 03:29:28.532] Parameter: skipExtract = y
[2020-06-19 03:29:28.532] Parameter: clean = n
[2020-06-19 03:29:28.532] Parameter: unsorted = y
[2020-06-19 03:29:28.533] Parameter: movieFormat = {plex.derive{" [$vs-$vf][$ac][$channels][$vc]"}}
[2020-06-19 03:29:28.533] Parameter: excludeList = /volume1/filebot/excludes.txt
[2020-06-19 03:29:28.538] Argument[0]: /volume1/Library/CouchPotato/100 Bloody Acres (2012)
[2020-06-19 03:29:28.682] Use excludes: /volume1/filebot/excludes.txt
[2020-06-19 03:29:28.750] Ignore video extra: /volume1/Library/CouchPotato/100 Bloody Acres (2012)/100 Bloody AcresBR-Rip-trailer.mp4
[2020-06-19 03:29:28.891] Input: /volume1/Library/CouchPotato/100 Bloody Acres (2012)/100 Bloody AcresBR-Rip.mkv
[2020-06-19 03:29:28.900] Process as Movie [Movie]
[2020-06-19 03:29:28.908] Group: {Movie=true} => [100 Bloody AcresBR-Rip.mkv]
[2020-06-19 03:29:29.013] Rename movies using [TheMovieDB]
[2020-06-19 03:29:29.493] [TEST] from [/volume1/Library/CouchPotato/100 Bloody Acres (2012)/100 Bloody AcresBR-Rip.mkv] to [/volume1/Library/Movies/100 Bloody Acres (2012)/100 Bloody Acres (2012).mkv]
[2020-06-19 03:29:29.493] Processed 1 files
[2020-06-19 03:29:29.499] Done ヾ(＠⌒ー⌒＠)ノ

And here is the command I ran against the parent folder:

Code: Select all

docker run --rm -it -v /mnt/Media:/volume1 -v data:/data rednoah/filebot -script 'fn:amc' '/volume1/Library/CouchPotato' --output '/volume1/Library' --action test --conflict auto --lang en --def 'ut_label=Movie' 'artwork=y' 'skipExtract=y' 'clean=n' 'unsorted=y' 'movieFormat={plex.derive{" [$vs-$vf][$ac][$channels][$vc]"}}' excludeList='/volume1/filebot/excludes.txt' --apply refresh --log all --log-file '/volume1/filebot/filebot.log'

And the log result:

Code: Select all

[2020-06-19 03:33:18.372] Using persistent disk cache: /data/.filebot/cache/0
[2020-06-19 03:33:23.539] Run script [fn:amc] at [Fri Jun 19 03:33:23 GMT 2020]
[2020-06-19 03:33:23.571] Parameter: ut_label = Movie
[2020-06-19 03:33:23.572] Parameter: artwork = y
[2020-06-19 03:33:23.572] Parameter: skipExtract = y
[2020-06-19 03:33:23.572] Parameter: clean = n
[2020-06-19 03:33:23.572] Parameter: unsorted = y
[2020-06-19 03:33:23.573] Parameter: movieFormat = {plex.derive{" [$vs-$vf][$ac][$channels][$vc]"}}
[2020-06-19 03:33:23.573] Parameter: excludeList = /volume1/filebot/excludes.txt
[2020-06-19 03:33:23.578] Argument[0]: /volume1/Library/CouchPotato
[2020-06-19 03:33:23.746] Use excludes: /volume1/filebot/excludes.txt (1)
[2020-06-19 03:33:24.617] Ignore video extra: /volume1/Library/CouchPotato/100 Bloody Acres (2012)/100 Bloody AcresBR-Rip-trailer.mp4
[2020-06-19 03:33:24.833] Ignore hidden: /volume1/Library/CouchPotato/12 Years a Slave (2013)/.@__thumb
[2020-06-19 03:33:24.872] Ignore video extra: /volume1/Library/CouchPotato/13 Assassins (2010)/13 Assassins.2010.720p.6.XVID-trailer.mov

Note that the script logged skipping video extras for 100 Bloody Acres, 12 Years a Slave, and 13 Assassins, but it did not log anything about the movie files in those folders, nor the files in the folders for 10x10 or 12 Angry Men.

Heres my sysinfo:

Code: Select all

[2020-06-19 03:36:16.978] Using persistent disk cache: /data/.filebot/cache/0
FileBot 4.9.1 (r7372)
JNA Native: 5.2.0
MediaInfo: 17.12
[2020-06-19 03:36:19.539] Execute [7z]

7-Zip [64] 16.02 : Copyright (c) 1999-2016 Igor Pavlov : 2016-05-21
p7zip Version 16.02 (locale=C.UTF-8,Utf16=on,HugeFiles=on,64 bits,4 CPUs Intel(R) Core(TM) i7-4790 CPU @ 3.60GHz (306C3),ASM,AES-NI)

Usage: 7z <command> [<switches>...] <archive_name> [<file_names>...]
       [<@listfiles...>]

<Commands>
  a : Add files to archive
  b : Benchmark
  d : Delete files from archive
  e : Extract files from archive (without using directory names)
  h : Calculate hash values for files
  i : Show information about supported formats
  l : List contents of archive
  rn : Rename files in archive
  t : Test integrity of archive
  u : Update files to archive
  x : eXtract files with full paths

<Switches>
  -- : Stop switches parsing
  -ai[r[-|0]]{@listfile|!wildcard} : Include archives
  -ax[r[-|0]]{@listfile|!wildcard} : eXclude archives
  -ao{a|s|t|u} : set Overwrite mode
  -an : disable archive_name field
  -bb[0-3] : set output log level
  -bd : disable progress indicator
  -bs{o|e|p}{0|1|2} : set output stream for output/error/progress line
  -bt : show execution time statistics
  -i[r[-|0]]{@listfile|!wildcard} : Include filenames
  -m{Parameters} : set compression Method
    -mmt[N] : set number of CPU threads
  -o{Directory} : set Output directory
  -p{Password} : set Password
  -r[-|0] : Recurse subdirectories
  -sa{a|e|s} : set Archive name mode
  -scc{UTF-8|WIN|DOS} : set charset for for console input/output
  -scs{UTF-8|UTF-16LE|UTF-16BE|WIN|DOS|{id}} : set charset for list files
  -scrc[CRC32|CRC64|SHA1|SHA256|*] : set hash function for x, e, h commands
  -sdel : delete files after compression
  -seml[.] : send archive by email
  -sfx[{name}] : Create SFX archive
  -si[{name}] : read data from stdin
  -slp : set Large Pages mode
  -slt : show technical information for l (List) command
  -snh : store hard links as links
  -snl : store symbolic links as links
  -sni : store NT security information
  -sns[-] : store NTFS alternate streams
  -so : write data to stdout
  -spd : disable wildcard matching for file names
  -spe : eliminate duplication of root folder for extract command
  -spf : use fully qualified file paths
  -ssc[-] : set sensitive case mode
  -ssw : compress shared files
  -stl : set archive timestamp from the most recently modified file
  -stm{HexMask} : set CPU thread affinity mask (hexadecimal number)
  -stx{Type} : exclude archive type
  -t{Type} : Set type of archive
  -u[-][p#][q#][r#][x#][y#][z#][!newArchiveName] : Update options
  -v{Size}[b|k|m|g] : Create volumes
  -w[{path}] : assign Work directory. Empty path means a temporary directory
  -x[r[-|0]]{@listfile|!wildcard} : eXclude filenames
  -y : assume Yes on all queries

p7zip: p7zip Version 16.02 (locale=C.UTF-8,Utf16=on,HugeFiles=on,64 bits,4 CPUs Intel(R) Core(TM) i7-4790 CPU @ 3.60GHz (306C3),ASM,AES-NI)
[2020-06-19 03:36:19.622] Execute [unrar]

UNRAR 5.50 freeware      Copyright (c) 1993-2017 Alexander Roshal

Usage:     unrar <command> -<switch 1> -<switch N> <archive> <files...>
               <@listfiles...> <path_to_extract\>

<Commands>
  e             Extract files without archived paths
  l[t[a],b]     List archive contents [technical[all], bare]
  p             Print file to stdout
  t             Test archive files
  v[t[a],b]     Verbosely list archive contents [technical[all],bare]
  x             Extract files with full path

<Switches>
  -             Stop switches scanning
  @[+]          Disable [enable] file lists
  ad            Append archive name to destination path
  ag[format]    Generate archive name using the current date
  ai            Ignore file attributes
  ap<path>      Set path inside archive
  c-            Disable comments show
  cfg-          Disable read configuration
  cl            Convert names to lower case
  cu            Convert names to upper case
  dh            Open shared files
  ep            Exclude paths from names
  ep3           Expand paths to full including the drive letter
  f             Freshen files
  id[c,d,p,q]   Disable messages
  ierr          Send all messages to stderr
  inul          Disable all messages
  kb            Keep broken extracted files
  n<file>       Additionally filter included files
  n@            Read additional filter masks from stdin
  n@<list>      Read additional filter masks from list file
  o[+|-]        Set the overwrite mode
  ol[a]         Process symbolic links as the link [absolute paths]
  or            Rename files automatically
  ow            Save or restore file owner and group
  p[password]   Set password
  p-            Do not query password
  r             Recurse subdirectories
  sc<chr>[obj]  Specify the character set
  sl<size>      Process files with size less than specified
  sm<size>      Process files with size more than specified
  ta<date>      Process files modified after <date> in YYYYMMDDHHMMSS format
  tb<date>      Process files modified before <date> in YYYYMMDDHHMMSS format
  tn<time>      Process files newer than <time>
  to<time>      Process files older than <time>
  ts[m|c|a]     Save or restore file time (modification, creation, access)
  u             Update files
  v             List all volumes
  ver[n]        File version control
  vp            Pause before each volume
  x<file>       Exclude specified file
  x@            Read file names to exclude from stdin
  x@<list>      Exclude files listed in specified list file
  y             Assume Yes on all queries

unrar: UNRAR 5.50 freeware
[2020-06-19 03:36:20.658] Execute [fpcalc, -version]
fpcalc version 1.4.3

Chromaprint: 1.4.3
[2020-06-19 03:36:20.684] Write [xattr:net.filebot.metadata] {"@type":"date","value":1592537780675}
Extended Attributes: OK
Unicode Filesystem: OK
Script Bundle: 2020-06-12 (r652)
Groovy: 3.0.3
JRE: OpenJDK Runtime Environment 11.0.6
JVM: 64-bit OpenJDK 64-Bit Server VM
CPU/MEM: 4 Core / 1.5 GB Max Memory / 45 MB Used Memory
OS: Linux (amd64)
HW: Linux 1adb79f8d7d9 3.10.0-1127.8.2.el7.x86_64 #1 SMP Tue May 12 16:57:42 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
STORAGE: overlay [/] @ 20 GB | nfs4 [/volume1] @ 5 TB | xfs [/data] @ 20 GB | xfs [/etc/resolv.conf] @ 20 GB | xfs [/etc/hostname] @ 20 GB | xfs [/etc/hosts] @ 20 GB
DATA: /data/.filebot
Package: DOCKER
License: FileBot License P15380663 (Valid-Until: 2021-06-22)
[2020-06-19 03:36:21.327] Done ヾ(＠⌒ー⌒＠)ノ

[korzynski]

Also, since the NFS mount doesn't support xattr, I have enabled the option to store metadata in plain text files:

Code: Select all

[2020-06-19 04:10:27.554] Using persistent disk cache: /data/.filebot/cache/0
#FileBot System Properties
#Tue Jun 16 01:02:25 GMT 2020
net.filebot.logging.debug=ALL
net.filebot.xattr.store=.xattr
net.filebot.logging.time=true

[rednoah]

This log entry tells us that permissions are ok since FileBot was able to traverse the folder structure:

Code: Select all

Ignore video extra: /volume1/Library/CouchPotato/100 Bloody Acres (2012)/100 Bloody AcresBR-Rip-trailer.mp4

This log entry tells us that there is at least one file path that is explicitly excluded because it has been processed already:

Code: Select all

/volume1/filebot/excludes.txt (1)

Perhaps this one file isn't processed the second time around because it's not supposed to be processed a second time as per --def excludeList option?


If it can see some files, but not others, then that would indicate a NFS issue. Perhaps you only copied the beginning of the log and that why it seems to stop abruptly, but if you really have dozens of files, and it's only listing a few ones from the first folder, and then crashes and stops logging, that would be most strange indeed.

My first check would be to list files with FileBot to see the file system that FileBot sees through the docker and NFS abstraction layers:

Code: Select all

filebot -mediainfo -r /path/to/CouchPotato --format "{f}"

net.filebot.logging.debug=ALL will flood you with logging, which may or may not be useful. In this case, it's probably going to prevent us from seeing the problem by flooding us with logging irrelevant to local file system operations.

[korzynski]

This log entry tells us that there is at least one file path that is explicitly excluded because it has been processed already:

That's very strange, because the excludes.txt file is empty

The log file ends abruptly because I terminated the process after the first couple of folders. I have let it run through the entire folder tree, but it does the same thing on all of the folders and so I thought the included data would be enough to demonstrate the problem.

I use the mediainfo tool and it lists all of the files, including the ones that are skipped by the amc script.

So I tried copying a handful of movie subfolders to a new parent directory in order to run a full test scan without having to terminate it in the middle, and surprisingly it worked! The AMC script logged all of the files and correctly identified the movie files.

I suspect that this is somehow related to permissions, but don't know yet why this problem would only occur when scanning the parent folder and not when scanning a subfolder, since the permissions are the same on all folders. But the permissions are pretty janky since I'm accessing the files from within a Docker container running on CentOS over a mounted NFS share hosted on a Synology Btrfs filesystem using ACL permissions. I'm still trying to figure it out, but it seems like its probably not a problem with FileBot.

I'll post back here if/when I figure it out

[korzynski]

I think that the main issue was my misunderstanding of how the script processes files. Since it appeared to be processing the folders in alphabetical order, I assumed that I should see a log entry for each movie file as it encountered each folder. But it looks like it doesn't log the movie files until it's finished scanning through the entire folder tree and logged any skipped files or processing exceptions.

Since I have about 15,000 files in total, this first phase takes a long time, and I never waited long enough for it to finish logging the exceptions and get to the live media files. I assumed it wasn't working and terminated the script.

I ultimately installed FileBot on the Synology NAS directly to remove the complexity described in my previous post. It's working now, but I assume it would've also worked over the NFS mount as well if I just let it run long enough.

[rednoah]

Perhaps you only copied the beginning of the log and that why it seems to stop abruptly, ...

Well, I guess it's always a good idea to look at the complete log, or to run the amc script on only a single folder for testing, if the complete complete log isn't feasible.