Failed to process [A] because [B] is an exact copy and already exists

Running FileBot from the console, Groovy / FileBot scripting, shell scripts, etc
Post Reply
grsjst
Posts: 4
Joined: 25 Sep 2021, 16:47

Failed to process [A] because [B] is an exact copy and already exists

Post by grsjst »

Hello,

I am using an adapted version of https://github.com/filebot/plugins/blob ... process.sh, which in principle behaves as expected. However, I am a bit puzzled by the time it needs to complete (> 11 mins).

Find the log below:

Code: Select all

time TR_TORRENT_DIR=/volume1/downloads/video/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO  TR_TORRENT_NAME=Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi ./transmission-postprocess.sh
TR_TORRENT_DIR=/volume1/downloads/video/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO
TR_TORRENT_NAME=Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi
Run script [fn:amc] at [Sat Sep 25 18:50:35 CEST 2021]
Parameter: unsorted = y
Parameter: music = y
Parameter: artwork = y
Parameter: excludeList = .excludes
Parameter: ut_dir = /volume1/downloads/video/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi
Parameter: ut_kind = multi
Parameter: ut_title = Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi
Parameter: ut_label = N/A
Parameter: subtitles = eng,nld,fra
Parameter: clean = y
Parameter: skipExtract = y
Parameter: plex = *****
Use excludes: /volume1/video/.excludes (2055)
Input: /volume1/downloads/video/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi
Group: {Movie=Space Jam: A New Legacy (2021)} => [Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi]
Get [English] subtitles for 1 files
Please enter your login details by calling `filebot -script fn:configure`
Get [Dutch] subtitles for 1 files
Please enter your login details by calling `filebot -script fn:configure`
Get [French] subtitles for 1 files
Please enter your login details by calling `filebot -script fn:configure`
Rename movies using [TheMovieDB]
Auto-detect movie from context [/volume1/downloads/video/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi]
Failed to process [/volume1/downloads/video/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi] because [/volume1/video/Movies/Space Jam - A New Legacy (2021)/Space Jam - A New Legacy (2021).avi] is an exact copy and already exists [Last-Modified: Wed Sep 22 22:46:42 CEST 2021]
Processed 0 files
Processing 1 unsorted files
Skipped [/volume1/downloads/video/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi] because [/volume1/video/Unsorted/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi] already exists
Processed 0 files
Finished without processing any files
Abort (×_×)

real	11m44.664s
user	9m14.690s
sys	2m16.230s

I am running this on a synology DS218 (DSM7)

I was expecting the action to complete relatively fast (as it does on filebot-node) as it only concerns a single file. Yet it appears to be processing more than it needs to, but I am not entirely sure what (the "downloads" folder contains ~500G media files).

I'd like to ask if you have any idea what could be causing this? and otherwise perhaps some hints on how to debug this (i.e. help me identify where filebot is spending its time)

thanks much for any help you can give!
joost

The adapted transmission-postprocess.sh:

Code: Select all

#!/bin/bash
echo TR_TORRENT_DIR=$TR_TORRENT_DIR
echo TR_TORRENT_NAME=$TR_TORRENT_NAME

# Input Parameters
ARG_PATH="$TR_TORRENT_DIR/$TR_TORRENT_NAME"
ARG_NAME="$TR_TORRENT_NAME"
ARG_LABEL="N/A"

# Configuration
CONFIG_OUTPUT="/volume1/video"

export JAVA_OPTS="-Xmx512m"

/usr/local/bin/filebot -script fn:amc --output "$CONFIG_OUTPUT" --action hardlink --conflict auto -non-strict --order Airdate --log all --log-file filebot.log --lang en --apply refresh -no-xattr --def unsorted=y music=y artwork=y excludeList=".excludes" ut_dir="$ARG_PATH" ut_kind="multi" ut_title="$ARG_NAME" ut_label="$ARG_LABEL" subtitles="eng,nld,fra" clean=y skipExtract=y plex="192.168.1.128:ELRT7-236CsRyxwMTWam"
filebot -script fn:sysinfo

Code: Select all

filebot -script fn:sysinfo
Low Memory Limit: 168 MB
* Consider using JAVA_OPTS -Xmx384m or higher
* Consider using -no-index on low-memory devices
FileBot 4.9.4 (r8736)
JNA Native: 6.1.0
MediaInfo: 19.04
Tools: fpcalc/1.5.0 p7zip/16.02 unrar/5.70 ffprobe/2.7.7
Extended Attributes: OK
Unicode Filesystem: OK
Script Bundle: 2021-08-02 (r761)
Groovy: 3.0.8
JRE: OpenJDK Runtime Environment 16.0.2
JVM: 32-bit OpenJDK Client VM
CPU/MEM: 2 Core / 168 MB Max Memory / 25 MB Used Memory
OS: Linux (arm)
HW: Linux spidisk 3.10.108 #41890 SMP Thu Jul 15 03:40:54 CST 2021 armv7l GNU/Linux synology_monaco_ds216play
CPU/MEM: ARMv7 Processor rev 0 (v7l) | STi SoC with Flattened Device Tree [MemTotal: 689 MB | MemFree: 67 MB | SwapCached: 15 MB | SwapTotal: 2.1 GB | SwapFree: 1.7 GB]
STORAGE: ext4 [/] @ 1.2 GB | ext4 [/volume1] @ 2.2 TB | ext4 [/opt] @ 2.2 TB
USER: geurts
DATA: /var/packages/filebot/var/data/1026
Package: SPK
License: FileBot License P28891897 (Valid-Until: 2022-09-26)
User avatar
rednoah
The Source
Posts: 20177
Joined: 16 Nov 2011, 08:59

Re: transmission-postprocess.sh slow

Post by rednoah »

You'll want to run the command manually and observe the output to see if there's an obvious 10min gap between printing one line and the next?


My educated guess would be this line:

Code: Select all

Failed to process [A] because [B] is an exact copy and already exists [Last-Modified: Wed Sep 22 22:46:42 CEST 2021]
:!: If File A and File B have the same file size and last-modified date, and if File A and File B have in fact the exact same binary content, then filebot will end up reading File A and File B entirely as it's comparing them byte by byte, which can take a long time if the file is large and the drive is slow.


:arrow: The amc script has multiple options that prevent you from accidentally processing the same file over and over, by keeping track of already processed files, and preemptively excluding them in subsequent runs. Since you're using --action hardlink you can use --def excludeLink=y to preemptively exclude input files that have a link count of more than one already.
:idea: Please read the FAQ and How to Request Help.
grsjst
Posts: 4
Joined: 25 Sep 2021, 16:47

Re: Failed to process [A] because [B] is an exact copy and already exists

Post by grsjst »

Thanks for your help!

Actually, I am running the script manually (to ensure all works as expected when automating the whole). I was reprocessing the same file by removing it from the .excludes list, and therefore the message

Code: Select all

Failed to process [A] because [B] is an exact copy and already exists
didn't bother me too much.

However, after your hint that it may be performing a bitwise compare, i removed the destination file (which is a hardlink to the original file as you noticed already). The script now completes successfully (see log output below). It still takes over 8 minutes. though, which I find rather long, but perhaps this is normal? The bulk of the time seems to be spend after

Code: Select all

xattr: [Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi] => [Space Jam: A New Legacy (2021)] 
is printed. Any additional hints you may have are much appreciated!

thanks
joost

Code: Select all

time TR_TORRENT_DIR=/volume1/downloads/video/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO  TR_TORRENT_NAME=Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi ./transmission-postprocess.sh
+ ARG_PATH=/volume1/downloads/video/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi
+ ARG_NAME=Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi
+ ARG_LABEL=N/A
+ CONFIG_OUTPUT=/volume1/video
+ CONFIG_LOGFILE=filebot-tranmission.log
+ export JAVA_OPTS=-Xmx512m
+ JAVA_OPTS=-Xmx512m
+ /usr/local/bin/filebot -script fn:amc --output /volume1/video --action hardlink --conflict auto -non-strict --order Airdate --log all --log-file filebot-tranmission.log --lang en --apply refresh --def unsorted=y music=y artwork=y excludeList=.excludes ut_dir=/volume1/downloads/video/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi ut_kind=multi ut_title=Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi ut_label=N/A subtitles=eng,nld,fra clean=y skipExtract=y plex=192.168.1.128:ELRT7-236CsRyxwMTWam
Run script [fn:amc] at [Sat Oct 02 16:00:14 CEST 2021]
Parameter: unsorted = y
Parameter: music = y
Parameter: artwork = y
Parameter: excludeList = .excludes
Parameter: ut_dir = /volume1/downloads/video/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi
Parameter: ut_kind = multi
Parameter: ut_title = Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi
Parameter: ut_label = N/A
Parameter: subtitles = eng,nld,fra
Parameter: clean = y
Parameter: skipExtract = y
Parameter: plex = *****
Use excludes: /volume1/video/.excludes (2055)
Input: /volume1/downloads/video/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi
xattr: [Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi] => [Space Jam: A New Legacy (2021)]
Group: {Movie=Space Jam: A New Legacy (2021)} => [Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi]
Get [English] subtitles for 1 files
Please enter your login details by calling `filebot -script fn:configure`
Get [Dutch] subtitles for 1 files
Please enter your login details by calling `filebot -script fn:configure`
Get [French] subtitles for 1 files
Please enter your login details by calling `filebot -script fn:configure`
Rename movies using [TheMovieDB]
Auto-detect movie from context [/volume1/downloads/video/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi]
[HARDLINK] from [/volume1/downloads/video/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO/Space.Jam.a.New.Legacy.2021.HDRip.XviD.AC3-EVO.avi] to [/volume1/video/Movies/Space Jam - A New Legacy (2021)/Space Jam - A New Legacy (2021).avi]
[REFRESH] Refresh File Services (/volume1/video/Movies/Space Jam - A New Legacy (2021))
Processed 1 file
Fetching movie artwork for [Space Jam: A New Legacy (2021)] to [/volume1/video/Movies/Space Jam - A New Legacy (2021)]
Generate Movie NFO: Space Jam: A New Legacy [379686]
Fetching /volume1/video/Movies/Space Jam - A New Legacy (2021)/poster.jpg => [posters/2000x2964, en, 440344.0, https://image.tmdb.org/t/p/original/5bFK5d3mVTAvBCXi5NPWH0tYjKl.jpg]
Fetching /volume1/video/Movies/Space Jam - A New Legacy (2021)/fanart.jpg => [backdrops/3840x2160, 69854.0, https://image.tmdb.org/t/p/original/8s4h9friP6Ci3adRGahHARVd76E.jpg]
Fetching /volume1/video/Movies/Space Jam - A New Legacy (2021)/clearart.png => [hdmovieclearart, en, 5.0, https://assets.fanart.tv/fanart/movies/379686/hdmovieclearart/space-jam-a-new-legacy-60f1962e65ee6.png]
Fetching /volume1/video/Movies/Space Jam - A New Legacy (2021)/logo.png => [hdmovielogo, en, 10.0, https://assets.fanart.tv/fanart/movies/379686/hdmovielogo/space-jam-a-new-legacy-606664b98d584.png]
Fetching /volume1/video/Movies/Space Jam - A New Legacy (2021)/disc.png => [moviedisc/bluray, en, 4.0, https://assets.fanart.tv/fanart/movies/379686/moviedisc/space-jam-a-new-legacy-60f19db0907c8.png]
Notify Plex: [host:192.168.1.128, token:ELRT7-236CsRyxwMTWam]
GET: http://192.168.1.128:32400/library/sections/all/refresh?X-Plex-Token=ELRT7-236CsRyxwMTWam
Done ヾ(@⌒ー⌒@)ノ

real	8m6.460s
user	5m27.850s
sys	2m10.970s
User avatar
rednoah
The Source
Posts: 20177
Joined: 16 Nov 2011, 08:59

Re: Failed to process [A] because [B] is an exact copy and already exists

Post by rednoah »

Movie / Series grouping is one of the more CPU and RAM intensive phases of the amc script. It shouldn't take more than a few seconds, but if the machine is busy and out of memory already before filebot is even called, then memory swapping will almost certainly grind the system to a halt.

You can add --def ut_label=Movie to skip grouping entirely:

Code: Select all

--def ut_label=Movie
However, this will most likely only delay the problem until the Auto-detect movie from context step which shares a lot of code with the Group step, and then stall there as it runs out of RAM and starts swapping memory.


:!: -Xmx512m may be a problem on a MemTotal: 689 MB | MemFree: 67 MB machine. You'll want to pick a -Xmx value that is high enough for filebot to work well, but ideally low enough to fit into the available RAM so that the system doesn't have to swap memory to disk. htop can help you see what's going on.


:arrow: Maybe try with -Xmx384m and -no-index and see if you get different behaviour?

Code: Select all

* Consider using JAVA_OPTS -Xmx384m or higher
* Consider using -no-index on low-memory devices
:idea: Please read the FAQ and How to Request Help.
grsjst
Posts: 4
Joined: 25 Sep 2021, 16:47

Re: Failed to process [A] because [B] is an exact copy and already exists

Post by grsjst »

Thanks for the quick reply

-Xmx384m doesn't seem to make much of a difference

however, -no-index speeds things up significantly (1m22 to complete). What does -no-index do (or better doesn't do)?

thanks!
j
User avatar
rednoah
The Source
Posts: 20177
Joined: 16 Nov 2011, 08:59

Re: Failed to process [A] because [B] is an exact copy and already exists

Post by rednoah »

FileBot knows things, like "Avatar is the name of a movie from 2009", but if you use -no-index then FileBot knows nothing. This drastically reduces the amount of memory used. Depending on the files at hand, this may or may not be a problem.



EDIT: Ran a few tests on my DS213J (single core armv7l CPU with 512 MB RAM) and got 2m5s with -no-index and 3m34s without. So that's the general ballpark numbers we could expect from a low-end device. If you get better times then it's probably because your CPU is faster. If you get worse times then it's probably because you're running out of RAM.
:idea: Please read the FAQ and How to Request Help.
Post Reply