Stops working after handling a few torrents

jooks1 commented 2 years ago

I run deluge with filebot tool as well as filebot in a single docker container. After running for a while, filebot tool will no longer function, by just not moving files that finish downloading, and throwing a "no files found" error when trying to run it manually. Restarting the container fixes this for a short time, but it always comes back.

This has been extremely difficult to get logs and data for, as it functions differently almost every time, it seems, but I'll try to catalogue what I've got here.

the error thrown by manually running:

FilebotRuntimeError error on torrent 86a6aead81f0b450cb02c041e5fe39634933c5e4:
    FILEBOT OUTPUT DUMP:
    No input arguments
    Rename episodes using [TheTVDB] with [Airdate]
    No media files: []
    Failure (×_×)⌒☆

    stderr:

I have checked and there are media files. However, looking at the output of ps -auxww | grep -i filebot, I can see that it is not passing the filenames to be updated:

nobody     21690  0.0  0.0   7868  4028 ?        S    07:57   0:00 bash /usr/sbin/filebot -rename --format {n}/Season {s}/{n} - {s00e00} - {airdate.format('yyyy.MM.dd')}/{n} - {s00e00} - {airdate.format('yyyy.MM.dd')} - {t} --db TheTVDB --output /mnt/storage/downloads/TV --action move -r --conflict index -non-strict

nobody     21693  0.0  0.1 11168644 58536 ?      Sl   07:57   0:00 /usr/lib/jvm/java-11-openjdk/bin/java -Dapplication.deployment=aur --module-path /usr/share/filebot/openjfx --add-modules ALL-MODULE-PATH -Dapplication.update=skip -Dnet.filebot.archive.extractor=ShellExecutables --illegal-access=permit --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.lang.reflect=ALL-UNNAMED --add-opens=java.base/java.lang.invoke=ALL-UNNAMED --add-opens=java.base/java.util=ALL-UNNAMED --add-opens=java.base/java.util.function=ALL-UNNAMED --add-opens=java.base/java.util.regex=ALL-UNNAMED --add-opens=java.base/java.net=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.base/java.nio=ALL-UNNAMED --add-opens=java.base/java.nio.file=ALL-UNNAMED --add-opens=java.base/java.nio.file.attribute=ALL-UNNAMED --add-opens=java.base/java.nio.channels=ALL-UNNAMED --add-opens=java.base/java.nio.charset=ALL-UNNAMED --add-opens=java.base/java.time=ALL-UNNAMED --add-opens=java.base/java.time.chrono=ALL-UNNAMED --add-opens=java.base/java.util.concurrent=ALL-UNNAMED --add-opens=java.base/java.text=ALL-UNNAMED --add-opens=java.base/sun.nio.fs=ALL-UNNAMED --add-opens=java.logging/java.util.logging=ALL-UNNAMED --add-opens=java.desktop/java.awt=ALL-UNNAMED --add-opens=java.desktop/sun.awt=ALL-UNNAMED --add-opens=java.desktop/sun.swing=ALL-UNNAMED --add-opens=java.desktop/javax.swing.text.html=ALL-UNNAMED --add-opens=java.prefs/java.util.prefs=ALL-UNNAMED -Djna.boot.library.path=/usr/share/filebot/lib/x86_64:/lib64 -Djna.library.path=/usr/share/filebot/lib/x86_64:/lib64 -Djava.library.path=/usr/share/filebot/lib/x86_64:/lib64 -Dapplication.dir=/home/nobody/.config/filebot -Dapplication.cache=/home/nobody/.config/filebot/cache -Djava.io.tmpdir=/home/nobody/.config/filebot/tmp -Dfile.encoding=UTF-8 -Dsun.jnu.encoding=UTF-8 -Dprism.order=sw -Dnet.filebot.theme=Darcula -DuseGVFS=true -Dnet.filebot.gio.GVFS=/gvfs -jar /usr/share/filebot/jar/filebot.jar -rename --format {n}/Season {s}/{n} - {s00e00} - {airdate.format('yyyy.MM.dd')}/{n} - {s00e00} - {airdate.format('yyyy.MM.dd')} - {t} --db TheTVDB --output /mnt/storage/downloads/TV --action move -r --conflict index -non-strict

After this, I restarted the container, allowing the file to move and be renamed, but didn't think about grabbing log entries.

While attempting to find information, I found an issue that I've not seen yet, where the auto-run did not work, but manually did. The pertinent log info here: deluge-breakondownload-workonmanual-log.txt

I tried for nearly an hour to get the original error to throw but failed to do so. This has been happening for a couple of months now, so I do not believe that I somehow fixed this by trying to collect debugging data. I will attempt to add the log for that, if I can get it to do it, or if need be.

Docker Container: binhex/arch-delugevpn - modified by installing filebot from AUR within Deluge Version: 2.0.5.0 libtorrent version: 2.0.5.0

Filebot tool debug info: filebottool debug info.txt

Laharah commented 2 years ago

I have to admit, this is a weird one. It seems that the error is being introduced on the server side when it's trying to find the "OS" path for the files listed in the torrent data. From what I can see looking over the code, FileBot only works with what Deluge gives it; it never checks the OS directly. In turn, it looks like deluge goes based on what libtorrent gives it.

Here are my few hypotheses:

For some reason, when the FilebotTool was called all of the files were set to priority 0 or "skip." If that's the case, since FilebotTool skips any files that deluge has set to priority 0, there won't be any files in the list of files sent to FileBot.
A bug in deluge means that the torrent doesn't have metadata. I kind of doubt this one, though it does look like deluge returns an empty list of files if for some reason the torrent doesn't have the metadata flag flipped on.
A bug in libtorrent means that it sometimes returns an empty file list. I'm not very well versed in libtorrent, but it looks like that's where deluge ultimately gets the torrent's file list from. This one is pretty much the same as above but with the error further down the stack. A bug like this one is possible but unlikely given how many projects use libtorrent.
Your filesystem setup means that briefly your files aren't located where they're expected. This is where I think the issue is, but I'd have to know a bit more about your setup. It looks like you have your data drives loaded as mergerfs file systems. If those drives ("incomplete" and "Downloaded") are either network drives or are for some reason out of sync, there may be a brief moment when the files aren't where libtorrent expects.

For now try and make sure that neither deluge or any other plugins (like label plugins) are set to move your completed downloads anywhere. In deluge the setting is in Settings>Downloads>Move completed to. On that same page, make sure that you're using Full allocation and not compact allocation. With MergerFS there could be weird behavior where it makes a file jump between drives as it increases in size.

If the problem keeps persisting, let me know and I can try to make a special debug version with extra checks and logging to try and nail the problem down.

jooks1 commented 2 years ago

Thank you for the quick response! This tool has been an incredible utility and has been extremely useful forever, even with the need to manually re-run things, so I really appreciate it!

I have not set any files to skip. Most come from RSS feeds and just grab the entire thing
I've used a similar setup (same container) with deluge 1.3 for more than a year with no issue. This only started once I finally made the jump to v2, so I'm not sure the filesystem is the problem, but I suppose that the update could handle things a bit differently. The drives are all local to the system, incomplete and download are directories in the merged /mnt/storage/, mounted into the docker container specifically to only give the container access to those dirs. It should currently be working on only one disk, as it's much larger than the others, but the others are older and therefore have data on them as well, so, ultimately, everything is being moved around on the same disk at the time being by way of the mergerfs sorting.

As an example, to hopefully be as clear as possible: /mnt/store01 and /mnt/store02 are merged to /mnt/storage. incomplete and downloads are directories in /mnt/storage (and therefore the other two mounts). everything is currently, by way of mergerfs going to store02. So, it downloads into incomplete on store02, filebot will be copying it to downloads on store02.

It is already not set to not move completed, nor are any of the RSS feeds moving completed to anywhere. I have now turned on 'pre-allocate disk space', so we'll see.

It usually breaks sometime overnight for sure, so I should hopefully know in the morning, and will make sure to grab logs where it doesn't pass the filenames. I'll let you know!

Thanks again!

jooks1 commented 2 years ago

Looks like those changes did not work.

I ran a manual rename this morning after it did not do it last night and got the missing file error again. The torrent would have completed hours ago, so there should be no mistaking where the files reside, etc., or so I'd think.

Something odd, and possibly unrelated, at around 07:44:20 in the log, which is after opening the dialog but before clicking 'dry run', it's looking for, and unable to find something for a completely unrelated thing, that has already been dealt with and moved months ago.

Anyway, here is my log: debug log output.txt

jooks1 commented 2 years ago

@Laharah, It's been a while with no activity here, so I decided to do some testing myself.

I temporarily consolidated all of my downloads/incomplete onto single ext4 drives and let it run for a day and can now confirm that it is likely not the mergerFS mounting, as I'm still getting the following error:

    FILEBOT OUTPUT DUMP:
    No input arguments
    Rename episodes using [TheTVDB] with [Airdate]
    No media files: []
    Failure (×_×)⌒☆

    stderr:

Here's the filebot tool debug output showing that it recognizes /downloads and /incomplete as ext4: filebot debug info 5-20.txt

I will be putting my mergerFS setup back in place as I can confirm that this is still an issue without it.