Improve logging when subscriptions fail to start

diff --git a/debian/changelog b/debian/changelog
index 5831f7afe016ba4cd0e3d1cf741489a6b2da9152..c4cfae7212528ceb83d9f4283ae820c930e59fd5 100644 (file)
--- a/debian/changelog
+++ b/debian/changelog
@@ -10,6 +10,8 @@ hts-tvheadend (2.8) hts; urgency=low
     for people and it's only useful if you have complex setups with
     multiple adapters, etc.
 
+  * Improve logging when subscriptions fail to start
+
 hts-tvheadend (2.7) hts; urgency=low
 
   * Added support for DVB subtitles. Currently only forwarded over HTSP

diff --git a/src/dvb/dvb.h b/src/dvb/dvb.h
index b52b39eae57eaaacf1fdff4678ad8c8f661594c7..2a835da6cfca497e923a5dc1aab7bfa0167894e3 100644 (file)
--- a/src/dvb/dvb.h
+++ b/src/dvb/dvb.h
@@ -299,7 +299,7 @@ htsmsg_t *dvb_transport_build_msg(th_transport_t *t);
 /**
  * DVB Frontend
  */
-void dvb_fe_tune(th_dvb_mux_instance_t *tdmi, const char *reason);
+int dvb_fe_tune(th_dvb_mux_instance_t *tdmi, const char *reason);
 
 void dvb_fe_stop(th_dvb_mux_instance_t *tdmi);
 

diff --git a/src/dvb/dvb_fe.c b/src/dvb/dvb_fe.c
index d49e3bf9b77e69d2105ec14dad9cf8c333424b37..769a555968418285e078bc0fe14769830889e4fd 100644 (file)
--- a/src/dvb/dvb_fe.c
+++ b/src/dvb/dvb_fe.c
@@ -37,6 +37,7 @@
 #include "dvb_support.h"
 #include "diseqc.h"
 #include "notify.h"
+#include "transports.h"
 
 
 /**
@@ -283,7 +284,7 @@ dvb_fe_tune_s2(th_dvb_mux_instance_t *tdmi, dvb_mux_conf_t *dmc)
 /**
  *
  */
-void
+int
 dvb_fe_tune(th_dvb_mux_instance_t *tdmi, const char *reason)
 {
   th_dvb_adapter_t *tda = tdmi->tdmi_adapter;
@@ -299,7 +300,7 @@ dvb_fe_tune(th_dvb_mux_instance_t *tdmi, const char *reason)
   lock_assert(&global_lock);
 
   if(tda->tda_mux_current == tdmi)
-    return;
+    return 0;
   
   if(tdmi->tdmi_scan_queue != NULL) {
     TAILQ_REMOVE(tdmi->tdmi_scan_queue, tdmi, tdmi_scan_link);
@@ -368,6 +369,7 @@ dvb_fe_tune(th_dvb_mux_instance_t *tdmi, const char *reason)
     tvhlog(LOG_ERR, "dvb", "\"%s\" tuning to \"%s\""
      " -- Front configuration failed -- %s, frequency: %ld",
      tda->tda_rootpath, buf, strerror(errno), p->frequency);
+    return TRANSPORT_NOSTART_TUNING_FAILED;
   }   
 
   tda->tda_mux_current = tdmi;
@@ -377,4 +379,5 @@ dvb_fe_tune(th_dvb_mux_instance_t *tdmi, const char *reason)
   dvb_table_add_default(tdmi);
 
   dvb_adapter_notify(tda);
+  return 0;
 }

diff --git a/src/dvb/dvb_transport.c b/src/dvb/dvb_transport.c
index 0a9d495aaee955bb3b1640ef85e2c2709fdf442a..4492791fd76e5a617d3be21e61dff1e7617cf131 100644 (file)
--- a/src/dvb/dvb_transport.c
+++ b/src/dvb/dvb_transport.c
@@ -103,17 +103,17 @@ dvb_transport_open_demuxers(th_dvb_adapter_t *tda, th_transport_t *t)
 static int
 dvb_transport_start(th_transport_t *t, unsigned int weight, int force_start)
 {
-  int w;
+  int w, r;
   th_dvb_adapter_t *tda = t->tht_dvb_mux_instance->tdmi_adapter;
   th_dvb_mux_instance_t *tdmi = tda->tda_mux_current;
 
   lock_assert(&global_lock);
 
   if(tda->tda_rootpath == NULL)
-    return 1; /* hardware not present */
+    return TRANSPORT_NOSTART_NO_HARDWARE;
 
-  if(tdmi && !tdmi->tdmi_enabled)
-    return 1; /* Mux is disabled */
+  if(t->tht_dvb_mux_instance && !t->tht_dvb_mux_instance->tdmi_enabled)
+    return TRANSPORT_NOSTART_MUX_NOT_ENABLED; /* Mux is disabled */
 
   /* Check if adapter is idle, or already tuned */
 
@@ -121,20 +121,24 @@ dvb_transport_start(th_transport_t *t, unsigned int weight, int force_start)
 
     w = transport_compute_weight(&tdmi->tdmi_adapter->tda_transports);
     if(w >= weight)
-      return 1; /* We are outranked by weight, cant use it */
+      /* We are outranked by weight, cant use it */
+      return TRANSPORT_NOSTART_NOT_FREE;
 
     dvb_adapter_clean(tda);
   }
 
-  dvb_transport_open_demuxers(tda, t);
-
   pthread_mutex_lock(&tda->tda_delivery_mutex);
 
-  LIST_INSERT_HEAD(&tda->tda_transports, t, tht_active_link);
-  dvb_fe_tune(t->tht_dvb_mux_instance, "Transport start");
+  r = dvb_fe_tune(t->tht_dvb_mux_instance, "Transport start");
+  if(!r)
+    LIST_INSERT_HEAD(&tda->tda_transports, t, tht_active_link);
 
   pthread_mutex_unlock(&tda->tda_delivery_mutex);
-  return 0;
+
+  if(!r)
+    dvb_transport_open_demuxers(tda, t);
+
+  return r;
 }
 
 
@@ -285,7 +289,7 @@ dvb_transport_quality(th_transport_t *t)
 
   lock_assert(&global_lock);
 
-  return tdmi->tdmi_enabled ? tdmi->tdmi_quality : 0;
+  return tdmi->tdmi_adapter->tda_qmon ? tdmi->tdmi_quality : 100;
 }
 
 

diff --git a/src/dvr/dvr_rec.c b/src/dvr/dvr_rec.c
index b2a0bf3d8d52005f0a4cb4876abd49b4b577aa74..6d9eb743f2cc6249c2f806bd669a6f2c504ad730 100644 (file)
--- a/src/dvr/dvr_rec.c
+++ b/src/dvr/dvr_rec.c
@@ -239,7 +239,9 @@ dvr_rec_fatal_error(dvr_entry_t *de, const char *fmt, ...)
   vsnprintf(msgbuf, sizeof(msgbuf), fmt, ap);
   va_end(ap);
 
-  tvhlog(LOG_ERR, "pvr", "%s: %s", de->de_filename, msgbuf);
+  tvhlog(LOG_ERR, "pvr", 
+        "Recording error: \"%s\": %s",
+        de->de_filename ?: de->de_title, msgbuf);
 }
 
 
@@ -440,7 +442,8 @@ dvr_thread(void *aux)
 
     case SMT_NOSOURCE:
       dvr_rec_fatal_error(de, 
-                         "No source transport available, automatic retry");
+                         "Unable to start -- %s",
+                         transport_nostart2txt(sm->sm_code));
       break;
 
     case SMT_MPEGTS:

diff --git a/src/htsp.c b/src/htsp.c
index ecf7d0f9f833d164e14ea102c419fb78f5ca6925..f9dd00d36c2da1504f6aa86af0d23f965f24afa6 100644 (file)
--- a/src/htsp.c
+++ b/src/htsp.c
@@ -1517,7 +1517,7 @@ htsp_streaming_input(void *opaque, streaming_message_t *sm)
     break;
 
   case SMT_NOSOURCE:
-    htsp_subscription_status(hs, "No available sources");
+    htsp_subscription_status(hs, transport_nostart2txt(sm->sm_code));
     break;
 
   case SMT_MPEGTS:

diff --git a/src/streaming.c b/src/streaming.c
index b58e21e0c275f96308ad124293053d071d4e5ddf..82b1eff3eda83f1b388c118b6913b1f7335936cf 100644 (file)
--- a/src/streaming.c
+++ b/src/streaming.c
@@ -172,6 +172,7 @@ streaming_msg_clone(streaming_message_t *src)
 
   case SMT_STOP:
   case SMT_TRANSPORT_STATUS:
+  case SMT_NOSOURCE:
     dst->sm_code = src->sm_code;
     break;
 

diff --git a/src/subscriptions.c b/src/subscriptions.c
index 1d496d2f8e1b40312074a506cbfd3e1a1504719d..e522b37bce4de2496274b14b68f43aea249ea28d 100644 (file)
--- a/src/subscriptions.c
+++ b/src/subscriptions.c
@@ -132,7 +132,8 @@ subscription_reschedule(void *aux)
   th_subscription_t *s;
   th_transport_t *t;
   streaming_message_t *sm;
-
+  char buf[128];
+  int errorcode;
   lock_assert(&global_lock);
 
   gtimer_arm(&subscription_reschedule_timer, subscription_reschedule, NULL, 2);
@@ -144,12 +145,13 @@ subscription_reschedule(void *aux)
     if(s->ths_channel == NULL)
       continue; /* stale entry, channel has been destroyed */
 
-    t = transport_find(s->ths_channel, s->ths_weight);
+    snprintf(buf, sizeof(buf), "Subscription \"%s\"", s->ths_title);
+    t = transport_find(s->ths_channel, s->ths_weight, buf, &errorcode);
 
     if(t == NULL) {
       /* No transport available */
 
-      sm = streaming_msg_create(SMT_NOSOURCE);
+      sm = streaming_msg_create_code(SMT_NOSOURCE, errorcode);
       streaming_target_deliver(s->ths_output, sm);
       continue;
     }

diff --git a/src/transports.c b/src/transports.c
index d61cd3dc7e3f6bfa7ed7be5b0e8afb42c25daa35..f9ae02b18468d531453a9fe3d6bd2507149a315c 100644 (file)
--- a/src/transports.c
+++ b/src/transports.c
@@ -53,6 +53,23 @@ static struct th_transport_list transporthash[TRANSPORT_HASH_WIDTH];
 
 static void transport_data_timeout(void *aux);
 
+/**
+ *
+ */
+const char *
+transport_nostart2txt(int code)
+{
+  switch(code) {
+  case TRANSPORT_NOSTART_NO_HARDWARE:     return "No hardware present";
+  case TRANSPORT_NOSTART_MUX_NOT_ENABLED: return "No mux enabled";
+  case TRANSPORT_NOSTART_NOT_FREE:        return "Adapter in use by other subscription";
+  case TRANSPORT_NOSTART_TUNING_FAILED:   return "Tuning failed";
+  case TRANSPORT_NOSTART_SVC_NOT_ENABLED: return "No service enabled";
+  case TRANSPORT_NOSTART_BAD_SIGNAL:      return "Too bad signal quality";
+  }
+  return "Unknown error";
+}
+
 
 /**
  *
@@ -243,6 +260,7 @@ int
 transport_start(th_transport_t *t, unsigned int weight, int force_start)
 {
   th_stream_t *st;
+  int r;
 
   lock_assert(&global_lock);
 
@@ -253,8 +271,8 @@ transport_start(th_transport_t *t, unsigned int weight, int force_start)
   t->tht_dts_start = AV_NOPTS_VALUE;
   t->tht_pcr_drift = 0;
 
-  if(t->tht_start_feed(t, weight, force_start))
-    return -1;
+  if((r = t->tht_start_feed(t, weight, force_start)))
+    return r;
 
   pthread_mutex_lock(&t->tht_stream_mutex);
 
@@ -341,26 +359,44 @@ transportcmp(const void *A, const void *B)
  *
  */
 th_transport_t *
-transport_find(channel_t *ch, unsigned int weight)
+transport_find(channel_t *ch, unsigned int weight, const char *loginfo,
+              int *errorp)
 {
   th_transport_t *t, **vec;
-  int cnt = 0, i;
-  
+  int cnt = 0, i, r;
+  int error = 0;
+
   lock_assert(&global_lock);
 
   /* First, sort all transports in order */
 
   LIST_FOREACH(t, &ch->ch_transports, tht_ch_link)
-      if(t->tht_enabled && t->tht_quality_index(t) > 10)
-      cnt++;
+    cnt++;
 
   vec = alloca(cnt * sizeof(th_transport_t *));
-  i = 0;
-  LIST_FOREACH(t, &ch->ch_transports, tht_ch_link)
-    if(t->tht_enabled && t->tht_quality_index(t) > 10)
-      vec[i++] = t;
+  cnt = 0;
+  LIST_FOREACH(t, &ch->ch_transports, tht_ch_link) {
+
+    if(!t->tht_enabled) {
+      error = TRANSPORT_NOSTART_SVC_NOT_ENABLED;
+      if(loginfo != NULL) {
+       tvhlog(LOG_NOTICE, "Transport", "%s: Skipping \"%s\" -- not enabled",
+              loginfo, transport_nicename(t));
+      }
+      continue;
+    }
 
-  assert(i == cnt);
+    if(t->tht_quality_index(t) < 10) {
+      error = TRANSPORT_NOSTART_BAD_SIGNAL;
+      if(loginfo != NULL) {
+       tvhlog(LOG_NOTICE, "Transport", 
+              "%s: Skipping \"%s\" -- Quality below 10%",
+              loginfo, transport_nicename(t));
+      }
+      continue;
+    }
+    vec[cnt++] = t;
+  }
 
   /* Sort transports, lower priority should come come earlier in the vector
      (i.e. it will be more favoured when selecting a transport */
@@ -383,9 +419,16 @@ transport_find(channel_t *ch, unsigned int weight)
 
   for(i = 0; i < cnt; i++) {
     t = vec[i];
-    if(!transport_start(t, weight, 0))
+    if((r = transport_start(t, weight, 0)) == 0)
       return t;
+    error = r;
+    if(loginfo != NULL)
+      tvhlog(LOG_NOTICE, "Transport", 
+            "%s: Skipping \"%s\" -- %s",
+            loginfo, transport_nicename(t), transport_nostart2txt(r));
   }
+  if(errorp != NULL)
+    *errorp = error;
   return NULL;
 }
 

diff --git a/src/transports.h b/src/transports.h
index 775ca9222867a0706ea6835c8ccc98bce4042335..c215a9b0904bbff54752e6d430c25f0a20745ae2 100644 (file)
--- a/src/transports.h
+++ b/src/transports.h
@@ -23,6 +23,13 @@
 #include "htsmsg.h"
 #include "subscriptions.h"
 
+#define TRANSPORT_NOSTART_NO_HARDWARE     1
+#define TRANSPORT_NOSTART_MUX_NOT_ENABLED 2
+#define TRANSPORT_NOSTART_NOT_FREE        3
+#define TRANSPORT_NOSTART_TUNING_FAILED   4
+#define TRANSPORT_NOSTART_SVC_NOT_ENABLED 5
+#define TRANSPORT_NOSTART_BAD_SIGNAL      6
+
 void transport_init(void);
 
 unsigned int transport_compute_weight(struct th_transport_list *head);
@@ -40,7 +47,8 @@ th_transport_t *transport_find_by_identifier(const char *identifier);
 
 void transport_map_channel(th_transport_t *t, channel_t *ch, int save);
 
-th_transport_t *transport_find(channel_t *ch, unsigned int weight);
+th_transport_t *transport_find(channel_t *ch, unsigned int weight,
+                              const char *loginfo, int *errorp);
 
 th_stream_t *transport_stream_find(th_transport_t *t, int pid);
 
@@ -97,4 +105,6 @@ const char *transport_nicename(th_transport_t *t);
 
 const char *transport_component_nicename(th_stream_t *st);
 
+const char *transport_nostart2txt(int code);
+
 #endif /* TRANSPORTS_H */