From c40d1ad53c6b4256ed0cb52e9be529f05489162b Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Thu, 12 Apr 2018 22:47:42 +0100 Subject: [PATCH 1/8] Change the order of port allocation in rtp setup. Change some debug weights. --- player.c | 6 +++--- rtp.c | 27 ++++++++++++++++----------- 2 files changed, 19 insertions(+), 14 deletions(-) diff --git a/player.c b/player.c index 3552410a..43a5b5ef 100644 --- a/player.c +++ b/player.c @@ -1666,11 +1666,11 @@ static void *player_thread_func(void *arg) { inbuflength = inframe->length; if (inbuf) { play_number++; - if (play_number % 100 == 0) - debug(3, "Play frame %d.", play_number); +// if (play_number % 100 == 0) +// debug(3, "Play frame %d.", play_number); conn->play_number_after_flush++; if (inframe->timestamp == 0) { - debug(3, "Player has a supplied silent frame."); + debug(1, "Player has a supplied silent frame."); conn->last_seqno_read = (SUCCESSOR(conn->last_seqno_read) & 0xffff); // manage the packet out of sequence minder config.output->play(silence, conn->max_frames_per_packet * conn->output_sample_ratio); diff --git a/rtp.c b/rtp.c index 8168de14..a6d69933 100644 --- a/rtp.c +++ b/rtp.c @@ -137,15 +137,20 @@ void *rtp_audio_receiver(void *arg) { } seq_t seqno = ntohs(*(uint16_t *)(pktp + 2)); // increment last_seqno and see if it's the same as the incoming seqno - - if (last_seqno == -1) - last_seqno = seqno; - else { - last_seqno = (last_seqno + 1) & 0xffff; - // if (seqno != last_seqno) - // debug(3, "RTP: Packets out of sequence: expected: %d, got %d.", last_seqno, seqno); + + if ( type==0x60) { // regular audio data + if (last_seqno == -1) + last_seqno = seqno; + else { + last_seqno = (last_seqno + 1) & 0xffff; + // if (seqno != last_seqno) + // debug(3, "RTP: Packets out of sequence: expected: %d, got %d.", last_seqno, seqno); last_seqno = seqno; // reset warning... + } + } else { + debug(1, "Audio Port -- Retransmitted Audio Data Packet %u received.",seqno); } + int64_t timestamp = monotonic_timestamp(ntohl(*(uint32_t *)(pktp + 4)), conn); // if (packet[1]&0x10) @@ -345,10 +350,10 @@ void *rtp_control_receiver(void *arg) { debug(1, "Sync packet received before we got a timing packet back."); } } else if (packet[1] == 0xd6) { // resent audio data in the control path -- whaale only? - // debug(1, "Control Port -- Retransmitted Audio Data Packet received."); pktp = packet + 4; plen -= 4; seq_t seqno = ntohs(*(uint16_t *)(pktp + 2)); + debug(1, "Control Port -- Retransmitted Audio Data Packet %u received.",seqno); int64_t timestamp = monotonic_timestamp(ntohl(*(uint32_t *)(pktp + 4)), conn); @@ -851,12 +856,12 @@ void rtp_setup(SOCKADDR *local, SOCKADDR *remote, uint16_t cport, uint16_t tport conn->remote_control_port = cport; conn->remote_timing_port = tport; - conn->local_audio_port = bind_port(conn->connection_ip_family, conn->self_ip_string, - conn->self_scope_id, &conn->audio_socket); conn->local_control_port = bind_port(conn->connection_ip_family, conn->self_ip_string, conn->self_scope_id, &conn->control_socket); conn->local_timing_port = bind_port(conn->connection_ip_family, conn->self_ip_string, conn->self_scope_id, &conn->timing_socket); + conn->local_audio_port = bind_port(conn->connection_ip_family, conn->self_ip_string, + conn->self_scope_id, &conn->audio_socket); debug(2, "listening for audio, control and timing on ports %d, %d, %d.", conn->local_audio_port, conn->local_control_port, conn->local_timing_port); @@ -899,7 +904,7 @@ void clear_reference_timestamp(rtsp_conn_info *conn) { void rtp_request_resend(seq_t first, uint32_t count, rtsp_conn_info *conn) { if (conn->rtp_running) { // if (!request_sent) { - debug(3, "requesting resend of %d packets starting at %u.", count, first); + debug(1, "requesting resend of %d packets starting at %u.", count, first); // request_sent = 1; //} From d9c9009ff2c9f6a5d0ac43c759c1ad679c3856a7 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 13 Apr 2018 09:58:05 +0100 Subject: [PATCH 2/8] Add the ability to pseudo-randomly drop audio packets to simiulate a noisy network. --- common.h | 3 ++- rtp.c | 19 ++++++++++++------- scripts/shairport-sync.conf | 1 + shairport.c | 23 ++++++++++++++++++++--- 4 files changed, 35 insertions(+), 11 deletions(-) diff --git a/common.h b/common.h index 50b7a0fe..063f467d 100644 --- a/common.h +++ b/common.h @@ -183,7 +183,8 @@ typedef struct { // (about 15 minutes worth) #endif int disable_resend_requests; // set this to stop resend request being made for missing packets - + double diagnostic_drop_packet_fraction; // pseudo randomly drop this fraction of packets, for + // debugging. Currently audio packets only... } shairport_cfg; uint32_t nctohl(const uint8_t *p); // read 4 characters from *p and do ntohl on them diff --git a/rtp.c b/rtp.c index a6d69933..15cdb53f 100644 --- a/rtp.c +++ b/rtp.c @@ -39,6 +39,7 @@ #include #include #include +#include #include #include #include @@ -137,20 +138,20 @@ void *rtp_audio_receiver(void *arg) { } seq_t seqno = ntohs(*(uint16_t *)(pktp + 2)); // increment last_seqno and see if it's the same as the incoming seqno - - if ( type==0x60) { // regular audio data + + if (type == 0x60) { // regular audio data if (last_seqno == -1) last_seqno = seqno; else { last_seqno = (last_seqno + 1) & 0xffff; // if (seqno != last_seqno) // debug(3, "RTP: Packets out of sequence: expected: %d, got %d.", last_seqno, seqno); - last_seqno = seqno; // reset warning... + last_seqno = seqno; // reset warning... } } else { - debug(1, "Audio Port -- Retransmitted Audio Data Packet %u received.",seqno); + debug(1, "Audio Port -- Retransmitted Audio Data Packet %u received.", seqno); } - + int64_t timestamp = monotonic_timestamp(ntohl(*(uint32_t *)(pktp + 4)), conn); // if (packet[1]&0x10) @@ -161,7 +162,11 @@ void *rtp_audio_receiver(void *arg) { // check if packet contains enough content to be reasonable if (plen >= 16) { - player_put_packet(seqno, timestamp, pktp, plen, conn); + if ((config.diagnostic_drop_packet_fraction == 0.0) || + (drand48() > config.diagnostic_drop_packet_fraction)) + player_put_packet(seqno, timestamp, pktp, plen, conn); + else + debug(3, "Dropping audio packet %u to simulate a bad connection.", seqno); continue; } if (type == 0x56 && seqno == 0) { @@ -353,7 +358,7 @@ void *rtp_control_receiver(void *arg) { pktp = packet + 4; plen -= 4; seq_t seqno = ntohs(*(uint16_t *)(pktp + 2)); - debug(1, "Control Port -- Retransmitted Audio Data Packet %u received.",seqno); + debug(1, "Control Port -- Retransmitted Audio Data Packet %u received.", seqno); int64_t timestamp = monotonic_timestamp(ntohl(*(uint32_t *)(pktp + 4)), conn); diff --git a/scripts/shairport-sync.conf b/scripts/shairport-sync.conf index 02c81e39..be48f08b 100644 --- a/scripts/shairport-sync.conf +++ b/scripts/shairport-sync.conf @@ -152,4 +152,5 @@ diagnostics = // log_verbosity = 0; // "0" means no debug verbosity, "3" is most verbose. // log_show_time_since_startup = "no"; // set this to yes if you want the time since startup in the debug message -- seconds down to nanoseconds // log_show_time_since_last_message = "no"; // set this to yes if you want the time since the last debug message in the debug message -- seconds down to nanoseconds +// drop_this_fraction_of_audio_packets = 0.0; // use this to simulate a noisy network where this fraction of UDP packets are lost in transmission. E.g. a value of 0.01 would mean an average of 1% of packets are lost. Audio packets only. }; diff --git a/shairport.c b/shairport.c index bdc2817b..13e6bff8 100644 --- a/shairport.c +++ b/shairport.c @@ -31,12 +31,12 @@ #include #include #include -#include #include #include #include #include #include +#include #include #include #include @@ -333,6 +333,8 @@ int parse_options(int argc, char **argv) { config.airplay_volume = -18.0; // if no volume is ever set, default to initial default value if // nothing else comes in first. config.fixedLatencyOffset = 11025; // this sounds like it works properly. + config.diagnostic_drop_packet_fraction = 0.0; + #ifdef HAVE_METADATA_HUB config.cover_art_cache_dir = "/tmp/shairport-sync/.cache/coverart"; config.scan_interval_when_active = @@ -563,6 +565,19 @@ int parse_options(int argc, char **argv) { "or \"no\""); } + /* Get the drop packets setting. */ + if (config_lookup_float(config.cfg, "diagnostics.drop_this_fraction_of_audio_packets", + &dvalue)) { + if ((dvalue >= 0.0) && (dvalue <= 3.0)) + config.diagnostic_drop_packet_fraction = dvalue; + else + die("Invalid diagnostics drop_this_fraction_of_audio_packets setting \"%d\". It should " + "be " + "between 0.0 and 1.0, " + "inclusive.", + dvalue); + } + /* Get the ignore_volume_control setting. */ if (config_lookup_string(config.cfg, "general.ignore_volume_control", &str)) { if (strcasecmp(str, "no") == 0) @@ -1425,8 +1440,10 @@ int main(int argc, char **argv) { #endif debug(1, "loudness is %d.", config.loudness); debug(1, "loudness reference level is %f", config.loudness_reference_volume_db); - debug(1, "disable resend requests is %d -- non-zero means \"yes\"", - config.disable_resend_requests); + debug(1, "disable resend requests is %s.", config.disable_resend_requests ? "on" : "off"); + debug(1, "diagnostic_drop_packet_fraction is %f. A value of 0.0 means no packets will be dropped " + "deliberately.", + config.diagnostic_drop_packet_fraction); uint8_t ap_md5[16]; From 269dffacb45b676c4544f6033e3ca2f3cef07ed1 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 13 Apr 2018 09:58:31 +0100 Subject: [PATCH 3/8] Add the ability to pseudo-randomly drop audio packets to simiulate a noisy network. --- configure.ac | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/configure.ac b/configure.ac index 76a7b832..b3a47064 100644 --- 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], [3.2d38], [mikebrady@eircom.net]) +AC_INIT([shairport-sync], [3.2d39], [mikebrady@eircom.net]) AM_INIT_AUTOMAKE AC_CONFIG_SRCDIR([shairport.c]) AC_CONFIG_HEADERS([config.h]) From ce4495fa1480240aa2cf95567bc25f6d480ae256 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 13 Apr 2018 10:06:42 +0100 Subject: [PATCH 4/8] Update RELEASENOTES.md --- RELEASENOTES.md | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/RELEASENOTES.md b/RELEASENOTES.md index d13fa8f8..b6607556 100644 --- a/RELEASENOTES.md +++ b/RELEASENOTES.md @@ -1,3 +1,9 @@ +Version 3.2d39 +==== +**Enhancements** +* An extra diagnostic to artificially drop audio packets to simulate a noisy network has been added. Set the proportion of packets to be dropped in the `diagnostics` section of the configuration file using the tag `drop_this_fraction_of_audio_packets`. The value should be between 0.0 and 1.0. E.g. a value of 0.001 would mean one packet in a thousand would be dropped, on average. Look in the sample configuration file `/etc/shairport-sync.conf.sample` for the added entry. +* Compatibility with AirAudio has been added / restored. + Version 3.2d35 ==== **Enhancements** From e76a6366683d4346e54a9a7fd91daa1dd8afe5b5 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sat, 14 Apr 2018 13:01:42 +0100 Subject: [PATCH 5/8] Fix serious and long-standing bugs in the control, audio and timing threads that could be responsible for low resilience on noisy and unrealiable networks. Add ability to simiulate UDP receive and send failures on timing, control and audio ports. Significantly improve resend requesting and handling. --- player.c | 73 ++-- player.h | 1 + rtp.c | 718 +++++++++++++++++++----------------- scripts/shairport-sync.conf | 2 +- 4 files changed, 423 insertions(+), 371 deletions(-) diff --git a/player.c b/player.c index 43a5b5ef..38ac11bf 100644 --- a/player.c +++ b/player.c @@ -162,6 +162,7 @@ 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].sequence_number = 0; } conn->ab_synced = 0; @@ -503,6 +504,38 @@ void player_put_packet(seq_t seqno, int64_t timestamp, uint8_t *data, int len, conn->ab_read = seqno; conn->ab_synced = 1; } + + // here, we should check for missing frames + if (!conn->ab_buffering) { + int j; + for (j = 1; j <= 7; j++) { + // check j times, after a short period of has elapsed, assuming 352 frames per packet + int back_step = (((250 * 44100) / 352) / 1000) * (j); // approx 250, 500 and 750 ms + int k; + for (k = -2; k <= 2; k++) { + if (back_step < + 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) & 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) { + rtp_request_resend(next, 1, conn); + // if (j>=3) + debug(1, "Resend request level #%d for packet %u in range %u to %u.", j, next, + conn->ab_read, conn->ab_write); + conn->resend_requests++; + } + } + } + } + } + } + if (conn->ab_write == seqno) { // expected packet abuf = conn->audio_buffer + BUFIDX(seqno); conn->ab_write = SUCCESSOR(seqno); @@ -517,6 +550,7 @@ void player_put_packet(seq_t seqno, int64_t timestamp, uint8_t *data, int len, 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->sequence_number = 0; } @@ -554,6 +588,7 @@ void player_put_packet(seq_t seqno, int64_t timestamp, uint8_t *data, int len, } else { debug(1, "Bad audio packet detected and discarded."); abuf->ready = 0; + abuf->resend_level = 0; abuf->timestamp = 0; abuf->sequence_number = 0; } @@ -574,7 +609,7 @@ int32_t rand_in_range(int32_t exclusive_range_limit) { int64_t sp = lcg_prev; int64_t rl = exclusive_range_limit; lcg_prev = lcg_prev * 69069 + 3; // crappy psrg - sp = sp * rl; // 64 bit calculation. INtersting part if above the 32 rightmost bits; + sp = sp * rl; // 64 bit calculation. Interesting part is above the 32 rightmost bits; return sp >> 32; } @@ -714,8 +749,6 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { // int16_t buf_fill; uint64_t local_time_now; // struct timespec tn; - abuf_t *abuf = 0; - int i; abuf_t *curframe = 0; int notified_buffer_empty = 0; // diagnostic only @@ -795,6 +828,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { debug(1, "Dropping flushed packet seqno %u, timestamp %lld", curframe->sequence_number, curframe->timestamp); curframe->ready = 0; + curframe->resend_level = 0; flush_limit++; conn->ab_read = SUCCESSOR(conn->ab_read); } @@ -1171,28 +1205,13 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { // check if t+8, t+16, t+32, t+64, t+128, ... (buffer_start_fill / 2) // packets have arrived... last-chance resend - if (!conn->ab_buffering) { - // check once, after a short period of has elapsed, assuming 352 frames per packet - i = ((250 * 44100) / 352) / 1000; // approx 250 ms - if (i < seq_diff(conn->ab_read, conn->ab_write, conn->ab_read)) { - seq_t next = seq_sum(conn->ab_read, i); - abuf = conn->audio_buffer + BUFIDX(next); - if (!abuf->ready) { - if (config.disable_resend_requests == 0) { - rtp_request_resend(next, 1, conn); - // debug(1,"Resend request for packet %u.",next); - conn->resend_requests++; - } - } - } - } - if (!curframe->ready) { // debug(1, "Supplying a silent frame for frame %u", read); conn->missing_packets++; curframe->timestamp = 0; // indicate a silent frame should be substituted } curframe->ready = 0; + curframe->resend_level = 0; conn->ab_read = SUCCESSOR(conn->ab_read); pthread_mutex_unlock(&conn->ab_mutex); return curframe; @@ -1666,11 +1685,12 @@ static void *player_thread_func(void *arg) { inbuflength = inframe->length; if (inbuf) { play_number++; -// if (play_number % 100 == 0) -// debug(3, "Play frame %d.", play_number); + // if (play_number % 100 == 0) + // debug(3, "Play frame %d.", play_number); conn->play_number_after_flush++; if (inframe->timestamp == 0) { - debug(1, "Player has a supplied silent frame."); + debug(1, "Player has a supplied silent frame, (possibly frame %u).", + SUCCESSOR(conn->last_seqno_read)); conn->last_seqno_read = (SUCCESSOR(conn->last_seqno_read) & 0xffff); // manage the packet out of sequence minder config.output->play(silence, conn->max_frames_per_packet * conn->output_sample_ratio); @@ -1686,7 +1706,7 @@ static void *player_thread_func(void *arg) { config.output->play(silence, conn->max_frames_per_packet * conn->output_sample_ratio); } else if (frames_to_drop) { if (frames_to_drop > 3 * config.output_rate) - warn("Very large number of frames to drop: %" PRId64 ".",frames_to_drop); + warn("Very large number of frames to drop: %" PRId64 ".", frames_to_drop); debug(3, "%" PRId64 " frames to drop.", frames_to_drop); frames_to_drop -= inframe->length; if (frames_to_drop < 0) @@ -1772,6 +1792,9 @@ static void *player_thread_func(void *arg) { at_least_one_frame_seen = 1; + // now, go back as far as the total latency less, say, 100 ms, and check the presence of + // frames from then onwards + int64_t reference_timestamp; uint64_t reference_timestamp_time, remote_reference_timestamp_time; get_reference_timestamp_stuff(&reference_timestamp, &reference_timestamp_time, @@ -1888,7 +1911,9 @@ static void *player_thread_func(void *arg) { (!conn->player_thread_please_stop) && (config.resyncthreshold > 0.0) && (abs_sync_error > config.resyncthreshold * config.output_rate)) { if (abs_sync_error > 3 * config.output_rate) { - warn("Very large sync error: %" PRId64 " frames, with a delay of %" PRId64 "frames.",sync_error,delay); + warn("Very large sync error: %" PRId64 " frames, with a delay of %" PRId64 + "frames.", + sync_error, delay); } sync_error_out_of_bounds++; } else { diff --git a/player.h b/player.h index 6f1a8b5b..65ef31ec 100644 --- a/player.h +++ b/player.h @@ -37,6 +37,7 @@ typedef uint16_t seq_t; typedef struct audio_buffer_entry { // decoded audio packets int ready; + int resend_level; int64_t timestamp; seq_t sequence_number; signed short *data; diff --git a/rtp.c b/rtp.c index 15cdb53f..b21c52dc 100644 --- a/rtp.c +++ b/rtp.c @@ -125,58 +125,59 @@ void *rtp_audio_receiver(void *arg) { time_of_previous_packet_fp = local_time_now_fp; } - if (nread < 0) - break; - - ssize_t plen = nread; - uint8_t type = packet[1] & ~0x80; - if (type == 0x60 || type == 0x56) { // audio data / resend - pktp = packet; - if (type == 0x56) { - pktp += 4; - plen -= 4; - } - seq_t seqno = ntohs(*(uint16_t *)(pktp + 2)); - // increment last_seqno and see if it's the same as the incoming seqno - - if (type == 0x60) { // regular audio data - if (last_seqno == -1) - last_seqno = seqno; - else { - last_seqno = (last_seqno + 1) & 0xffff; - // if (seqno != last_seqno) - // debug(3, "RTP: Packets out of sequence: expected: %d, got %d.", last_seqno, seqno); - last_seqno = seqno; // reset warning... + if (nread >= 0) { + ssize_t plen = nread; + uint8_t type = packet[1] & ~0x80; + if (type == 0x60 || type == 0x56) { // audio data / resend + pktp = packet; + if (type == 0x56) { + pktp += 4; + plen -= 4; } - } else { - debug(1, "Audio Port -- Retransmitted Audio Data Packet %u received.", seqno); + seq_t seqno = ntohs(*(uint16_t *)(pktp + 2)); + // increment last_seqno and see if it's the same as the incoming seqno + + if (type == 0x60) { // regular audio data + if (last_seqno == -1) + last_seqno = seqno; + else { + last_seqno = (last_seqno + 1) & 0xffff; + // if (seqno != last_seqno) + // debug(3, "RTP: Packets out of sequence: expected: %d, got %d.", last_seqno, seqno); + last_seqno = seqno; // reset warning... + } + } else { + debug(1, "Audio Receiver -- Retransmitted Audio Data Packet %u received.", seqno); + } + + int64_t timestamp = monotonic_timestamp(ntohl(*(uint32_t *)(pktp + 4)), conn); + + // if (packet[1]&0x10) + // debug(1,"Audio packet Extension bit set."); + + pktp += 12; + plen -= 12; + + // check if packet contains enough content to be reasonable + if (plen >= 16) { + if ((config.diagnostic_drop_packet_fraction == 0.0) || + (drand48() > config.diagnostic_drop_packet_fraction)) + player_put_packet(seqno, timestamp, pktp, plen, conn); + else + debug(3, "Dropping audio packet %u to simulate a bad connection.", seqno); + continue; + } + if (type == 0x56 && seqno == 0) { + debug(2, "resend-related request packet received, ignoring."); + continue; + } + debug(1, "Audio receiver -- Unknown RTP packet of type 0x%02X length %d seqno %d", type, + nread, seqno); } - - int64_t timestamp = monotonic_timestamp(ntohl(*(uint32_t *)(pktp + 4)), conn); - - // if (packet[1]&0x10) - // debug(1,"Audio packet Extension bit set."); - - pktp += 12; - plen -= 12; - - // check if packet contains enough content to be reasonable - if (plen >= 16) { - if ((config.diagnostic_drop_packet_fraction == 0.0) || - (drand48() > config.diagnostic_drop_packet_fraction)) - player_put_packet(seqno, timestamp, pktp, plen, conn); - else - debug(3, "Dropping audio packet %u to simulate a bad connection.", seqno); - continue; - } - if (type == 0x56 && seqno == 0) { - debug(2, "resend-related request packet received, ignoring."); - continue; - } - debug(1, "Audio receiver -- Unknown RTP packet of type 0x%02X length %d seqno %d", type, - nread, seqno); + warn("Audio receiver -- Unknown RTP packet of type 0x%02X length %d.", type, nread); + } else { + debug(1, "Error receiving an audio packet."); } - warn("Audio receiver -- Unknown RTP packet of type 0x%02X length %d.", type, nread); } debug(3, "Audio receiver -- Server RTP thread interrupted. terminating."); @@ -209,172 +210,190 @@ void *rtp_control_receiver(void *arg) { if (conn->please_stop != 0) { break; } + nread = recv(conn->control_socket, packet, sizeof(packet), 0); // local_time_now = get_absolute_time_in_fp(); // clock_gettime(CLOCK_MONOTONIC,&tn); // local_time_now=((uint64_t)tn.tv_sec<<32)+((uint64_t)tn.tv_nsec<<32)/1000000000; - if (nread < 0) - break; + if (nread >= 0) { - ssize_t plen = nread; - if (packet[1] == 0xd4) { // sync data - /* - // the following stanza is for debugging only -- normally commented out. - { - char obf[4096]; - char *obfp = obf; - int obfc; - for (obfc = 0; obfc < plen; obfc++) { - snprintf(obfp, 3, "%02X", packet[obfc]); - obfp += 2; - }; - *obfp = 0; + if ((config.diagnostic_drop_packet_fraction == 0.0) || + (drand48() > config.diagnostic_drop_packet_fraction)) { + + ssize_t plen = nread; + if (packet[1] == 0xd4) { // sync data + /* + // the following stanza is for debugging only -- normally commented out. + { + char obf[4096]; + char *obfp = obf; + int obfc; + for (obfc = 0; obfc < plen; obfc++) { + snprintf(obfp, 3, "%02X", packet[obfc]); + 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 - client-time specified in the packet if there was no delay - // and (2) that the rt below is the timestamp of the frame that should be playing at - the client-time specified in the packet on this device taking account of the delay - // Thus, (3) the latency can be calculated by subtracting the second from the first. - // There must be more to it -- there something missing. + // 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 + client-time specified in the packet if there was no delay + // and (2) that the rt below is the timestamp of the frame that should be playing + at + the client-time specified in the packet on this device taking account of the delay + // 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 packe 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. + // In addition, it seems that if the value of the short represented by the second + pair + of bytes in the packe 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 rtlt = nctohl(&packet[4]); // raw timestamp less latency + // uint32_t rt = nctohl(&packet[16]); // raw timestamp - uint32_t fl = nctohs(&packet[2]); // + // 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 " - respectively.",monotonic_timestamp(rt, conn),monotonic_timestamp(rtlt, conn)); - } - */ - if (conn->local_to_remote_time_difference) { // need a time packet to be interchanged first... + // 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 " + respectively.",monotonic_timestamp(rt, conn),monotonic_timestamp(rtlt, conn)); + } + */ + if (conn->local_to_remote_time_difference) { // need a time packet to be interchanged + // first... - remote_time_of_sync = (uint64_t)nctohl(&packet[8]) << 32; - remote_time_of_sync += nctohl(&packet[12]); + remote_time_of_sync = (uint64_t)nctohl(&packet[8]) << 32; + remote_time_of_sync += nctohl(&packet[12]); - // debug(1,"Remote Sync Time: %0llx.",remote_time_of_sync); + // debug(1,"Remote Sync Time: %0llx.",remote_time_of_sync); - sync_rtp_timestamp = monotonic_timestamp(nctohl(&packet[16]), conn); - int64_t rtp_timestamp_less_latency = monotonic_timestamp(nctohl(&packet[4]), conn); + sync_rtp_timestamp = monotonic_timestamp(nctohl(&packet[16]), conn); + int64_t rtp_timestamp_less_latency = monotonic_timestamp(nctohl(&packet[4]), conn); - // debug(1,"Sync timestamp is %u.",ntohl(*((uint32_t *)&packet[16]))); + // debug(1,"Sync timestamp is %u.",ntohl(*((uint32_t *)&packet[16]))); - if (config.userSuppliedLatency) { - if (config.userSuppliedLatency != conn->latency) { - debug(1, "Using the user-supplied latency: %" PRId64 ".", config.userSuppliedLatency); - } - conn->latency = config.userSuppliedLatency; - } else { + if (config.userSuppliedLatency) { + if (config.userSuppliedLatency != conn->latency) { + debug(1, "Using the user-supplied latency: %" PRId64 ".", + config.userSuppliedLatency); + } + conn->latency = config.userSuppliedLatency; + } else { - // It seems that the second pair of bytes in the packet indicate whether a fixed - // delay of 11,025 frames should be added -- iTunes set this field to 7 and - // AirPlay sets it to 4. + // It seems that the second pair of bytes in the packet indicate whether a fixed + // delay of 11,025 frames should be added -- iTunes set this field to 7 and + // AirPlay sets it to 4. - // The value of 11,025 (0.25 seconds) is a guess based on the "Audio-Latency" parameter - // returned by an AE. + // The value of 11,025 (0.25 seconds) is a guess based on the "Audio-Latency" + // parameter + // returned by an AE. - // Sigh, it would be nice to have a published protocol... + // Sigh, it would be nice to have a published protocol... - uint16_t flags = nctohs(&packet[2]); - int64_t la = sync_rtp_timestamp - rtp_timestamp_less_latency; - if (flags == 7) - la += config.fixedLatencyOffset; - // debug(1,"Latency calculated from the sync packet is %" PRId64 " frames.",la); - if ((conn->maximum_latency) && (conn->maximum_latency < la)) - la = conn->maximum_latency; - if ((conn->minimum_latency) && (conn->minimum_latency > la)) - la = conn->minimum_latency; + uint16_t flags = nctohs(&packet[2]); + int64_t la = sync_rtp_timestamp - rtp_timestamp_less_latency; + if (flags == 7) + la += config.fixedLatencyOffset; + // debug(1,"Latency calculated from the sync packet is %" PRId64 " frames.",la); + if ((conn->maximum_latency) && (conn->maximum_latency < la)) + la = conn->maximum_latency; + if ((conn->minimum_latency) && (conn->minimum_latency > la)) + la = conn->minimum_latency; - const int max_frames = ((3 * BUFFER_FRAMES * 352) / 4) - 11025; + const int max_frames = ((3 * BUFFER_FRAMES * 352) / 4) - 11025; - if ((la < 0) || (la > max_frames)) { - warn("An out-of-range latency request of %" PRId64 - " frames was ignored. Must be %d frames or less (44,100 frames per second). " - "Latency remains at %" PRId64 " frames.", - la, max_frames, conn->latency); - } else { + if ((la < 0) || (la > max_frames)) { + warn("An out-of-range latency request of %" PRId64 + " frames was ignored. Must be %d frames or less (44,100 frames per second). " + "Latency remains at %" PRId64 " frames.", + la, max_frames, conn->latency); + } else { - if (la != conn->latency) { - conn->latency = la; - debug(2, "New latency detected: %" PRId64 ", sync latency: %" PRId64 - ", minimum latency: %" PRId64 ", maximum " - "latency: %" PRId64 ", fixed offset: %" PRId64 ".", - la, sync_rtp_timestamp - rtp_timestamp_less_latency, conn->minimum_latency, - conn->maximum_latency, config.fixedLatencyOffset); + if (la != conn->latency) { + conn->latency = la; + debug(2, "New latency detected: %" PRId64 ", sync latency: %" PRId64 + ", minimum latency: %" PRId64 ", maximum " + "latency: %" PRId64 ", fixed offset: %" PRId64 ".", + la, sync_rtp_timestamp - rtp_timestamp_less_latency, conn->minimum_latency, + conn->maximum_latency, config.fixedLatencyOffset); + } + } } + + pthread_mutex_lock(&conn->reference_time_mutex); + + // this is for debugging + // uint64_t old_remote_reference_time = conn->remote_reference_timestamp_time; + // int64_t old_reference_timestamp = conn->reference_timestamp; + // int64_t old_latency_delayed_timestamp = conn->latency_delayed_timestamp; + conn->remote_reference_timestamp_time = remote_time_of_sync; + conn->reference_timestamp_time = + remote_time_of_sync - conn->local_to_remote_time_difference; + conn->reference_timestamp = sync_rtp_timestamp; + conn->latency_delayed_timestamp = rtp_timestamp_less_latency; + pthread_mutex_unlock(&conn->reference_time_mutex); + + // this is for debugging + /* + uint64_t time_difference = remote_time_of_sync - old_remote_reference_time; + int64_t reference_frame_difference = sync_rtp_timestamp - old_reference_timestamp; + int64_t delayed_frame_difference = rtp_timestamp_less_latency - + old_latency_delayed_timestamp; + + if (old_remote_reference_time) + debug(1,"Time difference: %" PRIu64 " reference and delayed frame differences: %" + PRId64 " + and %" PRId64 ", giving rates of %f and %f respectively.", + (time_difference*1000000)>>32,reference_frame_difference,delayed_frame_difference,(1.0*(reference_frame_difference*10000000))/((time_difference*10000000)>>32),(1.0*(delayed_frame_difference*10000000))/((time_difference*10000000)>>32)); + else + debug(1,"First sync received"); + */ + + // debug(1,"New Reference timestamp and timestamp time..."); + // get estimated remote time now + // remote_time_now = local_time_now + local_to_remote_time_difference; + + // debug(1,"Sync Time is %lld us late (remote + // times).",((remote_time_now-remote_time_of_sync)*1000000)>>32); + // debug(1,"Sync Time is %lld us late (local + // times).",((local_time_now-reference_timestamp_time)*1000000)>>32); + } else { + debug(1, "Sync packet received before we got a timing packet back."); } - } + } else if (packet[1] == 0xd6) { // resent audio data in the control path -- whaale only? + pktp = packet + 4; + plen -= 4; + seq_t seqno = ntohs(*(uint16_t *)(pktp + 2)); + debug(1, "Control Receiver -- Retransmitted Audio Data Packet %u received.", seqno); - pthread_mutex_lock(&conn->reference_time_mutex); + int64_t timestamp = monotonic_timestamp(ntohl(*(uint32_t *)(pktp + 4)), conn); - // this is for debugging - // uint64_t old_remote_reference_time = conn->remote_reference_timestamp_time; - // int64_t old_reference_timestamp = conn->reference_timestamp; - // int64_t old_latency_delayed_timestamp = conn->latency_delayed_timestamp; - conn->remote_reference_timestamp_time = remote_time_of_sync; - conn->reference_timestamp_time = - remote_time_of_sync - conn->local_to_remote_time_difference; - conn->reference_timestamp = sync_rtp_timestamp; - conn->latency_delayed_timestamp = rtp_timestamp_less_latency; - pthread_mutex_unlock(&conn->reference_time_mutex); + pktp += 12; + plen -= 12; - // this is for debugging - /* - uint64_t time_difference = remote_time_of_sync - old_remote_reference_time; - int64_t reference_frame_difference = sync_rtp_timestamp - old_reference_timestamp; - int64_t delayed_frame_difference = rtp_timestamp_less_latency - - old_latency_delayed_timestamp; - - if (old_remote_reference_time) - debug(1,"Time difference: %" PRIu64 " reference and delayed frame differences: %" PRId64 " - and %" PRId64 ", giving rates of %f and %f respectively.", - (time_difference*1000000)>>32,reference_frame_difference,delayed_frame_difference,(1.0*(reference_frame_difference*10000000))/((time_difference*10000000)>>32),(1.0*(delayed_frame_difference*10000000))/((time_difference*10000000)>>32)); - else - debug(1,"First sync received"); - */ - - // debug(1,"New Reference timestamp and timestamp time..."); - // get estimated remote time now - // remote_time_now = local_time_now + local_to_remote_time_difference; - - // debug(1,"Sync Time is %lld us late (remote - // times).",((remote_time_now-remote_time_of_sync)*1000000)>>32); - // debug(1,"Sync Time is %lld us late (local - // times).",((local_time_now-reference_timestamp_time)*1000000)>>32); + // check if packet contains enough content to be reasonable + if (plen >= 16) { + player_put_packet(seqno, timestamp, pktp, plen, conn); + continue; + } else { + debug(3, "Too-short retransmitted audio packet received in control port, ignored."); + } + } else + debug(1, "Control Receiver -- Unknown RTP packet of type 0x%02X length %d, ignored.", + packet[1], nread); } else { - debug(1, "Sync packet received before we got a timing packet back."); + debug(1, "Control Receiver -- dropping a packet to simulate a bad network."); } - } else if (packet[1] == 0xd6) { // resent audio data in the control path -- whaale only? - pktp = packet + 4; - plen -= 4; - seq_t seqno = ntohs(*(uint16_t *)(pktp + 2)); - debug(1, "Control Port -- Retransmitted Audio Data Packet %u received.", seqno); - - int64_t timestamp = monotonic_timestamp(ntohl(*(uint32_t *)(pktp + 4)), conn); - - pktp += 12; - plen -= 12; - - // check if packet contains enough content to be reasonable - if (plen >= 16) { - player_put_packet(seqno, timestamp, pktp, plen, conn); - continue; - } else { - debug(3, "Too-short retransmitted audio packet received in control port, ignored."); - } - } else - debug(1, "Control Port -- Unknown RTP packet of type 0x%02X length %d, ignored.", packet[1], - nread); + } else { + debug(1, "Control Receiver -- error receiving a packet."); + } } debug(3, "Control RTP thread interrupted. terminating."); @@ -499,192 +518,199 @@ void *rtp_timing_receiver(void *arg) { arrival_time = get_absolute_time_in_fp(); // clock_gettime(CLOCK_MONOTONIC,&att); - if (nread < 0) - break; + if (nread >= 0) { - // ssize_t plen = nread; - // debug(1,"Packet Received on Timing Port."); - if (packet[1] == 0xd3) { // timing reply - /* - char obf[4096]; - char *obfp = obf; - int obfc; - for (obfc=0;obfcdeparture_time; + return_time = arrival_time - conn->departure_time; - uint64_t rtus = (return_time * 1000000) >> 32; + uint64_t rtus = (return_time * 1000000) >> 32; - if (rtus < 300000) { + if (rtus < 300000) { - // debug(2,"Synchronisation ping return time is %f milliseconds.",(rtus*1.0)/1000); + // debug(2,"Synchronisation ping return time is %f milliseconds.",(rtus*1.0)/1000); - // distant_receive_time = - // ((uint64_t)ntohl(*((uint32_t*)&packet[16])))<<32+ntohl(*((uint32_t*)&packet[20])); + // distant_receive_time = + // ((uint64_t)ntohl(*((uint32_t*)&packet[16])))<<32+ntohl(*((uint32_t*)&packet[20])); - distant_receive_time = (uint64_t)nctohl(&packet[16]) << 32; - distant_receive_time += nctohl(&packet[20]); + distant_receive_time = (uint64_t)nctohl(&packet[16]) << 32; + distant_receive_time += nctohl(&packet[20]); - // distant_transmit_time = - // ((uint64_t)ntohl(*((uint32_t*)&packet[24])))<<32+ntohl(*((uint32_t*)&packet[28])); + // distant_transmit_time = + // ((uint64_t)ntohl(*((uint32_t*)&packet[24])))<<32+ntohl(*((uint32_t*)&packet[28])); - distant_transmit_time = (uint64_t)nctohl(&packet[24]) << 32; - distant_transmit_time += nctohl(&packet[28]); + distant_transmit_time = (uint64_t)nctohl(&packet[24]) << 32; + distant_transmit_time += nctohl(&packet[28]); - // processing_time = distant_transmit_time - distant_receive_time; + // processing_time = distant_transmit_time - distant_receive_time; - // debug(1,"Return trip time: %lluuS, remote processing time: - // %lluuS.",(return_time*1000000)>>32,(processing_time*1000000)>>32); + // debug(1,"Return trip time: %lluuS, remote processing time: + // %lluuS.",(return_time*1000000)>>32,(processing_time*1000000)>>32); - uint64_t local_time_by_remote_clock = distant_transmit_time + return_time / 2; + uint64_t local_time_by_remote_clock = distant_transmit_time + return_time / 2; - unsigned int cc; - for (cc = time_ping_history - 1; cc > 0; cc--) { - conn->time_pings[cc] = conn->time_pings[cc - 1]; - conn->time_pings[cc].dispersion = - (conn->time_pings[cc].dispersion * 110) / - 100; // make the dispersions 'age' by this rational factor - } - // these are for diagnostics only -- not used - conn->time_pings[0].local_time = arrival_time; - conn->time_pings[0].remote_time = distant_transmit_time; - - conn->time_pings[0].local_to_remote_difference = local_time_by_remote_clock - arrival_time; - conn->time_pings[0].dispersion = return_time; - if (conn->time_ping_count < time_ping_history) - conn->time_ping_count++; - - uint64_t local_time_chosen = arrival_time; - ; - // uint64_t remote_time_chosen = distant_transmit_time; - // now pick the timestamp with the lowest dispersion - uint64_t l2rtd = conn->time_pings[0].local_to_remote_difference; - uint64_t tld = conn->time_pings[0].dispersion; - // chosen = 0; - for (cc = 1; cc < conn->time_ping_count; cc++) - if (conn->time_pings[cc].dispersion < tld) { - l2rtd = conn->time_pings[cc].local_to_remote_difference; - // chosen = cc; - tld = conn->time_pings[cc].dispersion; - local_time_chosen = conn->time_pings[cc].local_time; - // remote_time_chosen = conn->time_pings[cc].remote_time; + unsigned int cc; + for (cc = time_ping_history - 1; cc > 0; cc--) { + conn->time_pings[cc] = conn->time_pings[cc - 1]; + conn->time_pings[cc].dispersion = + (conn->time_pings[cc].dispersion * 110) / + 100; // make the dispersions 'age' by this rational factor } - // int64_t ji; + // these are for diagnostics only -- not used + conn->time_pings[0].local_time = arrival_time; + conn->time_pings[0].remote_time = distant_transmit_time; - if (conn->time_ping_count > 1) { - if (l2rtd > conn->local_to_remote_time_difference) { - local_to_remote_time_jitters = - local_to_remote_time_jitters + l2rtd - conn->local_to_remote_time_difference; - // ji = l2rtd - conn->local_to_remote_time_difference; + conn->time_pings[0].local_to_remote_difference = + local_time_by_remote_clock - arrival_time; + conn->time_pings[0].dispersion = return_time; + if (conn->time_ping_count < time_ping_history) + conn->time_ping_count++; + + uint64_t local_time_chosen = arrival_time; + + // uint64_t remote_time_chosen = distant_transmit_time; + // now pick the timestamp with the lowest dispersion + uint64_t l2rtd = conn->time_pings[0].local_to_remote_difference; + uint64_t tld = conn->time_pings[0].dispersion; + // chosen = 0; + for (cc = 1; cc < conn->time_ping_count; cc++) + if (conn->time_pings[cc].dispersion < tld) { + l2rtd = conn->time_pings[cc].local_to_remote_difference; + // chosen = cc; + tld = conn->time_pings[cc].dispersion; + local_time_chosen = conn->time_pings[cc].local_time; + // remote_time_chosen = conn->time_pings[cc].remote_time; + } + // int64_t ji; + + if (conn->time_ping_count > 1) { + if (l2rtd > conn->local_to_remote_time_difference) { + local_to_remote_time_jitters = + local_to_remote_time_jitters + l2rtd - conn->local_to_remote_time_difference; + // ji = l2rtd - conn->local_to_remote_time_difference; + } else { + local_to_remote_time_jitters = + local_to_remote_time_jitters + conn->local_to_remote_time_difference - l2rtd; + // ji = -(conn->local_to_remote_time_difference - l2rtd); + } + local_to_remote_time_jitters_count += 1; + } + // uncomment below to print jitter between client's clock and oour clock + // int64_t rtus = (tld*1000000)>>32; ji = (ji*1000000)>>32; debug(1,"Choosing time + // difference + // with dispersion of %lld us with delta of %lld us",rtus,ji); + + conn->local_to_remote_time_difference = l2rtd; + if (first_local_to_remote_time_difference == 0) { + first_local_to_remote_time_difference = conn->local_to_remote_time_difference; + // first_local_to_remote_time_difference_time = get_absolute_time_in_fp(); + } + + // int64_t clock_drift; + // int64_t clock_drift_in_usec; + // double clock_drift_ppm = 0.0; + if (first_local_time == 0) { + first_local_time = local_time_chosen; + // first_remote_time = remote_time_chosen; + // clock_drift = 0; } else { - local_to_remote_time_jitters = - local_to_remote_time_jitters + conn->local_to_remote_time_difference - l2rtd; - // ji = -(conn->local_to_remote_time_difference - l2rtd); + // uint64_t local_time_change = local_time_chosen - first_local_time; + // uint64_t remote_time_change = remote_time_chosen - first_remote_time; + + /* + if (remote_time_change >= local_time_change) + clock_drift = remote_time_change - local_time_change; + else + clock_drift = -(local_time_change - remote_time_change); + */ + /* + if (clock_drift >= 0) + clock_drift_in_usec = (clock_drift * 1000000) >> 32; + else + clock_drift_in_usec = -(((-clock_drift) * 1000000) >> 32); + */ + + // clock_drift_ppm = (1.0 * clock_drift_in_usec) / (local_time_change >> 32); } - local_to_remote_time_jitters_count += 1; - } - // uncomment below to print jitter between client's clock and oour clock - // int64_t rtus = (tld*1000000)>>32; ji = (ji*1000000)>>32; debug(1,"Choosing time - // difference - // with dispersion of %lld us with delta of %lld us",rtus,ji); - conn->local_to_remote_time_difference = l2rtd; - if (first_local_to_remote_time_difference == 0) { - first_local_to_remote_time_difference = conn->local_to_remote_time_difference; - // first_local_to_remote_time_difference_time = get_absolute_time_in_fp(); - } + int64_t source_drift_usec; + if (conn->play_segment_reference_frame != 0) { + int64_t reference_timestamp; + uint64_t reference_timestamp_time, remote_reference_timestamp_time; + get_reference_timestamp_stuff(&reference_timestamp, &reference_timestamp_time, + &remote_reference_timestamp_time, conn); + uint64_t frame_difference = 0; + if (reference_timestamp >= conn->play_segment_reference_frame) + frame_difference = + (uint64_t)reference_timestamp - (uint64_t)conn->play_segment_reference_frame; + else // rollover + frame_difference = (uint64_t)reference_timestamp + 0x100000000 - + (uint64_t)conn->play_segment_reference_frame; + uint64_t frame_time_difference_calculated = + (((uint64_t)frame_difference << 32) / 44100); + uint64_t frame_time_difference_actual = + remote_reference_timestamp_time - + conn->play_segment_reference_frame_remote_time; // this is all done by reference to + // the + // sources' system clock + // debug(1,"%llu frames since play started, %llu usec calculated, %llu usec + // actual",frame_difference, (frame_time_difference_calculated*1000000)>>32, + // (frame_time_difference_actual*1000000)>>32); + if (frame_time_difference_calculated >= + frame_time_difference_actual) // i.e. if the time it should have taken to send the + // packets is greater than the actual time difference + // measured on the source clock + // then the source DAC's clock is running fast relative to the source system clock + source_drift_usec = frame_time_difference_calculated - frame_time_difference_actual; + else + // otherwise the source DAC's clock is running slow relative to the source system + // clock + source_drift_usec = + -(frame_time_difference_actual - frame_time_difference_calculated); + } else + source_drift_usec = 0; + source_drift_usec = (source_drift_usec * 1000000) >> 32; // turn it to microseconds - // int64_t clock_drift; - // int64_t clock_drift_in_usec; - // double clock_drift_ppm = 0.0; - if (first_local_time == 0) { - first_local_time = local_time_chosen; - // first_remote_time = remote_time_chosen; - // clock_drift = 0; + // long current_delay = 0; + // if (config.output->delay) { + // config.output->delay(¤t_delay); + //} + // Useful for troubleshooting: + // debug(1, "clock_drift_ppm %f\tchosen %5d\tsource_drift_usec + // %10.1lld\treturn_time_in_usec + // %10.1llu", + // clock_drift_ppm, + // chosen, + //(session_corrections*1000000)/44100, + // current_delay, + // source_drift_usec, + // buffer_occupancy, + //(return_time*1000000)>>32); } else { - // uint64_t local_time_change = local_time_chosen - first_local_time; - // uint64_t remote_time_change = remote_time_chosen - first_remote_time; - - /* - if (remote_time_change >= local_time_change) - clock_drift = remote_time_change - local_time_change; - else - clock_drift = -(local_time_change - remote_time_change); - */ - /* - if (clock_drift >= 0) - clock_drift_in_usec = (clock_drift * 1000000) >> 32; - else - clock_drift_in_usec = -(((-clock_drift) * 1000000) >> 32); - */ - - // clock_drift_ppm = (1.0 * clock_drift_in_usec) / (local_time_change >> 32); + debug(1, "Time ping turnaround time: %lld us -- it looks like a timing ping was lost.", + rtus); } - - int64_t source_drift_usec; - if (conn->play_segment_reference_frame != 0) { - int64_t reference_timestamp; - uint64_t reference_timestamp_time, remote_reference_timestamp_time; - get_reference_timestamp_stuff(&reference_timestamp, &reference_timestamp_time, - &remote_reference_timestamp_time, conn); - uint64_t frame_difference = 0; - if (reference_timestamp >= conn->play_segment_reference_frame) - frame_difference = - (uint64_t)reference_timestamp - (uint64_t)conn->play_segment_reference_frame; - else // rollover - frame_difference = (uint64_t)reference_timestamp + 0x100000000 - - (uint64_t)conn->play_segment_reference_frame; - uint64_t frame_time_difference_calculated = (((uint64_t)frame_difference << 32) / 44100); - uint64_t frame_time_difference_actual = - remote_reference_timestamp_time - - conn->play_segment_reference_frame_remote_time; // this is all done by reference to - // the - // sources' system clock - // debug(1,"%llu frames since play started, %llu usec calculated, %llu usec - // actual",frame_difference, (frame_time_difference_calculated*1000000)>>32, - // (frame_time_difference_actual*1000000)>>32); - if (frame_time_difference_calculated >= - frame_time_difference_actual) // i.e. if the time it should have taken to send the - // packets is greater than the actual time difference - // measured on the source clock - // then the source DAC's clock is running fast relative to the source system clock - source_drift_usec = frame_time_difference_calculated - frame_time_difference_actual; - else - // otherwise the source DAC's clock is running slow relative to the source system clock - source_drift_usec = -(frame_time_difference_actual - frame_time_difference_calculated); - } else - source_drift_usec = 0; - source_drift_usec = (source_drift_usec * 1000000) >> 32; // turn it to microseconds - - // long current_delay = 0; - // if (config.output->delay) { - // config.output->delay(¤t_delay); - //} - // Useful for troubleshooting: - // debug(1, "clock_drift_ppm %f\tchosen %5d\tsource_drift_usec %10.1lld\treturn_time_in_usec - // %10.1llu", - // clock_drift_ppm, - // chosen, - //(session_corrections*1000000)/44100, - // current_delay, - // source_drift_usec, - // buffer_occupancy, - //(return_time*1000000)>>32); } else { - debug(1, "Time ping turnaround time: %lld us -- it looks like a timing ping was lost.", - rtus); + debug(1, "Timing port -- Unknown RTP packet of type 0x%02X length %d.", packet[1], nread); } } else { - debug(1, "Timing port -- Unknown RTP packet of type 0x%02X length %d.", packet[1], nread); + debug(1, "Timing receiver -- error receiving a packet."); } } @@ -909,7 +935,7 @@ void clear_reference_timestamp(rtsp_conn_info *conn) { void rtp_request_resend(seq_t first, uint32_t count, rtsp_conn_info *conn) { if (conn->rtp_running) { // if (!request_sent) { - debug(1, "requesting resend of %d packets starting at %u.", count, first); + debug(2, "requesting resend of %d packets starting at %u.", count, first); // request_sent = 1; //} diff --git a/scripts/shairport-sync.conf b/scripts/shairport-sync.conf index be48f08b..417aeb38 100644 --- a/scripts/shairport-sync.conf +++ b/scripts/shairport-sync.conf @@ -152,5 +152,5 @@ diagnostics = // log_verbosity = 0; // "0" means no debug verbosity, "3" is most verbose. // log_show_time_since_startup = "no"; // set this to yes if you want the time since startup in the debug message -- seconds down to nanoseconds // log_show_time_since_last_message = "no"; // set this to yes if you want the time since the last debug message in the debug message -- seconds down to nanoseconds -// drop_this_fraction_of_audio_packets = 0.0; // use this to simulate a noisy network where this fraction of UDP packets are lost in transmission. E.g. a value of 0.01 would mean an average of 1% of packets are lost. Audio packets only. +// drop_this_fraction_of_audio_packets = 0.0; // use this to simulate a noisy network where this fraction of UDP packets are lost in transmission. E.g. a value of 0.001 would mean an average of 0.1% of packets are lost, which is actually quite a high figure. }; From a0964e25370206766ea5a6f325c95be1b9dab428 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sat, 14 Apr 2018 13:02:26 +0100 Subject: [PATCH 6/8] Fix serious and long-standing bugs in the control, audio and timing threads that could be responsible for low resilience on noisy and unrealiable networks. Add ability to simiulate UDP receive and send failures on timing, control and audio ports. Significantly improve resend requesting and handling. --- configure.ac | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/configure.ac b/configure.ac index b3a47064..d5fc6295 100644 --- 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], [3.2d39], [mikebrady@eircom.net]) +AC_INIT([shairport-sync], [3.2d40], [mikebrady@eircom.net]) AM_INIT_AUTOMAKE AC_CONFIG_SRCDIR([shairport.c]) AC_CONFIG_HEADERS([config.h]) From 77f32d987df0e2c52174de5cb4b2c737a566eaaf Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sat, 14 Apr 2018 13:20:27 +0100 Subject: [PATCH 7/8] Update RELEASENOTES.md --- RELEASENOTES.md | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/RELEASENOTES.md b/RELEASENOTES.md index b6607556..5a2e63eb 100644 --- a/RELEASENOTES.md +++ b/RELEASENOTES.md @@ -1,8 +1,16 @@ +Version 3.2d50 +==== +**Bug Fixes** +* A number of serious and long-standing bugs have been identified and fixed in the threads that handle audio, control and timing packets. Specifically, if UDP reception or transmission errors occured (a rare occurence on a good network, but possible on noisy or congested networks), the threads would quit. An error on the reception of the first control packet could mute an entire play session. + +**Enhancements** +* the code used to request the retransmission of missing audio packets has been significantly improved. + Version 3.2d39 ==== **Enhancements** * An extra diagnostic to artificially drop audio packets to simulate a noisy network has been added. Set the proportion of packets to be dropped in the `diagnostics` section of the configuration file using the tag `drop_this_fraction_of_audio_packets`. The value should be between 0.0 and 1.0. E.g. a value of 0.001 would mean one packet in a thousand would be dropped, on average. Look in the sample configuration file `/etc/shairport-sync.conf.sample` for the added entry. -* Compatibility with AirAudio has been added / restored. +* Minimal compatibility with AirAudio has been added / restored. There remains a question about error correction for handling UDP packet loss. Thanks to [Janusz Kowalczyk](https://github.com/kowalcj0) for reporting the issues. Version 3.2d35 ==== From 49d5486df60a78db731922414b6c633a88546508 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sat, 14 Apr 2018 13:56:44 +0100 Subject: [PATCH 8/8] Keep timestamp info from the incoming audio packet --- player.c | 17 ++++++++++++----- player.h | 5 +++-- rtp.c | 10 ++++++---- 3 files changed, 21 insertions(+), 11 deletions(-) diff --git a/player.c b/player.c index 38ac11bf..75d0fbfc 100644 --- a/player.c +++ b/player.c @@ -463,10 +463,12 @@ static void free_audio_buffers(rtsp_conn_info *conn) { free(conn->audio_buffer[i].data); } -void player_put_packet(seq_t seqno, int64_t timestamp, uint8_t *data, int len, - rtsp_conn_info *conn) { +void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp, uint8_t *data, + int len, rtsp_conn_info *conn) { // all timestamps are done at the output rate + // the "actual_timestamp" is the one that comes in the packet, and is carried over for debugging + // and checking only. int64_t ltimestamp = timestamp * conn->output_sample_ratio; @@ -552,6 +554,7 @@ void player_put_packet(seq_t seqno, int64_t timestamp, uint8_t *data, int len, abuf->ready = 0; // to be sure, to be sure abuf->resend_level = 0; abuf->timestamp = 0; + abuf->given_timestamp = 0; abuf->sequence_number = 0; } // debug(1,"N %d s %u.",seq_diff(ab_write,PREDECESSOR(seqno))+1,ab_write); @@ -584,12 +587,14 @@ void player_put_packet(seq_t seqno, int64_t timestamp, uint8_t *data, int len, 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->given_timestamp = 0; abuf->sequence_number = 0; } } @@ -1911,9 +1916,11 @@ static void *player_thread_func(void *arg) { (!conn->player_thread_please_stop) && (config.resyncthreshold > 0.0) && (abs_sync_error > config.resyncthreshold * config.output_rate)) { if (abs_sync_error > 3 * config.output_rate) { - warn("Very large sync error: %" PRId64 " frames, with a delay of %" PRId64 - "frames.", - sync_error, delay); + warn("Very large sync error: %" PRId64 " frames, with delay: %" PRId64 + ", td_in_frames: %" PRId64 ", rt: %" PRId64 ", nt: %" PRId64 + ", current_delay: %" PRId64 ", seqno: %u, given timestamp: %" PRIu32 ".", + sync_error, delay, td_in_frames, rt, nt, current_delay, + inframe->sequence_number, inframe->given_timestamp); } sync_error_out_of_bounds++; } else { diff --git a/player.h b/player.h index 65ef31ec..ec4e4248 100644 --- a/player.h +++ b/player.h @@ -40,6 +40,7 @@ typedef struct audio_buffer_entry { // decoded audio packets int resend_level; int64_t timestamp; seq_t sequence_number; + uint32_t given_timestamp; // for debugging and checking signed short *data; int length; // the length of the decoded data } abuf_t; @@ -194,8 +195,8 @@ void player_stop(rtsp_conn_info *conn); void player_volume(double f, rtsp_conn_info *conn); void player_volume_without_notification(double f, rtsp_conn_info *conn); void player_flush(int64_t timestamp, rtsp_conn_info *conn); -void player_put_packet(seq_t seqno, int64_t timestamp, uint8_t *data, int len, - rtsp_conn_info *conn); +void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp, uint8_t *data, + int len, rtsp_conn_info *conn); int64_t monotonic_timestamp(uint32_t timestamp, rtsp_conn_info *conn); // add an epoch to the timestamp. The monotonic diff --git a/rtp.c b/rtp.c index b21c52dc..9ef7be2c 100644 --- a/rtp.c +++ b/rtp.c @@ -150,7 +150,8 @@ void *rtp_audio_receiver(void *arg) { debug(1, "Audio Receiver -- Retransmitted Audio Data Packet %u received.", seqno); } - int64_t timestamp = monotonic_timestamp(ntohl(*(uint32_t *)(pktp + 4)), conn); + uint32_t actual_timestamp = ntohl(*(uint32_t *)(pktp + 4)); + int64_t timestamp = monotonic_timestamp(actual_timestamp, conn); // if (packet[1]&0x10) // debug(1,"Audio packet Extension bit set."); @@ -162,7 +163,7 @@ void *rtp_audio_receiver(void *arg) { if (plen >= 16) { if ((config.diagnostic_drop_packet_fraction == 0.0) || (drand48() > config.diagnostic_drop_packet_fraction)) - player_put_packet(seqno, timestamp, pktp, plen, conn); + player_put_packet(seqno, actual_timestamp, timestamp, pktp, plen, conn); else debug(3, "Dropping audio packet %u to simulate a bad connection.", seqno); continue; @@ -373,14 +374,15 @@ void *rtp_control_receiver(void *arg) { seq_t seqno = ntohs(*(uint16_t *)(pktp + 2)); debug(1, "Control Receiver -- Retransmitted Audio Data Packet %u received.", seqno); - int64_t timestamp = monotonic_timestamp(ntohl(*(uint32_t *)(pktp + 4)), conn); + uint32_t actual_timestamp = ntohl(*(uint32_t *)(pktp + 4)); + int64_t timestamp = monotonic_timestamp(actual_timestamp, conn); pktp += 12; plen -= 12; // check if packet contains enough content to be reasonable if (plen >= 16) { - player_put_packet(seqno, timestamp, pktp, plen, conn); + player_put_packet(seqno, actual_timestamp, timestamp, pktp, plen, conn); continue; } else { debug(3, "Too-short retransmitted audio packet received in control port, ignored.");