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

incorporate 3.2d30 stuff -- lots of important bug fixes -- and include the extra diagnostic information from RC2

Browse Source
This commit is contained in:
Mike Brady
2018-04-14 14:06:09 +01:00
parent ad450d745b 49d5486df6
commit 3823f337d0
6 changed files with 451 additions and 386 deletions
Download Patch File Download Diff File Expand all files Collapse all files
common.h
+2 -1
View File
@@ -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
player.c
+51 -26
View File
@@ -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;
@@ -462,11 +463,12 @@ static void free_audio_buffers(rtsp_conn_info *conn) {
free(conn->audio_buffer[i].data);
}
void player_put_packet(seq_t seqno, uint32_t actual_timestamp, 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.
// 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;
@@ -504,6 +506,38 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp
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);
@@ -518,6 +552,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp
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->given_timestamp = 0;
abuf->sequence_number = 0;
@@ -557,6 +592,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp
} 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;
@@ -578,7 +614,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;
}
@@ -718,8 +754,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
@@ -799,6 +833,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);
}
@@ -1175,28 +1210,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 = ((125 * 44100) / 352) / 1000; // approx 125 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;
@@ -1670,11 +1690,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(3, "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);
@@ -1776,6 +1797,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,
@@ -1895,7 +1919,8 @@ static void *player_thread_func(void *arg) {
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, delay, td_in_frames, rt, nt, current_delay,
inframe->sequence_number, inframe->given_timestamp);
}
sync_error_out_of_bounds++;
} else {
player.h
+3 -3
View File
@@ -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;
uint32_t given_timestamp; // for debugging and checking
@@ -194,9 +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, uint32_t actual_timestamp, 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
// timestamp guaranteed to start between 2^32 2^33
rtp.c
+374 -353
View File
@@ -39,6 +39,7 @@
#include <netinet/in.h>
#include <pthread.h>
#include <stdio.h>
#include <stdlib.h>
#include <sys/socket.h>
#include <sys/types.h>
#include <time.h>
@@ -124,51 +125,60 @@ void *rtp_audio_receiver(void *arg) {
time_of_previous_packet_fp = local_time_now_fp;
}
if (nread < 0)
break;
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
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;
debug(3,"resent packet %u received in audio port.",ntohs(*(uint16_t *)(pktp + 2)));
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);
}
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.");
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, actual_timestamp, 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);
}
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);
last_seqno = seqno; // reset warning...
}
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.");
pktp += 12;
plen -= 12;
// check if packet contains enough content to be reasonable
if (plen >= 16) {
player_put_packet(seqno, actual_timestamp, timestamp, pktp, plen, conn);
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.");
@@ -201,186 +211,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.");
}
}
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 {
uint8_t type = packet[1] & ~0x80;
if ((type == 0x60) || (type == 0x56)) { // audio data / resent audio data in the control path -- whaale only?
pktp = packet;
if (type == 0x56) { // resent audio data in the control path -- whaale only?
// debug(1, "Control Port -- Retransmitted Audio Data Packet received.");
} 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));
if (type==0x56)
debug(3,"Resent audio packet %u received in the control port.",seqno);
else
debug(1,"Audio packet %u received in the control port.",seqno);
uint32_t actual_timestamp = ntohl(*(uint32_t *)(pktp + 4));
int64_t timestamp = monotonic_timestamp(actual_timestamp, conn);
seq_t seqno = ntohs(*(uint16_t *)(pktp + 2));
debug(1, "Control Receiver -- Retransmitted Audio Data Packet %u received.", seqno);
pktp += 12;
plen -= 12;
uint32_t actual_timestamp = ntohl(*(uint32_t *)(pktp + 4));
int64_t timestamp = monotonic_timestamp(actual_timestamp, conn);
// check if packet contains enough content to be reasonable
pktp += 12;
plen -= 12;
if (plen >= 16) {
player_put_packet(seqno, actual_timestamp, timestamp, pktp, plen, conn);
continue;
} else {
debug(3, "Too-short retransmitted audio packet received in control port, ignored.");
}
// check if packet contains enough content to be reasonable
if (plen >= 16) {
player_put_packet(seqno, actual_timestamp, 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, "Control Port -- Unknown RTP packet of type 0x%02X length %d, ignored.", packet[1],
nread);
debug(1, "Control Receiver -- dropping a packet to simulate a bad network.");
}
} else {
debug(1, "Control Receiver -- error receiving a packet.");
}
}
@@ -506,192 +520,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;obfc<plen;obfc++) {
snprintf(obfp, 3, "%02X", packet[obfc]);
obfp+=2;
};
*obfp=0;
//debug(1,"Timing Packet Received: \"%s\"",obf);
*/
// 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;obfc<plen;obfc++) {
snprintf(obfp, 3, "%02X", packet[obfc]);
obfp+=2;
};
*obfp=0;
//debug(1,"Timing Packet Received: \"%s\"",obf);
*/
// arrival_time = ((uint64_t)att.tv_sec<<32)+((uint64_t)att.tv_nsec<<32)/1000000000;
// departure_time = ((uint64_t)dtt.tv_sec<<32)+((uint64_t)dtt.tv_nsec<<32)/1000000000;
// arrival_time = ((uint64_t)att.tv_sec<<32)+((uint64_t)att.tv_nsec<<32)/1000000000;
// departure_time = ((uint64_t)dtt.tv_sec<<32)+((uint64_t)dtt.tv_nsec<<32)/1000000000;
return_time = arrival_time - conn->departure_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(&current_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(&current_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.");
}
}
@@ -868,12 +889,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);
@@ -916,7 +937,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(2, "requesting resend of %d packets starting at %u.", count, first);
// request_sent = 1;
//}
scripts/shairport-sync.conf
+1
View File
@@ -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.001 would mean an average of 0.1% of packets are lost, which is actually quite a high figure.
};
shairport.c
+20 -3
View File
@@ -31,12 +31,12 @@
#include <libconfig.h>
#include <libgen.h>
#include <memory.h>
#include <sys/socket.h>
#include <net/if.h>
#include <popt.h>
#include <stdio.h>
#include <stdlib.h>
#include <sys/socket.h>
#include <sys/socket.h>
#include <sys/stat.h>
#include <sys/types.h>
#include <sys/wait.h>
@@ -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];