The issues I was experiencing appeared to have been resolved. Thank you
I’m running into the same issues as well. Refreshing EPG (0%)—Initializing after the server reboots. It’s been happening for months.
Plex Server: 1.15.2.793
Mac Os: 10.13.6
I’ve deleted the database files and ran a full disk check on the mac. Nothing came back from the disk check saying anything was needing to be fixed.
I’ve deleted the tv.plex.providers.epg.onconnect db files and rebooted the server. I have my server to shut down from 1am-8am since nobody uses it during these times.
What time was it stuck at 0% ?
It is not happening on all guide refreshes.
The last two refreshes were ok. At 09:33, 09:04 on 26th,
There were database locks for the refresh at 08:03. Is this the one you are referring to?
Correct on the 8:03am. The server reboots at 8am, and it will be stuck at 0% refreshing until I manually go in and reboot plex media server app. I’ve let this go to see how long it will last and it will never get past initializing unless I intervene. Once it’s done I can manually scan/refresh which you saw at 9:33 and so on.
I just recently (few weeks ago) rebuilt the entire plex server to resolve another issue I couldn’t fix. This was happening before and after the rebuild. I’ve removed the files in the plug-in support, rebooted and it will be fine for that reboot. Next reboot it breaks again.
once we get the database lockout exception, it would need another restart to clear
So it is always the first launch after the server being shutdown for the night
Mar 26, 2019 08:02:19.710 [0x70000ed9c000] DEBUG - Running migrations. (EPG 1)
Mar 26, 2019 08:02:19.747 [0x70000ed9c000] DEBUG - Media Provider: Registering provider tv.plex.providers.epg.onconnect:4
Mar 26, 2019 08:02:19.761 [0x70000ed9c000] DEBUG - Activity: registered new activity 16b308f8-e3c7-4531-a99e-7b61d7edb7d8 - Refreshing guide data
Mar 26, 2019 08:02:19.761 [0x70000ed9c000] DEBUG - Activity: updated activity 16b308f8-e3c7-4531-a99e-7b61d7edb7d8 - completed 0% - Refreshing guide data
Mar 26, 2019 08:02:19.761 [0x70000ed9c000] DEBUG - EPG[onconnect]: Scheduling next refresh for 2019-03-26 12:02:19.
Mar 26, 2019 08:02:19.871 [0x70000ed9c000] DEBUG - Activity: registered new activity 759df08d-e9b8-48b7-aa0a-ad4e431c0123 - Processing subscriptions
Mar 26, 2019 08:02:22.445 [0x70000f237000] WARN - Waited one whole second for a busy database.
Mar 26, 2019 08:02:25.852 [0x70000f2ba000] WARN - Waited one whole second for a busy database.
Mar 26, 2019 08:02:26.597 [0x70000e5ef000] DEBUG - DVR:Device: Device device://tv.plex.grabbers.hdhomerun/104C860B was already known, refreshing database info
Mar 26, 2019 08:02:29.917 [0x70000f237000] WARN - Waited one whole second for a busy database.
Mar 26, 2019 08:02:36.064 [0x70000f2ba000] WARN - Waited one whole second for a busy database.
Mar 26, 2019 08:02:38.635 [0x70000f2ba000] WARN - Waited one whole second for a busy database.
Mar 26, 2019 08:02:41.239 [0x70000f2ba000] WARN - Waited one whole second for a busy database.
Mar 26, 2019 08:02:43.838 [0x70000f2ba000] WARN - Waited one whole second for a busy database.
Mar 26, 2019 08:02:46.428 [0x70000f2ba000] WARN - Waited one whole second for a busy database.
I don’t know if there is a mac OS diagnostic tool like SysInternals Process Monitor on Windows that we can get info on which threads locking the database file. Are you familiar with dtrace ? That is the only i have seen mentioned. What I am after is establish what is locking the database and get trace of all database file locking / unlocking to go with logs of the problem - assuming it is easily repeatable
.
Yes this happens every night after the mac reboots. The mac is rebooting on a schedule at 1am and turns on at 8am. If I reboot the Mac manually it’s hit and miss if it will get stuck.
I am not familiar with dtrace. Are you referring to this? If so I’ll start reading and try to get it going. I’m not a Mac guy I’m a Windows guy so I’ll start reading up on what I can do to log those db files.
On windows I use SysInternals Process Monitor exctensively for troubleshooting and i think dtrace would be the equivalent - or close for mac os
1 Like
I’ve been playing around with dtrace and some other software and so far the only process that ever seems to touch these files is called “Plex Media Server 5335 keyboardservicessd 5334 AppleSpell Process ID 533”
I used a program called ‘what’s keeping me’ and it gives a nice GUI display. I’ll report back in the next couple of days and see if anything else is touching these files.
It could be different threads within the Plex Media Server process that are using the database files. We identify the threads in logs with the pthread address
I’m still trying to get more info on what is locking the file within the Plex app. Everything I’m running just keeps pointing to the Plex Media Server 5335. The odd thing is I didn’t have issues all last week or up until today. Right now it’s been suck “initializing” since it booted up at 8am.
The console log just keeps coming up with “EventSource: Retrying in 600 seconds”
You disabled debug logging 3 days earlier. So nothing to see about the EPG refresh
That could be relating to some shared servers being inaccessible or failure to connect to Plex pubsub servers
You are right I did disable it. Urgh, sorry about that. I just re-enabled it and I’ll let it run.
Debug logging is enabled and here are the current logs. The process is stuck right now and I’m going to leave it as is for now.
Any ideas on the cause of this? There is nothing on my mac that is talking to those files other than Plex when I check it out. It’s still getting stuck after reboots and if I don’t manually fix it my guide data doesn’t get updated and Plex misses recordings.
Thanks!
I just bit the bullet and did a fresh plex -reinstall. Plex is housed on my NAS and not my Mac. This made the process of deleting the database files slightly more complex for a fresh install, but it worked for now. The weirdest thing is I have 2 NAS, and had plex installed on both. Long story involving a ransomware attack on my NAS, but its the same WD NAS and configuration. One worked and one didn’t with regards to this issue. The good news is a fresh install shouldn’t effect anything but the plex software. Just re-scan your files, setup your recording schedule again (I took screen captures of my recording list.) and you should be back in business. Hope this helps!
1 Like
I do not know why it is happening and why only on your system. I have not seen any EPG Guide DB lockout in other user logs. May be some disk transfers not terminating?
All i can suggest is providing more diagnostics and from latest versions of Plex Media Server. There is some info on this web page about finding what files are open - this of course needs to be done at the time of the database being locked out -
I have linked to reference to activity monitor utility but there are other examples given.
ideally want a timeline showing all file i/o captured with all opens/closes/read/write/locks - i know on windows i can get that using SysInternals Process Monitor but not sure what is readily available for users on Mac. This capture together with debug logs covering time from server launch would help getting some answers
I unfortunately don’t know much about Mac and I’m having a hard time getting the info needed. I’ve used a few tools and ran lsof in terminal and all that I ever see touching the DB files is Plex. I can’t figure out how to dig deeper to see what Plex is doing using the tools. I’m reading the man for lsof to see if I can get more details out of it.
Here is the log file I just pulled. It’s stuck refreshing right now and Plex is up to date. Should I turn on Verbos Logging and download those?
Plex Media (4.0 MB)
Here is what lsof gave me when I looked at the .db file. Once I know more on how to use this tool I get some more details.
HellSingServer:~ colby$ lsof /Users/colby/Library/Application\ Support/Plex\ Media\ Server/Plug-in\ Support/Databases/tv.plex.providers.epg.onconnect-c8ed2c73-7270-4abe-8841-7d3029bc348b.db
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
Plex\x20M 360 colby 83u REG 1,3 47579136 105136358 /Users/colby/Library/Application Support/Plex Media Server/Plug-in Support/Databases/tv.plex.providers.epg.onconnect-c8ed2c73-7270-4abe-8841-7d3029bc348b.db
Plex\x20M 360 colby 119u REG 1,3 47579136 105136358 /Users/colby/Library/Application Support/Plex Media Server/Plug-in Support/Databases/tv.plex.providers.epg.onconnect-c8ed2c73-7270-4abe-8841-7d3029bc348b.db
Plex\x20M 360 colby 121u REG 1,3 47579136 105136358 /Users/colby/Library/Application Support/Plex Media Server/Plug-in Support/Databases/tv.plex.providers.epg.onconnect-c8ed2c73-7270-4abe-8841-7d3029bc348b.db
Plex\x20M 360 colby 123u REG 1,3 47579136 105136358 /Users/colby/Library/Application Support/Plex Media Server/Plug-in Support/Databases/tv.plex.providers.epg.onconnect-c8ed2c73-7270-4abe-8841-7d3029bc348b.db
Plex\x20M 360 colby 125u REG 1,3 47579136 105136358 /Users/colby/Library/Application Support/Plex Media Server/Plug-in Support/Databases/tv.plex.providers.epg.onconnect-c8ed2c73-7270-4abe-8841-7d3029bc348b.db
Plex\x20M 360 colby 127u REG 1,3 47579136 105136358 /Users/colby/Library/Application Support/Plex Media Server/Plug-in Support/Databases/tv.plex.providers.epg.onconnect-c8ed2c73-7270-4abe-8841-7d3029bc348b.db
Plex\x20M 360 colby 129u REG 1,3 47579136 105136358 /Users/colby/Library/Application Support/Plex Media Server/Plug-in Support/Databases/tv.plex.providers.epg.onconnect-c8ed2c73-7270-4abe-8841-7d3029bc348b.db
Plex\x20M 360 colby 131u REG 1,3 47579136 105136358 /Users/colby/Library/Application Support/Plex Media Server/Plug-in Support/Databases/tv.plex.providers.epg.onconnect-c8ed2c73-7270-4abe-8841-7d3029bc348b.db
Plex\x20M 360 colby 133u REG 1,3 47579136 105136358 /Users/colby/Library/Application Support/Plex Media Server/Plug-in Support/Databases/tv.plex.providers.epg.onconnect-c8ed2c73-7270-4abe-8841-7d3029bc348b.db
Plex\x20M 360 colby 135u REG 1,3 47579136 105136358 /Users/colby/Library/Application Support/Plex Media Server/Plug-in Support/Databases/tv.plex.providers.epg.onconnect-c8ed2c73-7270-4abe-8841-7d3029bc348b.db
I have actually done a full reinstall of Plex, and Max OSx to try and solve or another issue. After the new setup this started to happen after a few weeks. I have another system which is identical in hardware and I setup Plex on there, no issues with that one.
I’m playing with some software that will allow me to kill plex after 10min and restart it. Basically what I do manually but I’ll just do it with a quick script and delayed launcher app.
May be it is Plex. lsof just gives a static view. What we really need is some tool that gives the file i/o actions and times and outcomes -
Can’t remember if I asked this before but is this directory on an internal disk and not symlinked to elsewhere?
/Users/colby/Library/Application Support/Plex Media Server/Plug-in Support/Databases
What I am after is some Mac OS diagnostic tool like the windows sysinternals process monitor and windows event logs
I have come across these web pages
This shows that the Mac Console is the equivalent to the Windows Event Log
So looking into any exceptions / issues at the time of the db locks
May be there are disc errors / recovery actions at the time
This shows the time of the problem and it appears to be on the main db initially.
May 17, 2019 08:02:04.230 [0x700004c0c000] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=1): Cannot begin transaction. database is locked
May 17, 2019 08:02:04.713 [0x700004c0c000] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=2): Cannot begin transaction. database is locked
May 17, 2019 08:02:05.681 [0x700004c0c000] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=3): Cannot begin transaction. database is locked
May 17, 2019 08:02:06.614 [0x700004c0c000] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=4): Cannot begin transaction. database is locked
May 17, 2019 08:02:07.481 [0x700004c0c000] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=5): Cannot begin transaction. database is locked
May 17, 2019 08:02:08.214 [0x700004c0c000] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=6): Cannot begin transaction. database is locked
May 17, 2019 08:02:08.678 [0x700004c0c000] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=7): Cannot begin transaction. database is locked
May 17, 2019 08:02:09.610 [0x700004c0c000] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=8): Cannot begin transaction. database is locked
May 17, 2019 08:02:10.475 [0x700004c0c000] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=9): Cannot begin transaction. database is locked
May 17, 2019 08:02:11.207 [0x700004c0c000] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=10): Cannot begin transaction. database is locked
May 17, 2019 08:02:11.207 [0x700004c0c000] ERROR - Fixup 29DatabaseFixupsSyncCollections threw an exception: Cannot begin transaction. database is locked
May 17, 2019 08:02:20.833 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:02:23.439 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:02:26.062 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:02:28.652 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:02:31.234 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:02:33.828 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:02:36.392 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:02:39.024 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:02:41.662 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:02:44.255 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:02:46.879 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:02:49.469 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:02:52.097 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:02:54.717 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:02:57.373 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:03:00.024 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:03:02.657 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:03:05.294 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:03:07.917 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:03:10.553 [0x700003c2f000] WARN - Waited one whole second for a busy database.
May 17, 2019 08:03:12.061 [0x700003c2f000] ERROR - Thread: Uncaught exception running async task which was spawned by thread 0x700004771000: sqlite3_statement_backend::loadOne: database is locked
I don’t know if any of the tools here are free and do provide the file i/o information I am after
https://alternativeto.net/software/process-monitor/?platform=mac
I had the same issue for months and had not spent the time to try any other fixes mentioned except periodically deleting the guide databases and letting them rebuild. What I did do was upgrade the memory (older mac mini) from 4GB to 16GB. My issues with the guide data have vanished since!
Wow this is frustrating… So I’m running PMS on an Shield TV and experiencing this same issue. What makes things worse is I can’t even seem to access the logs because when I use the web interface if I try to navigate to Troubleshooting (or just about anywhere else) I can’t access it, it says “server settings unavailable.” Is there another way to output the log files that I’m not aware of?
