Unmanic / unmanic

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

Wait for copy, avoid overlapping file events #441

Closed BlakeGardner closed 3 months ago

BlakeGardner commented 4 months ago

Pull request

CLA

Checklist

Problem Statement:

During testing, it was observed that Unmanic would attempt to test/process files before they were fully written to disk. In my setup, file copying to shared/mounted drives can sometimes take a minute or two to complete.

Additionally, a single file copy was found to trigger multiple overlapping created and modified events. This caused the file monitoring system to repeatedly attempt testing the same file.

Proposed Changes in This PR:

This PR aims to address these issues by implementing the following fixes:

  1. Event Listening Improvements: Now listens for both created and modified events to accurately capture file changes across all test scenarios.
  2. Write-in-Progress Check: Implements a check to avoid testing a file if it is still being written to. This prevents Unmanic from processing files prematurely.
  3. Thread Lock Usage: Utilizes a thread lock to ensure that multiple overlapping events do not lead to redundant file testing.

Before Changes

Simulate a slow file copy

rsync --inplace --bwlimit=39321 --progress ~/Movie.mkv ~/Code/unmanic-docker/library

INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/Movie.mkv'
DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...
INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'modified' event on file path '/library/Movie.mkv'
INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'modified' event on file path '/library/Movie.mkv'

File system copy

cp ~/Movie.mkv ~/Code/unmanic-docker/library

INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/Movie.mkv'
DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...
INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'modified' event on file path '/library/Movie.mkv'
INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'modified' event on file path '/library/Movie.mkv'

Directly move a file

mv Movie.mkv foo.mkv

INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/foo.mkv'
DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...
INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'modified' event on file path '/library/foo.mkv'

Create a file

touch hello.mkv

INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/hello.mkv'
DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...

Modify a file

echo "hello" >> hello.mkv

INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'modified' event on file path '/library/hello.mkv'

Create a new file by copying an existing

cp foo.mkv new.mkv

INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/new.mkv'
DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...
INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'modified' event on file path '/library/new.mkv'
INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'modified' event on file path '/library/new.mkv'

After Changes

Simulate a slow file copy

rsync --inplace --bwlimit=39321 --progress ~/Movie.mkv ~/Code/unmanic-docker/library

2023-12-29T22:50:57:INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/Movie.mkv'
2023-12-29T22:50:57:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:50:58:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:50:59:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:00:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:01:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:02:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:03:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:04:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:05:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:06:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:07:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:08:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:09:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:10:DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...
2023-12-29T22:51:10:DEBUG:Unmanic.EventProcessor - [FORMATTED] - Ignoring 'modified' event on file path '/library/Movie.mkv' due to other events
2023-12-29T22:51:11:DEBUG:Unmanic.Plugin.video_transcoder - File '/library/Movie.mkv' should be added to task list. Plugin found streams require processing.
2023-12-29T22:51:13:DEBUG:Unmanic.Task - [FORMATTED] - Created new task with ID: 1 for /library/Movie.mkv
2023-12-29T22:51:13:INFO:Unmanic.TaskHandler - [FORMATTED] - Adding inotify job to queue - /library/Movie.mkv

File system copy

cp ~/Movie.mkv ~/Code/unmanic-docker/library

2023-12-29T22:51:37:INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/Movie.mkv'
2023-12-29T22:51:37:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:38:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:39:DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...
2023-12-29T22:51:39:DEBUG:Unmanic.EventProcessor - [FORMATTED] - Ignoring 'modified' event on file path '/library/Movie.mkv' due to other events
2023-12-29T22:51:40:DEBUG:Unmanic.Plugin.video_transcoder - File '/library/Movie.mkv' should be added to task list. Plugin found streams require processing.
2023-12-29T22:51:41:INFO:Unmanic.TaskHandler - [FORMATTED] - Skipping inotify job already in the queue - /library/Movie.mkv

Directly move a file

mv Movie.mkv foo.mkv

2023-12-29T22:52:38:INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/foo.mkv'
2023-12-29T22:52:38:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/foo.mkv' still being written to, waiting.
2023-12-29T22:52:39:DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...
2023-12-29T22:52:39:DEBUG:Unmanic.EventProcessor - [FORMATTED] - Ignoring 'modified' event on file path '/library/foo.mkv' due to other events
2023-12-29T22:52:41:DEBUG:Unmanic.Plugin.video_transcoder - File '/library/foo.mkv' should be added to task list. Plugin found streams require processing.
2023-12-29T22:52:41:DEBUG:Unmanic.Task - [FORMATTED] - Created new task with ID: 2 for /library/foo.mkv
2023-12-29T22:52:41:INFO:Unmanic.TaskHandler - [FORMATTED] - Adding inotify job to queue - /library/foo.mkv

Create a file

touch hello.mkv

2023-12-29T22:53:05:INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/hello.mkv'
2023-12-29T22:53:05:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/hello.mkv' still being written to, waiting.
2023-12-29T22:53:06:DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...
2023-12-29T22:53:09:DEBUG:Unmanic.Plugin.video_transcoder - File unable to be probed by FFProbe - '/library/hello.mkv'

Modify a file

echo "hello" >> hello.mkv

2023-12-29T22:53:27:INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'modified' event on file path '/library/hello.mkv'
2023-12-29T22:53:27:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/hello.mkv' still being written to, waiting.
2023-12-29T22:53:30:DEBUG:Unmanic.Plugin.video_transcoder - File unable to be probed by FFProbe - '/library/hello.mkv'

Create a new file by copying an existing

cp foo.mkv new.mkv

2023-12-29T22:53:57:INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/new.mkv'
2023-12-29T22:53:57:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/new.mkv' still being written to, waiting.
2023-12-29T22:53:58:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/new.mkv' still being written to, waiting.
2023-12-29T22:53:59:DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...
2023-12-29T22:53:59:DEBUG:Unmanic.EventProcessor - [FORMATTED] - Ignoring 'modified' event on file path '/library/new.mkv' due to other events
2023-12-29T22:54:00:DEBUG:Unmanic.Plugin.video_transcoder - File '/library/new.mkv' should be added to task list. Plugin found streams require processing.
2023-12-29T22:54:02:DEBUG:Unmanic.Task - [FORMATTED] - Created new task with ID: 3 for /library/new.mkv
2023-12-29T22:54:02:INFO:Unmanic.TaskHandler - [FORMATTED] - Adding inotify job to queue - /library/new.mkv
BlakeGardner commented 3 months ago

I am closing this PR because the solution I feel is a bit too complex for the problem I was originally trying to solve.