nils/shairport-sync
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Improve NQPTP clock diagnostics, tidy up some messages.

Browse Source
This commit is contained in:
Mike Brady
2021-05-10 14:16:57 +01:00
parent 829ea399fc
commit 04c7f84564
5 changed files with 113 additions and 82 deletions
Download Patch File Download Diff File Expand all files Collapse all files
player.c
+3 -4
View File
@@ -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);
player.h
+15 -1
View File
@@ -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...
ptp-utilities.c
+13 -33
View File
@@ -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;
}
rtp.c
+78 -40
View File
@@ -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 response = ptp_get_clock_info(&actual_clock_id, &actual_offset);
int ptp_status = 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);
rtsp.c
+4 -4
View File
@@ -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 {