From: Mike Brady Date: Sat, 14 Apr 2018 12:01:42 +0000 (+0100) Subject: Fix serious and long-standing bugs in the control, audio and timing threads that... X-Git-Tag: 3.2RC3b~2^2~3 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=e76a6366683d4346e54a9a7fd91daa1dd8afe5b5;p=thirdparty%2Fshairport-sync.git 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. --- 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; + } + 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); } - } else { - debug(1, "Audio Port -- Retransmitted Audio Data Packet %u received.", seqno); - } - int64_t timestamp = monotonic_timestamp(ntohl(*(uint32_t *)(pktp + 4)), conn); + int64_t timestamp = monotonic_timestamp(ntohl(*(uint32_t *)(pktp + 4)), conn); - // if (packet[1]&0x10) - // debug(1,"Audio packet Extension bit set."); + // if (packet[1]&0x10) + // debug(1,"Audio packet Extension bit set."); - pktp += 12; - plen -= 12; + 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; + // 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); } - 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; - - 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 (nread >= 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... - - 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); - - 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 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]); + + // 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); + + // 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 { + + // 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. + + // 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; + + 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 != 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 (config.userSuppliedLatency) { - if (config.userSuppliedLatency != conn->latency) { - debug(1, "Using the user-supplied latency: %" PRId64 ".", config.userSuppliedLatency); + 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."); } - 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. + } 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); - // The value of 11,025 (0.25 seconds) is a guess based on the "Audio-Latency" parameter - // returned by an AE. + int64_t timestamp = monotonic_timestamp(ntohl(*(uint32_t *)(pktp + 4)), conn); - // Sigh, it would be nice to have a published protocol... + pktp += 12; + plen -= 12; - 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; - - 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); + // check if packet contains enough content to be reasonable + if (plen >= 16) { + player_put_packet(seqno, timestamp, pktp, plen, conn); + continue; } 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); - } + debug(3, "Too-short retransmitted audio packet received in control port, ignored."); } - } - - 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 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(1, "Control Receiver -- Unknown RTP packet of type 0x%02X length %d, ignored.", + packet[1], nread); } else { - debug(3, "Too-short retransmitted audio packet received in control port, ignored."); + debug(1, "Control Receiver -- dropping a packet to simulate a bad network."); } - } 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 + } + // 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; + } + // 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 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; + // 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 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; + 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 { - // 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. };