Warum? Gute Frage ... also mal ein Log, was passiert:
Timer auf heute ARD 22:50, VPS aktiviert (noch mit VDR 2.4.7, ändert aber nichts):
Bis zum "entered VPS margin" ist alles ok.
May 25 22:48:01 vdr: [6369] timer 37 (1 2250-0020 VPS 'Die Einzelteile der Liebe') entered VPS margin
May 25 22:48:01 vdr: [6369] switching device 2 to channel 1 S19.2E-1-1019-10301 (Das Erste HD)
May 25 22:49:42 vdr: epg2vdr: --- EPG 'refresh' started ---
May 25 22:49:57 vdr: epg2vdr: --- EPG refresh finished ---
May 25 22:50:57 vdr: epg2vdr: Updating table timers (and remove deleted and finished timers older than 2 days)
May 25 22:50:57 vdr: epg2vdr: Updating table timers done
May 25 22:51:57 vdr: epg2vdr: Updating table timers (and remove deleted and finished timers older than 2 days)
May 25 22:51:57 vdr: epg2vdr: Updating table timers done
Die Aufnahme wird mit epg2vdr nicht starten, wenn man nicht live auf "Das Erste" schaltet - beobachtet, also vorsichtshalber mal auf Kanal 1 schalten:
May 25 22:57:17 vdr: [6369] switching to channel 1 S19.2E-1-1019-10301 (Das Erste HD)
May 25 22:57:17 vdr: [9373] osdteletext-receiver thread started (pid=6369, tid=9373, prio=high)
May 25 22:57:17 vdr: [9374] device 1 TS buffer thread started (pid=6369, tid=9374, prio=high)
May 25 22:57:18 vdr: [6373] SignalInfo: adapter 0(S/ -1)* [1] SIGNAL cnt: 207
May 25 22:57:18 vdr: [6373] SignalInfo: adapter 1(S/-100)* [1] SIGNAL cnt: 0
May 25 22:57:27 vdr: epg2vdr: Handler: Toggle vps flag for 'Deutschlandbilder' at 'S19.2E-1-1019-10301' from 26.05.2021 04:40:00 to 26.05.2021 04:39:00
May 25 22:57:28 vdr: epg2vdr: Got epgd state 'busy (match)' (4)
May 25 22:57:28 vdr: epg2vdr: Change handler state to 'standby'
May 25 22:57:38 vdr: [6369] switching device 1 to channel 1 S19.2E-1-1019-10301 (Das Erste HD)
May 25 22:57:38 vdr: [6369] timer 37 (1 2250-0020 VPS 'Die Einzelteile der Liebe') start
May 25 22:57:38 vdr: [6369] Title: 'Die Einzelteile der Liebe' Subtitle: 'Drama (D 2019)'
May 25 22:57:38 vdr: [6369] executing '/usr/lib/vdr/vdr-recordingaction before "/srv/vdr/video/local/Die_Einzelteile_der_Liebe/2021-05-25.22.50.1-0.rec"'
May 25 22:57:38 vdr: [6369] record /srv/vdr/video/local/Die_Einzelteile_der_Liebe/2021-05-25.22.50.1-0.rec
May 25 22:57:38 vdr: [6369] creating directory /srv/vdr/video/local/Die_Einzelteile_der_Liebe
May 25 22:57:38 vdr: [6369] creating directory /srv/vdr/video/local/Die_Einzelteile_der_Liebe/2021-05-25.22.50.1-0.rec
May 25 22:57:38 vdr: [6369] Starting NALU fill dumper
May 25 22:57:38 vdr: [6369] recording to '/srv/vdr/video/local/Die_Einzelteile_der_Liebe/2021-05-25.22.50.1-0.rec/00001.ts'
May 25 22:57:38 vdr: [6369] markad: cStatusMarkAd::Recording(): recording <Die Einzelteile der Liebe> [/srv/vdr/video/local/Die_Einzelteile_der_Liebe/2021-05-25.22.50.1-0.rec] started
May 25 22:57:38 vdr: [6369] markad: cStatusMarkAd::GetEventID(): eventID 589939 from event for recording <Die Einzelteile der Liebe> timer <Die Einzelteile der Liebe> timer start 1621975800 stop 1621981200
May 25 22:57:38 vdr: [6369] markad: cStatusMarkAd::GetEventID(): timer <Die Einzelteile der Liebe> uses VPS
May 25 22:57:38 vdr: [9392] recording thread started (pid=6369, tid=9392, prio=high)
May 25 22:57:40 vdr: epg2vdr: Recording of 'Die Einzelteile der Liebe' has 'started' [/srv/vdr/video/local/Die_Einzelteile_der_Liebe/2021-05-25.22.50.1-0.rec]
May 25 22:57:40 vdr: [6369] writing timer id '37@roadrunner' to /srv/vdr/video/local/Die_Einzelteile_der_Liebe/2021-05-25.22.50.1-0.rec/.timer
May 25 22:57:40 vdr: epg2vdr: Info: Recording 'Die Einzelteile der Liebe' with doneid -1 added to running list
May 25 22:57:40 vdr: epg2vdr: Try to lookup timer with id 1526
May 25 22:57:40 vdr: epg2vdr: Found timer 1526
May 25 22:57:41 vdr: epg2vdr: Cleanup deleted recordings at database (forced)
May 25 22:57:42 vdr: epg2vdr: Info: Marked 0 recordings as deleted
May 25 22:57:42 vdr: epg2vdr: Updating recording list table
May 25 22:59:26 vdr: epg2vdr: Info: 'Insert' recording 'Die Einzelteile der Liebe / Drama (D 2019)' due to 17 changes [..]
May 25 22:59:26 vdr: epg2vdr: Info: Found 5596 recordings; 1 inserted; 0 updated and 679 directories
May 25 22:59:26 vdr: epg2vdr: Updating recording info in info.epg2vdr
May 25 22:59:26 vdr: epg2vdr: Storing event details to '/srv/vdr/video/local/Die_Einzelteile_der_Liebe/2021-05-25.22.50.1-0.rec/info.epg2vdr'
May 25 22:59:26 vdr: epg2vdr: Updated/Created recording info for 589939 in info.epg2vdr with 13 changes
May 25 22:59:26 vdr: epg2vdr: Updated 1 pending info.epg2vdr files
May 25 22:59:26 vdr: epg2vdr: Updating table timers (and remove deleted and finished timers older than 2 days)
May 25 22:59:26 vdr: epg2vdr: Updating table timers done
May 25 23:00:26 vdr: epg2vdr: Update info.epg2vdr recordings
May 25 23:01:15 vdr: epg2vdr: Storing event details to '/srv/vdr/video/local/Die_Einzelteile_der_Liebe/2021-05-25.22.50.1-0.rec/info.epg2vdr'
May 25 23:01:15 vdr: epg2vdr: Update recording info for 589939 in info.epg2vdr with 1 changes
May 25 23:01:15 vdr: epg2vdr: Updated 1 info.epg2vdr files
May 25 23:01:16 vdr: epg2vdr: Updating table timers (and remove deleted and finished timers older than 2 days)
May 25 23:01:16 vdr: epg2vdr: Updating table timers done
May 25 23:02:10 vdr: epg2vdr: Got epgd state 'standby' (1)
May 25 23:02:10 vdr: epg2vdr: Change handler state to 'active'
May 25 23:02:10 vdr: [6433] SVDRP roadrunner < 192.168.1.2:55612 lost connection to client
May 25 23:02:10 vdr: [6433] SVDRP roadrunner < 192.168.1.2:55612 connection closed
May 25 23:02:10 vdr: [6433] SVDRP roadrunner < 192.168.1.2:55612 server destroyed
May 25 23:02:10 vdr: epg2vdr: Updating table timers (and remove deleted and finished timers older than 2 days)
May 25 23:02:10 vdr: epg2vdr: Updating table timers done
Alles anzeigen
Die Aufnahme startet dann sofort und läuft, bis zum nächsten epg2vdr EPG Update des VDR wenig später:
May 25 23:02:10 vdr: epg2vdr: --- EPG 'refresh' started ---
May 25 23:02:10 vdr: epg2vdr: Update EPG, loading changes since 25.05.2021 22:49:56
May 25 23:02:12 vdr: [9392] recording thread ended (pid=6369, tid=9392)
May 25 23:02:12 vdr: [6369] NALU fill dumper: 84598 of 2408352 packets dropped, 3%
May 25 23:02:12 vdr: [6369] buffer stats: 625664 (0%) used
May 25 23:02:12 vdr: [6369] timer 37 (1 2250-0020 VPS 'Die Einzelteile der Liebe') stop
May 25 23:02:12 vdr: [6369] removing /srv/vdr/video/local/Die_Einzelteile_der_Liebe/2021-05-25.22.50.1-0.rec/.timer
May 25 23:02:12 vdr: [6369] markad: cStatusMarkAd::Recording(): recording <(null)> [/srv/vdr/video/local/Die_Einzelteile_der_Liebe/2021-05-25.22.50.1-0.rec] stopped
May 25 23:02:12 vdr: [6369] markad: cStatusMarkAd::Recording(): remove recording <(null)> [/srv/vdr/video/local/Die_Einzelteile_der_Liebe/2021-05-25.22.50.1-0.rec] from list
May 25 23:02:12 vdr: [6369] markad: cStatusMarkAd::Remove(): remove /srv/vdr/video/local/Die_Einzelteile_der_Liebe/2021-05-25.22.50.1-0.rec from position 0
May 25 23:02:12 vdr: epg2vdr: Recording of '(null)' has 'stopped' [/srv/vdr/video/local/Die_Einzelteile_der_Liebe/2021-05-25.22.50.1-0.rec]
May 25 23:02:12 roadrunner vdr: [6369] executing '/usr/lib/vdr/vdr-recordingaction after "/srv/vdr/video/local/Die_Einzelteile_der_Liebe/2021-05-25.22.50.1-0.rec"'
May 25 23:02:13 vdr: [9447] epg data writer thread started (pid=6369, tid=9447, prio=low)
May 25 23:02:15 vdr: [9447] epg data writer thread ended (pid=6369, tid=9447)
May 25 23:02:19 vdr: [6407] timer 37 (1 2250-0020 VPS 'Die Einzelteile der Liebe') set to no event
May 25 23:02:19 vdr: [6407] timer 37 (1 2250-0020 VPS 'Die Einzelteile der Liebe') set to event Di. 25.05.2021 22:50-00:20 (VPS: 25.05. 22:50) 'Die Einzelteile der Liebe'
May 25 23:02:19 vdr: epg2vdr: Processed channel 'S19.2E-1-1019-10301' - 'Das Erste HD' with 24 updates
[..]
May 25 23:02:30 vdr: epg2vdr: Updated changes since '25.05.2021 22:49:56'; 91 channels, 90 events (0 deletions) in 20.057 seconds
May 25 23:02:30 vdr: epg2vdr: Storing 'lastEventsUpdateAt' for '705CACD0-806D-43A1-BF7B-6AFD5D198836' with value '1621976550'
May 25 23:02:31 vdr: [9449] epg data writer thread started (pid=6369, tid=9449, prio=low)
May 25 23:02:31 vdr: epg2vdr: --- EPG refresh finished ---
May 25 23:02:32 vdr: [9449] epg data writer thread ended (pid=6369, tid=9449)
May 25 23:02:32 vdr: [6433] SVDRP roadrunner < 192.168.1.2:55616 client connection accepted
May 25 23:02:32 vdr: [6433] SVDRP roadrunner > 192.168.1.2:55616 server created
May 25 23:02:32 vdr: epg2vdr: Got epgd state 'standby' (1)
May 25 23:02:32 vdr: epg2vdr: Change handler state to 'active'May 25 23:02:32 vdr: epg2vdr: Info: valid timer for recording 'Die Einzelteile der Liebe' on Server '(null)'
May 25 23:02:32 vdr: epg2vdr: Info: valid event for recording 'Die Einzelteile der Liebe'
May 25 23:02:32 vdr: epg2vdr: Info: pendingTimer->Event()->Vps() (1621975800)
May 25 23:02:32 vdr: epg2vdr: Info: Finished (1526) 'Die Einzelteile der Liebe' (not complete! - recorded only 5%); VPS Yes
May 25 23:02:32 vdr: epg2vdr: Try to lookup timer with id 1526
May 25 23:02:32 vdr: epg2vdr: Found timer 1526
May 25 23:02:32 vdr: epg2vdr: Cleanup deleted recordings at database (forced)
May 25 23:02:33 vdr: epg2vdr: Info: Marked 0 recordings as deleted
May 25 23:02:33 vdr: epg2vdr: Updating recording list table
Alles anzeigen
Kurz darauf wird der Timer wieder aktiv / inaktiv / aktiv / ... bis zum Ende des Timers
Also das hier:
23:02:19 vdr: [6407] timer 37 (1 2250-0020 VPS 'Die Einzelteile der Liebe') set to no event
23:02:19 vdr: [6407] timer 37 (1 2250-0020 VPS 'Die Einzelteile der Liebe') set to event Di. 25.05.2021 22:50-00:20 (VPS: 25.05. 22:50) 'Die Einzelteile der Liebe'
Was da genau passiert, ist mir nicht ganz klar.
Endweder mag der VDR die (externen) EPG Updates dann nicht, oder epg2vdr greift aktiv in die Timer ein.
Soweit die Beobachtung,
Stefan