Squashed commit of the following:

commit 3dda7928b6df6ba7febc20f22faff5c8be024ef4
Author: Mike Brady <mikebrady@eircom.net>
Date:   Sun Sep 22 20:59:50 2019 +0100

    Update RELEASENOTES-DEVELOPMENT.md

commit 153eb84cff292bd127c516e6486ba9c1f9a3ce16
Author: Mike Brady <mikebrady@eircom.net>
Date:   Sat Sep 21 19:30:26 2019 +0100

    Update RELEASENOTES-DEVELOPMENT.md

commit b574d49b37f874cc7b91163a81fcb9dc6c760ef4
Author: Mike Brady <mikebrady@eircom.net>
Date:   Sat Sep 21 19:03:13 2019 +0100

    Update RELEASENOTES-DEVELOPMENT.md

commit bce0613283e233ddfa24d080adff3450b4ddd909
Author: Mike Brady <mikebrady@eircom.net>
Date:   Sat Sep 21 18:59:18 2019 +0100

    Update configure.ac

commit 7dc145361186806a560495d8171a387f5856f2f0
Author: Mike Brady <mikebrady@eircom.net>
Replace the code for determining when resends should be sent for missing audio packets.

Multiple sequential resend requests are now rolled up into one.

Should address Issue #865.

RELEASENOTES-DEVELOPMENT.md

@@ -1,3 +1,12 @@
+Version 3.3.3d7
+====
+
+**Duh**
+* Versions 3.3.2d3 to 3.3.2d6 should have been labelled 3.3.3d\<something\>.
+
+**Enhancement**
+* Rewrite the logic for identifying missing packets of audio and for asking for resends. It seems more robust -- there was a suspicion of the previous logic that resend requests were not made for some missing packets. In addition, requests for resends of continuous sequences of packets are rolled into one.
+
 Version 3.3.2d6
 ====
 **Enhancements**

common.h

@@ -100,6 +100,9 @@ enum sps_format_t {
 const char *sps_format_description_string(enum sps_format_t format);
 
 typedef struct {
+  double resend_wait_before_check; // wait this long before asking for a missing packet to be resent
+  double resend_wait_between_checks; // wait this long between making requests
+  double resend_last_check_before_use; // if the packet is missing this close to the time of use, give up
   pthread_mutex_t lock;
   config_t *cfg;
   int endianness;

player.c

@@ -122,7 +122,9 @@ static void ab_resync(rtsp_conn_info *conn) {
   int i;
   for (i = 0; i < BUFFER_FRAMES; i++) {
     conn->audio_buffer[i].ready = 0;
-    conn->audio_buffer[i].resend_level = 0;
+    conn->audio_buffer[i].resend_request_number = 0;
+    conn->audio_buffer[i].resend_time = 0; // this is either zero or the time the last resend was requested.
+    conn->audio_buffer[i].initialisation_time = 0; // this is either the time the packet was received or the time it was noticed the packet was missing.    
     conn->audio_buffer[i].sequence_number = 0;
   }
   conn->ab_synced = 0;
@@ -130,6 +132,36 @@ static void ab_resync(rtsp_conn_info *conn) {
   conn->ab_buffering = 1;
 }
 
+// given starting and ending points as unsigned 16-bit integers running modulo 2^16, returns the
+// position of x in the interval in *pos
+// returns true if x is actually within the buffer
+
+int position_in_modulo_uint16_t_buffer(uint16_t x, uint16_t start, uint16_t end, uint16_t *pos) {
+  int response = 0; // not in the buffer
+  if (start <= end) {
+    if (x < start) {
+      if (pos)
+        *pos = UINT16_MAX - start + 1 + x;
+    } else {
+      if (pos)
+        *pos = x - start;
+      if (x < end)
+        response = 1;
+    }
+  } else if ((x >= start)) { // && (x <= UINT16_MAX)) { // always true
+    response = 1;
+    if (pos)
+      *pos = x - start;
+  } else {
+    if (pos)
+      *pos = UINT16_MAX - start + 1 + x;
+    if (x < end) {
+      response = 1;
+    }
+  }
+  return response;
+}
+
 // given starting and ending points as unsigned 32-bit integers running modulo 2^32, returns the
 // position of x in the interval in *pos
 // returns true if x is actually within the buffer
@@ -146,7 +178,7 @@ int position_in_modulo_uint32_t_buffer(uint32_t x, uint32_t start, uint32_t end,
       if (x < end)
         response = 1;
     }
-  } else if ((x >= start) && (x <= UINT32_MAX)) {
+  } else if ((x >= start)) { // && (x <= UINT32_MAX)) { // always true
     response = 1;
     if (pos)
       *pos = x - start;
@@ -432,6 +464,8 @@ static void free_audio_buffers(rtsp_conn_info *conn) {
     free(conn->audio_buffer[i].data);
 }
 
+int first_possibly_missing_frame = -1;
+
 void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, int len,
                        rtsp_conn_info *conn) {
 
@@ -444,9 +478,10 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in
   }
 
   debug_mutex_lock(&conn->ab_mutex, 30000, 0);
+  uint64_t time_now = get_absolute_time_in_fp();
   conn->packet_count++;
   conn->packet_count_since_flush++;
-  conn->time_of_last_audio_packet = get_absolute_time_in_fp();
+  conn->time_of_last_audio_packet = time_now;
   if (conn->connection_state_to_output) { // if we are supposed to be processing these packets
 
     if ((conn->flush_rtp_timestamp != 0) && (actual_timestamp != conn->flush_rtp_timestamp) &&
@@ -496,16 +531,15 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in
 
       if (conn->ab_write ==
           seqno) { // if this is the expected packet (which could be the first packet...)
-        uint64_t reception_time = get_absolute_time_in_fp();
         if (conn->input_frame_rate_starting_point_is_valid == 0) {
           if ((conn->packet_count_since_flush >= 500) && (conn->packet_count_since_flush <= 510)) {
-            conn->frames_inward_measurement_start_time = reception_time;
+            conn->frames_inward_measurement_start_time = time_now;
             conn->frames_inward_frames_received_at_measurement_start_time = actual_timestamp;
             conn->input_frame_rate_starting_point_is_valid = 1; // valid now
           }
         }
 
-        conn->frames_inward_measurement_time = reception_time;
+        conn->frames_inward_measurement_time = time_now;
         conn->frames_inward_frames_received_at_measurement_time = actual_timestamp;
 
         abuf = conn->audio_buffer + BUFIDX(seqno);
@@ -522,8 +556,9 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in
         for (i = 0; i < gap; i++) {
           abuf = conn->audio_buffer + BUFIDX(seq_sum(conn->ab_write, i));
           abuf->ready = 0; // to be sure, to be sure
-          abuf->resend_level = 0;
-          // abuf->timestamp = 0;
+          abuf->resend_request_number = 0;
+          abuf->initialisation_time = time_now; // this represents when the packet was noticed to be missing
+          abuf->resend_time = 0;
           abuf->given_timestamp = 0;
           abuf->sequence_number = 0;
         }
@@ -553,17 +588,17 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in
 
       if (abuf) {
         int datalen = conn->max_frames_per_packet;
+        abuf->initialisation_time = time_now;
+        abuf->resend_time = 0;
         if (audio_packet_decode(abuf->data, &datalen, data, len, conn) == 0) {
           abuf->ready = 1;
           abuf->length = datalen;
-          // abuf->timestamp = ltimestamp;
           abuf->given_timestamp = actual_timestamp;
           abuf->sequence_number = seqno;
         } else {
           debug(1, "Bad audio packet detected and discarded.");
           abuf->ready = 0;
-          abuf->resend_level = 0;
-          // abuf->timestamp = 0;
+          abuf->resend_request_number = 0;
           abuf->given_timestamp = 0;
           abuf->sequence_number = 0;
         }
@@ -573,39 +608,69 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in
       int rc = pthread_cond_signal(&conn->flowcontrol);
       if (rc)
         debug(1, "Error signalling flowcontrol.");
-
-      // if it's at the expected time, do a look back for missing packets
-      // but release the ab_mutex when doing a resend
-      if (!conn->ab_buffering) {
-        int j;
-        for (j = 1; j <= number_of_resend_attempts; j++) {
-          // check j times, after a short period of has elapsed, assuming 352 frames per packet
-          // the higher the step_exponent, the less it will try. 1 means it will try very
-          // hard. 2.0 seems good.
-          float step_exponent = 2.0;
-          int back_step = (int)(resend_interval * pow(j, step_exponent));
-          int k;
-          for (k = -1; k <= 1; k++) {
-            if ((back_step + k) <
-                seq_diff(conn->ab_read, conn->ab_write,
-                         conn->ab_read)) { // if it's within the range of frames in use...
-              int item_to_check = (conn->ab_write - (back_step + k)) & 0xffff;
-              seq_t next = item_to_check;
-              abuf_t *check_buf = conn->audio_buffer + BUFIDX(next);
-              if ((!check_buf->ready) &&
-                  (check_buf->resend_level <
-                   j)) { // prevent multiple requests from the same level of lookback
-                check_buf->resend_level = j;
-                if (config.disable_resend_requests == 0) {
-                  debug_mutex_unlock(&conn->ab_mutex, 3);
-                  rtp_request_resend(next, 1, conn);
-                  conn->resend_requests++;
-                  debug_mutex_lock(&conn->ab_mutex, 20000, 1);
-                }
+      
+      // resend checks
+      {
+      	uint64_t minimum_wait_time = (uint64_t)(config.resend_wait_before_check * (uint64_t)0x100000000);
+      	uint64_t resend_repeat_interval = (uint64_t)(config.resend_wait_between_checks * (uint64_t)0x100000000);
+      	uint64_t minimum_remaining_time = (uint64_t)((config.resend_last_check_before_use + config.audio_backend_buffer_desired_length)* (uint64_t)0x100000000);
+      	uint64_t latency_time = (uint64_t)(conn->latency * (uint64_t)0x100000000);
+      	latency_time = latency_time / (uint64_t)conn->input_rate;
+      	        
+        int x;  // this is the first frame to be checked
+        // if we detected a first empty frame before and if it's still in the buffer!
+        if ((first_possibly_missing_frame >= 0) && (position_in_modulo_uint16_t_buffer(first_possibly_missing_frame, conn->ab_read, conn->ab_write, NULL))) {
+          x = first_possibly_missing_frame;
+        } else {
+          x = conn->ab_read;
+        }
+      
+      	int missing_frame_run_count = 0;
+      	int start_of_missing_frame_run = -1;
+        int number_of_missing_frames = 0;
+        debug(2,"check start");
+        while (x != conn->ab_write) {
+          abuf_t *check_buf = conn->audio_buffer + BUFIDX(x);
+          if (!check_buf->ready) {
+            number_of_missing_frames++;
+            // debug(1, "frame %u's initialisation_time is 0x%" PRIx64 ", latency_time is 0x%" PRIx64 ", time_now is 0x%" PRIx64 ", minimum_remaining_time is 0x%" PRIx64 ".", x, check_buf->initialisation_time, latency_time, time_now, minimum_remaining_time);
+            int too_late = ((check_buf->initialisation_time < (time_now - latency_time)) || ((check_buf->initialisation_time - (time_now - latency_time)) < minimum_remaining_time));
+            int too_early = ((time_now - check_buf->initialisation_time) < minimum_wait_time);
+            int too_soon_after_last_request = ((check_buf->resend_time != 0) && ((time_now - check_buf->resend_time) < resend_repeat_interval)); // time_now can never be less than the time_tag
+            if ((!too_soon_after_last_request) && (!too_late) && (!too_early)){
+              if (start_of_missing_frame_run == -1) {
+                start_of_missing_frame_run = x;
+                missing_frame_run_count = 1;
+              } else {
+                missing_frame_run_count++;
               }
+              check_buf->resend_time = time_now; // setting the time to now because we are definitely going to take action
+              check_buf->resend_request_number++;
+              debug(2,"Frame %d is missing with ab_read of %d.", x, conn->ab_read);            
             }
+            // if (too_late) {
+            //   debug(1,"too late to get missing frame %u.", x);
+            // }
+          }
+          //if (number_of_missing_frames != 0)
+          //  debug(1,"check with x = %u, ab_read = %u, ab_write = %u, first_possibly_missing_frame = %d.", x, conn->ab_read, conn->ab_write, first_possibly_missing_frame);
+          x = (x + 1) & 0xffff;
+          if (((check_buf->ready) || (x == conn->ab_write)) && (missing_frame_run_count > 0)) {
+          // send a resend request
+          	if (missing_frame_run_count > 1)
+          	  debug(2,"request resend of %d packets starting at seqno %u.", missing_frame_run_count, start_of_missing_frame_run);         
+            if (config.disable_resend_requests == 0) {
+              debug_mutex_unlock(&conn->ab_mutex, 3);
+              rtp_request_resend(start_of_missing_frame_run, missing_frame_run_count, conn);
+              debug_mutex_lock(&conn->ab_mutex, 20000, 1);
+              conn->resend_requests++;
+            }      
+            start_of_missing_frame_run = -1;
+            missing_frame_run_count = 0;
           }
         }
+        if (number_of_missing_frames == 0)
+          first_possibly_missing_frame = conn->ab_write;
       }
     }
   }
@@ -933,7 +998,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) {
                    "timestamp: %" PRIu32 ".",
                 curframe->sequence_number, curframe->given_timestamp, conn->flush_rtp_timestamp);
           curframe->ready = 0;
-          curframe->resend_level = 0;
+          curframe->resend_request_number = 0;
           curframe = NULL; // this will be returned and will cause the loop to go around again
           conn->initial_reference_time = 0;
           conn->initial_reference_timestamp = 0;
@@ -1330,7 +1395,6 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) {
       curframe->given_timestamp = 0; // indicate a silent frame should be substituted
     }
     curframe->ready = 0;
-    curframe->resend_level = 0;
   }
   conn->ab_read = SUCCESSOR(conn->ab_read);
   pthread_cleanup_pop(1);
@@ -1928,8 +1992,8 @@ void *player_thread_func(void *arg) {
         //          debug(3, "Play frame %d.", play_number);
         conn->play_number_after_flush++;
         if (inframe->given_timestamp == 0) {
-          debug(3, "Player has supplied a silent frame, (possibly frame %u) for play number %d.",
-                SUCCESSOR(conn->last_seqno_read), play_number);
+          debug(1, "Player has supplied a silent frame, (possibly frame %u) for play number %d, after %d resend requests.",
+                SUCCESSOR(conn->last_seqno_read), play_number, inframe->resend_request_number);
           conn->last_seqno_read = (SUCCESSOR(conn->last_seqno_read) &
                                    0xffff); // manage the packet out of sequence minder
 
@@ -2472,6 +2536,8 @@ void *player_thread_func(void *arg) {
           // mark the frame as finished
           inframe->given_timestamp = 0;
           inframe->sequence_number = 0;
+          inframe->resend_time = 0;
+          inframe->initialisation_time = 0;
 
           // update the watchdog
           if ((config.dont_check_timeout == 0) && (config.timeout != 0)) {

player.h

@@ -39,8 +39,9 @@ typedef uint16_t seq_t;
 
 typedef struct audio_buffer_entry { // decoded audio packets
   int ready;
-  int resend_level;
-  // int64_t timestamp;
+  uint64_t initialisation_time; // the time the packet was added or the time it was noticed the packet was missing
+  uint64_t resend_time; // time of last resend request or zero
+  int resend_request_number;
   seq_t sequence_number;
   uint32_t given_timestamp; // for debugging and checking
   signed short *data;

shairport.c

@@ -402,6 +402,9 @@ int parse_options(int argc, char **argv) {
 // i.e. when reducing volume, reduce the sw first before reducing the software.
 // this is because some hw mixers mute at the bottom of their range, and they don't always advertise
 // this fact
+  config.resend_wait_before_check = 0.10; // wait this many seconds before requesting the resending of a missing packet
+  config.resend_wait_between_checks = 0.25; // wait this many seconds before again requesting the resending of a missing packet
+  config.resend_last_check_before_use = 0.10; // give up if the packet is still missing this close to when it's needed
 
 #ifdef CONFIG_METADATA_HUB
   config.cover_art_cache_dir = "/tmp/shairport-sync/.cache/coverart";