Entry stays at processing after actual processing has done

journeym commented 1 month ago

Describe the bug After version 2.18 my transcodes started to stay in processing after actual processing has competed, file has been replaced and entry should have diappeared from staged files. As well i have a strange error on the node log file I use tdarr server in docker container, and node server with my own container with libdovi. Server and node both have latest version of tdarr. Another problem, is when i press requeue on this entry, it disappears from queue with all info (as well as job reports), it's nither in completed nor in error or queued tab. I can find the file in search and requeue form there, but it loses transcoding information that is availiable while it's in processing.

To Reproduce Im not sure how to reproduce

Expected behavior After processing entry form processing should dissapear.

Please provide the following information:

Config files [can be found in /app/configs/ when using Docker or in the /configs folder next to Tdarr_Updater if not using Docker] Tdarr_Node_Config.json Tdarr_Server_Config.json
Job reports: https://docs.tdarr.io/docs/other/job-reports bsZbF2rnq-log.txt
Log files [can be found in /app/logs/ when using Docker or in the /logs folder next to Tdarr_Updater if not using Docker] Tdarr_Server_Log.txt Tdarr_Node_Log.txt

-Worker error [can be found on the 'Tdarr' tab by pressing the 'i' button on a failed item in the staged file section or in the transcode error section at the bottom]

OS: Unraid docker
Browser: Edge
Version: latest

Additional context Add any other context about the problem here.

journeym commented 1 month ago

It's possible that it's somehow related with my cusom made node. But i have processed all my movie collection with it, and there were no problems, and i started noticing this strange behaivior after this year trarr update

journeym commented 1 month ago

I belive this all started after this change

Flows: Files successfully health checked in flow will automatically go into 'Health Check: Healthy' table after flow completes so don't need to re-healthcheck them

Im using plugin that modifies date for output file in the flow, would this somehow interfere with health check being valid and possibly lead to this error?

journeym commented 1 month ago

And another question, how can i downgrade to check my assumptions?

In docker, i can use haveagitgat/tdarr:2.17.01 and it will stay this version, or it will automatically update using internal Tdarr_Updater?
In my custom ubuntu node, how can i download older binary of Tdarr_Node?

thanks

HaveAGitGat commented 1 month ago

Hi, to change version please see here:

https://docs.tdarr.io/docs/releases/changing-version

To upgrade to latest, use the latest docker image tag. For the native packages, run Tdarr_Updater or download directly from [here](https://f000.backblazeb2.com/file/tdarrs/versions.json).

For the Windows, macOS and Linux native packages, you can set the requiredVersion in Tdarr_Updater_Config in the /configs folder and rerun the updater.

HaveAGitGat commented 1 month ago

[2024-06-14T02:10:34.442] [ERROR] Tdarr_Server - Unable to delete file:Error: EACCES: permission denied, rmdir '/mnt/media/torr/tdarr-workDir-node-eXzVfw4Qr-worker-rare-robin-ts-1717317025623/1717317039150'

Also seeing a lot of cache permission errors in the logs. Double check the server has permission to manage those folder/files or try stopping Tdarr and manually clearing them.

journeym commented 1 month ago

Downgraded, ill check bak in a week with results

HaveAGitGat commented 1 month ago

Ok thanks

journeym commented 4 weeks ago

All right, downgrade had the same problems, so i enabled debug logging, and it's indeed seems like permission issue. From the server log it seems that server cannot delete directory created by node. Node is creating all it's files as root user. Tdarr container uses nobody as a user.

I'm not really confident on linux permissions. Is there a simple way to fix this somehow? Should i create the same user on my node and run tdarr as nobody, or i can somehow force your image to use root? I have tried resetting permissions on the parent folder to 777 but it has no effect on neewly created dirs.

HaveAGitGat commented 4 weeks ago

What's your setup? Are the node and server on the same machine?

Are you using the internalNode inside the tdarr container or do you have a separate tdarr_node container?

journeym commented 4 weeks ago

Yes i have my own node container, mentioned here https://github.com/HaveAGitGat/Tdarr/issues/972 Im currently trying to rebuild it so it uses uid 99 for running tdarr_node

HaveAGitGat commented 4 weeks ago

Ok, other solution would be to use the tdarr container with internalNode=true env variable so the tdarr container runs a node inside which is sure to have the same permissions as server.

journeym commented 4 weeks ago

I wouldv'e for sure used your container if Handbrake you provided supported Dolby Vision, but as far as i understand it still doesnt.

journeym commented 4 weeks ago

I ended up just adding --user 99:100 in docker extra parameters, rebuilding the image for some reason stripped the qsv support on Handbrake

journeym commented 3 weeks ago

All right, im still getting the errors, despite there are no more server side permission errors Node side:

[2024-06-22T22:39:40.216] [INFO] Tdarr_Node - verbose:Running exiftool on file [2024-06-22T22:39:40.438] [INFO] Tdarr_Node - verbose:Beginning extractData on:/mnt/media/movies/Io Capitano (2023)/Io.Capitano.2023.BDRip.1080p.seleZen.mkv [2024-06-22T22:39:40.438] [INFO] Tdarr_Node - verbose:Tagging ffprobe data:/mnt/media/movies/Io Capitano (2023)/Io.Capitano.2023.BDRip.1080p.seleZen.mkv [2024-06-22T22:39:40.438] [INFO] Tdarr_Node - verbose:Tagging size data:/mnt/media/movies/Io Capitano (2023)/Io.Capitano.2023.BDRip.1080p.seleZen.mkv [2024-06-22T22:39:40.439] [INFO] Tdarr_Node - verbose:Tagging video res:/mnt/media/movies/Io Capitano (2023)/Io.Capitano.2023.BDRip.1080p.seleZen.mkv [2024-06-22T22:39:40.792] [INFO] Tdarr_Node - verbose:Running exiftool on file [2024-06-22T22:39:40.821] [ERROR] Tdarr_Node - Worker zesty-zebu exited with code 1 and signal null [2024-06-22T22:39:41.015] [ERROR] Tdarr_Node - Error [ERR_IPC_CHANNEL_CLOSED]: Channel closed at new NodeError (node:internal/errors:399:5) at target.send (node:internal/child_process:740:16) at /app/Tdarr_Node/srcug/commonModules/fileScanner/runExifToolSub.js:1:3937 at k (/app/Tdarr_Node/srcug/commonModules/fileScanner/runExifToolSub.js:1:2181) at Object.next (/app/Tdarr_Node/srcug/commonModules/fileScanner/runExifToolSub.js:1:1264) at h (/app/Tdarr_Node/srcug/commonModules/fileScanner/runExifToolSub.js:1:721) { code: 'ERR_IPC_CHANNEL_CLOSED' } [2024-06-22T22:39:53.065] [ERROR] Tdarr_Node - Worker zesty-zebu disconnected. Pruning. [2024-06-22T22:39:54.962] [INFO] Tdarr_Node - verbose:Launching worker

Server side:

[2024-06-22T22:37:31.396] [INFO] Tdarr_Server - Files have not changed since last stats update, no need to update stats again [2024-06-22T22:37:31.396] [INFO] Tdarr_Server - Delay until next stats update: 79260 ms [2024-06-22T22:38:50.658] [INFO] Tdarr_Server - Files have not changed since last stats update, no need to update stats again [2024-06-22T22:38:50.658] [INFO] Tdarr_Server - Delay until next stats update: 79260 ms [2024-06-22T22:39:35.394] [INFO] Tdarr_Server - Queue builder launched [2024-06-22T22:39:35.442] [INFO] Tdarr_Server - verbose:[47ms] Queue builder finished. 2642 files processed [2024-06-22T22:39:40.442] [INFO] Tdarr_Server - Queue builder launched [2024-06-22T22:39:40.470] [INFO] Tdarr_Server - verbose:[28ms] Queue builder finished. 2641 files processed [2024-06-22T22:39:45.471] [INFO] Tdarr_Server - Queue builder launched [2024-06-22T22:39:45.525] [INFO] Tdarr_Server - verbose:[54ms] Queue builder finished. 2641 files processed [2024-06-22T22:39:56.529] [INFO] Tdarr_Server - Queue builder launched [2024-06-22T22:39:56.558] [INFO] Tdarr_Server - verbose:[29ms] Queue builder finished. 2641 files processed [2024-06-22T22:40:00.407] [INFO] Tdarr_Server - verbose:Worker regal-ray requesting item. Nothing to process for this worker. [2024-06-22T22:40:00.871] [INFO] Tdarr_Server - Starting file scan [2024-06-22T22:40:00.872] [INFO] Tdarr_Server - k9LfoSZL0w Prep started [2024-06-22T22:40:00.897] [INFO] Tdarr_Server - [25ms] k9LfoSZL0w Prep finished [2024-06-22T22:40:00.897] [INFO] Tdarr_Server - Scanner k9LfoSZL0w launched [2024-06-22T22:40:01.071] [INFO] Tdarr_Server - 1 files sending [2024-06-22T22:40:01.072] [INFO] Tdarr_Server - [1ms] 1 files sent [2024-06-22T22:40:01.067] [INFO] Tdarr_Server - Online

Both logs have logLevel DEBUG Full logs: Tdarr_Node_Log.txt Tdarr_Server_Log.txt

Currently im out of ideas. Maybe you can provide more info from node trace?

journeym commented 3 weeks ago

Just tested it with your container internal node, and i have the same problem but different error node just errors out at the end of processing: Node:

[2024-06-23T11:08:50.556] [INFO] Tdarr_Node - verbose:Tagging ffprobe data:/mnt/media/movies/Call Sign Passenger (2024)/Pozyvnoj.Passazhir.2024.WEB-DL.1080p.mkv [2024-06-23T11:08:50.556] [INFO] Tdarr_Node - verbose:Tagging size data:/mnt/media/movies/Call Sign Passenger (2024)/Pozyvnoj.Passazhir.2024.WEB-DL.1080p.mkv [2024-06-23T11:08:50.557] [INFO] Tdarr_Node - verbose:Tagging video res:/mnt/media/movies/Call Sign Passenger (2024)/Pozyvnoj.Passazhir.2024.WEB-DL.1080p.mkv [2024-06-23T11:08:50.571] [INFO] Tdarr_Node - verbose:Running exiftool on file [2024-06-23T11:08:50.813] [INFO] Tdarr_Node - verbose:Beginning extractData on:/mnt/media/movies/Call Sign Passenger (2024)/Pozyvnoj.Passazhir.2024.WEB-DL.1080p.mkv [2024-06-23T11:08:50.813] [INFO] Tdarr_Node - verbose:Tagging ffprobe data:/mnt/media/movies/Call Sign Passenger (2024)/Pozyvnoj.Passazhir.2024.WEB-DL.1080p.mkv [2024-06-23T11:08:50.813] [INFO] Tdarr_Node - verbose:Tagging size data:/mnt/media/movies/Call Sign Passenger (2024)/Pozyvnoj.Passazhir.2024.WEB-DL.1080p.mkv [2024-06-23T11:08:50.815] [INFO] Tdarr_Node - verbose:Tagging video res:/mnt/media/movies/Call Sign Passenger (2024)/Pozyvnoj.Passazhir.2024.WEB-DL.1080p.mkv [2024-06-23T11:08:50.879] [INFO] Tdarr_Node - verbose:Running exiftool on file [2024-06-23T11:08:51.102] [INFO] Tdarr_Node - verbose:Beginning extractData on:/mnt/media/movies/Call Sign Passenger (2024)/Pozyvnoj.Passazhir.2024.WEB-DL.1080p.mkv [2024-06-23T11:08:51.102] [INFO] Tdarr_Node - verbose:Tagging ffprobe data:/mnt/media/movies/Call Sign Passenger (2024)/Pozyvnoj.Passazhir.2024.WEB-DL.1080p.mkv [2024-06-23T11:08:51.102] [INFO] Tdarr_Node - verbose:Tagging size data:/mnt/media/movies/Call Sign Passenger (2024)/Pozyvnoj.Passazhir.2024.WEB-DL.1080p.mkv [2024-06-23T11:08:51.102] [INFO] Tdarr_Node - verbose:Tagging video res:/mnt/media/movies/Call Sign Passenger (2024)/Pozyvnoj.Passazhir.2024.WEB-DL.1080p.mkv [2024-06-23T11:08:51.115] [INFO] Tdarr_Node - verbose:Running exiftool on file [2024-06-23T11:08:51.341] [INFO] Tdarr_Node - verbose:Beginning extractData on:/mnt/media/movies/Call Sign Passenger (2024)/Pozyvnoj.Passazhir.2024.WEB-DL.1080p.mkv [2024-06-23T11:08:51.342] [INFO] Tdarr_Node - verbose:Tagging ffprobe data:/mnt/media/movies/Call Sign Passenger (2024)/Pozyvnoj.Passazhir.2024.WEB-DL.1080p.mkv [2024-06-23T11:08:51.342] [INFO] Tdarr_Node - verbose:Tagging size data:/mnt/media/movies/Call Sign Passenger (2024)/Pozyvnoj.Passazhir.2024.WEB-DL.1080p.mkv [2024-06-23T11:08:51.343] [INFO] Tdarr_Node - verbose:Tagging video res:/mnt/media/movies/Call Sign Passenger (2024)/Pozyvnoj.Passazhir.2024.WEB-DL.1080p.mkv [2024-06-23T11:08:51.492] [ERROR] Tdarr_Node - Worker dead-dodo exited with code 1 and signal null [2024-06-23T11:09:03.561] [ERROR] Tdarr_Node - Worker dead-dodo disconnected. Pruning. [2024-06-23T11:09:05.008] [INFO] Tdarr_Node - verbose:Launching worker [2024-06-23T11:09:05.016] [INFO] Tdarr_Node - verbose:Worker wan-whelp launched [2024-06-23T11:09:05.161] [INFO] Tdarr_Node - verbose:Item request received [2024-06-23T11:09:05.161] [INFO] Tdarr_Node - verbose:Getting new task [2024-06-23T11:09:05.222] [INFO] Tdarr_Node - verbose:Running exiftool on file [2024-06-23T11:09:05.455] [INFO] Tdarr_Node - verbose:Running mediaInfo on file [2024-06-23T11:09:05.728] [INFO] Tdarr_Node - verbose:Beginning extractData on:/mnt/media/movies/Secret Passion (2024)/Taynoe.Vlechenie.2022.1080p.WEB-DL.mkv

Server:

[2024-06-23T11:07:55.384] [INFO] Tdarr_Server - Delay until next stats update: 79230 ms [2024-06-23T11:08:46.196] [INFO] Tdarr_Server - Queue builder launched [2024-06-23T11:08:46.233] [INFO] Tdarr_Server - verbose:[37ms] Queue builder finished. 2641 files processed [2024-06-23T11:08:48.142] [INFO] Tdarr_Server - W-2TZPXSp: detected file remove and drive location is accessible, removing from DB:/mnt/media/movies/Call Sign Passenger (2024)/Pozyvnoj.Passazhir.2024.WEB-DL.1080p.mkv [2024-06-23T11:08:50.934] [INFO] Tdarr_Server - W-2TZPXSp: detected file remove and drive location is accessible, removing from DB:/mnt/media/movies/Call Sign Passenger (2024)/Pozyvnoj.Passazhir.2024.WEB-DL.1080p.dates [2024-06-23T11:08:51.233] [INFO] Tdarr_Server - Queue builder launched [2024-06-23T11:08:51.278] [INFO] Tdarr_Server - verbose:[45ms] Queue builder finished. 2640 files processed [2024-06-23T11:08:56.279] [INFO] Tdarr_Server - Queue builder launched [2024-06-23T11:08:56.305] [INFO] Tdarr_Server - verbose:[26ms] Queue builder finished. 2640 files processed [2024-06-23T11:09:01.071] [INFO] Tdarr_Server - W-2TZPXSp: File detected, adding to queue:/mnt/media/movies/Call Sign Passenger (2024)/Pozyvnoj.Passazhir.2024.WEB-DL.1080p.mkv [2024-06-23T11:09:06.309] [INFO] Tdarr_Server - Queue builder launched

Item processing log: IPSbyfCkX-log.txt

journeym commented 3 weeks ago

I belive this to be a timeout issue. While recoding my parity disk usualy becomes spinned down, and in final stages of processing, when replacing the file it spins up to delete original file. This is the same time as error pops out, and processing stops. Can you check that? Thanks.

HaveAGitGat commented 3 weeks ago

If you remove/disconnect the 2 plugins after Replace Original File does it work okay?

journeym commented 3 weeks ago

It was the radar plugin that triggered the error and the problem

HaveAGitGat / Tdarr

Entry stays at processing after actual processing has done #1026