Unable to delete File - Please check your permissions

Plex Media Server Desktops & Laptops
101

@j-sta said:
Though I had also experienced the issue when no new media was being added; which should then, theoretically, mean that there were no refreshes occurring.

I too have had the issue when no new media has been added - since the last server restart. As per this comment:
https://forums.plex.tv/discussion/comment/1554064/#Comment_1554064
I thought I was going to be able to reproduce the issue, but… no dice. Following the same procedure that I thought caused the issue the first time, the issue wasn’t reproduced the second time. The issue continues at random times seemingly out of nowhere.

102

@j-sta said:
Do all libraries get refreshed when new media is added?

With partial directory scanning library setting, it ought only be the directory that had the changes - although this would depend on the library category

In any case, it would not be all libraries. Without partial directory scanning, it would be the whole library that gets refereshed

In the specific case where you are watching a TV Episode. At the end of streaming, the client app may ask the server for the item metadata xml and on getting such request. if the server notices that the directory in which this episode is in, has changed then a refresh request is made to the agent. In my testing this completed very quickly and did not get in the way of subsequent delete request

@j-sta said:
Since I created a whole new library for the standalone drive, then any refreshes that would have occurred would have only occurred if the new media file was added to said new library, correct? Or would new media added to original library also refresh media on test library?

It is the directory where the episode in that matters. Changes to other directories should not affect it unless automatic library updates is enabled and no partial directory scanning

@j-sta said:
Though I had also experienced the issue when no new media was being added; which should then, theoretically, mean that there were no refreshes occurring.

Will keep an open mind on this. There may be several causes

At this moment, I would like to see diagnostics form other users as well - similar to what you provided

103

SA2000, let me explain my set up so you can determine whether any future logs would be helpful or not.
My Plex Server is on an Intel NUC (NUC6i7KYK) running Windows 10 Professional (64 bit OS). The server is connected to a Seagate 8TB external drive via USB 3.0 which holds all media. Presentation, and deletion of, media is from an XBox One console. Network is gigabit with Cat5e cables.

104

@QuadPC-Plex said:
SA2000, let me explain my set up so you can determine whether any future logs would be helpful or not.
My Plex Server is on an Intel NUC (NUC6i7KYK) running Windows 10 Professional (64 bit OS). The server is connected to a Seagate 8TB external drive via USB 3.0 which holds all media. Presentation, and deletion of, media is from an XBox One console. Network is gigabit with Cat5e cables.

The client app used should not matter.
USB connected media may introduce potential issues with media having to be rescanned and re-matched if the connection to the disk is lost - this is similar to when having media on a NAS and it is the reason for recommending not to have trash emptied automatically when media is on a NAS.

I would like to look at other logs and proc mon capture of a playback and delete sequence - would probably be best to do with a test library and some short episodes. I was doing my tests with 7-minute children programme episodes - so something like that. Having procmon run for a long time would kill the machine as it uses up system resources

105

Oh, ok. Did not realize that may occur with a USB drive.

Also, I just updated to Win10 1709.

Before I waste any (more) of your time, let me migrate a few of my shows from the Seagate USB to my internal Samsung M2 960 Pro SSD to see if I still have trouble deleting the shows.

106

This happens to me with about half the shows I try to delete. Running the server on Windows 10 Pro (1709). Extremely frustrating!

107

Yea, about 10 times this weekend - and not at all last week.
Frustrating is an interesting word - and also quite an understatement.

108

sa2000 - playing with Process Monitor - did you want me to filter on something? Also, did you want the ProcMon logs and Plex logs posted here?

109

@QuadPC-Plex said:
sa2000 - playing with Process Monitor - did you want me to filter on something? Also, did you want the ProcMon logs and Plex logs posted here?

I would like unfiltered if you can manage that and upload as zip on dropbox / onedrive etc and send me link by private message. That makes it eaiser to sink with log file contents

And the zipped logs (all logs including added plugins logs)

110

Got all set up with ProcMon and now 10 shows in a row have deleted properly. This may take a bit…

(20 minutes later…) There was a change: I had been running HandBrake in the background (24/7) for transcoding shows into H265 and stopped it for this test.

111

@QuadPC-Plex said:
Got all set up with ProcMon and now 10 shows in a row have deleted properly. This may take a bit…

(20 minutes later…) There was a change: I had been running HandBrake in the background (24/7) for transcoding shows into H265 and stopped it for this test.

I have been looking into the 15 December diagnostics - procmon, opened files viewer and logs

This was for recording file
C:\Users\Plex\zRecordings\The Five (2011)\Season 2017\The Five (2011) - 2017-12-15 00 00 00 - Episode 12-15.ts

I am afraid the Opened Files Viewer export was no good - it just had one line in it, You would need to select all before exporting. The ProcMon was started after the file was locked out so did not show what actually opened it beforehand. I understand this could be impossible to capture - so just would like to go with logs and opened files viewer output

I am going to summarize what the logs showed

The Five (2011) Episode 12-15 was being watched until 18:10:04

Dec 15, 2017 18:10:04.031 [12768] DEBUG - Request: [192.168.1.215:49774 (Subnet)] GET /:/timeline?hasMDE=1&ratingKey=43138&key=%2Flibrary%2Fmetadata%2F43138&state=stopped&playQueueItemID=20366&time=2603237&duration=2771320 (15 live) TLS GZIP Signed-in Token (QuadPC-Plex)

Dec 15, 2017 18:10:04.031 [12768] DEBUG - Client [nnt3quu58pakwu13zjsh4s9u] reporting timeline state stopped, progress of 2603237/2771320ms for guid=, ratingKey=43138 url=, key=/library/metadata/43138, containerKey=, metadataId=43138

Dec 15, 2017 18:10:04.031 [12768] DEBUG - [Now] Updated play state for /library/metadata/43138.

Dec 15, 2017 18:10:04.031 [5140] DEBUG - Completed: [192.168.1.215:49774] 200 GET /:/timeline?hasMDE=1&ratingKey=43138&key=%2Flibrary%2Fmetadata%2F43138&state=stopped&playQueueItemID=20366&time=2603237&duration=2771320 (15 live) TLS GZIP 13ms 467 bytes (pipelined: 1)

Dec 15, 2017 18:10:04.046 [5140] DEBUG - Failed to stream media, client probably disconnected: 10054 - An existing connection was forcibly closed by the remote host

Dec 15, 2017 18:10:04.046 [5140] DEBUG - Completed: [192.168.1.215:49771] 200 GET /library/parts/225512/1513383745/file.ts (15 live) TLS GZIP 26220ms 23232512 bytes (pipelined: 1)

You then deleted a different episode successfully - may be Episode 12-14.ts (not sure)

Dec 15, 2017 18:10:16.781 [12768] DEBUG - Request: [192.168.1.215:49775 (Subnet)] DELETE /library/metadata/43115 (9 live) TLS GZIP Signed-in Token (QuadPC-Plex)
Dec 15, 2017 18:10:16.828 [10108] INFO - Library section 2 (TV Shows) will be updated because of a change in C:\Users\Plex\zRecordings\The Five (2011)\Season 2017
Dec 15, 2017 18:10:16.843 [12768] DEBUG - Deleting media item 203523.
Dec 15, 2017 18:10:16.843 [12768] DEBUG - Was connected to metadata item 43115, count is now 0.
Dec 15, 2017 18:10:16.843 [12768] DEBUG - Destroying metadata item 43115 (Episode 12-14)
Dec 15, 2017 18:10:16.843 [12768] DEBUG - Updating deletion state for metadata item 43037, is has a dead item count of 0.
Dec 15, 2017 18:10:16.843 [12768] DEBUG - Updating deletion state for metadata item 43036, is has a dead item count of 0.
Dec 15, 2017 18:10:16.859 [5140] DEBUG - Completed: [192.168.1.215:49775] 200 DELETE /library/metadata/43115 (9 live) TLS GZIP 85ms 195 bytes

This deletion triggered a library update which is delayed by a minute to stop us repeatedly doing library updates when files change

Dec 15, 2017 18:11:16.843 [10808] DEBUG - Library Updater: Queueing section 2
Dec 15, 2017 18:11:16.843 [2072] INFO - Notification: Scanning the "TV Shows" section - 
Dec 15, 2017 18:11:16.843 [2072] DEBUG - Scanning section 2
Dec 15, 2017 18:11:16.843 [2072] DEBUG - Killing job.
Dec 15, 2017 18:11:16.843 [2072] DEBUG - Job running: EAE_ROOT='\\?\c:\users\public\documents\Transcode\Sessions\EasyAudioEncoder' FFMPEG_EXTERNAL_LIBS='\\\\?\\C\:\\Users\\Plex\\AppData\\Local\\Plex\ Media\ Server\\Codecs\\b077134-1269-windows-i386\\' X_PLEX_TOKEN='xxxxxxxxxxxxxxxxxxxx' C:\Program Files (x86)\Plex\Plex Media Server\Plex Media Scanner.exe --scan --refresh --section 2 --directory "C:\Users\Plex\zRecordings\The Five (2011)\Season 2017"

The re-scan completed at 18:11:18 but there was still async activity

Dec 15, 2017 18:11:18.124 [2072] INFO - Notification: Library scan complete - Extra information may still be downloading from the Internet

The last localmedia agent activity was at 18:12:25

2017-12-15 18:12:25,197 (34d0) :  DEBUG (networking:166) - Requesting 'http://127.0.0.1:32400/library/metadata/43138/tree'
2017-12-15 18:12:25,207 (34d0) :  INFO (logkit:16) - Creating season 2017
2017-12-15 18:12:25,210 (34d0) :  INFO (logkit:16) - Looking for episode media (The Five) in 1 paths (root file: The Five (2011) - 2017-12-15 00 00 00 - Episode 12-15) with 1 media files.
2017-12-15 18:12:25,210 (34d0) :  INFO (logkit:16) - Paths: C:\Users\Plex\zRecordings\The Five (2011)\Season 2017
2017-12-15 18:12:25,213 (34d0) :  INFO (logkit:16) - Found 0 valid things for pattern The\ Five\ \(2011\)\ \-\ 2017\-12\-15\ 00\ 00\ 00\ \-\ Episode\ 12\-15(-|-thumb)?[0-9]? (ext: ['jpg', 'png', 'jpeg', 'tbn'])
2017-12-15 18:12:25,213 (34d0) :  INFO (logkit:16) - Looking for show media for None.
2017-12-15 18:12:25,220 (34d0) :  INFO (logkit:16) - Looking for show media (The Five) in 3 paths (root file: None) with 1 media files.
2017-12-15 18:12:25,220 (34d0) :  INFO (logkit:16) - Paths: C:\Users\Plex\zRecordings\The Five (2011), C:\Users\Plex\zRecordings\The Five (2011)\Season 2017, C:\Users\Plex\zRecordings
2017-12-15 18:12:25,221 (34d0) :  INFO (logkit:16) -   Local asset added: C:\Users\Plex\zRecordings\The Five (2011)\Poster.jpg (e7e3ff706dfddf4a62a375c28c4e5f90)
2017-12-15 18:12:25,223 (34d0) :  INFO (logkit:16) - Found 1 valid things for pattern (show|poster|folder)-?[0-9]? (ext: ['jpg', 'png', 'jpeg', 'tbn'])
2017-12-15 18:12:25,223 (34d0) :  INFO (logkit:16) - Found 0 valid things for pattern banner-?[0-9]? (ext: ['jpg', 'png', 'jpeg', 'tbn'])
2017-12-15 18:12:25,224 (34d0) :  INFO (logkit:16) -   Local asset added: C:\Users\Plex\zRecordings\The Five (2011)\Background.jpg (f40253c288fa140bf6b72dc81433bdd2)
2017-12-15 18:12:25,226 (34d0) :  INFO (logkit:16) - Found 1 valid things for pattern (fanart|art|background|backdrop)-?[0-9]? (ext: ['jpg', 'png', 'jpeg', 'tbn'])
2017-12-15 18:12:25,226 (34d0) :  INFO (logkit:16) - Found 0 valid things for pattern theme-?[0-9]? (ext: ['mp3'])
2017-12-15 18:12:25,226 (34d0) :  INFO (logkit:16) - Looking for season media for None season 2017.
2017-12-15 18:12:25,230 (34d0) :  INFO (logkit:16) - Looking for season media (The Five) in 3 paths (root file: None) with 1 media files.
2017-12-15 18:12:25,232 (34d0) :  INFO (logkit:16) - Paths: C:\Users\Plex\zRecordings\The Five (2011), C:\Users\Plex\zRecordings\The Five (2011)\Season 2017, C:\Users\Plex\zRecordings
2017-12-15 18:12:25,233 (34d0) :  INFO (logkit:16) - Found 0 valid things for pattern season-?0?2017[-a-z]?(-poster)? (ext: ['jpg', 'png', 'jpeg', 'tbn'])
2017-12-15 18:12:25,233 (34d0) :  INFO (logkit:16) - Found 0 valid things for pattern season-?0?2017-banner[-a-z]? (ext: ['jpg', 'png', 'jpeg', 'tbn'])
2017-12-15 18:12:25,233 (34d0) :  INFO (logkit:16) - Found 0 valid things for pattern season(-|0|\s)?2017-(fanart|art|background|backdrop)[-a-z]? (ext: ['jpg', 'png', 'jpeg', 'tbn'])
2017-12-15 18:12:25,234 (34d0) :  INFO (logkit:16) - Looking for subtitle media in 1 paths with 1 media files.
2017-12-15 18:12:25,234 (34d0) :  INFO (logkit:16) - Paths: C:\Users\Plex\zRecordings\The Five (2011)\Season 2017
2017-12-15 18:12:25,256 (34d0) :  DEBUG (model:229) - Serializing to C:\Users\Plex\AppData\Local\Plex Media Server\Metadata\TV Shows\7\986038e78c3377fb7088364c1b2134c1de6292d.bundle\Contents\com.plexapp.agents.localmedia\Info.xml
2017-12-15 18:12:25,259 (34d0) :  DEBUG (runtime:88) - Sending packed state data (110 bytes)
2017-12-15 18:12:25,259 (34d0) :  DEBUG (runtime:924) - Response: [200] str, 16 bytes

It is a bit too close - your first deletion attempt at 18:12:31

metadata/43095 (10 live) TLS GZIP 62ms 195 bytes (pipelined: 4)

Dec 15, 2017 18:12:31.328 [12768] DEBUG - Request: [192.168.1.215:49864 (Subnet)] DELETE /library/metadata/43138 (15 live) TLS GZIP Signed-in Token (QuadPC-Plex)

Dec 15, 2017 18:12:32.359 [12768] ERROR - SHFileOperationW returned 0x20 for FO_DELETE on 'C:\Users\Plex\zRecordings\The Five (2011)\Season 2017\The Five (2011) - 2017-12-15 00 00 00 - Episode 12-15.ts'. Falling back to deleting file.

Dec 15, 2017 18:12:32.359 [5140] DEBUG - Completed: [192.168.1.215:49864] 400 DELETE /library/metadata/43138 (16 live) TLS GZIP 1041ms 384 bytes (pipelined: 10)

It has not been possible to reproduce the issue for me.

If it was just timing then it would have cleared after this but repeated attempts to delete from Plex Web after the attempt on the Xbox One, failed in same way

Dec 15, 2017 18:27:51.386 [9268] DEBUG - Request: [192.168.1.14:58917 (Subnet)] DELETE /library/metadata/43138 (13 live) TLS GZIP Signed-in Token (QuadPC-Plex)
Dec 15, 2017 18:27:52.490 [9268] ERROR - SHFileOperationW returned 0x20 for FO_DELETE on 'C:\Users\Plex\zRecordings\The Five (2011)\Season 2017\The Five (2011) - 2017-12-15 00 00 00 - Episode 12-15.ts'. Falling back to deleting file.
Dec 15, 2017 18:27:52.503 [5140] DEBUG - Completed: [192.168.1.14:58917] 400 DELETE /library/metadata/43138 (15 live) TLS GZIP 1117ms 457 bytes (pipelined: 1)

which suggests a process/thread failed to release a file handle

Lets continue with this and try to get me the logs + opened files viewer export (of all entries) and as we get the confirmation that it is the agent - then can see if we can add some extra diagnostic logging

112

…could use some help from others contributing their time and logs to this problem.

113

@QuadPC-Plex said:
…could use some help from others contributing their time and logs to this problem.

Thanks for your time so far. It is clear that ProcMon capture is not viable unless one knows it is going to fail. The proc mon capture would need to start from time when the video was being streamed up to time of error

It is also clear from the last set of diagnostics that there may be some timing issues here - as the scan of the whole TV Show started about a minute after deleting an episode and in your case, appears to have completed only 5 seconds before you attempted to delete the 2nd episode which failed with the sharing violation

The problem that needs to be solved is where this happens but the file lock remains on until a restart of the server - so not a timing problem where deletion is temporarily failing but one where deletion is locked out permanently until the restart of the server

Assuming that we cannot get any useful ProcMon capture, we can just concentrate now on logs and all the records from the Opened Files Viewer output. If there is consistency in what is seen, then we can look into getting some additional debug logging added

114

WANTED:

High Level Experienced Code Monkeys willing to invest the time necessary to identify and fix this problem…
then tell Plex how to do it.

Please Apply Within.

There will be no pay, but you will get an astounding sense of fine JuJu by helping others.

115

This is really getting old. I’m sick and tired of having to go to my server, shutdown Plex, delete my file and restart Plex. This problem was identified a long time ago. Please get this bug fixed.

116

Oh, it got old back in July, 2017 when it quit working.

117

If Plex isn’t going to fix this we need an option in PMP or a taskbar entry that enables a PMS restart.

I can change the TV to the HDMI Server Port, but that screen doesn’t have the system tray - for restarting PMS when the files are all locked up. The ONLY solution is to travel to the server, restart PMS, delete the files manually or since the files aren’t locked up any more (for the next few minutes) delete normally from the client.

We’ve been sat right here since July - Plex seems just as interested in fixing it now as the day they broke it (read: not interested) - so we need work-around options.

118

If you’re lucky enough to have access to a Server Window from ‘the comfy chair’ - here’s a PMS Killer Work Around:

Otherwise you’ll have to get up, walk to the server and restart PMS to resume normal operations temporarily - until you have to do it again.

119

Bump.

Is this being worked? I’d hate to think I have to live with this bug forever.

120

@edbro said:
Bump.

Is this being worked? I’d hate to think I have to live with this bug forever.

last comment by a Plex person (sa2000) is that they have been unable to reproduce the issue, and were hoping to get some more folks to provide requested log files.

I’ve just been living with it.
I have no need to immediately delete the file, so I just take care of it usually the following day.
While yes, it is an extreme annoyance, it’s pretty minor really.
Not sure why it’s so absolutely crucial for some folks to need to immediately delete their media file(s)