From: Mike Brady <4265913+mikebrady@users.noreply.github.com>
Date: Mon, 10 May 2021 13:16:57 +0000 (+0100)
Subject: Improve NQPTP clock diagnostics, tidy up some messages.
X-Git-Tag: 4.0-dev~19
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=04c7f84564b2d8ff1fd30182573ad89b1aab2e24;p=thirdparty%2Fshairport-sync.git

Improve NQPTP clock diagnostics, tidy up some messages.
---

diff --git a/player.c b/player.c
index 754d30d1..69172e3f 100644
--- a/player.c
+++ b/player.c
@@ -1593,8 +1593,7 @@ void player_thread_cleanup_handler(void *arg) {
     debug(2, "Cancelling AP2 timing, control and audio threads...");
 
     if (conn->airplay_stream_type == realtime_stream) {
-      debug(2, "Connection %d: Delete Realtime Audio Stream thread",
-            conn->connection_number);
+      debug(2, "Connection %d: Delete Realtime Audio Stream thread", conn->connection_number);
       pthread_cancel(conn->rtp_realtime_audio_thread);
       pthread_join(conn->rtp_realtime_audio_thread, NULL);
 
@@ -1613,9 +1612,9 @@ void player_thread_cleanup_handler(void *arg) {
     pthread_join(conn->rtp_ap2_control_thread, NULL);
 
   } else {
-    debug(1, "Cancelling AP1-compatible timing, control and audio threads...");
+    debug(2, "Cancelling AP1-compatible timing, control and audio threads...");
 #else
-    debug(2, "Cancelling AP1 timing, control and audio threads...");
+  debug(2, "Cancelling AP1 timing, control and audio threads...");
 #endif
     debug(3, "Cancel timing thread.");
     pthread_cancel(conn->rtp_timing_thread);
diff --git a/player.h b/player.h
index 25003e5b..eb210ae5 100644
--- a/player.h
+++ b/player.h
@@ -33,7 +33,6 @@
 #define time_ping_history                                                                          \
   (1 << time_ping_history_power_of_two) // 2^7 is 128. At 1 per three seconds, approximately six
                                         // minutes of records
-
 typedef struct time_ping_record {
   uint64_t dispersion;
   uint64_t local_time;
@@ -42,6 +41,19 @@ typedef struct time_ping_record {
   int chosen;
 } time_ping_record;
 
+// these are for reporting the status of the clock
+typedef enum {
+  clock_no_anchor_info,
+  clock_ok,
+  clock_service_unavailable,
+  clock_access_error,
+  clock_data_unavailable,
+  clock_no_master,
+  clock_version_mismatch,
+  clock_not_synchronised,
+  clock_not_valid
+} clock_status_t;
+
 typedef uint16_t seq_t;
 
 typedef struct audio_buffer_entry { // decoded audio packets
@@ -258,6 +270,8 @@ typedef struct {
   uint64_t anchor_time; // this is the time according to the clock
   uint32_t anchor_rtptime;
 
+  clock_status_t clock_status;
+
 #ifdef CONFIG_AIRPLAY_2
   airplay_t airplay_type; // are we using AirPlay 1 or AirPlay 2 protocol on this connection?
   airplay_stream_t airplay_stream_type; // is it realtime audio or buffered audio...
diff --git a/ptp-utilities.c b/ptp-utilities.c
index 01d32c58..8dd412dc 100644
--- a/ptp-utilities.c
+++ b/ptp-utilities.c
@@ -42,8 +42,6 @@
 int shm_fd;
 void *mapped_addr = NULL;
 
-int failure_message_sent = 0;
-
 static pthread_mutex_t ptp_access_mutex = PTHREAD_MUTEX_INITIALIZER;
 
 // returns a copy of the shared memory data from the nqptp
@@ -63,9 +61,8 @@ int get_nqptp_data(struct shm_structure *nqptp_data) {
 }
 
 int ptp_get_clock_info(uint64_t *actual_clock_id, uint64_t *raw_offset) {
-  int response = -1;
+  int response = clock_ok;
   pthread_cleanup_debug_mutex_lock(&ptp_access_mutex, 10000, 1);
-  // 0 -> valid and working; -1 -> can't connect to nqptp
   if (actual_clock_id != NULL)
     *actual_clock_id = 0;
   if (raw_offset != NULL)
@@ -81,39 +78,28 @@ int ptp_get_clock_info(uint64_t *actual_clock_id, uint64_t *raw_offset) {
             *actual_clock_id = nqptp_data.master_clock_id;
           if (raw_offset != NULL)
             *raw_offset = nqptp_data.local_to_master_time_offset;
-          response = 0;
         } else {
-          debug(1, "clock not valid");
-          response = -2; // clock info not valid
+          response = clock_no_master;
         }
       } else {
-        if (failure_message_sent == 0) {
-          warn("This version of Shairport Sync requires an NQPTP with a Shared Memory Interface "
-               "Version %u, but the installed version is %u. Please install the correct version of "
-               "NQPTP.",
-               NQPTP_SHM_STRUCTURES_VERSION, nqptp_data.version);
-          failure_message_sent = 1;
-        }
+        response = clock_version_mismatch;
       }
+    } else {
+      response = clock_data_unavailable;
     }
-    if (response != -1)
-      response = ptp_shm_interface_close();
+    if (ptp_shm_interface_close() != 0)
+      response = clock_access_error;
   } else {
-    if (failure_message_sent == 0) {
-      warn("Can't open the interface to nqptp. Is the service running?");
-      failure_message_sent = 1;
-    }
+    response = clock_service_unavailable;
   }
   pthread_cleanup_pop(1); // release the mutex
-  if (response == 0)
-    failure_message_sent = 0;
   return response;
 }
 
 int ptp_shm_interface_open() {
   mapped_addr = NULL;
   int shared_memory_file_descriptor = shm_open("/nqptp", O_RDWR, 0);
-  int response = -1;
+  int response = 0;
   if (shared_memory_file_descriptor >= 0) {
     mapped_addr =
         // needs to be PROT_READ | PROT_WRITE to allow the mapped memory to be writable for the
@@ -121,19 +107,13 @@ int ptp_shm_interface_open() {
         mmap(NULL, sizeof(struct shm_structure), PROT_READ | PROT_WRITE, MAP_SHARED,
              shared_memory_file_descriptor, 0);
     if (mapped_addr == MAP_FAILED) {
-      if (failure_message_sent == 0) {
-        debug(1, "unable to open the shared memory interface with nqptp. Is the service running?");
-        failure_message_sent = 1;
-      }
+      response = -1;
     }
     if (close(shared_memory_file_descriptor) == -1) {
-      if (failure_message_sent == 0) {
-        debug(1, "error closing \"/nqptp\" after mapping it.");
-        failure_message_sent = 1;
-      }
-    } else {
-      response = 0;
+      response = -1;
     }
+  } else {
+    response = -1;
   }
   return response;
 }
diff --git a/rtp.c b/rtp.c
index 8877285d..1cc3b084 100644
--- a/rtp.c
+++ b/rtp.c
@@ -255,7 +255,7 @@ void *rtp_audio_receiver(void *arg) {
 }
 
 void rtp_control_handler_cleanup_handler(__attribute__((unused)) void *arg) {
-  debug(1, "Control Receiver Cleanup Done.");
+  debug(2, "Control Receiver Cleanup Done.");
 }
 
 void *rtp_control_receiver(void *arg) {
@@ -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 "
@@ -1226,13 +1226,13 @@ void reset_ptp_anchor_info(rtsp_conn_info *conn) {
 
 int get_ptp_anchor_local_time_info(rtsp_conn_info *conn, uint32_t *anchorRTP,
                                    uint64_t *anchorLocalTime) {
-  int response = 0;
-  uint64_t actual_clock_id, actual_offset;
 
-  int ptp_status = ptp_get_clock_info(&actual_clock_id, &actual_offset);
+  uint64_t actual_clock_id, actual_offset;
+  int response = ptp_get_clock_info(&actual_clock_id, &actual_offset);
 
-  if (ptp_status == 0) {
-    if (conn->anchor_remote_info_is_valid != 0) {
+  if (response == clock_ok) {
+    if (conn->anchor_remote_info_is_valid !=
+        0) { // i.e. if we have anchor clock ID and anchor time / rtptime
       if (actual_clock_id == conn->anchor_clock) {
         conn->last_anchor_clock_offset = actual_offset;
         conn->last_anchor_time_of_update = get_absolute_time_in_ns();
@@ -1263,29 +1263,60 @@ int get_ptp_anchor_local_time_info(rtsp_conn_info *conn, uint32_t *anchorRTP,
               *anchorLocalTime = conn->anchor_time - conn->last_anchor_clock_offset;
           }
         } else {
-          debug(2, "no clock and no old anchor times");
-          response = -1;
+          response = clock_not_valid; // no current clock information and no previous clock info
         }
       }
     } else {
-      debug(2, "don't have anchor_remote_time_info");
-      response = -1;
+      response = clock_no_anchor_info; // no anchor information
     }
-  } else if (ptp_status == -1) {
-    debug(3, "don't have the ptp clock interface");
-    response = -1;
-  } else if (ptp_status == -2) {
-    debug(1, "ptp clock not valid");
-    response = -1;
-  } else {
-    debug(3, "ptp clock error");
-    response = -1;
+  }
+
+  // here, check and update the clock status
+  if ((clock_status_t)response != conn->clock_status) {
+    switch (response) {
+    case clock_ok:
+      debug(1, "Connection %d: NQPTP clock is valid and available.", conn->connection_number);
+      break;
+    case clock_service_unavailable:
+      debug(1, "Connection %d: NQPTP clock is not available.", conn->connection_number);
+      warn("Can't access the NQPTP clock. Is NQPTP running?");
+      break;
+    case clock_access_error:
+      debug(1, "Connection %d: Error accessing the NQPTP clock interface.",
+            conn->connection_number);
+      break;
+    case clock_data_unavailable:
+      debug(1, "Connection %d: Can not access NQPTP clock information.", conn->connection_number);
+      break;
+    case clock_no_master:
+      debug(1, "Connection %d: No NQPTP master clock.", conn->connection_number);
+      break;
+    case clock_no_anchor_info:
+      debug(1, "Connection %d: No Clock Anchor.", conn->connection_number);
+      break;
+    case clock_version_mismatch:
+      debug(1, "Connection %d: NQPTP clock interface mismatch.", conn->connection_number);
+      warn("This version of Shairport Sync is not compatible with the installed version of NQPTP. "
+           "Please update.");
+      break;
+    case clock_not_synchronised:
+      debug(1, "Connection %d: NQPTP clock is not synchronised.", conn->connection_number);
+      break;
+    case clock_not_valid:
+      debug(1, "Connection %d: NQPTP clock information is not valid.", conn->connection_number);
+      break;
+    default:
+      debug(3, "Connection %d: NQPTP clock reports an unrecognised status: %u.",
+            conn->connection_number, response);
+      break;
+    }
+    conn->clock_status = response;
   }
   return response;
 }
 
 int have_ptp_timing_information(rtsp_conn_info *conn) {
-  if (get_ptp_anchor_local_time_info(conn, NULL, NULL) == 0)
+  if (get_ptp_anchor_local_time_info(conn, NULL, NULL) == clock_ok)
     return 1;
   else
     return 0;
@@ -1295,7 +1326,7 @@ int frame_to_ptp_local_time(uint32_t timestamp, uint64_t *time, rtsp_conn_info *
   int result = -1;
   uint32_t anchor_rtptime;
   uint64_t anchor_local_time;
-  if (get_ptp_anchor_local_time_info(conn, &anchor_rtptime, &anchor_local_time) == 0) {
+  if (get_ptp_anchor_local_time_info(conn, &anchor_rtptime, &anchor_local_time) == clock_ok) {
     int32_t frame_difference = timestamp - anchor_rtptime;
     int64_t time_difference = frame_difference;
     time_difference = time_difference * 1000000000;
@@ -1313,7 +1344,7 @@ int local_ptp_time_to_frame(uint64_t time, uint32_t *frame, rtsp_conn_info *conn
   int result = -1;
   uint32_t anchor_rtptime;
   uint64_t anchor_local_time;
-  if (get_ptp_anchor_local_time_info(conn, &anchor_rtptime, &anchor_local_time) == 0) {
+  if (get_ptp_anchor_local_time_info(conn, &anchor_rtptime, &anchor_local_time) == clock_ok) {
     int64_t time_difference = time - anchor_local_time;
     int64_t frame_difference = time_difference;
     frame_difference = frame_difference * conn->input_rate; // but this is by 10^9
@@ -1355,8 +1386,9 @@ void *rtp_event_receiver(void *arg) {
     if (nread < 0) {
       char errorstring[1024];
       strerror_r(errno, (char *)errorstring, sizeof(errorstring));
-      debug(1, "Connection %d: error in ap2 rtp_event_receiver %d: \"%s\". Could not recv a packet.", conn->connection_number, errno,
-            errorstring);
+      debug(1,
+            "Connection %d: error in ap2 rtp_event_receiver %d: \"%s\". Could not recv a packet.",
+            conn->connection_number, errno, errorstring);
       // if ((config.diagnostic_drop_packet_fraction == 0.0) ||
       //     (drand48() > config.diagnostic_drop_packet_fraction)) {
     } else if (nread > 0) {
@@ -1364,11 +1396,15 @@ void *rtp_event_receiver(void *arg) {
       // ssize_t plen = nread;
       debug(1, "Packet Received on Event Port.");
       if (packet[1] == 0xD7) {
-        debug(1, "Connection %d: AP2 Event Receiver -- Time Announce RTP packet of type 0x%02X length %d received.", conn->connection_number,
-              packet[1], nread);
+        debug(1,
+              "Connection %d: AP2 Event Receiver -- Time Announce RTP packet of type 0x%02X length "
+              "%d received.",
+              conn->connection_number, packet[1], nread);
       } else {
-        debug(1, "Connection %d: AP2 Event Receiver -- Unknown RTP packet of type 0x%02X length %d received.", conn->connection_number,
-              packet[1], nread);
+        debug(1,
+              "Connection %d: AP2 Event Receiver -- Unknown RTP packet of type 0x%02X length %d "
+              "received.",
+              conn->connection_number, packet[1], nread);
       }
       // } else {
       //   debug(3, "Event Receiver Thread -- dropping incoming packet to simulate a bad network.");
@@ -1377,7 +1413,8 @@ void *rtp_event_receiver(void *arg) {
       finished = 1;
     }
   } while (finished == 0);
-  debug(1, "Connection %d: AP2 Event Receiver RTP thread \"normal\" exit.", conn->connection_number);
+  debug(1, "Connection %d: AP2 Event Receiver RTP thread \"normal\" exit.",
+        conn->connection_number);
   pthread_cleanup_pop(1); // close the socket
 
   pthread_cleanup_pop(1); // do the cleanup
@@ -1680,7 +1717,7 @@ ssize_t buffered_read(buffered_tcp_desc *descriptor, void *buf, size_t count) {
 #define STANDARD_PACKET_SIZE 4096
 
 void buffered_tcp_reader_cleanup_handler(__attribute__((unused)) void *arg) {
-  debug(1, "Buffered TCP Reader Thread Exit via Cleanup.");
+  debug(2, "Buffered TCP Reader Thread Exit via Cleanup.");
 }
 
 void *buffered_tcp_reader(void *arg) {
@@ -1850,11 +1887,11 @@ void addADTStoPacket(uint8_t *packet, int packetLen) {
 }
 
 void rtp_buffered_audio_cleanup_handler(__attribute__((unused)) void *arg) {
-  debug(1, "Buffered Audio Receiver Cleanup Start.");
+  debug(2, "Buffered Audio Receiver Cleanup Start.");
   rtsp_conn_info *conn = (rtsp_conn_info *)arg;
   close(conn->buffered_audio_socket);
   conn->buffered_audio_socket = 0;
-  debug(1, "Buffered Audio Receiver Cleanup Done.");
+  debug(2, "Buffered Audio Receiver Cleanup Done.");
 }
 
 void *rtp_buffered_audio_processor(void *arg) {
@@ -2094,7 +2131,8 @@ void *rtp_buffered_audio_processor(void *arg) {
               if ((lead_time >= (int64_t)(reqested_lead_time * 1000000000)) ||
                   (streaming_has_started == 1)) {
                 if (streaming_has_started == 0)
-                  debug(2, "Connection %d: buffered audio lead time is %f seconds.", 0.000000001 * lead_time);
+                  debug(2, "Connection %d: buffered audio lead time is %f seconds.",
+                        0.000000001 * lead_time);
                 streaming_has_started = 1;
                 player_put_packet(0, 0, pcm_buffer_read_point_rtptime,
                                   pcm_buffer + pcm_buffer_read_point, 352, conn);
diff --git a/rtsp.c b/rtsp.c
index c82c6bd7..3f216eea 100644
--- a/rtsp.c
+++ b/rtsp.c
@@ -1395,7 +1395,7 @@ void handle_setrateanchori(rtsp_conn_info *conn, rtsp_message *req, rtsp_message
         debug(2, "Connection %d: Start playing.", conn->connection_number);
         conn->ap2_play_enabled = 1;
       } else {
-        debug(1, "Connection %d: Stop playing.", conn->connection_number);
+        debug(2, "Connection %d: Stop playing.", conn->connection_number);
         conn->ap2_play_enabled = 0;
         // not sure this is needed yet
         reset_anchor_info(conn); // needed if the player resumes
@@ -1934,7 +1934,7 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp)
       conn->input_num_channels = conn->stream.fmtp[7];
       conn->input_bit_depth = conn->stream.fmtp[3];
       conn->input_bytes_per_frame = conn->input_num_channels * ((conn->input_bit_depth + 7) / 8);
-      debug(1, "Realtime Stream Play");
+      debug(2, "Realtime Stream Play");
       if (conn->ap2_timing_peer_list_message)
         ptp_send_control_message_string(conn->ap2_timing_peer_list_message);
       else
@@ -2215,7 +2215,7 @@ void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) {
             msg_add_header(resp, "Session", "1");
 
             resp->respcode = 200; // it all worked out okay
-            debug(1,
+            debug(2,
                   "Connection %d: SETUP DACP-ID \"%s\" from %s to %s with UDP ports Control: "
                   "%d, Timing: %d and Audio: %d.",
                   conn->connection_number, conn->dacp_id, &conn->client_ip_string,
@@ -4239,7 +4239,7 @@ void *rtsp_listen_loop(__attribute((unused)) void *arg) {
           inet_ntop(conn->connection_ip_family, self_addr, conn->self_ip_string,
                     sizeof(conn->self_ip_string));
 
-          debug(1, "Connection %d: new connection from %s:%u to self at %s:%u.",
+          debug(2, "Connection %d: new connection from %s:%u to self at %s:%u.",
                 conn->connection_number, conn->client_ip_string, conn->client_rtsp_port,
                 conn->self_ip_string, conn->self_rtsp_port);
         } else {