]> git.ipfire.org Git - thirdparty/shairport-sync.git/commitdiff
Add timing to debug messages, make timing sender wait interruptable eveyr 20 ms,...
authorMike Brady <mikebrady@eircom.net>
Sat, 3 Feb 2018 20:24:58 +0000 (20:24 +0000)
committerMike Brady <mikebrady@eircom.net>
Sat, 3 Feb 2018 20:24:58 +0000 (20:24 +0000)
common.c
common.h
dacp.c
metadata_hub.c
metadata_hub.h
player.c
rtp.c
rtsp.c
scripts/shairport-sync.conf
shairport.c

index dd12d6cd24cefb40f399770f0dcec3e87166314d..ea6733ac10b830d971466d1772cb88616cab7612 100644 (file)
--- a/common.c
+++ b/common.c
@@ -25,6 +25,8 @@
  * OTHER DEALINGS IN THE SOFTWARE.
  */
 
+#include "common.h"
+#include <assert.h>
 #include <errno.h>
 #include <memory.h>
 #include <poll.h>
@@ -37,8 +39,6 @@
 #include <sys/wait.h>
 #include <time.h>
 #include <unistd.h>
-#include "common.h"
-#include <assert.h>
 
 #ifdef COMPILE_FOR_OSX
 #include <CoreServices/CoreServices.h>
@@ -124,11 +124,25 @@ void debug(int level, const char *format, ...) {
     return;
   char s[1024];
   s[0] = 0;
+  uint64_t time_now = get_absolute_time_in_fp();
+  uint64_t time_since_start = time_now - fp_time_at_startup;
+  uint64_t time_since_last_debug_message = time_now - fp_time_at_last_debug_message;
+  fp_time_at_last_debug_message = time_now;
+  uint64_t divisor = (uint64_t)1 << 32;
+  double tss = 1.0 * time_since_start / divisor;
+  double tsl = 1.0 * time_since_last_debug_message / divisor;
   va_list args;
   va_start(args, format);
   vsnprintf(s, sizeof(s), format, args);
   va_end(args);
-  daemon_log(LOG_DEBUG, "%s", s);
+  if ((config.debugger_show_elapsed_time) && (config.debugger_show_relative_time))
+    daemon_log(LOG_DEBUG, "|% 20.9f|% 20.9f|%s", tss, tsl, s);
+  else if (config.debugger_show_relative_time)
+    daemon_log(LOG_DEBUG, "% 20.9f|%s", tsl, s);
+  else if (config.debugger_show_elapsed_time)
+    daemon_log(LOG_DEBUG, "% 20.9f|%s", tss, s);
+  else
+    daemon_log(LOG_DEBUG, "%s", s);
 }
 
 void inform(const char *format, ...) {
@@ -664,15 +678,15 @@ uint32_t uatoi(const char *nptr) {
   return r;
 }
 
-
 double flat_vol2attn(double vol, long max_db, long min_db) {
   double vol_setting = min_db;
 
   if ((vol <= 0.0) && (vol >= -30.0)) {
-    vol_setting = ((max_db - min_db)*(30.0+vol)/30)+min_db;
-    debug(2,"Linear Volume Setting: %f in range %ld to %ld.",vol_setting,min_db,max_db);
+    vol_setting = ((max_db - min_db) * (30.0 + vol) / 30) + min_db;
+    debug(2, "Linear Volume Setting: %f in range %ld to %ld.", vol_setting, min_db, max_db);
   } else if (vol != -144.0) {
-    debug(1, "Linear volume request value %f is out of range: should be from 0.0 to -30.0 or -144.0.",
+    debug(1,
+          "Linear volume request value %f is out of range: should be from 0.0 to -30.0 or -144.0.",
           vol);
   }
   return vol_setting;
@@ -738,7 +752,8 @@ double vol2attn(double vol, long max_db, long min_db) {
     vol_setting = min_db; // for safety, return the lowest setting...
   }
   // debug(1,"returning an attenuation of %f.",vol_setting);
-  debug(2,"Standard profile Volume Setting for Airplay vol %f: %f in range %ld to %ld.",vol,vol_setting,min_db,max_db);
+  debug(2, "Standard profile Volume Setting for Airplay vol %f: %f in range %ld to %ld.", vol,
+        vol_setting, min_db, max_db);
   return vol_setting;
 }
 
index e36aae9a4b6690dd7a1f955c875512a7b846ecbd..22ebacc45727d4d8bfadcffd94bbd4e2d94ea3cc 100644 (file)
--- a/common.h
+++ b/common.h
@@ -136,7 +136,9 @@ typedef struct {
   char *piddir;
   char *computed_piddir; // the actual pid directory to create, if any
 
-  int logOutputLevel; // log output level
+  int logOutputLevel;              // log output level
+  int debugger_show_elapsed_time;  // in the debug message, display the time since startup
+  int debugger_show_relative_time; // in the debug message, display the time since the last one
   int statistics_requested, use_negotiated_latencies;
   enum playback_mode_type playback_mode;
   char *cmd_start, *cmd_stop, *cmd_set_volume;
@@ -185,7 +187,7 @@ typedef struct {
 #ifdef HAVE_METADATA_HUB
   char *cover_art_cache_dir;
 #endif
-       int     disable_resend_requests; //set this to stop resend request being made for missing packets
+  int disable_resend_requests; // set this to stop resend request being made for missing packets
 
 } shairport_cfg;
 
@@ -234,9 +236,11 @@ double flat_vol2attn(double vol, long max_db, long min_db);
 double vol2attn(double vol, long max_db, long min_db);
 
 // return a monolithic (always increasing) time in nanoseconds
-
 uint64_t get_absolute_time_in_fp(void);
 
+// time at startup for debugging timing
+uint64_t fp_time_at_startup, fp_time_at_last_debug_message;
+
 // this is for reading an unsigned 32 bit number, such as an RTP timestamp
 
 long endianness;
diff --git a/dacp.c b/dacp.c
index 04885d011461deae002fd4a4533d53ec2225d383..06b05b4fcff7ce5042e93cce18fa93cecc575378 100644 (file)
--- a/dacp.c
+++ b/dacp.c
@@ -301,9 +301,9 @@ void *dacp_monitor_thread_code(void *na) {
       if (le >= 8) {
         // here start looking for the contents of the status update
         if (dacp_tlv_crawl(&sp, &item_size) == 'cmst') { // status
-                                       // here, we know that we are receiving playerstatusupdates, so set a flag
-                                       metadata_hub_modify_prolog();
-                                       metadata_store.playerstatusupdates_are_received = 1;
+          // here, we know that we are receiving playerstatusupdates, so set a flag
+          metadata_hub_modify_prolog();
+          metadata_store.playerstatusupdates_are_received = 1;
           sp -= item_size; // drop down into the array -- don't skip over it
           le -= 8;
           char typestring[5];
@@ -545,7 +545,7 @@ void *dacp_monitor_thread_code(void *na) {
           }
 
           // finished possibly writing to the metadata hub
-               metadata_hub_modify_epilog();
+          metadata_hub_modify_epilog();
         } else {
           printf("Status Update not found.\n");
         }
index b5097c864f14062a0805c7acd9a5a89e43faa338..8f0f0480ce4b9e4eb0fdeecf50e3adeb4e9126e2 100644 (file)
@@ -77,33 +77,31 @@ void add_metadata_watcher(metadata_watcher fn, void *userdata) {
 }
 
 void metadata_hub_modify_prolog(void) {
-// always run this before changing an entry or a sequence of entries in the metadata_hub
-  debug(1,"locking metadata hub for writing");
+  // always run this before changing an entry or a sequence of entries in the metadata_hub
+  debug(1, "locking metadata hub for writing");
   pthread_rwlock_wrlock(&metadata_hub_re_lock);
-
 }
 
 void run_metadata_watchers(void) {
   int i;
-  debug(1,"locking metadata hub for reading");
+  debug(1, "locking metadata hub for reading");
   pthread_rwlock_rdlock(&metadata_hub_re_lock);
   for (i = 0; i < number_of_watchers; i++) {
     if (metadata_store.watchers[i]) {
       metadata_store.watchers[i](&metadata_store, metadata_store.watchers_data[i]);
     }
   }
-  debug(1,"unlocking metadata hub for reading");
+  debug(1, "unlocking metadata hub for reading");
   pthread_rwlock_unlock(&metadata_hub_re_lock);
 }
 
 void metadata_hub_modify_epilog(void) {
-// always run this after changing an entry or a sequence of entries in the metadata_hub
-  debug(1,"unlocking metadata hub for writing");
+  // always run this after changing an entry or a sequence of entries in the metadata_hub
+  debug(1, "unlocking metadata hub for writing");
   pthread_rwlock_unlock(&metadata_hub_re_lock);
   run_metadata_watchers();
 }
 
-
 char *metadata_write_image_file(const char *buf, int len) {
 
   // warning -- this removes all files from the directory apart from this one, if it exists
@@ -153,7 +151,7 @@ char *metadata_write_image_file(const char *buf, int len) {
     debug(1, "Unidentified image type of cover art -- jpg extension used.");
     ext = jpg;
   }
-       mode_t oldumask = umask(000);
+  mode_t oldumask = umask(000);
   int result = mkpath(config.cover_art_cache_dir, 0777);
   umask(oldumask);
   if ((result == 0) || (result == -EEXIST)) {
@@ -227,10 +225,10 @@ void metadata_hub_process_metadata(uint32_t type, uint32_t code, char *data, uin
   // metadata coming in from the audio source or from Shairport Sync itself passes through here
   // this has more information about tags, which might be relevant:
   // https://code.google.com/p/ytrack/wiki/DMAP
-  
+
   // all the following items of metadata are contained in one metadata packet
   // they are preseded by an 'ssnc' 'mdst' item and followed by an 'ssnc 'mden' item.
-  
+
   if (type == 'core') {
     switch (code) {
     case 'asal':
@@ -258,7 +256,7 @@ void metadata_hub_process_metadata(uint32_t type, uint32_t code, char *data, uin
     case 'ascm':
       if ((metadata_store.comment == NULL) ||
           (strncmp(metadata_store.comment, data, length) != 0)) {
-        if (metadata_store.comment) 
+        if (metadata_store.comment)
           free(metadata_store.comment);
         metadata_store.comment = strndup(data, length);
         // debug(1, "MH Comment set to: \"%s\"", metadata_store.comment);
@@ -354,13 +352,12 @@ void metadata_hub_process_metadata(uint32_t type, uint32_t code, char *data, uin
     }
   } else if (type == 'ssnc') {
     switch (code) {
-    
+
     // ignore the following
     case 'pcst':
     case 'pcen':
-       break;
-       
-    
+      break;
+
     case 'mdst':
       debug(1, "MH Metadata stream processing start.");
       metadata_hub_modify_prolog();
@@ -371,12 +368,12 @@ void metadata_hub_process_metadata(uint32_t type, uint32_t code, char *data, uin
       break;
     case 'PICT':
       if (length > 16) {
-       metadata_hub_modify_prolog();
-       debug(1, "MH Picture received, length %u bytes.", length);
+        metadata_hub_modify_prolog();
+        debug(1, "MH Picture received, length %u bytes.", length);
         if (metadata_store.cover_art_pathname)
           free(metadata_store.cover_art_pathname);
         metadata_store.cover_art_pathname = metadata_write_image_file(data, length);
-       metadata_hub_modify_epilog();
+        metadata_hub_modify_epilog();
       }
       break;
     case 'clip':
index 70d2fcf7a5f86fe704e0045d37be9eb7757083d2..2a7d844542af573673052b99f26b587d0f83ef1a 100644 (file)
@@ -99,7 +99,7 @@ void add_metadata_watcher(metadata_watcher fn, void *userdata);
 void metadata_hub_init(void);
 void metadata_hub_process_metadata(uint32_t type, uint32_t code, char *data, uint32_t length);
 
-// these functions lock and unlock the read-write mutex on the metadata hub and run the watchers afterwards
+// these functions lock and unlock the read-write mutex on the metadata hub and run the watchers
+// afterwards
 void metadata_hub_modify_prolog(void);
 void metadata_hub_modify_epilog(void);
-
index a83974265604e5dc399c47b386d98eb8c0d6a084..c05a958ef4db951383ac7c4b6ab0b64863d998ac 100644 (file)
--- a/player.c
+++ b/player.c
@@ -816,9 +816,9 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) {
 
 // say we have started playing here
 #ifdef HAVE_METADATA_HUB
-                                               metadata_hub_modify_prolog();
+            metadata_hub_modify_prolog();
             metadata_store.player_state = PS_PLAYING;
-                                               metadata_hub_modify_epilog();
+            metadata_hub_modify_epilog();
 #endif
             if (reference_timestamp) { // if we have a reference time
               // debug(1,"First frame seen with timestamp...");
@@ -1106,7 +1106,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) {
     if (do_wait == 0)
       if ((conn->ab_synced != 0) && (conn->ab_read == conn->ab_write)) { // the buffer is empty!
         if (notified_buffer_empty == 0) {
-          debug(2, "Buffers exhausted.");
+          debug(3, "Buffers exhausted.");
           notified_buffer_empty = 1;
         }
         do_wait = 1;
@@ -1159,10 +1159,10 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) {
       seq_t next = seq_sum(conn->ab_read, i);
       abuf = conn->audio_buffer + BUFIDX(next);
       if (!abuf->ready) {
-       if (config.disable_resend_requests==0) {
-                                       rtp_request_resend(next, 1, conn);
-                                       // debug(1,"Resend %u.",next);
-                                       conn->resend_requests++;
+        if (config.disable_resend_requests == 0) {
+          rtp_request_resend(next, 1, conn);
+          // debug(1,"Resend %u.",next);
+          conn->resend_requests++;
         }
       }
     }
@@ -1632,7 +1632,7 @@ static void *player_thread_func(void *arg) {
 
   player_volume(config.airplay_volume, conn);
   int64_t frames_to_drop = 0;
-  
+
   while (!conn->player_thread_please_stop) {
     abuf_t *inframe = buffer_get_frame(conn);
     if (inframe) {
@@ -1659,7 +1659,7 @@ static void *player_thread_func(void *arg) {
         } else if (frames_to_drop) {
           // debug(2,"%lld frames to drop.",frames_to_drop);
           frames_to_drop -= inframe->length;
-          if (frames_to_drop<0)
+          if (frames_to_drop < 0)
             frames_to_drop = 0;
         } else {
           int enable_dither = 0;
@@ -1872,7 +1872,7 @@ static void *player_thread_func(void *arg) {
                   config.resyncthreshold * config.output_rate; // number of samples
               if ((sync_error > 0) && (sync_error > filler_length)) {
                 debug(1, "Large positive sync error: %lld.", sync_error);
-                frames_to_drop = sync_error/conn->output_sample_ratio;
+                frames_to_drop = sync_error / conn->output_sample_ratio;
               } else if ((sync_error < 0) && ((-sync_error) > filler_length)) {
                 // debug(1, "Large negative sync error: %lld. Inserting silence.", sync_error);
                 size_t silence_length = -sync_error;
@@ -2208,8 +2208,6 @@ static void *player_thread_func(void *arg) {
 
   if (config.output->stop)
     config.output->stop();
-  usleep(100000); // allow this time to (?) allow the alsa subsystem to finish cleaning up after
-                  // itself. 50 ms seems too short
 
   debug(2, "Shut down audio, control and timing threads");
   conn->please_stop = 1;
@@ -2217,14 +2215,17 @@ static void *player_thread_func(void *arg) {
   pthread_kill(rtp_control_thread, SIGUSR1);
   pthread_kill(rtp_timing_thread, SIGUSR1);
   pthread_join(rtp_timing_thread, NULL);
-  debug(3, "timing thread joined");
+  debug(1, "timing thread joined");
   pthread_join(rtp_audio_thread, NULL);
-  debug(3, "audio thread joined");
+  debug(1, "audio thread joined");
   pthread_join(rtp_control_thread, NULL);
-  debug(3, "control thread joined");
+  debug(1, "control thread joined");
   clear_reference_timestamp(conn);
   conn->rtp_running = 0;
 
+  usleep(100000); // allow this time to (?) allow the alsa subsystem to finish cleaning up after
+                  // itself. 50 ms seems too short
+
   free_audio_buffers(conn);
   terminate_decoders(conn);
   // remove flow control and mutexes
@@ -2423,10 +2424,11 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c
     if (config.ignore_volume_control == 1)
       scaled_attenuation = max_db;
     else if (config.volume_control_profile == VCP_standard)
-        scaled_attenuation = vol2attn(airplay_volume, max_db, min_db);
+      scaled_attenuation = vol2attn(airplay_volume, max_db, min_db);
     else if (config.volume_control_profile == VCP_flat)
-        scaled_attenuation = flat_vol2attn(airplay_volume, max_db, min_db); 
-    else debug(1,"Unrecognised volume control profile");
+      scaled_attenuation = flat_vol2attn(airplay_volume, max_db, min_db);
+    else
+      debug(1, "Unrecognised volume control profile");
 
     if (hw_range_db) {
       // if there is a hardware mixer
@@ -2509,9 +2511,9 @@ void player_flush(int64_t timestamp, rtsp_conn_info *conn) {
 #endif
 
 #ifdef HAVE_METADATA_HUB
-               metadata_hub_modify_prolog();
-               metadata_store.player_state = PS_PAUSED;
-               metadata_hub_modify_epilog();
+  metadata_hub_modify_prolog();
+  metadata_store.player_state = PS_PAUSED;
+  metadata_hub_modify_epilog();
 #endif
 }
 
@@ -2539,9 +2541,9 @@ int player_play(rtsp_conn_info *conn) {
   pthread_create(pt, &tattr, player_thread_func, (void *)conn);
   pthread_attr_destroy(&tattr);
 #ifdef HAVE_METADATA_HUB
-       metadata_hub_modify_prolog();
-       metadata_store.player_state = PS_PLAYING;
-       metadata_hub_modify_epilog();
+  metadata_hub_modify_prolog();
+  metadata_store.player_state = PS_PLAYING;
+  metadata_hub_modify_epilog();
 #endif
   return 0;
 }
@@ -2559,9 +2561,9 @@ void player_stop(rtsp_conn_info *conn) {
     free(conn->player_thread);
     conn->player_thread = NULL;
 #ifdef HAVE_METADATA_HUB
-               metadata_hub_modify_prolog();
-               metadata_store.player_state = PS_STOPPED;
-               metadata_hub_modify_epilog();
+    metadata_hub_modify_prolog();
+    metadata_store.player_state = PS_STOPPED;
+    metadata_hub_modify_epilog();
 #endif
   } else {
     debug(3, "player thread of RTSP conversation %d is already deleted.", conn->connection_number);
diff --git a/rtp.c b/rtp.c
index f0fc14927d6f40ce921570f1938075f90b194bf8..570a0db58a3f389bdc7f8ef235925298bcdd0934 100644 (file)
--- a/rtp.c
+++ b/rtp.c
@@ -165,7 +165,7 @@ void *rtp_audio_receiver(void *arg) {
     warn("Audio receiver -- Unknown RTP packet of type 0x%02X length %d.", type, nread);
   }
 
-  debug(3, "Audio receiver -- Server RTP thread interrupted. terminating.");
+  debug(2, "Audio receiver -- Server RTP thread interrupted. terminating.");
   close(conn->audio_socket);
 
   return NULL;
@@ -299,7 +299,7 @@ void *rtp_control_receiver(void *arg) {
             nread);
   }
 
-  debug(3, "Control RTP thread interrupted. terminating.");
+  debug(2, "Control RTP thread interrupted. terminating.");
   close(conn->control_socket);
 
   return NULL;
@@ -365,12 +365,24 @@ void *rtp_timing_sender(void *arg) {
       debug(1, "Error %d using send-to to the timing socket: \"%s\".", errno, em);
     }
     request_number++;
+
+    // this is to deal with the possibility of missing a timing_sender_stop signal.
+    // if the signal came in just before the usleep, then it wouldn't cause the sleep to end.
+    // so, we will wait a maximum time of the wait_interval
+
+    int wait_time;
+    int wait_interval = 20000; // 20 milliseconds
+
     if (request_number <= 4)
-      usleep(500000);
+      wait_time = 500000;
     else
-      sleep(3);
+      wait_time = 3000000;
+    while ((wait_time > 0) && (conn->timing_sender_stop == 0)) {
+      usleep(wait_interval);
+      wait_time -= wait_interval;
+    }
   }
-  debug(3, "rtp_timing_sender thread interrupted. terminating.");
+  debug(2, "rtp_timing_sender thread interrupted. terminating.");
   return NULL;
 }
 
@@ -591,14 +603,14 @@ void *rtp_timing_receiver(void *arg) {
     }
   }
 
-  debug(3, "Timing thread interrupted. terminating.");
+  debug(2, "Timing thread interrupted. terminating.");
   conn->timing_sender_stop = 1;
   void *retval;
   pthread_kill(timer_requester, SIGUSR1);
   debug(3, "Wait for timer requester to exit.");
   pthread_join(timer_requester, &retval);
   debug(3, "Closed and terminated timer requester thread.");
-  debug(3, "Timing RTP thread terminated.");
+  debug(2, "Timing RTP thread terminated.");
   close(conn->timing_socket);
 
   return NULL;
diff --git a/rtsp.c b/rtsp.c
index 81afc415b491e92f248efba294a17e595385c2b2..f6f31c075c74f99112842f425036e0b448fdc4fb 100644 (file)
--- a/rtsp.c
+++ b/rtsp.c
@@ -80,7 +80,7 @@ enum rtsp_read_request_response {
   rtsp_read_request_response_immediate_shutdown_requested,
   rtsp_read_request_response_bad_packet,
   rtsp_read_request_response_channel_closed,
-  rtsp_read_request_response_read_error,  
+  rtsp_read_request_response_read_error,
   rtsp_read_request_response_error
 };
 
@@ -518,7 +518,7 @@ static enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn,
         continue;
       char errorstring[1024];
       strerror_r(errno, (char *)errorstring, sizeof(errorstring));
-      debug(1,"rtsp_read_request_response_read_error %d: \"%s\".",errno,(char *)errorstring);
+      debug(1, "rtsp_read_request_response_read_error %d: \"%s\".", errno, (char *)errorstring);
       reply = rtsp_read_request_response_read_error;
       goto shutdown;
     }
@@ -665,7 +665,10 @@ static void msg_write_response(int fd, rtsp_message *resp) {
 }
 
 static void handle_record(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) {
-  debug(3, "Connection %d: RECORD", conn->connection_number);
+  debug(2, "Connection %d: RECORD", conn->connection_number);
+
+  player_play(conn); // the thread better be 0
+
   resp->respcode = 200;
   // I think this is for telling the client what the absolute minimum latency
   // actually is,
@@ -696,7 +699,7 @@ static void handle_record(rtsp_conn_info *conn, rtsp_message *req, rtsp_message
       }
     }
   }
-  usleep(500000);
+  // usleep(500000);
 }
 
 static void handle_options(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) {
@@ -708,7 +711,7 @@ static void handle_options(rtsp_conn_info *conn, rtsp_message *req, rtsp_message
 }
 
 static void handle_teardown(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) {
-  debug(3, "Connection %d: TEARDOWN", conn->connection_number);
+  debug(2, "Connection %d: TEARDOWN", conn->connection_number);
   // if (!rtsp_playing())
   //  debug(1, "This RTSP connection thread (%d) doesn't think it's playing, but "
   //           "it's sending a response to teardown anyway",conn->connection_number);
@@ -756,7 +759,7 @@ static void handle_flush(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *
 }
 
 static void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) {
-  debug(3, "Connection %d: SETUP", conn->connection_number);
+  debug(2, "Connection %d: SETUP", conn->connection_number);
   int cport, tport;
   int lsport, lcport, ltport;
 
@@ -817,8 +820,6 @@ static void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *
       strcat(hdr, q); // should unsplice the timing port entry
   }
 
-  player_play(conn); // the thread better be 0
-
   char *resphdr = alloca(200);
   *resphdr = 0;
   sprintf(resphdr, "RTP/AVP/"
@@ -1050,14 +1051,13 @@ void metadata_create(void) {
   char *path = malloc(pl + 1);
   snprintf(path, pl + 1, "%s", config.metadata_pipename);
 
-       mode_t oldumask = umask(000);
+  mode_t oldumask = umask(000);
 
   if (mkfifo(path, 0666) && errno != EEXIST)
     die("Could not create metadata FIFO %s", path);
 
   free(path);
   umask(oldumask);
-
 }
 
 void metadata_open(void) {
@@ -1418,12 +1418,16 @@ static void handle_set_parameter(rtsp_conn_info *conn, rtsp_message *req, rtsp_m
 }
 
 static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) {
-  debug(3, "Connection %d: ANNOUNCE", conn->connection_number);
+  debug(2, "Connection %d: ANNOUNCE", conn->connection_number);
   int have_the_player = 0;
 
   // interrupt session if permitted
   if (pthread_mutex_trylock(&play_lock) == 0) {
     have_the_player = 1;
+  } else if ((playing_conn) &&
+             (playing_conn->connection_number == conn->connection_number)) { // duplicate ANNOUNCE
+    debug(1, "Duplicate ANNOUNCE, by the look of it!");
+    have_the_player = 1;
   } else {
     int should_wait = 0;
 
@@ -1494,12 +1498,12 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag
 
     if (pminlatency) {
       conn->minimum_latency = atoi(pminlatency);
-      debug(1, "Minimum latency %d specified", conn->minimum_latency);
+      debug(3, "Minimum latency %d specified", conn->minimum_latency);
     }
 
     if (pmaxlatency) {
       conn->maximum_latency = atoi(pmaxlatency);
-      debug(1, "Maximum latency %d specified", conn->maximum_latency);
+      debug(3, "Maximum latency %d specified", conn->maximum_latency);
     }
 
     if ((paesiv == NULL) && (prsaaeskey == NULL)) {
@@ -1827,7 +1831,7 @@ static void *rtsp_conversation_thread_func(void *pconn) {
   char *hdr, *auth_nonce = NULL;
 
   enum rtsp_read_request_response reply;
-  
+
   int rtsp_read_request_attempt_count = 1; // 1 means exit immediately
 
   while (conn->stop == 0) {
@@ -1879,16 +1883,19 @@ static void *rtsp_conversation_thread_func(void *pconn) {
       int tstop = 0;
       if (reply == rtsp_read_request_response_immediate_shutdown_requested)
         tstop = 1;
-      else if ((reply == rtsp_read_request_response_channel_closed) || (reply == rtsp_read_request_response_read_error)) {
+      else if ((reply == rtsp_read_request_response_channel_closed) ||
+               (reply == rtsp_read_request_response_read_error)) {
         if (conn->player_thread) {
           rtsp_read_request_attempt_count--;
-          if (rtsp_read_request_attempt_count==0)
+          if (rtsp_read_request_attempt_count == 0)
             tstop = 1;
           else {
             if (reply == rtsp_read_request_response_channel_closed)
-              debug(2,"RTSP channel unexpectedly closed -- will try again %d time(s).",rtsp_read_request_attempt_count);
+              debug(2, "RTSP channel unexpectedly closed -- will try again %d time(s).",
+                    rtsp_read_request_attempt_count);
             if (reply == rtsp_read_request_response_read_error)
-              debug(2,"RTSP channel read error -- will try again %d time(s).",rtsp_read_request_attempt_count);
+              debug(2, "RTSP channel read error -- will try again %d time(s).",
+                    rtsp_read_request_attempt_count);
             usleep(20000);
           }
         } else {
@@ -1901,7 +1908,7 @@ static void *rtsp_conversation_thread_func(void *pconn) {
         debug(3, "Synchronously terminate playing thread of RTSP conversation thread %d.",
               conn->connection_number);
         if (conn->player_thread)
-          debug(1,"RTSP Channel unexpectedly closed or erred -- closing the session.");
+          debug(1, "RTSP Channel unexpectedly closed or erred -- closing the session.");
         player_stop(conn);
         debug(3, "Successful termination of playing thread of RTSP conversation thread %d.",
               conn->connection_number);
index 4586ba2422cdea29437d1a29d79f8ab20734a23e..bba9db47aa653ecbc31e0e575fa8836f73c76315 100644 (file)
@@ -150,4 +150,6 @@ diagnostics =
 //     disable_resend_requests = "no"; // set this to yes to stop Shairport Sync from requesting the retransmission of missing packets. Default is "no".
 //     statistics = "no"; // set to "yes" to print statistics in the log
 //     log_verbosity = 0; // "0" means no debug verbosity, "3" is most verbose.
+//     log_show_time_since_startup = "no"; // set this to yes if you want the time since startup in the debug message -- seconds down to nanoseconds
+//     log_show_time_since_last_message = "no"; // set this to yes if you want the time since the last debug message in the debug message -- seconds down to nanoseconds
 };
index 6193857df162029076a2e1343d11160908019c68..24de8a47497ec1930c8ab7577967f6cf7e3f932b 100644 (file)
@@ -508,7 +508,8 @@ int parse_options(int argc, char **argv) {
 
       /* Get the statistics setting. */
       if (config_lookup_string(config.cfg, "general.statistics", &str)) {
-       warn("The \"general\" \"statistics\" setting is deprecated. Please use the \"diagnostics\" \"statistics\" setting instead.");
+        warn("The \"general\" \"statistics\" setting is deprecated. Please use the \"diagnostics\" "
+             "\"statistics\" setting instead.");
         if (strcasecmp(str, "no") == 0)
           config.statistics_requested = 0;
         else if (strcasecmp(str, "yes") == 0)
@@ -541,7 +542,8 @@ int parse_options(int argc, char **argv) {
 
       /* Get the verbosity setting. */
       if (config_lookup_int(config.cfg, "general.log_verbosity", &value)) {
-       warn("The \"general\" \"log_verbosity\" setting is deprecated. Please use the \"diagnostics\" \"log_verbosity\" setting instead.");
+        warn("The \"general\" \"log_verbosity\" setting is deprecated. Please use the "
+             "\"diagnostics\" \"log_verbosity\" setting instead.");
         if ((value >= 0) && (value <= 3))
           debuglev = value;
         else
@@ -555,11 +557,34 @@ int parse_options(int argc, char **argv) {
         if ((value >= 0) && (value <= 3))
           debuglev = value;
         else
-          die("Invalid diagnostics log_verbosity setting option choice \"%d\". It should be between 0 and 3, "
+          die("Invalid diagnostics log_verbosity setting option choice \"%d\". It should be "
+              "between 0 and 3, "
               "inclusive.",
               value);
       }
 
+      /* Get the show elapsed time in debug messages setting. */
+      if (config_lookup_string(config.cfg, "diagnostics.log_show_time_since_startup", &str)) {
+        if (strcasecmp(str, "no") == 0)
+          config.debugger_show_elapsed_time = 0;
+        else if (strcasecmp(str, "yes") == 0)
+          config.debugger_show_elapsed_time = 1;
+        else
+          die("Invalid diagnostics log_show_time_since_startup option choice \"%s\". It should be "
+              "\"yes\" or \"no\"");
+      }
+
+      /* Get the show relative time in debug messages setting. */
+      if (config_lookup_string(config.cfg, "diagnostics.log_show_time_since_last_message", &str)) {
+        if (strcasecmp(str, "no") == 0)
+          config.debugger_show_relative_time = 0;
+        else if (strcasecmp(str, "yes") == 0)
+          config.debugger_show_relative_time = 1;
+        else
+          die("Invalid diagnostics log_show_time_since_last_message option choice \"%s\". It "
+              "should be \"yes\" or \"no\"");
+      }
+
       /* Get the statistics setting. */
       if (config_lookup_string(config.cfg, "diagnostics.statistics", &str)) {
         if (strcasecmp(str, "no") == 0)
@@ -567,10 +592,10 @@ int parse_options(int argc, char **argv) {
         else if (strcasecmp(str, "yes") == 0)
           config.statistics_requested = 1;
         else
-          die("Invalid diagnostics statistics option choice \"%s\". It should be \"yes\" or \"no\"");
+          die("Invalid diagnostics statistics option choice \"%s\". It should be \"yes\" or "
+              "\"no\"");
       }
 
-
       /* Get the disable_resend_requests setting. */
       if (config_lookup_string(config.cfg, "diagnostics.disable_resend_requests", &str)) {
         config.disable_resend_requests = 0; // this is for legacy -- only set by -t 0
@@ -629,7 +654,8 @@ int parse_options(int argc, char **argv) {
         else if (strcasecmp(str, "flat") == 0)
           config.volume_control_profile = VCP_flat;
         else
-          die("Invalid volume_control_profile choice \"%s\". It should be \"standard\" (default) or \"flat\"");
+          die("Invalid volume_control_profile choice \"%s\". It should be \"standard\" (default) "
+              "or \"flat\"");
       }
 
       /* Get the interface to listen on, if specified Default is all interfaces */
@@ -1065,7 +1091,9 @@ void exit_function() {
 }
 
 int main(int argc, char **argv) {
-
+  fp_time_at_startup = get_absolute_time_in_fp();
+  fp_time_at_last_debug_message = fp_time_at_startup;
+  //  debug(1,"startup");
   daemon_set_verbosity(LOG_DEBUG);
   memset(&config, 0, sizeof(config)); // also clears all strings, BTW
   atexit(exit_function);
@@ -1443,7 +1471,8 @@ int main(int argc, char **argv) {
 #endif
   debug(1, "loudness is %d.", config.loudness);
   debug(1, "loudness reference level is %f", config.loudness_reference_volume_db);
-  debug(1, "disable resend requests is %d -- non-zero means \"yes\"", config.disable_resend_requests);
+  debug(1, "disable resend requests is %d -- non-zero means \"yes\"",
+        config.disable_resend_requests);
 
   uint8_t ap_md5[16];