[epgsearch] Suchtimer erzeugt nicht alle passenden Timer

War das ein einmaliger "Ausreisser" oder kam das öfter vor?

Ich hab deine Ausgaben hier mal eingebaut und beobachte es. Ist aber bisher noch nicht aufgetreten.

Kommt schon öfter vor, vor allem bei Ereignissen in der Vergangenheit. VDR zeigt dann auch 2 Events an (wenn EPG linger entsprechend gesetzt ist).

Im Bild gibt es zwei Einträge um 2:00.

2024-09-25T06:07:24.921614+02:00 rpi4s vdr: [1670969] eit.c, channel 118 (QVC) old ID  2911, TBL 4E, V  9 'Mi. 25.09.2024 02:00-03:00 'AQUA CLEAN Reinigen mit Sauerstoff''                                                                                                                                                   2024-09-25T06:07:24.921945+02:00 rpi4s vdr: [1670969] eit.c, channel 118 (QVC) new ID  3391, TBL 50, V 18 start 'Wed Sep 25 02:00:00 2024' end 'Wed Sep 25 03:00:00 2024'

2024-09-25T06:07:24.923187+02:00 rpi4s vdr: [1670969] epg.c, cSchedule::DropOutdated, TableID Version [50 18], SegmentStart Mi. 25.09.2024 02:00, SegmentEnd Mi. 25.09.2024 05:00                                                                                                                                             2024-09-25T06:07:24.923344+02:00 rpi4s vdr: [1670969] epg.c, cSchedule::DropOutdated, first  event ID  2911, TBL 4E, V  9 'Mi. 25.09.2024 02:00-03:00 'AQUA CLEAN Reinigen mit Sauerstoff''                                                                                                                                   2024-09-25T06:07:24.923498+02:00 rpi4s vdr: [1670969] epg.c, cSchedule::DropOutdated, second event ID  3391, TBL 50, V 18 'Mi. 25.09.2024 02:00-03:00 'AQUA CLEAN Reinigen mit Sauerstoff''

Es gibt da noch ein Problem:

*** A ***
2024-09-25T06:05:53.515723+02:00 rpi4s vdr: [1670967] eit.c, channel 1837 (ORF RADIO V) old ID  3965, TBL 50, V  0 'Mi. 25.09.2024 06:04-07:04 'Guten Morgen Vorarlberg''                           2024-09-25T06:05:53.515902+02:00 rpi4s vdr: [1670967] eit.c, channel 1837 (ORF RADIO V) new ID  4942, TBL 4E, V 22 start 'Wed Sep 25 06:04:00 2024' end 'Wed Sep 25 07:04:00 2024'
*** B ***
2024-09-25T06:05:54.532506+02:00 rpi4s vdr: [1670967] epg.c, cSchedule::DropOutdated, TableID Version [51  2], SegmentStart So. 29.09.2024 23:04, SegmentEnd Mo. 30.09.2024 02:04
2024-09-25T06:05:54.532580+02:00 rpi4s vdr: [1670967] epg.c, cSchedule::DropOutdated, first  event ID  3965, TBL 50, V  0 'Mi. 25.09.2024 06:04-07:04 'Guten Morgen Vorarlberg''
2024-09-25T06:05:54.532665+02:00 rpi4s vdr: [1670967] epg.c, cSchedule::DropOutdated, second event ID  4942, TBL 4E, V 22 'Mi. 25.09.2024 06:04-07:04 'Guten Morgen Vorarlberg''
2024-09-25T06:05:54.532739+02:00 rpi4s vdr: [1670967] epg.c, cSchedule::DropOutdated, running event: event Mi. 25.09.2024 06:04-07:04 'Guten Morgen Vorarlberg', event ID 4942, RunningStatus 4
2024-09-25T06:05:54.532807+02:00 rpi4s vdr: [1670967] (no channel)    event ID  3965, event Mi. 25.09.2024 06:04-07:04 'Guten Morgen Vorarlberg' status 0->1
*** C ***
2024-09-25T06:05:54.605527+02:00 rpi4s vdr: [1670967] epg.c, del [4E 22] ID  3965, TBL 50, V  0 'Mi. 25.09.2024 06:04-07:04 'Guten Morgen Vorarlberg''

Zum Zeitpunkt *** A *** wird das doppelte Event angelegt.

Zum Zeitpunkt *** B *** wurde die Sektion, in der Event 3965 ist, noch nicht vollständig bearbeitet. Daher hier noch das doppelte Event

Zum Zeitpunkt *** C *** wurde die Sektion, in der Event 3965 ist, vollständig bearbeitet. Hier wird dieses Event dann auch gelöscht.

Wie's aussieht passiert das dann, wenn ein Event von einer Table in die nächst "aktuellere" wandert und dabei die ID geändert wird.

Ich hab jetzt mal vor dem Check auf RunningStatusUndefined eingebaut, dass, wenn zwei Events mit gleicher Startzeit gefunden werden, der zweite davon gelöscht wird. Damit auch sichergestellt ist, dass der Event aus der aktuelleren Table "vorne" in der Liste ist, habe ich cEvent::Compare() entsprechend erweitert.

Anbei der komplette Diff gegen die Version im GIT.

Hi Klaus,

Das sieht jetzt richtig gut aus!

@all: Im git von live ist ein Update. Damit wir bei allen Events, die ein Timer aufzeichnet, das TImer Symbol angezeigt. Und nicht nur beim Ersten.

~ Markus

Warum finde eigentlich immer ich die Fehler?

Hier sieht das noch richtig gut aus:

2024-09-27T17:00:05.456257+02:00 rpi4s vdr: [1874199] channel 40 (SR Fernsehen HD) event Fr. 27.09.2024 16:05-17:00 (VPS: 27.09. 16:05) 'Kaffee oder Tee' status 4->1
2024-09-27T17:00:05.456771+02:00 rpi4s vdr: [1874199] channel 40 (SR Fernsehen HD) event Fr. 27.09.2024 17:00-17:05 (VPS: 27.09. 17:00) 'SR info' status 0->4
2024-09-27T17:00:06.562682+02:00 rpi4s vdr: [1874194] timer 24 (40 1605-1700 VPS 'Kaffee oder Tee') set to event Fr. 27.09.2024 17:05-18:00 (VPS: 27.09. 16:05) 'Kaffee oder Tee'
2024-09-27T17:00:20.624250+02:00 rpi4s vdr: [1874194] timer 24 (40 1605-1700 VPS 'Kaffee oder Tee') finished with 1 error

Doch dann habe ich VDR neu gestartet. Und direkt nach dem Neustart:

2024-09-27T17:01:10.169224+02:00 rpi4s vdr: [1882629] VDR version 2.7.2 started
2024-09-27T17:01:12.327644+02:00 rpi4s vdr: [1882629] timer 23 (40 1605-1700 VPS 'Kaffee oder Tee') set to event Fr. 27.09.2024 16:05-17:00 (VPS: 27.09. 16:05) 'Kaffee oder Tee'
2024-09-27T17:01:12.328621+02:00 rpi4s vdr: [1882629] switching device 2 to channel 40 S19.2E-1-1039-10378 (SR Fernsehen HD)
2024-09-27T17:01:12.328755+02:00 rpi4s vdr: [1882629] timer 23 (40 1605-1700 VPS 'Kaffee oder Tee') set to no event
2024-09-27T17:01:12.328891+02:00 rpi4s vdr: [1882629] deleting timer 23 (40 1605-1700 VPS 'Kaffee oder Tee')

Dann wurde die 2. Hälfte (17:05-18:00) nicht mehr aufgenommen .

Hi,

Quote from nobanzai

Und ich hab das bei diversen Fussballsendungen auch immer noch, dass ich ihn zwingen muss, die 2. Hälfte aufzunehmen.

Probiere doch mal VDR 2.7.2, und wende den hier attachten Patch an. Damit sollte die 2. Hälfte zuverlässig mit aufgenommen werden.

Wenn du das aktuelle live git verwendest, zeigt live das auch korrekt an.

Falls es doch noch Fehler gibt: Bitte hier melden.

~ Markus

Ich habe meinen Test von #67 wiederholt, diesmal mit meinem Patch aus #69:

2024-09-30T17:00:11.536871+02:00 rpi4s vdr: [2011580] channel 41 (SWR BW HD) event Mo. 30.09.2024 16:05-17:00 (VPS: 30.09. 16:05) 'Kaffee oder Tee' status 4->1
2024-09-30T17:00:11.537519+02:00 rpi4s vdr: [2011580] channel 41 (SWR BW HD) event Mo. 30.09.2024 17:00-17:05 (VPS: 30.09. 17:00) 'SWR Aktuell Baden-Württemberg' status 0->4
2024-09-30T17:00:12.824598+02:00 rpi4s vdr: [2011574] timer 20 (41 1605-1700 VPS 'Kaffee oder Tee') set to event Mo. 30.09.2024 17:05-18:00 (VPS: 30.09. 16:05) 'Kaffee oder Tee'
2024-09-30T17:00:26.891196+02:00 rpi4s vdr: [2011574] timer 20 (41 1605-1700 VPS 'Kaffee oder Tee') finished with 0 errors

Dann habe ich VDR neu gestartet. Und direkt nach dem Neustart:

2024-09-30T17:03:37.224351+02:00 rpi4s vdr: [2014120] VDR version 2.7.2 started
2024-09-30T17:03:40.211126+02:00 rpi4s vdr: [2014120] timer 20 (41 1605-1700 VPS 'Kaffee oder Tee') set to event Mo. 30.09.2024 16:05-17:00 (VPS: 30.09. 16:05) 'Kaffee oder Tee'
2024-09-30T17:03:42.654826+02:00 rpi4s vdr: [2014120] timer 20 (41 1605-1700 VPS 'Kaffee oder Tee') set to event Mo. 30.09.2024 17:05-18:00 (VPS: 30.09. 16:05) 'Kaffee oder Tee'
2024-09-30T17:05:10.226759+02:00 rpi4s vdr: [2014123] channel 41 (SWR BW HD) event Mo. 30.09.2024 17:05-18:00 (VPS: 30.09. 16:05) 'Kaffee oder Tee' status 0->4
2024-09-30T17:05:10.843527+02:00 rpi4s vdr: [2014120] timer 20 (41 1605-1700 VPS 'Kaffee oder Tee') start
2024-09-30T17:59:23.800995+02:00 rpi4s vdr: [2014125] channel 41 (SWR BW HD) event Mo. 30.09.2024 17:05-18:00 (VPS: 30.09. 16:05) 'Kaffee oder Tee' status 4->1
2024-09-30T17:59:38.997960+02:00 rpi4s vdr: [2014120] timer 20 (41 1605-1700 VPS 'Kaffee oder Tee') finished with 0 errors
2024-09-30T18:01:09.816210+02:00 rpi4s vdr: [2014120] timer 20 (41 1605-1700 VPS 'Kaffee oder Tee') set to no event
2024-09-30T18:01:09.817152+02:00 rpi4s vdr: [2014120] deleting timer 20 (41 1605-1700 VPS 'Kaffee oder Tee')

Wie erwartet, verhindert der Patch das Löschen des Timers, und die 2. Hälfte wird auch aufgezeichnet.

MarkusE Ich habe gestern einen Timer für diese Sendung gesetzt und er hat beide Teile aufgenommen.

Sehe ich das richtig, dass der Fehler nur passiert, wenn VDR zwischen den beiden Teilen neu gestartet wird?

Quote from kls

Sehe ich das richtig, dass der Fehler nur passiert, wenn VDR zwischen den beiden Teilen neu gestartet wird?

Kann ich jetzt nicht sagen. Wie in #67 geschrieben, habe ich den Rechner an diesem Tag neu gestartet, und da ist der Fehler aufgetreten.

Quote from kls

Sehe ich das richtig, dass der Fehler nur passiert, wenn VDR zwischen den beiden Teilen neu gestartet wird?

In VDR 2.7.2 ist ja sichergestellt, dass ein Event nur dann den notRunning Status bekommt, falls ein späteres Event einen größeren Running Status hat .

Es ist aber nicht sichergestellt, dass immer alle "vergangenen" Events den notRunning Status bekommen. Das kann z.B. passieren:

• Direkt nach dem VDR Start
• Bei einem Sender hat (kurzzeitig) kein Event einen größeren Running Status
• Der EPG Scan noch nicht auf dem entsprechenden Sender war, ev. auch bei Pause EPG scan
• ...

Wenn der Timer gelöscht ist, ist er halt weg. Da hilft es dann auch nicht, wenn der Running Status der Events eine Sekunde später wieder stimmt.

~ Markus

MarkusE Magst du mal diese Variante deines Vorschlags probieren?

--- timers.c    2024/03/06 14:37:15     5.20
+++ timers.c    2024/10/09 06:48:20
@@ -727,8 +727,23 @@
 {
   if (IsSingleEvent() && !Recording()) {
      time_t ExpireTime = StopTimeEvent();
-     if (HasFlags(tfVps))
+     if (HasFlags(tfVps)) {
+        if (event) {
+           if (ExpireTime <= time(NULL)) {
+              LOCK_SCHEDULES_READ;
+              if (const cSchedule *Schedule = event->Schedule()) {
+                 for (const cEvent *e = Schedule->Events()->Next(event); e; e = Schedule->Events()->Next(e)) {
+                     if (event->Vps() == e->Vps()) {
+                        ExpireTime = e->EndTime();
+                        dsyslog("further VPS event found: %s", *e->ToDescr());//XXX
+                        break;
+                        }
+                     }
+                 }
+              }
+           }
         ExpireTime += EXPIRELATENCY;
+        }
      return ExpireTime <= time(NULL);
      }
   return false;

Ich habe für heute Nachmittag einen VPS-Timer für "Kaffee oder Tee" gesetzt und werde über einen cron-Job VDR um 17:02 Uhr neu starten lassen. Mal sehen, was passiert...

kls ,

Der Patch müsste das Problem auch lösen.

Ob LOCK_SCHEDULES_READ in dieser Methode zu invalid lock sequence Fehlern führen kann, ist mir unklar. Daher habe ich diese Variante nicht gewählt.

Aus Performancegründen würde ich die for Schleife über die Events nur dann ausführen, wenn zwingend notwendig. Also wenn der Timer ohne diesen zusätzlichen Test gelöscht würde. Das ist bei Deinem Patch für "ExpireTime <= time(NULL) <= ExpireTime + EXPIRELATENCY" nicht der Fall.

Dann müsste man noch eine Variable für "jetzt" einführen, z.B. "time_t now = time(NULL);". Um sicherzustellen, dass die if Abfragen in Zeile 10 und 25 immer zum gleichen Ergebnis führen.

Außerdem habe ich "if (event)" entfernt und hohle Schedule aus Channel(): Der Test sollte auch dann gemacht werden, wenn dem Timer (z.B. wegen einem Fehler) kein Event zugeordnet ist.

Damit komme ich zu:

Index: vdr-2.7.2_sik/timers.c
===================================================================
--- vdr-2.7.2_sik.orig/timers.c 2024-10-09 16:26:06.376644971 +0200
+++ vdr-2.7.2_sik/timers.c  2024-10-09 17:03:58.927848702 +0200
@@ -727,9 +727,24 @@
 {
   if (IsSingleEvent() && !Recording()) {
      time_t ExpireTime = StopTimeEvent();
-     if (HasFlags(tfVps))
+     time_t now = time(NULL);
+     if (HasFlags(tfVps)) {
         ExpireTime += EXPIRELATENCY;
-     return ExpireTime <= time(NULL);
+        if (ExpireTime <= now) {
+           Matches(); // now we have the correct startTime, as this is a single event
+           LOCK_SCHEDULES_READ;
+           if (const cSchedule *Schedule = Schedules->GetSchedule(Channel()) ) {
+              for (const cEvent *e = Schedule->Events()->First(); e; e = Schedule->Events()->Next(e)) {
+                if (e->Vps() == startTime) {
+                   ExpireTime = e->EndTime() + EXPIRELATENCY;
+                   if (e != event)
+                      dsyslog("further VPS event found: %s", *e->ToDescr());//XXX
+                   }
+                }
+              }
+           }
+        }
+     return ExpireTime <= now;
      }
   return false;
 }

~ Markus

Quote from MarkusE

Ob LOCK_SCHEDULES_READ in dieser Methode zu invalid lock sequence Fehlern führen kann, ist mir unklar. Daher habe ich diese Variante nicht gewählt.

cTimers::Expired() wird über Timers->DeleteExpired() aus der Hauptschleife heraus aufgerufen, da erwarte ich keine Probleme mit diesem Lock.

Quote from MarkusE

Aus Performancegründen würde ich die for Schleife über die Events nur dann ausführen, wenn zwingend notwendig

OK.

Quote from MarkusE

Außerdem habe ich "if (event)" entfernt und hohle Schedule aus Channel(): Der Test sollte auch dann gemacht werden, wenn dem Timer (z.B. wegen einem Fehler) kein Event zugeordnet ist.

Im Normalfall hat der Timer hier einen Event. Ich habe deine Methode jetzt mal als Fallback übernommen.

Ein explizites Matches() ist hier nicht nötig, denn das macht bereits StopTimeEvent() über StopTime().

Damit sähe das dann aus meiner Sicht so aus:

--- timers.c    2024/03/06 14:37:15     5.20
+++ timers.c    2024/10/10 09:23:34
@@ -726,10 +726,40 @@
 bool cTimer::Expired(void) const
 {
   if (IsSingleEvent() && !Recording()) {
+     time_t Now = time(NULL);
      time_t ExpireTime = StopTimeEvent();
-     if (HasFlags(tfVps))
+     if (HasFlags(tfVps)) {
         ExpireTime += EXPIRELATENCY;
-     return ExpireTime <= time(NULL);
+        if (ExpireTime <= Now) {
+           LOCK_SCHEDULES_READ;
+           const cSchedule *Schedule = event ? event->Schedule() : NULL;
+           const cEvent *FirstEvent = event;
+           if (Schedule)
+              FirstEvent = Schedule->Events()->Next(FirstEvent);
+           else if ((Schedule = Schedules->GetSchedule(Channel())) != NULL) {
+              FirstEvent = Schedule->Events()->First();
+              if (FirstEvent)
+                 dsyslog("timer %s had no event, got %s from channel/schedule", *ToDescr(), *FirstEvent->ToDescr());
+              }
+           if (FirstEvent) {
+              if (Schedule) {
+                 for (const cEvent *e = FirstEvent; e; e = Schedule->Events()->Next(e)) {
+                     if (e->Vps() == startTime) {
+                        ExpireTime = e->EndTime() + EXPIRELATENCY;
+                        dsyslog("timer %s is waiting for next VPS event %s", *ToDescr(), *e->ToDescr());
+                        if (event)
+                           break;
+                        }
+                     }
+                 }
+              }
+           else {
+              dsyslog("timer %s has no event, setting expiration to +24h", *ToDescr());
+              ExpireTime += 3600 * 24;
+              }
+           }
+        }
+     return ExpireTime <= Now;
      }
   return false;
 }

Ich lasse heute Nachmittag den Test mit "Kaffee oder Tee" und Neustart um 17:02 Uhr damit laufen.

Nachtrag: vor dem 'break' sollte wohl noch 'if (event)' abgefragt werden, damit die Schleife im Fallback-Fall ganz durchläuft. Hab's im Diff ergänzt.

Hi Klaus,

der Fallback falls es kein Event gibt gefällt mir sehr gut.

Ich würde die Zeilen 30&31:

+                        if (event)
+                           break;

komplett weglassen. Nimm einfach mal an, es gibt 3 Events, dem Timer wurde das 1. Event zugeordnet, und das 2. Event liegt auch in der Vergangenheit. Das 3. Event ist aber noch aktuell. Wir wollen ja ganz sicher sein.

Performance sollte weniger kritisch sein, da die Schleife doch recht selten durchlaufen wird.

~ Markus

Quote from MarkusE

Wir wollen ja ganz sicher sein.

Na gut ;-).

--- timers.c    2024/03/06 14:37:15     5.20
+++ timers.c    2024/10/10 18:52:01
@@ -726,10 +726,39 @@
 bool cTimer::Expired(void) const
 {
   if (IsSingleEvent() && !Recording()) {
+     time_t Now = time(NULL);
      time_t ExpireTime = StopTimeEvent();
-     if (HasFlags(tfVps))
+     if (HasFlags(tfVps)) {
         ExpireTime += EXPIRELATENCY;
-     return ExpireTime <= time(NULL);
+        if (ExpireTime <= Now) {
+           LOCK_SCHEDULES_READ;
+           const cSchedule *Schedule = event ? event->Schedule() : NULL;
+           const cEvent *FirstEvent = event;
+           if (Schedule)
+              FirstEvent = Schedule->Events()->Next(FirstEvent);
+           else if ((Schedule = Schedules->GetSchedule(Channel())) != NULL) {
+              FirstEvent = Schedule->Events()->First();
+              if (FirstEvent)
+                 dsyslog("timer %s had no event, got %s from channel/schedule", *ToDescr(), *FirstEvent->ToDescr());
+              }
+           if (FirstEvent) {
+              if (Schedule) {
+                 for (const cEvent *e = FirstEvent; e; e = Schedule->Events()->Next(e)) {
+                     if (e->Vps() == startTime) {
+                        ExpireTime = e->EndTime() + EXPIRELATENCY;
+                        dsyslog("timer %s is waiting for next VPS event %s", *ToDescr(), *e->ToDescr());
+                        // no break here - let's play it safe and look at *all* events
+                        }
+                     }
+                 }
+              }
+           else {
+              dsyslog("timer %s has no event, setting expiration to +24h", *ToDescr());
+              ExpireTime += 3600 * 24;
+              }
+           }
+        }
+     return ExpireTime <= Now;
      }
   return false;

Dann gehe ich mal davon aus, dass das die endgültige Fassung ist.