search

cedarrapidsboy / pms-postprocessing

Post processing scripts to augment the Plex Media Server DVR functionality.
MIT License
18 stars 4 forks source link

Recording "fails" with rename error - recording is actually fine #2

Closed cedarrapidsboy closed 3 years ago

cedarrapidsboy commented 4 years ago

Discovered a recording the PMS GUI labeled as a failure, but it played fine and was converted to H264 fine. No warnings or errors from the transcode script. However, the following log snippet shows a PMS error after transcoding:

May 13, 2020 23:00:08.772 [0x7fdaf3fff700] DEBUG - Jobs: '/config/Library/Application Support/Plex Media Server/Scripts/transcode_internal.sh' exit code for process 29620 is 0 (success)
May 13, 2020 23:00:08.932 [0x7fda717fa700] DEBUG - Recorder: Postprocessing script '/config/Library/Application Support/Plex Media Server/Scripts/transcode_internal.sh' seems to have renamed output file '"/share/CACHEDEV1_DATA/videos/Videos/TV Recordings/.grab/157ff26abfbaa01d4a11106325e9765b5e8cdff2-7f9f7b46b1f30e96a88eaba2808c869ec4e3f4a8/Survivor (2019) - S40E14 - It All Boils Down to This.ts"' to '"/share/CACHEDEV1_DATA/videos/Videos/TV Recordings/.grab/157ff26abfbaa01d4a11106325e9765b5e8cdff2-7f9f7b46b1f30e96a88eaba2808c869ec4e3f4a8/Survivor (2019) - S40E14 - It All Boils Down to This.mp4"'
May 13, 2020 23:00:08.932 [0x7fda717fa700] DEBUG - Recorder: Postprocessing script '/config/Library/Application Support/Plex Media Server/Scripts/transcode_internal.sh' was successful in 3608.1 seconds. Nicely done.
May 13, 2020 23:00:08.932 [0x7fda717fa700] DEBUG - Grabber: Scheduling 'Survivor - E14 - It All Boils Down to This' for assimilation.
May 13, 2020 23:00:08.938 [0x7fdaccff9700] DEBUG - HTTP requesting GET http://192.168.1.10:80/discover.json
May 13, 2020 23:00:08.941 [0x7fda25ffb700] WARN - SLOW QUERY: It took 1127490.000000 ms to retrieve 2 items.
May 13, 2020 23:00:08.945 [0x7fdaccff9700] DEBUG - HTTP 200 response from GET http://192.168.1.10:80/discover.json
May 13, 2020 23:00:08.946 [0x7fdaccff9700] DEBUG - HTTP requesting GET http://192.168.1.10:80/lineup_status.json
May 13, 2020 23:00:08.953 [0x7fda73fff700] DEBUG - Subscription: Resolved subscription to library item 'Survivor' (55104)
May 13, 2020 23:00:08.961 [0x7fdaccff9700] DEBUG - HTTP 200 response from GET http://192.168.1.10:80/lineup_status.json
May 13, 2020 23:00:08.982 [0x7fda73fff700] DEBUG - There were 1 top-level paths for Survivor.
May 13, 2020 23:00:08.982 [0x7fda73fff700] DEBUG - Assimilator: Postprocessing, we're going to put `Survivor - E14 - It All Boils Down to This` in `/share/CACHEDEV1_DATA/videos/Videos/TV Recordings/Survivor (2019)/Season 40/Survivor (2019) - S40E14 - It All Boils Down to This.mp4`
May 13, 2020 23:00:09.521 [0x7fda25ffb700] DEBUG - It took 60.000000 ms to retrieve 43 items.
May 13, 2020 23:00:09.558 [0x7fda73fff700] DEBUG - Assimilator: Moving "/share/CACHEDEV1_DATA/videos/Videos/TV Recordings/.grab/157ff26abfbaa01d4a11106325e9765b5e8cdff2-7f9f7b46b1f30e96a88eaba2808c869ec4e3f4a8/Survivor (2019) - S40E14 - It All Boils Down to This.mp4" to "/share/CACHEDEV1_DATA/videos/Videos/TV Recordings/Survivor (2019)/Season 40/Survivor (2019) - S40E14 - It All Boils Down to This.mp4"
May 13, 2020 23:00:09.559 [0x7fda73fff700] DEBUG - Assimilator: Moving "/share/CACHEDEV1_DATA/videos/Videos/TV Recordings/.grab/157ff26abfbaa01d4a11106325e9765b5e8cdff2-7f9f7b46b1f30e96a88eaba2808c869ec4e3f4a8/.nfs0000000011fc075800000017" to "/share/CACHEDEV1_DATA/videos/Videos/TV Recordings/Survivor (2019)/Season 40/.nfs0000000011fc075800000017"
May 13, 2020 23:00:09.559 [0x7fda73fff700] ERROR - Couldn't rename file "/share/CACHEDEV1_DATA/videos/Videos/TV Recordings/.grab/157ff26abfbaa01d4a11106325e9765b5e8cdff2-7f9f7b46b1f30e96a88eaba2808c869ec4e3f4a8/.nfs0000000011fc075800000017" to "/share/CACHEDEV1_DATA/videos/Videos/TV Recordings/Survivor (2019)/Season 40/.nfs0000000011fc075800000017": Device or resource busy
May 13, 2020 23:00:09.559 [0x7fda73fff700] DEBUG - Grabber: Operation for 'Survivor - E14 - It All Boils Down to This' on channel 2.1 completed with status error (Could not move recorded media to destination)

/share/CACHEDEV1_DATA/videos is an NFS location (NAS server).

This may need investigation.

cedarrapidsboy commented 4 years ago

This may happen when the script ends and Plex attempts to move all the remaining files to the Library. Between the "rm" command in the script that removes the original file, and the Plex "mv" command, NFS has not has enough time to release the original file handle and clean-up the .nfsxxx placeholder. So Plex tries moving both the transcoded .mp4 file and the file left-over by NFS (.nfsxxx).

As shown above, the error does not affect the addition of the .mp4 file to the library.

Perhaps an artificial delay in the transcoding script would give NFS more time for clean-up? Or, maybe the .nfsxxx file hangs around for some other reason.

cedarrapidsboy commented 3 years ago

OBE