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. };