@sa2000 said:
33145 was the episode - which has a parent id and a grandparent id
The requests that were being made were for the episode which is what I wanted to see
Anything you filter out of the PML file must not have a path value for the episode file
Upload zip to dropbox or google drive etc and send me link by PM
The xml I want is that for the metadata number that shows on the DELETE /library/metadata/xxxxx line
If you give me other episode xml - then I would need the full set of logs to look into the idās and how they got referenced
is the episode a singular unique ID that doesnāt change if the episode is removed and re-added?
2 are identical and all 3 are only a single-line long. These are for 33145.
the 2 in the library folder:
MediaContainer size=ā0ā identifier=ācom.plexapp.plugins.libraryā mediaTagPrefix=ā/system/bundle/media/flags/ā mediaTagVersion=ā1509120104ā></MediaContainer
Still working on the PML.
PML file size only dropped 2 gigs; to 22gb total.
Attempting to ZIP, which is currently at >930mb in size and about 79% complete.
Thank you for the PML - it captured the whole period when thetvdb process that Opened Files View implicated.
Spent a long time going through the 49 million events - picked up all the file accesses.
My conclusion is that Opened Files Viewer was lying or - it cannot handle Drive Pool environments. There is no evidence of thetvdb agent opening the file and locking it out
The following processes were the only processes that accessed this file Z:\Recorded TV\TV Shows\Chicago P.D\Chicago P.D. - S05E06 - Fallen - HDTV-720p REAL.mkv
DrivePool Service
Microsoft Windows Defender
Plex Media Server
Plex Media Scanner
The subzero plugin
System
The procmon shows the file being in 2 drive pool areas.
I am referring my findings and analysis to the development team but I would really want to see similar diagnostics from an environment that does not have DrivePool
Iāll make a test library on my D drive, that way the files are not on the DrivePool drive.
Windows Resource Monitor shows the lock by PlexScriptHost as well, so itās not only OpenedFilesView reporting that.
I also want to reiterate that this issue did not exist until after updating Plex to 1.7.5.4035
@j-sta said:
Iāll make a test library on my D drive, that way the files are not on the DrivePool drive.
Windows Resource Monitor shows the lock by PlexScriptHost as well, so itās not only OpenedFilesView reporting that.
I also want to reiterate that this issue did not exist until after updating Plex to 1.7.5.4035
I will grab output from handle as well.
Thanks
Do you remember what version the update to 1.7.5.4035 was from?
@j-sta said:
Iāll make a test library on my D drive, that way the files are not on the DrivePool drive.
Windows Resource Monitor shows the lock by PlexScriptHost as well, so itās not only OpenedFilesView reporting that.
I also want to reiterate that this issue did not exist until after updating Plex to 1.7.5.4035
I will grab output from handle as well.
Thanks
Do you remember what version the update to 1.7.5.4035 was from?
most likely it was 1.5.7.4016
thatās the installer prior to 1.7.5 available in the Updates folder.
So it does still occur when the media is on a standalone (non-DrivePool) drive.
This time there are 2 different PlexScriptHost processes accessing the file.
The access began some 5+ minutes after I started streaming to my Roku.
At the same time, I saw a PlexTranscoder process was spawned to thumbnail new media.
Additionally, there was 2nd PlexTranscoder process running on the media file I was in the middle of streaming (which had already had thumbnails created.) That, too, was not spawned for some 5+ minutes in to streaming.
Media is direct stream/play to my Roku, so there is no other reason for PlexTranscoder to process the media, other than the thumbnail creation.
handlecapture is attached.
Family Guy - S16E06 - The D in Apartment 23 - HDTV-720p.mkv
Edit:
Streamed another show, 2 PlexScriptHost processes. New media added while streaming. Was not at my computer to see any processes launching though.
Next show (third), again PlexTranscoder process launches for new media. A second PlexTranscoder process launches for currently-streaming media. >10 minutes in. Again, direct stream/play to Roku, no transcoding. Though again, both PlexTranscoder processes do close.
Previous 2 PIDs (from show 2) still locking file, so killed processes.
More new media added. A couple seconds before PlexTranscoder process spawns for new media, PlexScriptHost spawns for currently-streaming media.
It does appear that there may be a correlation with processes spawning for new media also spawning processes for currently-streaming media.
So, 30āish seconds after PlexTranscoder finished for new media, a second PlexScriptHost spawned for currently-streaming media. In OpenedFilesView, the āFile Positionā for the PlexScriptHost processes is identical to (and follows along with) the Plex Media Server process (in case that matters/helps.) Difference being that the PlexScriptHost processes donāt close/stop/end.
that handle output was from the non DrivePool file.
Attached are the PMS logs.
I donāt know if it will still contain what you need since I just grabbed those.
Additionally, you may try to see if you can reproduce yourself now, with the added needed steps. Or, at least, what may be the trigger in my case. Obviously canāt speak for others with the same/similar issue.
Stream media, while streaming add new media with the generate video preview thumbnails enabled.
@j-sta said:
that handle output was from the non DrivePool file.
Attached are the PMS logs.
I donāt know if it will still contain what you need since I just grabbed those.
Additionally, you may try to see if you can reproduce yourself now, with the added needed steps. Or, at least, what may be the trigger in my case. Obviously canāt speak for others with the same/similar issue.
Stream media, while streaming add new media with the generate video preview thumbnails enabled.
Thank you - will try to reproduce
The logs for the agents do not go to the time
I will have to now discard the ProcMon capture as it did not show any references to the file for the PlexScriptHost.exe for thetvdb = so may be not all events got saved.
If you do get another delete error for a file not on drive pool, please capture the handle.exe and the logs and note down the time the handle.exe output was obtained
I wanted to thank you folks for spending the time to troubleshoot this maddening issue. Iām afraid most of this if well over my head. But thank you. Once this issue is resolved I think it will prevent quite a few PMS users from pulling their hair out every time their wife yells at them when they can delete their shows.
The logs for the agents do not go to the time
I will have to now discard the ProcMon capture as it did not show any references to the file for the PlexScriptHost.exe for thetvdb = so may be not all events got saved.
If you do get another delete error for a file not on drive pool, please capture the handle.exe and the logs and note down the time the handle.exe output was obtained
Soā¦ undecided if itās related to new media scanning while streaming.
One still locked tonight, while I made sure no new media was being added.
None of the Plex processes should have been running on any existing media.
Iāll move some media back on to the standalone drive/library tomorrow.
@j-sta said:
File lock started at just before 7:02pm.
Logs were grabbed about 7:14pm.
The Mayor (2017) - S01E07 - Here Comes the Governor - HDTV-720p.mkv
PML was filtered (Logfile_Filtered.zip)
ProcessMonitor caused the server to crash/reboot in the middle of streaming, so I had to restart everything.
Whilst I still do not understand how the PlexScriptHost.exe process (in this case the imdb one) has the file open when proc mon does not show PID 10176 accessing the file. the evidence provided this time shows the video file in use and streaming until 19:14:27 - so it would be locked at 19:02 - that was when streaming started for device on IP 192.168.1.12
Nov 15, 2017 19:01:18.496 [8068] DEBUG - Request: [192.168.1.12:42175 (Subnet)] GET /library/parts/165371/1510752141/file.mkv (10 live) TLS Signed-in Token (j-sta)
Nov 15, 2017 19:01:18.496 [8068] DEBUG - Request range: 266078715 to 0
Nov 15, 2017 19:01:18.512 [8068] DEBUG - Content-Length of D:\TestPlex\The Mayor (2017)\Season 01\The Mayor (2017) - S01E07 - Here Comes the Governor - HDTV-720p.mkv is 672497744.
Nov 15, 2017 19:12:17.409 [2548] DEBUG - Completed: [192.168.1.12:42175] 200 GET /library/parts/165371/1510752141/file.mkv (6 live) TLS 660334ms 406419029 bytes (pipelined: 2)
and now playing updates continued till 19:14 when state changed to state=stopped
So I do expect the file to be locked to 19:14:27 at least
There is also no evidence of attempt to delete the file and failing
Regardless, I do need to understand how the PlexScriptHost.exe has the file open without it showing up in procmon. The procmon capture did cover from start of process so should have all activity by that process
@j-sta said:
File lock started at just before 7:02pm.
Logs were grabbed about 7:14pm.
The Mayor (2017) - S01E07 - Here Comes the Governor - HDTV-720p.mkv
PML was filtered (Logfile_Filtered.zip)
ProcessMonitor caused the server to crash/reboot in the middle of streaming, so I had to restart everything.
Whilst I still do not understand how the PlexScriptHost.exe process (in this case the imdb one) has the file open when proc mon does not show PID 10176 accessing the file. the evidence provided this time shows the video file in use and streaming until 19:14:27 - so it would be locked at 19:02 - that was when streaming started for device on IP 192.168.1.12
Nov 15, 2017 19:01:18.496 [8068] DEBUG - Request: [192.168.1.12:42175 (Subnet)] GET /library/parts/165371/1510752141/file.mkv (10 live) TLS Signed-in Token (j-sta)
Nov 15, 2017 19:01:18.496 [8068] DEBUG - Request range: 266078715 to 0
Nov 15, 2017 19:01:18.512 [8068] DEBUG - Content-Length of D:\TestPlex\The Mayor (2017)\Season 01\The Mayor (2017) - S01E07 - Here Comes the Governor - HDTV-720p.mkv is 672497744.
Nov 15, 2017 19:12:17.409 [2548] DEBUG - Completed: [192.168.1.12:42175] 200 GET /library/parts/165371/1510752141/file.mkv (6 live) TLS 660334ms 406419029 bytes (pipelined: 2)
and now playing updates continued till 19:14 when state changed to state=stopped
So I do expect the file to be locked to 19:14:27 at least
There is also no evidence of attempt to delete the file and failing
Regardless, I do need to understand how the PlexScriptHost.exe has the file open without it showing up in procmon. The procmon capture did cover from start of process so should have all activity by that process
What were the filters for ProcMon?
I did not try to delete the file. When the stream completed, I checked my computer and saw PlexScriptHost accessing the file, so a delete attempt would have been futile.
The filter I added was:
Process Name contains Plex [Include]
I do still have the unfiltered PML
@j-sta said:
File lock started at just before 7:02pm.
Logs were grabbed about 7:14pm.
The Mayor (2017) - S01E07 - Here Comes the Governor - HDTV-720p.mkv
PML was filtered (Logfile_Filtered.zip)
ProcessMonitor caused the server to crash/reboot in the middle of streaming, so I had to restart everything.
Whilst I still do not understand how the PlexScriptHost.exe process (in this case the imdb one) has the file open when proc mon does not show PID 10176 accessing the file. the evidence provided this time shows the video file in use and streaming until 19:14:27 - so it would be locked at 19:02 - that was when streaming started for device on IP 192.168.1.12
Nov 15, 2017 19:01:18.496 [8068] DEBUG - Request: [192.168.1.12:42175 (Subnet)] GET /library/parts/165371/1510752141/file.mkv (10 live) TLS Signed-in Token (j-sta)
Nov 15, 2017 19:01:18.496 [8068] DEBUG - Request range: 266078715 to 0
Nov 15, 2017 19:01:18.512 [8068] DEBUG - Content-Length of D:\TestPlex\The Mayor (2017)\Season 01\The Mayor (2017) - S01E07 - Here Comes the Governor - HDTV-720p.mkv is 672497744.
Nov 15, 2017 19:12:17.409 [2548] DEBUG - Completed: [192.168.1.12:42175] 200 GET /library/parts/165371/1510752141/file.mkv (6 live) TLS 660334ms 406419029 bytes (pipelined: 2)
and now playing updates continued till 19:14 when state changed to state=stopped
So I do expect the file to be locked to 19:14:27 at least
There is also no evidence of attempt to delete the file and failing
Regardless, I do need to understand how the PlexScriptHost.exe has the file open without it showing up in procmon. The procmon capture did cover from start of process so should have all activity by that process
What were the filters for ProcMon?
I did not try to delete the file. When the stream completed, I checked my computer and saw PlexScriptHost accessing the file, so a delete attempt would have been futile.
The filter I added was:
Process Name contains Plex [Include]
I do still have the unfiltered PML
Thanks
Filter the PML file you have on Path contains The Mayor and remove all other filters
Ok, so this has occurred all three times now on this same media.
Yesterday, began streaming while running ProcMon and everything. PlexScriptHost popped up, but then server crashed due to ProcMon.
Everything rebooted, started everything back up and resumed streaming. PlexScriptHost cropped up again.
Grabbed the files.
Testing a thought this morning, streamed same media. Within 5 minutes, PlexScriptHost cropped up again.
Gotta head off to work, but this evening I will try a fourth time with running everything again.
Should not need to gather 20 minutes worth of data if issue crops up within 5 minutes, which would make it easier to review the ProcMon logs.
Issue possibly tied to particular media/shows? Since it isnāt occurring on every media file.
So it didnāt reproduce on the 4th try.
Got another one though.
Filtered out all registry activity (eg Reg Read, Reg Query, etc), TCP and UDP activity.
Currently unable to grab the plugin logs, because PlexScriptHost is hanging on to those as well. 3 of the logs havenāt had any entries in 10 minutes, and 2 havenāt had any entries for 30 minutes, but itās hanging on.
Interestingly, the new PML (still) wonāt show anything new. Despite Resource Monitor, OpenedFilesView, and Handle all showing the process accessing/locking the file.
When I filter to only PlexScriptHost process, the media filename cannot be found.
Just a lot of access to the SubZero channel/plugin data, then scanning/accessing existing media.
The proc mon capture does not make sense when the file is supposedly open by one or more of the PlexScriptHost.agent processes but the access does not appear in the procmon capture
I have been spending time trying to reproduce the problem without success.
I can see from the evidence I captured, that the media file does get opened by the agent process and in my case it shows up in ProcMon capture, but the access to the file is for short period and appeared to be synchronous and by the time I got to want to delete the file, it was no longer open by the agent process
I have established that if the TV Show or Season directory changes (eg new episodes added) then a refresh of the TV Show is carried out and this does open all the media files for the TV Show, In my case, the file was no longer open by the time I came to Delete.
So in theory, I suppose, if the agent process hangs or does not release the file then there would be an issue. But, there was no evidence in any hang or even the file being opened in the logs seen from @j-sta
In my tests, when the agent opened the file, there was a log entry for that in the agent log
I know tests were carried out with the media file outside DrivePool - but drive pool was still active and all file accesses are intercepted by the Drive Pool service
Whilst I have referred the issue to the development team, it would be good if we have further diagnostics from someone else - if anyone prepared to take the challenge of getting logs, proc mon capture, handle.exe (the latter would only be needed if the procmon capture does not show the access)
@sa2000 said:
I have established that if the TV Show or Season directory changes (eg new episodes added) then a refresh of the TV Show is carried out and this does open all the media files for the TV Show, In my case, the file was no longer open by the time I came to Delete.
So in theory, I suppose, if the agent process hangs or does not release the file then there would be an issue. But, there was no evidence in any hang or even the file being opened in the logs seen from @j-sta
In my tests, when the agent opened the file, there was a log entry for that in the agent log
I know tests were carried out with the media file outside DrivePool - but drive pool was still active and all file accesses are intercepted by the Drive Pool service
Do all libraries get refreshed when new media is added?
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?
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.
