PMS 1.6.1 still replaces complete EPG with incomplete EPG -- ERRORs in log, replaces anyway

General Discussions Plex Features
1

I’m running Plex 1.6.1 on my Linux server – won’t change to 1.7.x until things seem to settle down. This version still occasionally replaces a complete EPG with an incomplete version when it updates. (I turned off automatic guide updates so I can babysit it, but somehow it updated automatically anyway.)

An excerpt from the log:

Jun 13, 2017 10:59:37.485 [0x7f2df93ff700] DEBUG - Downloading document http://127.0.0.1:32400/tv.plex.providers.epg.onconnect:4/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F12035441
Jun 13, 2017 10:59:37.486 [0x7f2df93ff700] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Jun 13, 2017 10:59:37.486 [0x7f2df93ff700] DEBUG - Auth: Came in with the master token, authorization succeeded.
Jun 13, 2017 10:59:37.487 [0x7f2df93ff700] ERROR - downloadContainer: expected MediaContainer element, found html
Jun 13, 2017 10:59:37.487 [0x7f2df93ff700] WARN - MediaSub: No container available for /tv.plex.providers.epg.onconnect:4/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F12035441
Jun 13, 2017 10:59:37.487 [0x7f2df93ff700] DEBUG - Activity: updated activity 946d675b-416e-4411-a5a8-53d36b44a03e - completed 1% - Processing subscriptions
Jun 13, 2017 10:59:37.487 [0x7f2df93ff700] DEBUG - MediaSub: Looking for something of type 2 (guid: com.gracenote.onconnect://show/8677098 thumb: http://tmsimg.plex.tv/assets/p13232610_b_v5_aa.jpg title: Grimm type: 2 year: 2011)
Jun 13, 2017 10:59:37.487 [0x7f2df93ff700] DEBUG - MediaSub: Resolved subscription to library item 'Grimm' (343590)
Jun 13, 2017 10:59:37.488 [0x7f2df93ff700] DEBUG - MediaSub: Not checking provider Library, type not supported.
Jun 13, 2017 10:59:37.488 [0x7f2df93ff700] DEBUG - MediaSub: Checking in provider Program Guide
Jun 13, 2017 10:59:37.488 [0x7f2df93ff700] DEBUG - MediaSub: MATCH for GUID scheme, directly checking.
Jun 13, 2017 10:59:37.488 [0x7f2df93ff700] DEBUG - Downloading document http://127.0.0.1:32400/tv.plex.providers.epg.onconnect:4/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F8677098
Jun 13, 2017 10:59:37.489 [0x7f2df93ff700] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Jun 13, 2017 10:59:37.489 [0x7f2df93ff700] DEBUG - Auth: Came in with the master token, authorization succeeded.
Jun 13, 2017 10:59:37.490 [0x7f2df93ff700] ERROR - downloadContainer: expected MediaContainer element, found html
Jun 13, 2017 10:59:37.490 [0x7f2df93ff700] WARN - MediaSub: No container available for /tv.plex.providers.epg.onconnect:4/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F8677098
Jun 13, 2017 10:59:37.490 [0x7f2df93ff700] DEBUG - MediaSub: Looking for something of type 2 (guid: com.gracenote.onconnect://show/9538723 thumb: http://tmsimg.plex.tv/assets/p9538723_b_v5_aa.jpg title: Gatsmart type: 2 year: 2012)

So clearly Plex tries to download a chunk of EPG data and detects that there’s no MediaContainer in the reply, just some HTML code. This means that one chunk (6 hours) is missing. Still it continues with the next chunk, until it finally believes it is done:

Jun 13, 2017 11:37:15.556 [0x7f2df7bff700] DEBUG - EPG[onconnect]: Step 55/56 (2017-06-26T13:00Z) (network: 2101.4 sec, database: 191.0 sec total: 2257.2 sec)
Jun 13, 2017 11:37:15.556 [0x7f2df7bff700] DEBUG - Activity: updated activity 78464114-104b-4253-97b7-f11d4d5bd1d8 - completed 100% - Refreshing EPG
Jun 13, 2017 11:37:15.556 [0x7f2df7bff700] DEBUG - Activity: updated activity 78464114-104b-4253-97b7-f11d4d5bd1d8 - completed 100% - Refreshing EPG
Jun 13, 2017 11:37:15.556 [0x7f2df7bff700] DEBUG - Activity: updated activity 78464114-104b-4253-97b7-f11d4d5bd1d8 - completed 100% - Refreshing EPG
Jun 13, 2017 11:37:15.556 [0x7f2df7bff700] DEBUG - Activity: registered new activity 6bb4895b-c1e8-41c6-adc2-d4e4e013c79c - Optimizing database
Jun 13, 2017 11:37:15.556 [0x7f2df7bff700] DEBUG - Database optimization: Optimizing database. Starting by capturing all sessions.
Jun 13, 2017 11:37:15.556 [0x7f2df7bff700] DEBUG - Activity: updated activity 6bb4895b-c1e8-41c6-adc2-d4e4e013c79c - completed 0% - Optimizing database
...
Jun 13, 2017 11:37:21.336 [0x7f2df7bff700] DEBUG - EPG[onconnect]: Total time to load EPG was 2263.0 (HTTP details cached 85.5%, CloudFlare grid cached: 0.0%, 0 HTTP errors)

Then it replaces the old complete database with the new incomplete one, starts recomputing the recording schedule and skips several shows in the afternoon.

Before a manual refresh:

-rw-r--r-- 1 plex  plex    6898688 jun 13 14:09 tv.plex.providers.epg.onconnect-963cabf3-c42d-4b94-a82c-638fc16f4db0.db
-rw-r--r-- 1 plex  plex      32768 jun 13 16:44 tv.plex.providers.epg.onconnect-963cabf3-c42d-4b94-a82c-638fc16f4db0.db-shm
-rw-r--r-- 1 plex  plex    1084712 jun 13 16:44 tv.plex.providers.epg.onconnect-963cabf3-c42d-4b94-a82c-638fc16f4db0.db-wal

After a manual refresh – a complete database:

-rw-r--r-- 1 plex  plex    9197568 jun 13 17:33 tv.plex.providers.epg.onconnect-963cabf3-c42d-4b94-a82c-638fc16f4db0.db
-rw-r--r-- 1 plex  plex      32768 jun 13 17:34 tv.plex.providers.epg.onconnect-963cabf3-c42d-4b94-a82c-638fc16f4db0.db-shm
-rw-r--r-- 1 plex  plex    1070040 jun 13 17:34 tv.plex.providers.epg.onconnect-963cabf3-c42d-4b94-a82c-638fc16f4db0.db-wal
2

So, bottom line is not to rely on the automatic refresh – do it manually every morning. However, this morning I did just that and new episodes of ‘Downward Dog’ on ABC were not listed. I still don’t trust it and I won’t go forward to 1.7.x. May have to try Emby.

3

Yes, I normally use manual refresh but this time it refreshed automatically anyway for some reason.

Unlike some other bugs this seems rather straightforward: Part of Plex realizes that a chunk didn’t appear, but another part still replaces the old database.

4

Hey, Plex! @jonkv found the issue. Waiting for the fix :o