Bug: PMS : Concurrent DVR postprocessing fails because .grab/uuid folder of second run is deleted

Plex Media Server Desktops & Laptops
1

Server Version#: 1.41.6.9685 (also reproduced with 1.40.2.8395) (MacOS)

Description:
When postprocessing DVR recordings, it seems that if more than one are running concurrently, the second one to finish will fail.

Plex might complain the postprocessing script deleted the source file (and call the script “Silly”…),
The script might complain the file disappeared, or fail encoding.
The end result is that the a recording fails.

Steps to reproduce:

  • Have a tuner with more than 1 tuners (e.g: hdhomerun)
  • setup a postprocessing script that will convert the .ts file to something else (.mkv in my case)
    • the postprocessing receives the ts file as the first argument. After converting it a new mkv file in the same folder, it removes the ts file.
  • start 2 concurrent recordings
  • wait a bit so there is something encode
  • stop both recordings (quickly)
    • (simulating 2 recordings ending at the same time)

Expected behavior: Both postprocessing work correctly, the recordings are available

What happened instead: After the first postprocessing script is done, plex deletes the ts file in .grab for the second recording - the second script fails in one way or another.

Workaround: In the postprocessing script:

  • don’t use the .grab folder, neither for reading or writing:
    • don’t use the ts file in the .grab/uuid-uuid/ folder to perform the conversion, create a hardlink to it, and convert the hardlinked file.
    • don’t encode the output file to the .grab/uuid-uuid/ folder, use a different work folder somewhere
  • When it’s time to replace the original ts file with the converted mkv, attempt to recreate the .grab/uuid-uuid/ folder first (e.g mkdir -p $(dirname "$1")), then put the mkv file where plex expects it.
    • might want to try twice just in case - the create folder and move file isn’t atomic, so there might be a race between the two :frowning:
  • Don’t error out if deleting the ts file causes a problem
    • Note, this might still be racy… I’ve had good success so far, but it’s somewhat of a hack for sure.

Technical steps to witness the issue :

  • start your concurrent recordings
  • In a terminal, go in the .grab folder, and start a watch -d -n1 find .
  • In another terminal, start a watch -n1 'ps aux | grep your_script_name | grep -v grep'
  • stop the recordings
  • watch how the files actively being postprocessed in the .grab folders disappear shortly after the first postprocessing script is done.

Logs of issue, with possible cause
The plex server debug logging seems to show the issue :
After the first processing script is done, we can see the following - the second folder is considered orphaned :frowning:

DEBUG - Grabber: Cleaning up orphaned grabs.
DEBUG - Grabber: Deleting "/Volumes/Drobo2k19/Media/DVR/TV shows/.grab/7d4c4e95e8ad48bf2efd7fe7730cae30bcf1c127-0dfa96406391b597d58a3cb6ad2fbe78cc468c62".
DEBUG - Grabber: Cleaned up 1 decrepit directories in 0.0 sec.

The full sequence of events is as follows (edited for brevity)

#Two postprocessing launch
# 7f99cec61e26e08b2a798b27534e52ba9f28c536
# and 
# 7d4c4e95e8ad48bf2efd7fe7730cae30bcf1c127
18:55:08.134 : Job running: "plexDvrEncode" ".grab/7f99cec61e26e08b2a798b27534e52ba9f28c536-0dfa96406391b597d58a3cb6ad2fbe78cc468c62
18:55:10.128 : Job running: "plexDvrEncode" ".grab/7d4c4e95e8ad48bf2efd7fe7730cae30bcf1c127-0dfa96406391b597d58a3cb6ad2fbe78cc468c6

#One finishes, 7f99cec61e26e08b2a798b27534e52ba9f28c536
18:55:30.658 : Recorder: Postprocessing script 'plexDvrEncode' seems to have renamed output file '".grab/7f99cec61e26e08b2a798b27534e52ba9f28c536-0dfa96406391b597d58a3cb6ad2fbe78cc468c62/file.ts"' to '.grab/7f99cec61e26e08b2a798b27534e52ba9f28c536-0dfa96406391b597d58a3cb6ad2fbe78cc468c62/file.mkv"'
18:55:30.668 : Assimilator: Moving ".grab/7f99cec61e26e08b2a798b27534e52ba9f28c536-0dfa96406391b597d58a3cb6ad2fbe78cc468c62/file.mkv" to "/Somepath/file.mkv"

#Cleaner cleans orphans... but it's not really an orphan, it's the other encode! :( 
#Cleaner removes 7d4c4e95e8ad48bf2efd7fe7730cae30bcf1c127
18:55:33.428 : Grabber: Cleaning up orphaned grabs.
18:55:33.429 : Grabber: Deleting ".grab/7d4c4e95e8ad48bf2efd7fe7730cae30bcf1c127-0dfa96406391b597d58a3cb6ad2fbe78cc468c62".
18:55:33.429 : Grabber: Cleaned up 1 decrepit directories in 0.0 sec.

#Second postprocessing finishes
#7d4c4e95e8ad48bf2efd7fe7730cae30bcf1c127
#Usually fails here, but in my case, I've worked around it so it works. See workaround
18:55:51.096 : Recorder: Postprocessing script 'plexDvrEncode' seems to have renamed output file '".grab/7d4c4e95e8ad48bf2efd7fe7730cae30bcf1c127-0dfa96406391b597d58a3cb6ad2fbe78cc468c62/file.ts"' to '".grab/7d4c4e95e8ad48bf2efd7fe7730cae30bcf1c127-0dfa96406391b597d58a3cb6ad2fbe78cc468c62/file.mkv"'

plexbug.concurrentpostprocessing.trimmed.log (8.2 KB)

Full logs of a reproduction available on demand, but they shouldn’t be needed…

1 Like
2

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.