dvr/epg: added some more debug (trace) to look at what might be going on

diff --git a/src/dvr/dvr_db.c b/src/dvr/dvr_db.c
index 100400c25af09ed956e6594dd633adbdc51d8a29..4e5774999bbb4aa7a74e80335e8e94c565e72d1f 100644 (file)
--- a/src/dvr/dvr_db.c
+++ b/src/dvr/dvr_db.c
@@ -215,19 +215,12 @@ dvr_make_title(char *output, size_t outlen, dvr_entry_t *de)
   }
 }
 
-/**
- *
- */
 static void
-dvr_entry_link(dvr_entry_t *de)
+dvr_entry_set_timer(dvr_entry_t *de)
 {
   time_t now, preamble;
   dvr_config_t *cfg = dvr_config_find_by_name_default(de->de_config_name);
 
-  de->de_refcnt = 1;
-
-  LIST_INSERT_HEAD(&dvrentries, de, de_global_link);
-
   time(&now);
 
   preamble = de->de_start - (60 * de->de_start_extra) - 30;
@@ -243,10 +236,25 @@ dvr_entry_link(dvr_entry_t *de)
   } else if (de->de_channel) {
     de->de_sched_state = DVR_SCHEDULED;
 
+    tvhtrace("dvr", "entry timer scheduled for %"PRItime_t, preamble);
     gtimer_arm_abs(&de->de_timer, dvr_timer_start_recording, de, preamble);
   } else {
     de->de_sched_state = DVR_NOSTATE;
   }
+}
+
+/**
+ *
+ */
+static void
+dvr_entry_link(dvr_entry_t *de)
+{
+  de->de_refcnt = 1;
+
+  LIST_INSERT_HEAD(&dvrentries, de, de_global_link);
+
+  dvr_entry_set_timer(de);
+
   htsp_dvr_entry_add(de);
 }
 
@@ -369,8 +377,9 @@ static dvr_entry_t *_dvr_entry_create (
     LIST_INSERT_HEAD(&dae->dae_spawns, de, de_autorec_link);
   }
 
-  tvhlog(LOG_INFO, "dvr", "\"%s\" on \"%s\" starting at %s, "
+  tvhlog(LOG_INFO, "dvr", "entry %d \"%s\" on \"%s\" starting at %s, "
         "scheduled for recording by \"%s\"",
+   de->de_id,
         lang_str_get(de->de_title, NULL), DVR_CH_NAME(de), tbuf, creator);
         
   dvrdb_changed();
@@ -726,6 +735,8 @@ static dvr_entry_t *_dvr_entry_update
     de->de_stop_extra = stop_extra;
     save = 1;
   }
+  if (save)
+    dvr_entry_set_timer(de);
 
   /* Title */ 
   if (e && e->episode && e->episode->title) {
@@ -803,6 +814,11 @@ dvr_event_replaced(epg_broadcast_t *e, epg_broadcast_t *new_e)
 
   /* Existing entry */
   if ((de = dvr_entry_find_by_event(e))) {
+    tvhtrace("dvr",
+             "dvr entry %d event replaced %s on %s @ %"PRItime_t
+             " to %"PRItime_t,
+             de->de_id, epg_broadcast_get_title(e, NULL), e->channel->ch_name,
+             e->start, e->stop);
 
     /* Unlink the broadcast */
     e->putref(e);
@@ -811,6 +827,11 @@ dvr_event_replaced(epg_broadcast_t *e, epg_broadcast_t *new_e)
     /* Find match */
     RB_FOREACH(e, &e->channel->ch_epg_schedule, sched_link) {
       if (dvr_entry_fuzzy_match(de, e)) {
+        tvhtrace("dvr",
+                 "  replacement event %s on %s @ %"PRItime_t
+                 " to %"PRItime_t,
+                 epg_broadcast_get_title(e, NULL), e->channel->ch_name,
+                 e->start, e->stop);
         e->getref(e);
         de->de_bcast = e;
         _dvr_entry_update(de, e, NULL, NULL, NULL, 0, 0, 0, 0);
@@ -832,6 +853,12 @@ void dvr_event_updated ( epg_broadcast_t *e )
       if (de->de_bcast) continue;
       if (de->de_channel != e->channel) continue;
       if (dvr_entry_fuzzy_match(de, e)) {
+        tvhtrace("dvr",
+                 "dvr entry %d link to event %s on %s @ %"PRItime_t
+                 " to %"PRItime_t,
+                 de->de_id, epg_broadcast_get_title(e, NULL),
+                 e->channel->ch_name,
+                 e->start, e->stop);
         e->getref(e);
         de->de_bcast = e;
         _dvr_entry_update(de, e, NULL, NULL, NULL, 0, 0, 0, 0);

diff --git a/src/epg.c b/src/epg.c
index 89c40904d88c8869719e1d0c8d0718a1b38de780..e031ae07972423b08a6b4c42887e47ee4867338c 100644 (file)
--- a/src/epg.c
+++ b/src/epg.c
@@ -100,8 +100,8 @@ void epg_updated ( void )
 
   /* Remove unref'd */
   while ((eo = LIST_FIRST(&epg_object_unref))) {
-    tvhlog(LOG_DEBUG, "epg",
-           "unref'd object %u (%s) created during update", eo->id, eo->uri);
+    tvhtrace("epg",
+             "unref'd object %u (%s) created during update", eo->id, eo->uri);
     LIST_REMOVE(eo, un_link);
     eo->destroy(eo);
   }
@@ -1377,8 +1377,8 @@ static void _epg_channel_timer_callback ( void *p )
 
     /* Expire */
     if ( ebc->stop <= dispatch_clock ) {
-      tvhlog(LOG_DEBUG, "epg", "expire event %u from %s",
-             ebc->id, ch->ch_name);
+      tvhlog(LOG_DEBUG, "epg", "expire event %u (%s) from %s",
+             ebc->id, epg_broadcast_get_title(ebc, NULL), ch->ch_name);
       _epg_channel_rem_broadcast(ch, ebc, NULL);
       continue; // skip to next
 
@@ -1447,6 +1447,8 @@ static epg_broadcast_t *_epg_channel_add_broadcast
       _epg_object_create(ret);
       // Note: sets updated
       _epg_object_getref(ret);
+      tvhtrace("epg", "added event %u (%s) on %s @ %"PRItime_t " to %"PRItime_t,
+               ret->id, epg_broadcast_get_title(ret, NULL), ch->ch_name, ret->start, ret->stop);
 
     /* Existing */
     } else {
@@ -1460,6 +1462,8 @@ static epg_broadcast_t *_epg_channel_add_broadcast
       } else {
         ret->stop = (*bcast)->stop;
         _epg_object_set_updated(ret);
+        tvhtrace("epg", "updated event %u (%s) on %s @ %"PRItime_t " to %"PRItime_t,
+                 ret->id, epg_broadcast_get_title(ret, NULL), ch->ch_name, ret->start, ret->stop);
       }
     }
   }
@@ -1470,12 +1474,16 @@ static epg_broadcast_t *_epg_channel_add_broadcast
   /* Remove overlapping (before) */
   while ( (ebc = RB_PREV(ret, sched_link)) != NULL ) {
     if ( ebc->stop <= ret->start ) break;
+    tvhtrace("epg", "remove overlap (b) event %u (%s) on %s @ %"PRItime_t " to %"PRItime_t,
+             ebc->id, epg_broadcast_get_title(ebc, NULL), ch->ch_name, ebc->start, ebc->stop);
     _epg_channel_rem_broadcast(ch, ebc, ret);
   }
 
   /* Remove overlapping (after) */
   while ( (ebc = RB_NEXT(ret, sched_link)) != NULL ) {
     if ( ebc->start >= ret->stop ) break;
+    tvhtrace("epg", "remove overlap (a) event %u (%s) on %s @ %"PRItime_t " to %"PRItime_t,
+             ebc->id, epg_broadcast_get_title(ebc, NULL), ch->ch_name, ebc->start, ebc->stop);
     _epg_channel_rem_broadcast(ch, ebc, ret);
   }