search

kmahon37 / plex-dvr-waker

Plex DVR Waker is a simple command-line tool for waking the computer before the next scheduled recording.
MIT License
8 stars 0 forks source link

[BUG] Plex DVR Waker monitoring tasks prevents guide updates. #27

Closed JWohlgem closed 4 years ago

JWohlgem commented 4 years ago

Describe the bug I've noticed that after a couple weeks, my guide runs out of information. Attempting to manually refresh it, doesn't seem to fix the problem. Logs seem to indicate a problem editing the database. To see if it was related to Plex DVR Waker, I manually stopped the monitor task via Task Scheduler, and then retried the refresh and it worked properly. So, I suspect that the monitoring task is holding a file open exclusively that interferes with Plex's ability to update the guide.

To Reproduce Run a guide update when the monitoring task is enabled. Look for failures in the log, you may need to increase the verbosity.

Expected behavior Plex can periodically refresh it's guide information regardless of whether the monitoring task is running or not.

Desktop (please complete the following information):

Additional context Add any other context about the problem here.

kmahon37 commented 4 years ago

Plex DVR Waker does not ever hold the database open. In fact, it only opens the database (always as readonly) when fetching the list of scheduled recordings, and then closes the connection immediately afterwards. When running the monitor task, it uses a standard "file watcher" to detect when the Plex library database file has been modified, and when triggered it then opens the database, fetches the list of recordings, and then closes the database. And then it waits for the file to change again.

I've been running the monitor task on my personal machine since my initial release last summer/fall, and Plex always manages to update the guide with no issues.

In order to investigate further, it would be helpful to have any logs from Plex itself and Plex DVR Waker and maybe Task Scheduler (if enabled) from the point in time when the issue occurred. Also, if you can reproduce it again, that would be good to know. It's possible that Plex DVR Waker got hung up or stuck in a loop while it had the database open, and the logs may provide some insight, but I don't have much to go on right now.

I doubt you did, but did you previously install v1.1.7 or v1.1.8? (I have since removed the releases because they were flawed)

JWohlgem commented 4 years ago

@kmahon37 - I spent some time this morning and was able to reproduce and analyze the issue a bit further. I'm not sure if I previously ran 1.1.7 or 1.1.8, but when I updated to 2.0.0, I deleted all the PlexDvrWaker binaries, scheduled tasks, un-installed the old CoreCLR runtime, and started fresh. Analysis follows, if you want me to provide you the dump or raw log files, I can do that, but I'd need a private way to send that information to you.

Plex Media Server.log (verbose) with PlexDvrMonitor.exe monitor task running end of EPG update:

Jun 14, 2020 10:18:31.363 [12544] DEBUG - Activity: updated activity a38d229b-c3b9-4010-b8da-fa0307a70979 - completed 100.0% - Refreshing guide data Jun 14, 2020 10:18:31.392 [12544] DEBUG - Captured session 0. Jun 14, 2020 10:18:31.392 [12544] DEBUG - Captured session 1. Jun 14, 2020 10:18:31.392 [12544] DEBUG - Captured session 2. Jun 14, 2020 10:18:31.392 [12544] DEBUG - Captured session 3. Jun 14, 2020 10:18:31.392 [12544] DEBUG - Captured session 4. Jun 14, 2020 10:18:31.392 [12544] DEBUG - Captured session 5. Jun 14, 2020 10:18:31.392 [12544] DEBUG - Captured session 6. Jun 14, 2020 10:18:31.392 [12544] DEBUG - Captured session 7. Jun 14, 2020 10:18:31.392 [12544] DEBUG - Captured session 8. Jun 14, 2020 10:18:31.392 [12544] DEBUG - Captured session 9. Jun 14, 2020 10:18:31.395 [12544] ERROR - Couldn't rename file "C:\Users\Jason\AppData\Local\Plex Media Server\Plug-in Support\Databases\tv.plex.providers.epg.cloud-7f1f5473-07aa-4e00-a662-a86cbc83fc81-loading.db" to "C:\Users\Jason\AppData\Local\Plex Media Server\Plug-in Support\Databases\tv.plex.providers.epg.cloud-7f1f5473-07aa-4e00-a662-a86cbc83fc81.db": Access is denied Jun 14, 2020 10:18:31.412 [14772] DEBUG - Database analyze: starting analyze (all tables) Jun 14, 2020 10:18:31.413 [12544] DEBUG - EPG[cloud]: Total time to load EPG was 152.5 (HTTP details cached 14.1%, CloudFlare grid cached: 91.1%, 0 HTTP errors) Jun 14, 2020 10:18:31.413 [12544] DEBUG - Activity: Ended activity a38d229b-c3b9-4010-b8da-fa0307a70979.

Plex Media Server.log (verbose) without PlexDvrMonitor.exe monitor task running end of EPG update:

Jun 14, 2020 10:28:51.566 [4136] DEBUG - Activity: updated activity 71e2677f-25b2-421b-95e6-3f06171f39e1 - completed 100.0% - Refreshing guide data Jun 14, 2020 10:28:51.591 [4136] DEBUG - Captured session 0. Jun 14, 2020 10:28:51.591 [4136] DEBUG - Captured session 1. Jun 14, 2020 10:28:51.591 [4136] DEBUG - Captured session 2. Jun 14, 2020 10:28:51.591 [4136] DEBUG - Captured session 3. Jun 14, 2020 10:28:51.591 [4136] DEBUG - Captured session 4. Jun 14, 2020 10:28:51.591 [4136] DEBUG - Captured session 5. Jun 14, 2020 10:28:51.591 [4136] DEBUG - Captured session 6. Jun 14, 2020 10:28:51.591 [4136] DEBUG - Captured session 7. Jun 14, 2020 10:28:51.591 [4136] DEBUG - Captured session 8. Jun 14, 2020 10:28:51.591 [4136] DEBUG - Captured session 9. Jun 14, 2020 10:28:51.616 [14240] DEBUG - Database analyze: starting analyze (all tables) Jun 14, 2020 10:28:51.617 [4136] DEBUG - EPG[cloud]: Total time to load EPG was 175.0 (HTTP details cached 13.1%, CloudFlare grid cached: 83.9%, 0 HTTP errors) Jun 14, 2020 10:28:51.617 [4136] DEBUG - Activity: Ended activity 71e2677f-25b2-421b-95e6-3f06171f39e1.

From above repro, the Sysinternals tool Handle (https://docs.microsoft.com/en-us/sysinternals/downloads/handle) shows the file is open by PlexDvrWaker.exe:

PlexDvrWaker.exe pid: 3192

. . . 4A0: File (RW-) C:\Users\Jason\AppData\Local\Plex Media Server\Plug-in Support\Databases\tv.plex.providers.epg.cloud-7f1f5473-07aa-4e00-a662-a86cbc83fc81.db

4A4: File (RW-) C:\Users\Jason\AppData\Local\Plex Media Server\Plug-in Support\Databases\tv.plex.providers.epg.cloud-7f1f5473-07aa-4e00-a662-a86cbc83fc81.db-wal

4A8: File (RW-) C:\Users\Jason\AppData\Local\Plex Media Server\Plug-in Support\Databases\tv.plex.providers.epg.cloud-7f1f5473-07aa-4e00-a662-a86cbc83fc81.db-shm

. . .

560: File (RW-) C:\Users\Jason\AppData\Local\Plex Media Server\Plug-in Support\Databases\tv.plex.providers.epg.cloud-7f1f5473-07aa-4e00-a662-a86cbc83fc81.db

564: File (RW-) C:\Users\Jason\AppData\Local\Plex Media Server\Plug-in Support\Databases\tv.plex.providers.epg.cloud-7f1f5473-07aa-4e00-a662-a86cbc83fc81.db-wal

Crash Dump Analysis:

I was able to capture a crash dump of PlexDvrWaker.exe shortly after the repro, and I did just a bit of analysis on the dump.

There were 5 threads in the process.

This was a casual glance, I didn't see anything obvious.

Given that there were two instances of the file open, is it possible there is a leaked handle to the database in some code path?

kmahon37 commented 4 years ago

Wow, thanks for this detail. I was able to find the same "Access denied" error 3 times in my Plex Media Server logs, but I guess maybe it succeeds sometimes because my guide is definitely up-to-date. It appears that Plex is trying to copy/replace the "epg" db file when it refreshes the guide. I originally thought that copying might interfere with the "file watcher" I use, but I only watch for changes to the com.plexapp.plugins.library.db file and there is only one query I do that hits the tv.plex.providers.epg.cloud file after a change to the other file is detected.

I tried to correlate the 3 errors in my Plex Media Server logs to my PlexDvrWaker.log files, and at each of the 3 times PlexDvrWaker was not actively querying the databases. So, I am baffled at what caused these errors. I may try stopping my "monitor" task for a few days and see what happens. I'd be interested to see if your PlexDvrWaker.log files shows anything around the time of your error (Jun 14, 2020 10:18:31.395).

I tried using the "Handle" tool, but I don't see PlexDvrWaker holding onto anything during a guide refresh. I tried this several times. The only way I could get it to show up was to basically stop the code in the middle of a database query with the connection open.

As far as the dump analysis and the threads go... The main thread running that is trying to read the console input is just a way to pause the program indefinitely so that the file watcher can continue to monitor the database files in a background thread(s) which might be the other threads you are seeing.

Every database connection that I open looks like this in the C# code (example). The using statement is a standard C# construct that automatically closes the database connection even if an error occurs. So I am fairly confident that there is no leak.

using (var conn = new SQLiteConnection($"Data Source={databaseFileName};Version=3;Read Only=True;"))
{
    // do stuff to query the database
}
kmahon37 commented 4 years ago

I may have identified the culprit, and you may have been right about a "leak" of sorts. I found 3 spots where I was using SQLiteDataReader instances but I wasn't closing/disposing them with the C# using syntax that I'm normally very good about. One of those spots is accessing the epg database file. After reading some forums/discussions/etc, it sounds like its a known problem with SQLite database connections in .NET where it holds onto the database unless you close/dispose everything. I'm testing it now for a few days to see if the error shows up in my Plex logs anymore.

kmahon37 commented 4 years ago

I think I may have fixed the issue in v2.1.1. Please give it a try and let me know.

JWohlgem commented 4 years ago

Thanks! I've installed the latest version and will report back in a couple weeks if the issue still occurs.