Slightly better timing. Bumped version for ejurgensen's new pair_ap work.

diff --git a/configure.ac b/configure.ac
index fdeaa1395839d74e51736fd3ad37430f2ba828aa..087ef5a6d9cc241f22ade90569efca63e108c24d 100644 (file)
--- a/configure.ac
+++ b/configure.ac
@@ -2,7 +2,7 @@
 # Process this file with autoconf to produce a configure script.
 
 AC_PREREQ([2.50])
-AC_INIT([shairport-sync], [4.0d1], [4265913+mikebrady@users.noreply.github.com])
+AC_INIT([shairport-sync], [4.0d2], [4265913+mikebrady@users.noreply.github.com])
 AM_INIT_AUTOMAKE
 AC_CONFIG_SRCDIR([shairport.c])
 AC_CONFIG_HEADERS([config.h])

diff --git a/player.c b/player.c
index e8d79115628905403cd179f74e136c66e3aeb4a7..24640c5ae0081f703d366fb0ac7b4d3b6c00088d 100644 (file)
--- a/player.c
+++ b/player.c
@@ -442,6 +442,8 @@ void player_put_packet(int original_format, seq_t seqno, uint32_t actual_timesta
       conn->ab_write = seqno;
       conn->ab_read = seqno;
       conn->ab_synced = 1;
+      conn->first_packet_timestamp = 0;
+      debug(1,"synced by first packet");
     } else if (original_format == 0) {
       // if the packet is coming in original format, the sequence number is important
       // otherwise, ignore is by setting it equal to the expected sequence number in ab_write
@@ -1279,7 +1281,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(3, "Buffers exhausted.");
+          debug(1, "Buffers exhausted.");
           notified_buffer_empty = 1;
           // reset_input_flow_metrics(conn); // don't do a full flush parameters reset
           conn->initial_reference_time = 0;
@@ -1559,11 +1561,11 @@ void player_thread_cleanup_handler(void *arg) {
     int elapsedMin = (rawSeconds / 60) % 60;
     int elapsedSec = rawSeconds % 60;
     if (conn->frame_rate_status)
-      inform("Playback Stopped. Total playing time %02d:%02d:%02d. Input: %0.2f, output: %0.2f "
-             "frames per second.",
+      inform("Connection %d: Playback Stopped. Total playing time %02d:%02d:%02d. Input: %0.2f, output: %0.2f "
+             "frames per second.", conn->connection_number,
              elapsedHours, elapsedMin, elapsedSec, conn->input_frame_rate, conn->frame_rate);
     else
-      inform("Playback Stopped. Total playing time %02d:%02d:%02d. Input: %0.2f frames per second.",
+      inform("Connection %d: Playback Stopped. Total playing time %02d:%02d:%02d. Input: %0.2f frames per second.", conn->connection_number,
              elapsedHours, elapsedMin, elapsedSec, conn->input_frame_rate);
   }
 
@@ -2280,7 +2282,7 @@ void *player_thread_func(void *arg) {
               int64_t filler_length =
                   (int64_t)(config.resyncthreshold * config.output_rate); // number of samples
               if ((sync_error > 0) && (sync_error > filler_length)) {
-                debug(2, "Large positive sync error: %" PRId64 ".", sync_error);
+                debug(1, "Large positive sync error of: %" PRId64 " frames (%f seconds).", sync_error, (sync_error * 1.0)/config.output_rate);
                 int64_t local_frames_to_drop = sync_error / conn->output_sample_ratio;
                 uint32_t frames_to_drop_sized = local_frames_to_drop;
 
@@ -2292,10 +2294,10 @@ void *player_thread_func(void *arg) {
                 debug_mutex_unlock(&conn->flush_mutex, 3);
 
               } else if ((sync_error < 0) && ((-sync_error) > filler_length)) {
-                debug(2,
-                      "Large negative sync error: %" PRId64 " with should_be_frame_32 of %" PRIu32
+                debug(1,
+                      "Large negative sync error of: %" PRId64 " frames (%f seconds), with should_be_frame_32 of %" PRIu32
                       ", nt of %" PRId64 " and current_delay of %" PRId64 ".",
-                      sync_error, should_be_frame_32,
+                      sync_error, (sync_error * 1.0)/config.output_rate, should_be_frame_32,
                       inframe->given_timestamp * conn->output_sample_ratio, current_delay);
                 int64_t silence_length = -sync_error;
                 if (silence_length > (filler_length * 5))

diff --git a/rtp.c b/rtp.c
index 06c7324d1692768d97c19c8c974fbd511ad799c4..182d19ba1911b7817eb8a6e36ce7128e45a5db5f 100644 (file)
--- a/rtp.c
+++ b/rtp.c
@@ -290,8 +290,8 @@ void *rtp_control_receiver(void *arg) {
                                                                 obfp += 2;
                                                               };
                                                               *obfp = 0;
-                                             
-                                             
+
+
                                                               // get raw timestamp information
                                                               // I think that a good way to understand these timestamps is that
                                                               // (1) the rtlt below is the timestamp of the frame that should be playing at the
@@ -302,19 +302,19 @@ void *rtp_control_receiver(void *arg) {
                                                               // Thus, (3) the latency can be calculated by subtracting the second from the
                                                               // first.
                                                               // There must be more to it -- there something missing.
-                                             
+
                                                               // In addition, it seems that if the value of the short represented by the second
                                                               // pair of bytes in the packet is 7
                                                               // then an extra time lag is expected to be added, presumably by
                                                               // the AirPort Express.
-                                             
+
                                                               // Best guess is that this delay is 11,025 frames.
-                                             
+
                                                               uint32_t rtlt = nctohl(&packet[4]); // raw timestamp less latency
                                                               uint32_t rt = nctohl(&packet[16]);  // raw timestamp
-                                             
+
                                                               uint32_t fl = nctohs(&packet[2]); //
-                                             
+
                                                               debug(1,"Sync Packet of %d bytes received: \"%s\", flags: %d, timestamps %u and %u,
                                                           giving a latency of %d frames.",plen,obf,fl,rt,rtlt,rt-rtlt);
                                                               //debug(1,"Monotonic timestamps are: %" PRId64 " and %" PRId64 "
@@ -2065,8 +2065,9 @@ void *rtp_buffered_audio_processor(void *arg) {
       get_audio_buffer_size_and_occupancy(&player_buffer_size, &player_buffer_occupancy, conn);
       // debug(1,"player buffer size and occupancy: %u and %u", player_buffer_size,
       // player_buffer_occupancy);
+      double reqested_lead_time = 0.4; //
       if (player_buffer_occupancy >
-          ((0.25 + 0.1) * 44100.0 / 352)) { // must be greater than the lead time.
+          ((reqested_lead_time + 0.1) * 44100.0 / 352)) { // must be greater than the lead time.
         // if there is enough stuff in the player's buffer, sleep for a while and try again
         // debug(1,"sleep for 20 ms");
         usleep(20000); // wait for a while
@@ -2089,8 +2090,7 @@ void *rtp_buffered_audio_processor(void *arg) {
                 0) {
               int64_t lead_time = buffer_should_be_time - get_absolute_time_in_ns();
               // debug(1,"lead time in buffered_audio is %f milliseconds.", lead_time * 0.000001);
-              // ask for 0.5 sec of leadtime
-              if ((lead_time >= (int64_t)(0.25 * 1000000000)) || (streaming_has_started == 1)) {
+              if ((lead_time >= (int64_t)(reqested_lead_time * 1000000000)) || (streaming_has_started == 1)) {
                 if (streaming_has_started == 0)
                   debug(1, "rtp lead time is %f ms.", 0.000001 * lead_time);
                 streaming_has_started = 1;

diff --git a/rtsp.c b/rtsp.c
index ade661454f10cf3b9fc495619025f7b970058100..74a1249a844476e4dd4e00b785c38d6c2c3a47cf 100644 (file)
--- a/rtsp.c
+++ b/rtsp.c
@@ -3163,6 +3163,7 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag
 #ifdef CONFIG_AIRPLAY_2
     conn->airplay_type = ap_1;
     conn->timing_type = ts_ntp;
+    debug(1, "Connection %d. AirPlay 1 Audio Stream Detected.", conn->connection_number);
 #endif
 
     conn->stream.type = ast_unknown;