search

Unmanic / unmanic

Unmanic - Library Optimiser
GNU General Public License v3.0
1.65k stars 82 forks source link

Jobs finish, but don't always transition to "completed tasks" #143

Closed kythorn closed 3 years ago

kythorn commented 3 years ago

Description

My instance sometimes gets into a state where workers "finish", but never show up as a success or a failure. I have looked in the output cache, and they seem to have be 'done'. I am not sure why they fail to be moved out and logged as a success (or a failure, if it failed).

This doesn't always happen, but when it does happen, it happens to every job, even if I restart the container. The only way I have been able to resolve it is to stop the container, delete the unmanic.db.* files, and restart it.

Steps to Reproduce

Start container. Let it process. Eventually, this starts to happen. I don't specifically know how to trigger it, but I can say it doesn't seem specific to the file being processed, as after deleting the database and restarting that file always finishes fine.

Expected behavior:

All workers completing result in either a successful or 'failed' completed task. Successful files are copied out of the cache replacing the input file.

Actual behavior:

Workers run, but the results just vanish. Nothing in the completed tasks list, and the output mkvs just sit in the cache directory.

Reproduces how often: [What percentage of the time does it reproduce?] I am not able to run unmanic for longer than a day without this happening.

Versions

0.0.1+25fc87e

The version can be found at the footer of the WebUI. Also, please include the OS details and what version you are running (e.g. cat /etc/os-release).

Installation Method Used

I use the docker image josh5/unmanic:latest

At this time, that is digest b77135832093c092c1e51958894bf8c645d1251a63cd99b55f0c2cab672b80ff

Manually installed and run or run through Docker?

Docker

Additional Information

Any additional information, configuration or data that might be necessary to reproduce the issue.

I run unmanic in docker under WSL2 on a Win10 machine, targetting a library on my synology NAS mounted over CIFS.

I have tried 3 different 'host' computers, all exhibit the same behavior within a day of the container being started.

MRobi1 commented 3 years ago

I'm seeing this exact same thing Version - 0.0.1+95b3646

cbrherms commented 3 years ago

I'm now seeing the same thing also. This is the first time this has happened, but is quite consistent now and at present the last 10 tasks have "finished" but not transferred and not appeared on completed list as either fail or complete.

The only thing that has recently changed that could potentially affect this was the fact I started to make hardlinks within my transcodes folder to files that I wanted to transcode, rather than pointing at my entire movie library. The first job completed, but everything after that did not. I wouldn't be surprised if in the background the above people are using hardlinks on some files also? As this is a potential situation if files are still being seeded etc.

Version: 0.0.1+25fc87e OS: Ubuntu 18.04.4 LXC on proxmox, source files on NFS share Install method: manually - ran as service

Output from systemd:

Jan 18 01:22:24 plex python3[9148]: Starting migrations
Jan 18 01:22:24 plex python3[9148]: There is nothing to migrate
Jan 18 01:52:25 plex python3[9148]: Exception in thread PostProcessor:
Jan 18 01:52:25 plex python3[9148]: Traceback (most recent call last):
Jan 18 01:52:25 plex python3[9148]:   File "/usr/lib/python3.6/shutil.py", line 550, in move
Jan 18 01:52:25 plex python3[9148]:     os.rename(src, real_dst)
Jan 18 01:52:25 plex python3[9148]: OSError: [Errno 18] Invalid cross-device link: '/tmp/unmanic/unmanic_file_conversion-1610932945.4042923/Knives Out (2019) - [Bluray-1080p]-1610932945.4043047.mkv' -> '/mnt/DATA/Media/transcode/Knives Out (2019)/Knives Out (2019) - [Bluray-1080p].mkv'
Jan 18 01:52:25 plex python3[9148]: During handling of the above exception, another exception occurred:
Jan 18 01:52:25 plex python3[9148]: Traceback (most recent call last):
Jan 18 01:52:25 plex python3[9148]:   File "/usr/lib/python3.6/threading.py", line 916, in _bootstrap_inner
Jan 18 01:52:25 plex python3[9148]:     self.run()
Jan 18 01:52:25 plex python3[9148]:   File "/var/lib/plexmediaserver/.local/lib/python3.6/site-packages/unmanic-0.0.1.dev11-py3.6.egg/unmanic/libs/postprocessor.py", line 132, in run
Jan 18 01:52:25 plex python3[9148]:     self.post_process_file()
Jan 18 01:52:25 plex python3[9148]:   File "/var/lib/plexmediaserver/.local/lib/python3.6/site-packages/unmanic-0.0.1.dev11-py3.6.egg/unmanic/libs/postprocessor.py", line 159, in post_process_file
Jan 18 01:52:25 plex python3[9148]:     shutil.move(cache_path, destination_data['abspath'])
Jan 18 01:52:25 plex python3[9148]:   File "/usr/lib/python3.6/shutil.py", line 564, in move
Jan 18 01:52:25 plex python3[9148]:     copy_function(src, real_dst)
Jan 18 01:52:25 plex python3[9148]:   File "/usr/lib/python3.6/shutil.py", line 263, in copy2
Jan 18 01:52:25 plex python3[9148]:     copyfile(src, dst, follow_symlinks=follow_symlinks)
Jan 18 01:52:25 plex python3[9148]:   File "/usr/lib/python3.6/shutil.py", line 121, in copyfile
Jan 18 01:52:25 plex python3[9148]:     with open(dst, 'wb') as fdst:
Jan 18 01:52:25 plex python3[9148]: PermissionError: [Errno 13] Permission denied: '/mnt/DATA/Media/transcode/Knives Out (2019)/Knives Out (2019) - [Bluray-1080p].mkv'
Jan 18 01:52:25 plex python3[9148]: [I 210118 01:52:25 __init__:465] Running job Every 30 minutes do scheduled_job() (last run: [never], next run: 2021-01-18 01:52:24)
Jan 18 02:22:36 plex python3[9148]: [I 210118 02:22:36 __init__:465] Running job Every 30 minutes do scheduled_job() (last run: 2021-01-18 01:52:36, next run: 2021-01-18 02:22:36)
Josh5 commented 3 years ago

I'm now seeing the same thing also. This is the first time this has happened, but is quite consistent now and at present the last 10 tasks have "finished" but not transferred and not appeared on completed list as either fail or complete.

The only thing that has recently changed that could potentially affect this was the fact I started to make hardlinks within my transcodes folder to files that I wanted to transcode, rather than pointing at my entire movie library. The first job completed, but everything after that did not. I wouldn't be surprised if in the background the above people are using hardlinks on some files also? As this is a potential situation if files are still being seeded etc.

Version: 0.0.1+25fc87e OS: Ubuntu 18.04.4 LXC on proxmox, source files on NFS share Install method: manually - ran as service

Output from systemd:

Jan 18 01:22:24 plex python3[9148]: Starting migrations
Jan 18 01:22:24 plex python3[9148]: There is nothing to migrate
Jan 18 01:52:25 plex python3[9148]: Exception in thread PostProcessor:
Jan 18 01:52:25 plex python3[9148]: Traceback (most recent call last):
Jan 18 01:52:25 plex python3[9148]:   File "/usr/lib/python3.6/shutil.py", line 550, in move
Jan 18 01:52:25 plex python3[9148]:     os.rename(src, real_dst)
Jan 18 01:52:25 plex python3[9148]: OSError: [Errno 18] Invalid cross-device link: '/tmp/unmanic/unmanic_file_conversion-1610932945.4042923/Knives Out (2019) - [Bluray-1080p]-1610932945.4043047.mkv' -> '/mnt/DATA/Media/transcode/Knives Out (2019)/Knives Out (2019) - [Bluray-1080p].mkv'
Jan 18 01:52:25 plex python3[9148]: During handling of the above exception, another exception occurred:
Jan 18 01:52:25 plex python3[9148]: Traceback (most recent call last):
Jan 18 01:52:25 plex python3[9148]:   File "/usr/lib/python3.6/threading.py", line 916, in _bootstrap_inner
Jan 18 01:52:25 plex python3[9148]:     self.run()
Jan 18 01:52:25 plex python3[9148]:   File "/var/lib/plexmediaserver/.local/lib/python3.6/site-packages/unmanic-0.0.1.dev11-py3.6.egg/unmanic/libs/postprocessor.py", line 132, in run
Jan 18 01:52:25 plex python3[9148]:     self.post_process_file()
Jan 18 01:52:25 plex python3[9148]:   File "/var/lib/plexmediaserver/.local/lib/python3.6/site-packages/unmanic-0.0.1.dev11-py3.6.egg/unmanic/libs/postprocessor.py", line 159, in post_process_file
Jan 18 01:52:25 plex python3[9148]:     shutil.move(cache_path, destination_data['abspath'])
Jan 18 01:52:25 plex python3[9148]:   File "/usr/lib/python3.6/shutil.py", line 564, in move
Jan 18 01:52:25 plex python3[9148]:     copy_function(src, real_dst)
Jan 18 01:52:25 plex python3[9148]:   File "/usr/lib/python3.6/shutil.py", line 263, in copy2
Jan 18 01:52:25 plex python3[9148]:     copyfile(src, dst, follow_symlinks=follow_symlinks)
Jan 18 01:52:25 plex python3[9148]:   File "/usr/lib/python3.6/shutil.py", line 121, in copyfile
Jan 18 01:52:25 plex python3[9148]:     with open(dst, 'wb') as fdst:
Jan 18 01:52:25 plex python3[9148]: PermissionError: [Errno 13] Permission denied: '/mnt/DATA/Media/transcode/Knives Out (2019)/Knives Out (2019) - [Bluray-1080p].mkv'
Jan 18 01:52:25 plex python3[9148]: [I 210118 01:52:25 __init__:465] Running job Every 30 minutes do scheduled_job() (last run: [never], next run: 2021-01-18 01:52:24)
Jan 18 02:22:36 plex python3[9148]: [I 210118 02:22:36 __init__:465] Running job Every 30 minutes do scheduled_job() (last run: 2021-01-18 01:52:36, next run: 2021-01-18 02:22:36)

The log you provided look like an issue with the way unmanic is able to read or write to your library. That could be incorrectly set permissions on the files, incorrectly set permissions on the mount or it could be that the shutil module does not handle hard links for some reason.

Could you try using changing back to not using hard links and see if the issue persists?

Could you also provide you systems unit?

SkinnySkelly commented 3 years ago

Same issue here. Just randomly started happening. I am using a network share that unmanic is reading from. But for about a week before the issue arose it was perfectly fine.

Hime0698 commented 3 years ago

Same issue in the LinuxServer Docker image on Unraid....

Tried Deleting the unmanic.db files and also rebooting, re-installing, clearing appdata and then re-installing.

Can't seem to fix it, or at least not more than temporarily or inconsistently

Edit: Update, Cleaned out appdata and reinstalled again, may have fixed the issue. If I haven't updated in a day or two someone ping me to ask.

Hime0698 commented 3 years ago

Issue seemed to be fixed, but now seems to be back, Docker log contains:

Exception in thread PostProcessor:
Traceback (most recent call last):
File "/usr/lib/python3.8/threading.py", line 932, in _bootstrap_inner
self.run()
File "/usr/local/lib/python3.8/dist-packages/unmanic/libs/postprocessor.py", line 126, in run
self.post_process_file()
File "/usr/local/lib/python3.8/dist-packages/unmanic/libs/postprocessor.py", line 272, in post_process_file
os.rmdir(task_cache_directory)
OSError: [Errno 39] Directory not empty: '/tmp/unmanic/unmanic_file_conversion-1631693305.1320677'

And also:

UnmanicLogger - SETUP LOGGER
Clearing cache path - /tmp/unmanic/unmanic_file_conversion-1631650844.4150126
Clearing cache path - /tmp/unmanic/unmanic_file_conversion-1631650854.6116574
Clearing cache path - /tmp/unmanic/unmanic_file_conversion-1631650858.2412345
Clearing cache path - /tmp/unmanic/unmanic_file_conversion-1631650864.9760451
Clearing cache path - /tmp/unmanic/unmanic_file_conversion-1631650870.2116933
Clearing cache path - /tmp/unmanic/unmanic_file_conversion-1631650874.2528205
Clearing cache path - /tmp/unmanic/unmanic_file_conversion-1631650879.3962443
Clearing cache path - /tmp/unmanic/unmanic_file_conversion-1631650884.4761813
Clearing cache path - /tmp/unmanic/unmanic_file_conversion-1631650890.9754224
Clearing cache path - /tmp/unmanic/unmanic_file_conversion-1631657243.8324327
Clearing cache path - /tmp/unmanic/unmanic_file_conversion-1631660213.1170955
Clearing cache path - /tmp/unmanic/unmanic_file_conversion-1631670057.0125268
Task was destroyed but it is pending!
task: <Task pending name='Task-29205' coro=<HTTP1ServerConnection._server_request_loop() running at /usr/local/lib/python3.8/dist-packages/tornado/http1connection.py:817> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x152408db2370>()]> cb=[IOLoop.add_future.<locals>.<lambda>() at /usr/local/lib/python3.8/dist-packages/tornado/ioloop.py:690]>
Task was destroyed but it is pending!
task: <Task pending name='Task-29212' coro=<HTTP1ServerConnection._server_request_loop() running at /usr/local/lib/python3.8/dist-packages/tornado/http1connection.py:817> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x152408cc3700>()]> cb=[IOLoop.add_future.<locals>.<lambda>() at /usr/local/lib/python3.8/dist-packages/tornado/ioloop.py:690]>
Task was destroyed but it is pending!
task: <Task pending name='Task-29213' coro=<HTTP1ServerConnection._server_request_loop() running at /usr/local/lib/python3.8/dist-packages/tornado/http1connection.py:817> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x15240b784100>()]> cb=[IOLoop.add_future.<locals>.<lambda>() at /usr/local/lib/python3.8/dist-packages/tornado/ioloop.py:690]>
Task was destroyed but it is pending!
task: <Task pending name='Task-30199' coro=<RequestHandler._execute() done, defined at /usr/local/lib/python3.8/dist-packages/tornado/web.py:1655> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x152408d6ef10>()]> cb=[_HandlerDelegate.execute.<locals>.<lambda>() at /usr/local/lib/python3.8/dist-packages/tornado/web.py:2329]>
Task was destroyed but it is pending!
task: <Task pending name='Task-30202' coro=<DashboardWebSocket.async_workers_info() done, defined at /usr/local/lib/python3.8/dist-packages/unmanic/webserver/main.py:126> wait_for=<Task pending name='Task-30582' coro=<WebSocketProtocol13.write_message.<locals>.wrapper() running at /usr/local/lib/python3.8/dist-packages/tornado/websocket.py:1104> wait_for=<Future pending cb=[BaseIOStream.write.<locals>.<lambda>() at /usr/local/lib/python3.8/dist-packages/tornado/iostream.py:556, <TaskWakeupMethWrapper object at 0x152408cc3b80>()]> cb=[<TaskWakeupMethWrapper object at 0x152408db22e0>()]> cb=[IOLoop.add_future.<locals>.<lambda>() at /usr/local/lib/python3.8/dist-packages/tornado/ioloop.py:690]>
Task was destroyed but it is pending!
task: <Task pending name='Task-30203' coro=<DashboardWebSocket.async_completed_tasks_info() done, defined at /usr/local/lib/python3.8/dist-packages/unmanic/webserver/main.py:139> wait_for=<Task pending name='Task-30583' coro=<WebSocketProtocol13.write_message.<locals>.wrapper() running at /usr/local/lib/python3.8/dist-packages/tornado/websocket.py:1104> wait_for=<Future pending cb=[BaseIOStream.write.<locals>.<lambda>() at /usr/local/lib/python3.8/dist-packages/tornado/iostream.py:556, <TaskWakeupMethWrapper object at 0x152408cc32b0>()]> cb=[<TaskWakeupMethWrapper object at 0x152408db2610>()]> cb=[IOLoop.add_future.<locals>.<lambda>() at /usr/local/lib/python3.8/dist-packages/tornado/ioloop.py:690]>
Task was destroyed but it is pending!
task: <Task pending name='Task-30582' coro=<WebSocketProtocol13.write_message.<locals>.wrapper() done, defined at /usr/local/lib/python3.8/dist-packages/tornado/websocket.py:1102> wait_for=<Future pending cb=[BaseIOStream.write.<locals>.<lambda>() at /usr/local/lib/python3.8/dist-packages/tornado/iostream.py:556, <TaskWakeupMethWrapper object at 0x152408cc3b80>()]> cb=[<TaskWakeupMethWrapper object at 0x152408db22e0>()]>
Task was destroyed but it is pending!
task: <Task pending name='Task-30583' coro=<WebSocketProtocol13.write_message.<locals>.wrapper() done, defined at /usr/local/lib/python3.8/dist-packages/tornado/websocket.py:1102> wait_for=<Future pending cb=[BaseIOStream.write.<locals>.<lambda>() at /usr/local/lib/python3.8/dist-packages/tornado/iostream.py:556, <TaskWakeupMethWrapper object at 0x152408cc32b0>()]> cb=[<TaskWakeupMethWrapper object at 0x152408db2610>()]>
[cont-finish.d] executing container finish scripts...
[cont-finish.d] done.
[s6-finish] waiting for services.
[s6-finish] sending all processes the TERM signal.
[s6-finish] sending all processes the KILL signal and exiting.

[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] 01-envfile: executing...
[cont-init.d] 01-envfile: exited 0.
[cont-init.d] 10-adduser: executing...
usermod: no changes

I am not sure if either or both of these are related, these are just what I have. I will be enabling debug mode.

Josh5 commented 3 years ago

What versions are you running to get these errors?

@kythorn , @MRobi1 @cbrherms - Your three reports are now on such old versions of Unmanic that I cannot possibly provide you with any support. Could you please update Unmanic and let me know if you still have an issue?

@SkinnySkelly , @Hime0698 I need to know what versions you are running on also. If you are having problems with Unmanic, could you please open separate issues and supply all the requested information.

Hime0698 commented 3 years ago

This seems to have been fixed with the latest update a couple of days ago. at least for me.

Josh5 commented 3 years ago

Closing issue because either the report is out dated or resolved

gotbletu commented 2 years ago

just started using unmanic today, had the same issue. i checked the logs, it was a write permission issue

podman run -ti -d \
  --name=unmanic \
  -e PUID=1000 \
  -e PGID=1000 \
  -p 8888:8888 \
  -v /media/bravo/unmanic/config:/config \
  -v /media/alfa/unmanic_watch:/library \
  -v /media/bravo/unmanic/cache:/tmp/unmanic \
  -v /media/bravo/unmanic/media:/media \
  josh5/unmanic:latest

only /tmp/unmanic folder has proper write permissions once it is mounted on the host machine

ls -la 
drwxrwxr-x /config
drwxrwxrwx /tmp/unmanic
drwxrwxr-x /library
drwxrwxr-x /media

you do not have write permission in /library once is mounted on the host machine. Or any other folder besides the /tmp/unmanic, so you will not be able to delete or move anything with the mover_v2 plugin.

quick solution for other people reading this, all you gotta do is allow the folders you using with mover_v2 plugin to have write permissions

chmod -R 777 /media/alfa/unmanic_watch       # my /library mount
chmod -R 777 /media/bravo/unmanic/media      # my /media mount where all the completed files are moved to

P.S: im using Ubuntu Server 20.04 if that matters 5.4.0-110-generic x86_64 x86_64 x86_64 GNU/Linux

Josh5 commented 2 years ago

For a little context. The docker image has a startup script that will set the permissions of the Unmanic config directory and the default /tmp/unmanic directory. It does not modify the permissions of any directories that unmanic is not 100% in charge of so as to avoid messing up peoples libraries.