Add some sanity checking of latency-affecting settings.

diff --git a/player.c b/player.c
index 59ff4ccc172f0f6a5bf5f36d0a245bd8865af001..dadfc48be4436503902c27fa8af7a9652ea03716 100644 (file)
--- a/player.c
+++ b/player.c
@@ -1743,6 +1743,8 @@ void *player_thread_func(void *arg) {
   int previous_frames_played_valid = 0;
 
   // pthread_cleanup_push(player_thread_initial_cleanup_handler, arg);
+  conn->latency_warning_issued =
+      0; // be permitted to generate a warning each time a play is attempted
   conn->packet_count = 0;
   conn->packet_count_since_flush = 0;
   conn->previous_random_number = 0;

diff --git a/player.h b/player.h
index 526c99f28a172af5bc320f86b5f66dee6dcf34bc..453c5f49b48c922a2caccab4b395e3b526a460ec 100644 (file)
--- a/player.h
+++ b/player.h
@@ -145,10 +145,11 @@ typedef struct flush_request_t {
 #endif
 
 typedef struct {
-  int connection_number;     // for debug ID purposes, nothing else...
-  int resend_interval;       // this is really just for debugging
-  char *UserAgent;           // free this on teardown
-  int AirPlayVersion;        // zero if not an AirPlay session. Used to help calculate latency
+  int connection_number; // for debug ID purposes, nothing else...
+  int resend_interval;   // this is really just for debugging
+  char *UserAgent;       // free this on teardown
+  int AirPlayVersion;    // zero if not an AirPlay session. Used to help calculate latency
+  int latency_warning_issued;
   uint32_t latency;          // the actual latency used for this play session
   uint32_t minimum_latency;  // set if an a=min-latency: line appears in the ANNOUNCE message; zero
                              // otherwise

diff --git a/rtp.c b/rtp.c
index 07942ae9c9b767dd6993fed0887b6c3e5d1f4aa4..c38ea96667c5bb7caecfcb7562f65ee3a3cfa2de 100644 (file)
--- a/rtp.c
+++ b/rtp.c
@@ -1668,95 +1668,118 @@ void *rtp_ap2_control_receiver(void *arg) {
       debug(1, "Discarding early timing packet.");
     }
 
-    if ((nread > 0) && (time_since_start > 10000000)) {
-      packet_number++;
-
-      if (packet_number == 1) {
-        if ((packet[0] & 0x10) != 0) {
-          debug(2, "First packet is a sentinel packet.");
-        } else {
-          debug(1, "First packet is a not a sentinel packet!");
-        }
-      }
-      // debug(1,"rtp_ap2_control_receiver coded: %u, %u", packet[0], packet[1]);
+    if (nread > 0) {
+      if ((time_since_start < 10000000) && ((packet[0] & 0x10) == 0)) {
+        debug(1,
+              "Dropping what looks like a (non-sentinel) packet left over from a previous session "
+              "at %f ms.",
+              0.000001 * time_since_start);
+      } else {
+        packet_number++;
 
-      if ((config.diagnostic_drop_packet_fraction == 0.0) ||
-          (drand48() > config.diagnostic_drop_packet_fraction)) {
-        // store the from_sock_addr if we haven't already done so
-        // v remember to zero this when you're finished!
-        if (conn->ap2_remote_control_socket_addr_length == 0) {
-          memcpy(&conn->ap2_remote_control_socket_addr, &from_sock_addr, from_sock_addr_length);
-          conn->ap2_remote_control_socket_addr_length = from_sock_addr_length;
+        if (packet_number == 1) {
+          if ((packet[0] & 0x10) != 0) {
+            debug(2, "First packet is a sentinel packet.");
+          } else {
+            debug(1, "First packet is a not a sentinel packet!");
+          }
         }
-        switch (packet[1]) {
-        case 215: // code 215, effectively an anchoring announcement
-        {
-          // struct timespec tnr;
-          // clock_gettime(CLOCK_REALTIME, &tnr);
-          // uint64_t local_realtime_now = timespec_to_ns(&tnr);
-
-          /*
-                    char obf[4096];
-                    char *obfp = obf;
-                    int obfc;
-                    for (obfc=0;obfc<nread;obfc++) {
-                      snprintf(obfp, 3, "%02X", packet[obfc]);
-                      obfp+=2;
-                    };
-                    *obfp=0;
-                    debug(1,"AP2 Timing Control Received: \"%s\"",obf);
-          */
-
-          uint64_t remote_packet_time_ns = nctoh64(packet + 8);
-          uint64_t clock_id = nctoh64(packet + 20);
-
-          // debug(1, "we have clock_id: %" PRIx64 ".", clock_id);
-          // debug(1,"remote_packet_time_ns: %" PRIx64 ", local_realtime_now_ns: %" PRIx64 ".",
-          // remote_packet_time_ns, local_realtime_now);
-          uint32_t frame_1 =
-              nctohl(packet + 4); // this seems to be the frame with latency of 77165 included
-          uint32_t frame_2 = nctohl(packet + 16); // this seems to be the frame the time refers to
-          // this just updates the anchor information contained in the packet
-          // the frame and its remote time
-          // add in the audio_backend_latency_offset;
-          int32_t notified_latency = frame_2 - frame_1;
-          int32_t added_latency = (int32_t)(config.audio_backend_latency_offset * conn->input_rate);
-          // the actual latency is the notified latency plus the fixed latency + the added latency
-
-          if (added_latency < (-(notified_latency + 11035)))
-            debug(1, "the audio_backend_latency_offset is causing a negative latency!");
+        // debug(1,"rtp_ap2_control_receiver coded: %u, %u", packet[0], packet[1]);
+
+        if ((config.diagnostic_drop_packet_fraction == 0.0) ||
+            (drand48() > config.diagnostic_drop_packet_fraction)) {
+          // store the from_sock_addr if we haven't already done so
+          // v remember to zero this when you're finished!
+          if (conn->ap2_remote_control_socket_addr_length == 0) {
+            memcpy(&conn->ap2_remote_control_socket_addr, &from_sock_addr, from_sock_addr_length);
+            conn->ap2_remote_control_socket_addr_length = from_sock_addr_length;
+          }
+          switch (packet[1]) {
+          case 215: // code 215, effectively an anchoring announcement
+          {
+            // struct timespec tnr;
+            // clock_gettime(CLOCK_REALTIME, &tnr);
+            // uint64_t local_realtime_now = timespec_to_ns(&tnr);
+
+            /*
+                      char obf[4096];
+                      char *obfp = obf;
+                      int obfc;
+                      for (obfc=0;obfc<nread;obfc++) {
+                        snprintf(obfp, 3, "%02X", packet[obfc]);
+                        obfp+=2;
+                      };
+                      *obfp=0;
+                      debug(1,"AP2 Timing Control Received: \"%s\"",obf);
+            */
+
+            uint64_t remote_packet_time_ns = nctoh64(packet + 8);
+            uint64_t clock_id = nctoh64(packet + 20);
+
+            // debug(1, "we have clock_id: %" PRIx64 ".", clock_id);
+            // debug(1,"remote_packet_time_ns: %" PRIx64 ", local_realtime_now_ns: %" PRIx64 ".",
+            // remote_packet_time_ns, local_realtime_now);
+            uint32_t frame_1 =
+                nctohl(packet + 4); // this seems to be the frame with latency of 77165 included
+            uint32_t frame_2 = nctohl(packet + 16); // this seems to be the frame the time refers to
+            // this just updates the anchor information contained in the packet
+            // the frame and its remote time
+            // add in the audio_backend_latency_offset;
+            int32_t notified_latency = frame_2 - frame_1;
+            int32_t added_latency =
+                (int32_t)(config.audio_backend_latency_offset * conn->input_rate);
+            // the actual latency is the notified latency plus the fixed latency + the added latency
+
+            int32_t net_latency =
+                notified_latency + 11035 +
+                added_latency; // this is the latency between incoming frames and the DAC
+            net_latency = net_latency -
+                          (int32_t)(config.audio_backend_buffer_desired_length * conn->input_rate);
+            // debug(1, "Net latency is %d frames.", net_latency);
+
+            if (net_latency <= 0) {
+              if (conn->latency_warning_issued == 0) {
+                warn("The stream latency (%f seconds) it too short to accommodate an offset of %f seconds and a backend buffer of %f seconds.", ((notified_latency + 11035) * 1.0)/conn->input_rate, config.audio_backend_latency_offset, config.audio_backend_buffer_desired_length);
+                warn("(FYI the stream latency needed would be %f seconds.)", config.audio_backend_buffer_desired_length - config.audio_backend_latency_offset);
+                conn->latency_warning_issued = 1;
+              }
+              conn->latency = notified_latency + 11035;
+            } else {
+              conn->latency = notified_latency + 11035 + added_latency;
+            }
 
-          /*
-          debug_mutex_lock(&conn->reference_time_mutex, 1000, 0);
-          conn->remote_reference_timestamp_time = remote_packet_time_ns;
-          conn->reference_timestamp =
-              frame_1 - 11035 - added_latency; // add the latency in to the anchortime
-          debug_mutex_unlock(&conn->reference_time_mutex, 0);
-          */
-          // this is now only used for calculating when to ask for resends
-          conn->latency = notified_latency + 11035 + added_latency;
-          // debug(1,"conn->latency is %d.", conn->latency);
-          set_ptp_anchor_info(conn, clock_id, frame_1 - 11035 - added_latency,
-                              remote_packet_time_ns);
-
-        } break;
-        case 0xd6:
-          // six bytes in is the sequence number at the start of the encrypted audio packet
-          // returns the sequence number but we're not really interested
-          decipher_player_put_packet(packet + 6, nread - 6, conn);
-          break;
-        default: {
-          char *packet_in_hex_cstring =
-              debug_malloc_hex_cstring(packet, nread); // remember to free this afterwards
-          debug(1,
+            /*
+            debug_mutex_lock(&conn->reference_time_mutex, 1000, 0);
+            conn->remote_reference_timestamp_time = remote_packet_time_ns;
+            conn->reference_timestamp =
+                frame_1 - 11035 - added_latency; // add the latency in to the anchortime
+            debug_mutex_unlock(&conn->reference_time_mutex, 0);
+            */
+            // this is now only used for calculating when to ask for resends
+            // debug(1, "conn->latency is %d.", conn->latency);
+            set_ptp_anchor_info(conn, clock_id, frame_1 - 11035 - added_latency,
+                                remote_packet_time_ns);
+
+          } break;
+          case 0xd6:
+            // six bytes in is the sequence number at the start of the encrypted audio packet
+            // returns the sequence number but we're not really interested
+            decipher_player_put_packet(packet + 6, nread - 6, conn);
+            break;
+          default: {
+            char *packet_in_hex_cstring =
+                debug_malloc_hex_cstring(packet, nread); // remember to free this afterwards
+            debug(
+                1,
                 "AP2 Control Receiver Packet of first byte 0x%02X, type 0x%02X length %d received: "
                 "\"%s\".",
                 packet[0], packet[1], nread, packet_in_hex_cstring);
-          free(packet_in_hex_cstring);
-        } break;
+            free(packet_in_hex_cstring);
+          } break;
+          }
+        } else {
+          debug(1, "AP2 Control Receiver -- dropping a packet.");
         }
-      } else {
-        debug(1, "AP2 Control Receiver -- dropping a packet.");
       }
     } else if (nread == 0) {
       debug(1, "AP2 Control Receiver -- connection closed.");