search

pymedusa / Medusa

Automatic Video Library Manager for TV Shows. It watches for new episodes of your favorite shows, and when they are posted it does its magic.
https://pymedusa.com
GNU General Public License v3.0
1.79k stars 276 forks source link

How do I get the download handler to post-process files? #10822

Closed strike84 closed 2 years ago

strike84 commented 2 years ago

Describe the bug I've never been able to get the download handler to post-process my finished downloads. I've always used the scheduled Post-Processor. But after updating to 1.0.5 that will not work either if the download handler is enabled. And in order to get the torrents to pause right after they are finished downloading I have to have the download handler enabled or else it will seed forever. See: https://github.com/pymedusa/Medusa/issues/10529

I use the deluge connecting to the daemon.

There is always nothing in the Post-process Queue, even if there are finished downloads in the client. And when the download handler check every 10 min all that get logged is what i pasted in the logs below. Nothing more happens. Same thing if I force it in manage-searches. Nothing gets post-processed.

To Reproduce Steps to reproduce the behavior:

  1. Enable the download handler in post-processing and wait for it to start.

Expected behavior The download handler should move my finished downloads into my tv directory

Screenshots image image image image

Medusa (please complete the following information): image

Debug logs (at least 50 lines): General > Advanced Settings > Enable debug

```2022-07-14 15:14:45 DEBUG DOWNLOADHANDLER :: [918cfe7] Starting new thread: DOWNLOADHANDLER 2022-07-14 15:14:45 DEBUG DOWNLOADHANDLER :: [918cfe7] Checking DelugeD torrent 8d0587a2806bcf49cc9f08c0a67497886747924c status. 2022-07-14 15:14:45 DEBUG DOWNLOADHANDLER :: [918cfe7] Found torrent on **********d with info_hash 8d0587a2806bcf49cc9f08c0a67497886747924c 2022-07-14 15:14:45 DEBUG DOWNLOADHANDLER :: [918cfe7] Checking DelugeD torrent cfc86241edad161af5aee5ff8740589272c50e75 status. 2022-07-14 15:14:45 DEBUG DOWNLOADHANDLER :: [918cfe7] Found torrent on **********d with info_hash cfc86241edad161af5aee5ff8740589272c50e75 2022-07-14 15:14:45 DEBUG DOWNLOADHANDLER :: [918cfe7] Checking DelugeD torrent 8d0587a2806bcf49cc9f08c0a67497886747924c status. 2022-07-14 15:14:45 DEBUG DOWNLOADHANDLER :: [918cfe7] Checking DelugeD torrent cfc86241edad161af5aee5ff8740589272c50e75 status. 2022-07-14 15:44:47 DEBUG DOWNLOADHANDLER :: [918cfe7] Starting new thread: DOWNLOADHANDLER ```

Additional context Before 1.0.5 I had the scheduled Post-Processor and the download handler enabled and the scheduled Post-Processor would work. Now It doesn't anymore. My goal is to get the download handler to post-process my files but no dice so far.

p0psicles commented 2 years ago

That's just a partial log. Could you provide a full log of the download handler threat.

Also on the history page. Does it change the status for downloads? That should give more info.

strike84 commented 2 years ago

On the history page it does not change the status to downloaded. So I guess that is part of the issue. image

Edit: Well, I guess it will only change to downloaded once it has been post-processed?

And regarding the log, the only other thing regarding the downloadhandler in the log is this:

2022-07-14 18:05:02 DEBUG   DOWNLOADHANDLER :: [918cfe7] Starting new thread: DOWNLOADHANDLER
2022-07-14 17:55:01 DEBUG   DOWNLOADHANDLER :: [918cfe7] Starting new thread: DOWNLOADHANDLER
2022-07-14 17:45:00 DEBUG   DOWNLOADHANDLER :: [918cfe7] Starting new thread: DOWNLOADHANDLER
2022-07-14 17:34:59 DEBUG   DOWNLOADHANDLER :: [918cfe7] Starting new thread: DOWNLOADHANDLER
2022-07-14 17:24:58 DEBUG   DOWNLOADHANDLER :: [918cfe7] Starting new thread: DOWNLOADHANDLER
2022-07-14 17:14:57 DEBUG   DOWNLOADHANDLER :: [918cfe7] Starting new thread: DOWNLOADHANDLER
2022-07-14 17:04:56 DEBUG   DOWNLOADHANDLER :: [918cfe7] Starting new thread: DOWNLOADHANDLER
2022-07-14 16:54:55 DEBUG   DOWNLOADHANDLER :: [918cfe7] Starting new thread: DOWNLOADHANDLER
2022-07-14 16:44:54 DEBUG   DOWNLOADHANDLER :: [918cfe7] Starting new thread: DOWNLOADHANDLER
2022-07-14 16:34:53 DEBUG   DOWNLOADHANDLER :: [918cfe7] Starting new thread: DOWNLOADHANDLER
2022-07-14 16:24:52 DEBUG   DOWNLOADHANDLER :: [918cfe7] Starting new thread: DOWNLOADHANDLER
2022-07-14 16:14:51 DEBUG   DOWNLOADHANDLER :: [918cfe7] Starting new thread: DOWNLOADHANDLER

That and the log i posted earlier is literally everything there is regarding the downloadhandler.

p0psicles commented 2 years ago

It says paused, seeded, completed. So that's probably why it's not being postprocessed. Do you have any actions configured in deluge? Like pause the torrent after seeding?

strike84 commented 2 years ago

Yes, I had "stop seed at ratio" and ratio 0 enabled. Which will pause the torrent. I will try to disable that and see what happens.

p0psicles commented 2 years ago

Yeah, you want Medusa handle that

strike84 commented 2 years ago

No, that didn't work. The stop at seed ratio is disabled in deluge. And in medusa I have set it to pause the torrent at ratio 0. What happens is that it will NOT pause the torrent. And it will keep seeding forever and nothing gets post-processed.. Even if in history it says the same as before, "paused,seeded,completed" but in fact the torrent is NOT paused, it is seeding. Nothing new in the log either, same as before.

strike84 commented 2 years ago

Actually after a second look, it looks like medusa paused the torrent BUT it doesn't get updated in deluge. In deluge it says it seeding, but when I look at "seeding time" in deluge it says 3min 40 sec, which probably is when the download handler checked the status. And it stays at that time, it still says seeding but I can see there is actually no uploading going on. And there are plenty of peers as this is new torrent.

strike84 commented 2 years ago

Bah, scratch that. I had a another torrent in radarr seeding and when I paused that the medusa torrent started seeding. So I guess it was in queue.

strike84 commented 2 years ago

I rolled back to 1.0.3 to get the Scheduled Post-Processor to work again. Some observation tho, I have always had the "stop at ratio" and a ratio of 0 enabled in deluge. As my previous issue here: https://github.com/pymedusa/Medusa/issues/10529 that suddenly stopped working with medusa. So I enabled the download handler and set action pause and ratio 0. Then torrents would pause as intended again.

So my observation is when download handled is enabled AND "stop at ratio" is enabled in deluge it will pause the torrent. But the download handler will not post-process anything. Post-processing will first happen when the Scheduled Post-Processor kicks in. If Scheduled Post-Processor is disabled nothing gets processed even if the download handler is enabled. And medusa will think the torrent is paused when it's actually not (if "stop at ratio 0" is disabled in deluge).

When download handler is disabled torrents will not pause at set ratio even if deluge is configured to do so.

And after 1.0.5 Scheduled Post-Processor doesn't work anymore.

p0psicles commented 2 years ago

Afaik we haven't touched the scheduled pp in a while. But I'll need to double check that.

What version of deluge do you use. I'll have to try reproduce your issue

strike84 commented 2 years ago

I use deluge server 2.0.5 and client 2.1.0 dev 90

p0psicles commented 2 years ago

I rolled back to 1.0.3 to get the Scheduled Post-Processor to work again.

so your saying scheduled postprocessing isn't working anymore in the latest version. If this is true, i'll need to look at that first. So is scheduled pp not working only if download handling is enabled since 1.0.5. Or does scheduled pp also not work when download handling is disabled?

Can we focus on this. As you kinda claim something broke here. While I can't remember making any changes to the PP in the last 5 releases.

Can you help me reproducing this?

strike84 commented 2 years ago

I updated again to test this for you, but now the scheduled postprocessing is actually working. Weird.. I updated two times earlier and on first start everything looked ok on the status page. Post process said "true" on both alive and enabled, but when it should actually start the alive changed to false. I then played with setting the download handler to disabled and disabling and re-enabling the scheduled postprocessing but I couldn't get it to say true on alive anymore. I even restarted the docker container several times.

But now it's actually working. I will leave it for tomorrow and just check that it keeps working.

p0psicles commented 2 years ago

I know that there is a known issue with a wrong reporting in the status page on the postprocessing process. So it will report the thread has stopped, but actually it hasn't. You have to check the logs if the pp thread has stopped by checking your logs. Logs/application.log.*

strike84 commented 2 years ago

It wasn't wrong reporting, that's for sure. Because nothing was processed in a hole day. I didn't check the log that time, but nothing was processed. It says in the description in the settings not to use the scheduled postprocessing when download handler is enabled, but that is the only way I can get things processed. But i would really like for the download handing to work, do you have any idea why it's not working?

To me it looks like medusa is unable to read/update the status in deluge. That is confirmed by disabling the stop at ratio in deluge, then it would keep seeding but medusa think it's paused. Medusa should pause it,but it doesn't.

p0psicles commented 2 years ago

The reason why we don't recommend to use download handler with scheduled, is cause you can get unexpected results. Like when one moves files so the other can't find it anymore.

It wasn't wrong reporting, that's for sure. Because nothing was processed in a hole day.

So you set up schedule pp, and files where moved to your pp dir, but nothing got postprocessed? That's not right.

p0psicles commented 2 years ago

To me it looks like medusa is unable to read/update the status in deluge. That is confirmed by disabling the stop at ratio in deluge, then it would keep seeding but medusa think it's paused. Medusa should pause it,but it doesn't.

what I think is the issue. Is that somehow medusa thinks the torrent got paused by Deluge. And therefor skips it. It's very timeconsuming for me to setup a Deluge docker container, configure with medusa. Download torrents, and try to reproduce. So first i'd like to know what all your deviations from the default config in deluge are. As when I tested it with deluge. And pretty much used the default config. Like only changing maybe the destination download folder.

Also I can't get my docker container setup, so that I can connect from medusa to it's daemon. Have you tried connecting to the web interface? okay was able to connect to daemon

Okay I think I was able to reproduce the issue. Will see if I can fix it.

strike84 commented 2 years ago

So you set up schedule pp, and files where moved to your pp dir, but nothing got postprocessed? That's not right.

Yes, when I first updated to 1.0.5 schedule pp was enabled, but I then realized nothing was getting processed. Then as I mentioned when I saw on the status page schedule pp was not alive, and I could not get it to start. Files where moved by deluge to the completed dir which obviously is my pp dir in medusa, but nothing was processed because it was unable to start. But as I also mentioned it's working now tho, so not really sure what happened.

strike84 commented 2 years ago

Okay I think I was able to reproduce the issue. Will see if I can fix it.

Oooh, that sounds promising :)

p0psicles commented 2 years ago

Do you know how to checkout a specific branch in git?

strike84 commented 2 years ago

That was fast! No, I don't really know how to check out a specific branch in docker. I was doing it years ago before I used docker tho. But I think I can figure it out. I see I can't choose the dev branch in the webui, so i probably have to do it in cli. If not the container author has a tag for the develop branch, I'll check that first. Will report back if I need some assistance. :)

p0psicles commented 2 years ago

Nah, in docker it's difficult. I'll merge my changes to develop. then you can start testing in develop branch.

strike84 commented 2 years ago

Yeah, I couldn't really figure out how to change my current container to the develop branch. But I see you have an official image on dockerhub with the develop tag so I'll set up that maybe tomorrow to test it out.

p0psicles commented 2 years ago

@strike84 just use the develop tag. Could you test it? it's merged to develop

strike84 commented 2 years ago

Tested, and it's not working. But I can see in the log that the download handler is updating the status now. It doesn't do that in the master branch.

2022-07-16 20:57:00 INFO DOWNLOADHANDLER :: [135a704] Updating status to [Downloading, Seeded] for Watergate.Blueprint.For.A.Scandal.2012.S01 2022-07-16 21:17:02 INFO DOWNLOADHANDLER :: [135a704] Updating status to [Seeded, Completed] for Watergate.Blueprint.For.A.Scandal.2012.S01

And under history in now says this: image

But the torrent is not paused (which medusa should have done according to the settings) and just keeps seeding and nothing is getting processed.

Just to confirm, my branch and commit is correct right? image

p0psicles commented 2 years ago

So you started with a new snatch? What does the history page show for that download? O I see. Seeded + completed. I'm checking for that status now, so now it should start the postprocessing for it.

strike84 commented 2 years ago

Yup. I spun up your official container (normally I use the liunxserver container) with the develop branch just for testing. Snatched a new show and waited to see what happened. The history page show what i posted in my last comment for all ep, here it is again:

image

Yeah I haven't used any other clients before so I don't know what's normal. But yeah, it does seem kinda weird registering as downloading,seeded. In the master branch it won't even register that it's downloading tho IIRC. It just updates with paused,completed,seeded when it's finished, even if the torrent is not paused.

strike84 commented 2 years ago

~~ O I see. Seeded + completed. I'm checking for that status now, so now it should start the postprocessing for it.

Oooh, nice. Will test again tomorrow.

p0psicles commented 2 years ago

You should run the pymedusa/medusa docker image. And then use the develop tag. And with my previous commit, this should already work.

ooh and enable debug logs and restart.

strike84 commented 2 years ago

It should work now? You sure? I just tested when I posted my last comment. Did you do any changes now? It was not working when I tested as i posted earlier.

strike84 commented 2 years ago

yeah, and debug is enabled

strike84 commented 2 years ago

I even waited for the download handler to run several times. In case it just updated the status first then processed with next run. But nothing is happening and the torrent just keeps seeding.

p0psicles commented 2 years ago

I'll look into it some more tomorrow

strike84 commented 2 years ago

Cool. Thank you so much for your help so far.

Btw I just tried to pause the torrent manually and wait for the download handler to see if it would process then, but it did not. So I resumed it again. It updates the status correct now tho.

2022-07-16 22:29:00 DEBUG DOWNLOADHANDLER :: [135a704] Checking DelugeD torrent b0bc69039dc85ebccba63c3fa3583ca005639dee status. 2022-07-16 22:29:00 INFO DOWNLOADHANDLER :: [135a704] Updating status to [Seeded, Completed] for Watergate.Blueprint.For.A.Scandal.2012.S01.WEBRip.x264-ION10 with info_hash b0bc69039dc85ebccba63c3fa3583ca005639dee 2022-07-16 22:29:00 DEBUG DOWNLOADHANDLER :: [135a704] Found torrent on **d with info_hash b0bc69039dc85ebccba63c3fa3583ca005639dee 2022-07-16 22:29:00 DEBUG DOWNLOADHANDLER :: [135a704] Checking DelugeD torrent b0bc69039dc85ebccba63c3fa3583ca005639dee status. 2022-07-16 22:29:00 DEBUG DOWNLOADHANDLER :: [135a704] Starting new thread: DOWNLOADHANDLER 2022-07-16 22:18:59 DEBUG DOWNLOADHANDLER :: [135a704] Checking DelugeD torrent b0bc69039dc85ebccba63c3fa3583ca005639dee status. 2022-07-16 22:18:59 INFO DOWNLOADHANDLER :: [135a704] Updating status to [Paused, Seeded, Completed] for Watergate.Blueprint.For.A.Scandal.2012.S01.WEBRip.x264-ION10 with info_hash b0bc69039dc85ebccba63c3fa3583ca005639dee 2022-07-16 22:18:59 DEBUG DOWNLOADHANDLER :: [135a704] Found torrent on **d with info_hash b0bc69039dc85ebccba63c3fa3583ca005639dee 2022-07-16 22:18:59 DEBUG DOWNLOADHANDLER :: [135a704] Checking DelugeD torrent b0bc69039dc85ebccba63c3fa3583ca005639dee status. 2022-07-16 22:18:59 DEBUG DOWNLOADHANDLER :: [135a704] Starting new thread: DOWNLOADHANDLER

I also tried to set it to hardlink instead of move, since medusa doesn't pause the torrent and just keeps seeding. Figured it would throw an error in the log if it wasn't able to move because of seeding but can't see anything at all, just the above. But with hardlink it should be able to process is even when seeding I think.

p0psicles commented 2 years ago

I've changed my snatched download to the status Paused + Seeded + Completed. And it directly tried to postprocess the files. But because i'm on docker it couldn't locate the files from within the container. But that's expected.

Can you send (maybe PM) me your application.log? You can contact me on Discord.

strike84 commented 2 years ago

I'm having trouble logging into my discord. But here is the log. I just deleted the show and snatched it again. This time stop at ratio was enabled in deluge. So the status in now Paused + Seeded + Completed. That's the only way I can get the paused status, either that or pause it manually. Is it possible to change the status manually in history in medusa application.log ?

p0psicles commented 2 years ago

So it seems that your still on the master image. I've checked the commit https://github.com/pymedusa/Medusa/commit/cb13ff9. Make sure you've really pulled the develop tag. Maybe recreate the container.

strike84 commented 2 years ago

When I fist started the container yesterday I was on master yes. But I changed it. The log is from when i first started the container yesterday and all the way up today. So if you scroll down you'll see that I'm on develop.

2022-07-17 09:54:11 INFO MAIN :: [135a704] Starting Medusa [develop] using '/config/config.ini' 2022-07-17 09:54:11 INFO TORNADO :: [135a704] Starting Medusa on http://0.0.0.0:8081/

You should scroll all the way down to the bottom to get the most recent log.

p0psicles commented 2 years ago

The thing is, that I'm pretty confident I fixed it with that commit. So if your really running the right code, it should now pp for you. I tested it myself, with the same status. And it pp now fine.

strike84 commented 2 years ago

Well, I don't know what to tell you. It doesn't work for me. Are you saying medusa is reporting the wrong info in the webui and in the log? image

It does say I'm on develop and on the commit which is referenced in your fix. But maybe I can try to delete the container and start from scratch again. I don't know why that would make a difference since medusa is reporting I'm on the right code.

p0psicles commented 2 years ago

I think recreate the container is worth the effort. Else you might need to wait for the release.

strike84 commented 2 years ago

Ok, I'll try to do that.

strike84 commented 2 years ago

Yeah, you where right. It was worth the effort recreating the container. I can confirm it's working now :) So closing this. Thanks a lot for coming with a quick fix :) Don't know why it was not working before, maybe medusa did report the wrong info being on the correct commit, idk. But that's what I love about docker, it so quick to recreate the container with all your settings intact or even roll back to an earlier version. It literately takes 15 seconds.

p0psicles commented 2 years ago

I made some more small adjustments to how the ratio is communicated. Do you might want to test that more extensive

strike84 commented 2 years ago

Ok, I did in fact set the ratio at 0.1 in medusa before I tested this last time. Just to make sure 0 wasn't causing any problems. But I had stop at ratio 0 enabled in deluge anyway so the torrent paused when it was completed. I haven't tested if medusa will pause the torrent since it was working the way I wanted to anyway. I'll test that out some more when I have the time. But I'm fairly confident that it's working as intended according to this in the log:

2022-07-17 21:08:42 DEBUG DOWNLOADHANDLER :: [135a704] Checking DelugeD torrent b0bc69039dc85ebccba63c3fa3583ca005639dee status. 2022-07-17 21:08:42 DEBUG DOWNLOADHANDLER :: [135a704] Action after seeding disabled 2022-07-17 21:08:42 DEBUG DOWNLOADHANDLER :: [135a704] Ratio of (0.025444194674491882) reached for torrent b0bc69039dc85ebccba63c3fa3583ca005639dee, starting action: pause.

Just say the word if you want me to test something specific!.