EPG refresh

Live TV & DVR
,
1

Server Version#: 1.29.2.6364
Player Version#: PlexWeb 4.94.2
Tuner Make/Model: Fritz!Box 6690 Cable

Hello @sa2000,
I have a question about the EPG refresh.
I’ve noticed for a long time that the EPG refresh doesn’t seem to take place during the maintenance work at night between 4 and 8 a.m., but only in the morning after the maintenance work when you open Plex, for example.

image
(german translation is also missing) :wink:

I’m not sure if the refresh happens at a fixed time or is triggered by calling PlexWeb.- But certainly not at 4 in the morning.

PS: EPG-refresh starts at 7:50 in the morning.

2

Yet you just said it starts 10 minutes before the maintenance window closes… Looks fine to me.

3

But the screenshot said about 4 am…
When it starts at 7:50 it’s running until 08:30+

I’ll check it tomorrow again, i’ve changed the maintenance time to 4-7 am, now

4

That happens usually when Plex Server has not been running during the maintenance period, so it couldn’t update the EPG.
If the EPG data are too old, it is refreshed automatically after startup of Plex server.

Remember, on Windows Plex server will be closed if you log out.
(unless you are running it as a Windows system service – but that has its own drawbacks)

5

It’s running 24/7 on my Synology DS920+

6

Maybe it’s employing some cunning power saving, where it shuts down the whole NAS during the night? Or maybe just certain apps?

The same effect could be caused if the network/internet connection would be unavailable during the night. For instance if (part of) the network infrastructure (wireless APs, router, switches) shuts down during the night to save power.
Or some other critical network device is somehow switched off because it happens to be conected to the same switched power bar as your main PC.

7

hm, no, not really…
I’ll check it tomorrow and grab some logs

8

Ok, i think today the EPG-update runs about 6:15am until 6:40am.
Is this a normal error?

Nov 13, 2022 06:16:58.542 [0x7f5bfa257b38] INFO - Running forward migration 202209271322.
Nov 13, 2022 06:16:58.542 [0x7f5bfa257b38] DEBUG - Captured session 0.
Nov 13, 2022 06:16:58.542 [0x7f5bfa257b38] DEBUG - Captured session 1.
Nov 13, 2022 06:16:58.542 [0x7f5bfa257b38] DEBUG - Captured session 2.
Nov 13, 2022 06:16:58.542 [0x7f5bfa257b38] DEBUG - Captured session 3.
Nov 13, 2022 06:16:58.542 [0x7f5bfa257b38] DEBUG - Captured session 4.
Nov 13, 2022 06:16:58.548 [0x7f5bfa257b38] INFO - SQLITE3:0x80000001, 17, statement aborts at 58: [select * from metadata_items limit 1] database schema has changed
Nov 13, 2022 06:16:58.551 [0x7f5bfa257b38] INFO - SQLITE3:0x80000001, 17, statement aborts at 58: [select * from metadata_items limit 1] database schema has changed
Nov 13, 2022 06:16:58.554 [0x7f5bfa257b38] INFO - SQLITE3:0x80000001, 17, statement aborts at 58: [select * from metadata_items limit 1] database schema has changed
Nov 13, 2022 06:16:58.556 [0x7f5bfa257b38] INFO - SQLITE3:0x80000001, 17, statement aborts at 58: [select * from metadata_items limit 1] database schema has changed
Nov 13, 2022 06:16:58.558 [0x7f5bfa257b38] INFO - Completed forward migration 202209271322.
Nov 13, 2022 06:16:58.558 [0x7f5bfa257b38] DEBUG - Captured session 0.
Nov 13, 2022 06:16:58.558 [0x7f5bfa257b38] DEBUG - Captured session 1.
Nov 13, 2022 06:16:58.558 [0x7f5bfa257b38] DEBUG - Captured session 2.
Nov 13, 2022 06:16:58.558 [0x7f5bfa257b38] DEBUG - Captured session 3.
Nov 13, 2022 06:16:58.558 [0x7f5bfa257b38] DEBUG - Captured session 4.
Nov 13, 2022 06:16:58.558 [0x7f5bfa257b38] INFO - Analyzing database.
Nov 13, 2022 06:16:58.560 [0x7f5bfa257b38] INFO - Vacuuming database.
Nov 13, 2022 06:16:58.853 [0x7f5bfa257b38] INFO - SQLITE3:0x80000001, 17, statement aborts at 58: [select * from metadata_items limit 1] database schema has changed
Nov 13, 2022 06:16:58.855 [0x7f5bfa257b38] INFO - SQLITE3:0x80000001, 17, statement aborts at 58: [select * from metadata_items limit 1] database schema has changed
Nov 13, 2022 06:16:58.858 [0x7f5bfa257b38] INFO - SQLITE3:0x80000001, 17, statement aborts at 58: [select * from metadata_items limit 1] database schema has changed
Nov 13, 2022 06:16:58.861 [0x7f5bfa257b38] INFO - SQLITE3:0x80000001, 17, statement aborts at 58: [select * from metadata_items limit 1] database schema has changed

Content of

select * from metadata_items limit 1

image
image1942×159 35.3 KB

9

there were two maybe timeouts.
But there was no disconnect/new IP in on my router logs.

Nov 13, 2022 03:17:10.378 [0x7f5c10d66b38] DEBUG - CERT: incomplete TLS handshake from 45.227.254.54:64627: wrong version number

Nov 13, 2022 03:20:01.990 [0x7f5bf52f9b38] DEBUG - EPG[cloud]: Next thing to start/end is at 2022-11-13 03:23:00 (in 180 seconds)
Nov 13, 2022 03:21:48.334 [0x7f5c10d66b38] DEBUG - [EventSourceClient/pubsub/172.105.245.168:443] Failure: 125 - Operation canceled.
Nov 13, 2022 03:21:48.334 [0x7f5c10d66b38] DEBUG - [EventSourceClient/pubsub/172.105.245.168:443] MyPlex: We appear to have lost Internet connectivity, resetting device URL cache.
Nov 13, 2022 03:21:48.334 [0x7f5c10d66b38] ERROR - [EventSourceClient/pubsub/172.105.245.168:443] Retrying in 15 seconds.

Nov 13, 2022 03:22:23.335 [0x7f5c10d66b38] DEBUG - [EventSourceClient/pubsub/172.105.245.168:443] Failure: 125 - Operation canceled.
Nov 13, 2022 03:22:23.335 [0x7f5c10d66b38] DEBUG - [EventSourceClient/pubsub/172.105.245.168:443] MyPlex: We appear to have lost Internet connectivity, resetting device URL cache.
Nov 13, 2022 03:22:23.335 [0x7f5c10d66b38] ERROR - [EventSourceClient/pubsub/172.105.245.168:443] Retrying in 15 seconds.
Nov 13, 2022 03:22:38.336 [0x7f5c10d66b38] DEBUG - [EventSourceClient/pubsub/172.105.245.168:443] Resolving 172.105.245.168 port 443
Nov 13, 2022 03:22:38.336 [0x7f5c10d66b38] DEBUG - [EventSourceClient/pubsub/172.105.245.168:443] Resolved 172.105.245.168 to 172.105.245.168:443
Nov 13, 2022 03:22:38.377 [0x7f5c10d66b38] DEBUG - [EventSourceClient/pubsub/172.105.245.168:443] Connected in 41 ms.
Nov 13, 2022 03:22:38.377 [0x7f5c10d66b38] DEBUG - [EventSourceClient/pubsub/172.105.245.168:443] Wrote data, reading reply.
Nov 13, 2022 03:22:38.482 [0x7f5c10f69b38] DEBUG - [EventSourceClient/pubsub/172.105.245.168:443] Read HTTP reply header.
Nov 13, 2022 03:22:38.482 [0x7f5c10f69b38] DEBUG - [EventSourceClient/pubsub/172.105.245.168:443] MyPlex: We appear to have regained Internet connectivity.
Nov 13, 2022 03:22:38.486 [0x7f5c10f69b38] DEBUG - [EventSourceClient/pubsub/172.105.245.168:443] PublicAddressManager: Obtaining public address and mapping port.
Nov 13, 2022 03:22:38.486 [0x7f5c10f69b38] DEBUG - [EventSourceClient/pubsub/172.105.245.168:443] MyPlex: async reachability check - current mapped state: ‘Mapped - Not Published’.
Nov 13, 2022 03:22:38.486 [0x7f5c10f69b38] WARN - [EventSourceClient/pubsub/172.105.245.168:443] MyPlex: we have an existing connectivity refresh request for async identifier 50fdf62f-bcfb-416d-8d5a-35a301d3ef1e, but it has expired so we will try again.

10

Sorry, these log snippets are not useful. These messages are not even connected to the issue, as far as I can see.

11

We setup a random time during the maintenance period for the EPG refresh - so in your case a delayed action would be queued within a random time beween 4am and 8am - the scheduled tasks period

I would need to see debug server logs covering the period and into the time when the EPG refresh happens later

12

Not a perfect message - it is sometime after 4am

13

This would be the relevant log line (an example of what it would look like)

Nov 14, 2022 01:03:57.000 [5776] DEBUG - Butler: Scheduling randomized task 'RefreshEpgGuides' in 42 minutes.

and then seeing what happens in the log at the stated delayed time

The 42 minutes is random

14

ah, i see…

Nov 14, 2022 04:04:44.895 [0x7f5bf54bfb38] DEBUG - Butler: Scheduling randomized task 'RefreshEpgGuides' in 139 minutes.
Nov 14, 2022 04:04:44.896 [0x7f5bf54bfb38] DEBUG - Butler: Scheduling randomized task 'RefreshPeriodicMetadata' in 88 minutes.
Nov 14, 2022 04:04:44.896 [0x7f5bf54bfb38] DEBUG - Butler: Scheduling randomized task 'ReverseGeocode' in 41 minutes.

Nov 14, 2022 06:23:44.896 [0x7f5bf5ab4b38] DEBUG - Butler: Starting delayed task RefreshEpgGuides.