int64_t ranarray64i() { return (ranarrayval() >> 1); }
-uint32_t nctohl(const uint8_t *p) { // read 4 characters from the p and do ntohl on them
+uint32_t nctohl(const uint8_t *p) { // read 4 characters from *p and do ntohl on them
// this is to avoid possible aliasing violations
uint32_t holder;
memcpy(&holder, p, sizeof(holder));
return ntohl(holder);
}
+uint16_t nctohs(const uint8_t *p) { // read 2 characters from *p and do ntohs on them
+ // this is to avoid possible aliasing violations
+ uint16_t holder;
+ memcpy(&holder, p, sizeof(holder));
+ return ntohs(holder);
+}
+
pthread_mutex_t barrier_mutex = PTHREAD_MUTEX_INITIALIZER;
void memory_barrier() {
} shairport_cfg;
-uint32_t nctohl(const uint8_t *p); // read 4 characters from the p and do ntohl on them
+uint32_t nctohl(const uint8_t *p); // read 4 characters from *p and do ntohl on them
+uint16_t nctohs(const uint8_t *p); // read 2 characters from *p and do ntohs on them
+
void memory_barrier();
// true if Shairport Sync is supposed to be sending output to the output device, false otherwise
int ndata = recv(sockfd, buffer, sizeof(buffer), 0);
// debug(1,"Received %d bytes: \"%s\".",ndata,buffer);
if (ndata <= 0) {
- debug(1, "Error receiving data.");
+ debug(2, "dacp_send_command -- error receiving response for command \"%s\".",command);
free(response.body);
response.body = NULL;
response.malloced_size = 0;
// debug(1,"Sent command\"%s\" with a response body of size %d.",command,response.size);
// debug(1,"dacp_conversation_lock released.");
} else {
- debug(1, "Could not acquire a lock on the dacp transmit/receive section when attempting to "
+ debug(3, "Could not acquire a lock on the dacp transmit/receive section when attempting to "
"send the command \"%s\". Possible timeout?",
command);
response.code = 494; // This client is already busy
// index) hasn't already taken over the dacp service
sps_pthread_mutex_timedlock(
&dacp_server_information_lock, 500000,
- "set_dacp_server_information couldn't get DACP server information lock in 0.5 second!.", 1);
+ "set_dacp_server_information couldn't get DACP server information lock in 0.5 second!.", 2);
if (dacp_server.players_connection_thread_index == conn->connection_number)
dacp_server.players_connection_thread_index = 0;
pthread_mutex_unlock(&dacp_server_information_lock);
void set_dacp_server_information(rtsp_conn_info *conn) {
sps_pthread_mutex_timedlock(
&dacp_server_information_lock, 500000,
- "set_dacp_server_information couldn't get DACP server information lock in 0.5 second!.", 1);
+ "set_dacp_server_information couldn't get DACP server information lock in 0.5 second!.", 2);
dacp_server.players_connection_thread_index = conn->connection_number;
if (strcmp(conn->dacp_id, dacp_server.dacp_id) != 0) {
strncpy(dacp_server.dacp_id, conn->dacp_id, sizeof(dacp_server.dacp_id));
sps_pthread_mutex_timedlock(
&dacp_server_information_lock, 500000,
"dacp_monitor_port_update_callback couldn't get DACP server information lock in 0.5 second!.",
- 1);
+ 2);
if (strcmp(dacp_id, dacp_server.dacp_id) == 0) {
dacp_server.port = port;
if (port == 0)
metadata_hub_modify_epilog(ch);
pthread_cond_signal(&dacp_server_information_cv);
} else {
- debug(1, "dacp port monitor reporting on and out-of-use remote.");
+ debug(1, "dacp port monitor reporting on an out-of-use remote.");
}
pthread_mutex_unlock(&dacp_server_information_lock);
}
int result;
sps_pthread_mutex_timedlock(
&dacp_server_information_lock, 500000,
- "dacp_monitor_thread_code couldn't get DACP server information lock in 0.5 second!.", 1);
+ "dacp_monitor_thread_code couldn't get DACP server information lock in 0.5 second!.", 2);
while (dacp_server.scan_enable == 0) {
// debug(1, "Wait for a valid DACP port");
pthread_cond_wait(&dacp_server_information_cv, &dacp_server_information_lock);
case 2:
if (metadata_store.play_status != PS_STOPPED) {
metadata_store.play_status = PS_STOPPED;
- debug(1, "Play status is \"stopped\".");
+ debug(2, "Play status is \"stopped\".");
}
break;
case 3:
if (metadata_store.play_status != PS_PAUSED) {
metadata_store.play_status = PS_PAUSED;
- debug(1, "Play status is \"paused\".");
+ debug(2, "Play status is \"paused\".");
}
break;
case 4:
if (metadata_store.play_status != PS_PLAYING) {
metadata_store.play_status = PS_PLAYING;
- debug(1, "Play status changed to \"playing\".");
+ debug(2, "Play status changed to \"playing\".");
}
break;
default:
case 0:
if (metadata_store.shuffle_status != SS_OFF) {
metadata_store.shuffle_status = SS_OFF;
- debug(1, "Shuffle status is \"off\".");
+ debug(2, "Shuffle status is \"off\".");
}
break;
case 1:
if (metadata_store.shuffle_status != SS_ON) {
metadata_store.shuffle_status = SS_ON;
- debug(1, "Shuffle status is \"on\".");
+ debug(2, "Shuffle status is \"on\".");
}
break;
default:
case 0:
if (metadata_store.repeat_status != RS_OFF) {
metadata_store.repeat_status = RS_OFF;
- debug(1, "Repeat status is \"none\".");
+ debug(2, "Repeat status is \"none\".");
}
break;
case 1:
if (metadata_store.repeat_status != RS_ONE) {
metadata_store.repeat_status = RS_ONE;
- debug(1, "Repeat status is \"one\".");
+ debug(2, "Repeat status is \"one\".");
}
break;
case 2:
if (metadata_store.repeat_status != RS_ALL) {
metadata_store.repeat_status = RS_ALL;
- debug(1, "Repeat status is \"all\".");
+ debug(2, "Repeat status is \"all\".");
}
break;
default:
char *th = (char *)shairport_sync_advanced_remote_control_get_loop_status(skeleton);
// enum volume_control_profile_type previous_volume_control_profile =
// config.volume_control_profile;
- debug(1, "notify_loop_status_callback called with loop status of \"%s\".", th);
+ // debug(1, "notify_loop_status_callback called with loop status of \"%s\".", th);
if (strcasecmp(th, "off") == 0)
send_simple_dacp_command("setproperty?dacp.repeatstate=0");
else if (strcasecmp(th, "one") == 0)
release_char_string(&track_metadata->sort_as);
free((char *)track_metadata);
} else {
- debug(1, "Releasing non-existent track metadata");
+ debug(3, "Asked to release non-existent track metadata");
}
}
// supposed to start playing this
have_sent_prefiller_silence = 0;
+ // debug(1, "First packet timestamp is %" PRId64 ".", conn->first_packet_timestamp);
+
// say we have started playing here
#ifdef CONFIG_METADATA
- debug(1, "pffr");
+ debug(2, "pffr");
send_ssnc_metadata(
'pffr', NULL, 0,
0); // "first frame received", but don't wait if the queue is locked
&conn->play_segment_reference_frame_remote_time, conn);
conn->play_segment_reference_frame *= conn->output_sample_ratio;
#ifdef CONFIG_METADATA
- debug(1, "prsm");
+ debug(2, "prsm");
send_ssnc_metadata('prsm', NULL, 0,
0); // "resume", but don't wait if the queue is locked
#endif
conn->fix_volume = 0x10000;
if (conn->latency == 0) {
- debug(3, "No latency has (yet) been specified. Setting 99,226 (2.25 seconds + 1 frame) frames "
+ debug(3, "No latency has (yet) been specified. Setting 88,200 (2 seconds) frames "
"as a default.");
- conn->latency = 99226;
+ conn->latency = 88200;
}
int rc = pthread_mutex_init(&conn->ab_mutex, NULL);
// only send a flush metadata message if the first packet has been seen -- it's a bogus message
// otherwise
if (conn->first_packet_timestamp) {
- debug(1, "pfls");
+ debug(2, "pfls");
send_ssnc_metadata('pfls', NULL, 0, 1);
}
#endif
BUFFER_FRAMES);
command_start();
#ifdef CONFIG_METADATA
- debug(1, "pbeg");
+ debug(2, "pbeg");
send_ssnc_metadata('pbeg', NULL, 0, 1);
#endif
pthread_t *pt = malloc(sizeof(pthread_t));
pthread_kill(*conn->player_thread, SIGUSR1);
pthread_join(*conn->player_thread, NULL);
#ifdef CONFIG_METADATA
- debug(1, "pend");
+ debug(2, "pend");
send_ssnc_metadata('pend', NULL, 0, 1);
#endif
command_stop();
// default buffer size
// needs to be a power of 2 because of the way BUFIDX(seqno) works
-#define BUFFER_FRAMES 512
+#define BUFFER_FRAMES 1024
typedef struct {
int encrypted;
int control_socket; // our local [server] control socket
int timing_socket; // local timing socket
+ int64_t latency_delayed_timestamp; // this is for debugging only...
int64_t reference_timestamp;
uint64_t reference_timestamp_time;
uint64_t remote_reference_timestamp_time;
* OTHER DEALINGS IN THE SOFTWARE.
*/
+#include "rtp.h"
+#include "common.h"
+#include "player.h"
+#include "rtsp.h"
#include <arpa/inet.h>
#include <errno.h>
#include <fcntl.h>
+#include <inttypes.h>
#include <math.h>
#include <memory.h>
#include <netdb.h>
#include <time.h>
#include <unistd.h>
-#include "common.h"
-#include "player.h"
-#include "rtp.h"
-#include "rtsp.h"
-
uint64_t local_to_remote_time_jitters;
uint64_t local_to_remote_time_jitters_count;
int rc = pthread_mutex_init(&conn->reference_time_mutex, NULL);
if (rc)
debug(1, "Error initialising reference_time_mutex.");
+
}
void rtp_terminate(rtsp_conn_info *conn) {
ssize_t plen = nread;
if (packet[1] == 0xd4) { // sync data
- /*
- char obf[4096];
- char *obfp = obf;
- int obfc;
- for (obfc=0;obfc<plen;obfc++) {
- sprintf(obfp,"%02X",packet[obfc]);
- obfp+=2;
- };
- *obfp=0;
- debug(1,"Sync Packet Received: \"%s\"",obf);
- */
+/*
+ // the following stanza is for debugging only -- normally commented out.
+ {
+ char obf[4096];
+ char *obfp = obf;
+ int obfc;
+ for (obfc = 0; obfc < plen; obfc++) {
+ sprintf(obfp, "%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.
+
+ // 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 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;
// 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: %lld.", config.userSuppliedLatency);
+ debug(1, "Using the user-supplied latency: %" PRId64 ".", config.userSuppliedLatency);
}
conn->latency = config.userSuppliedLatency;
- } else if (packet[0] &
- 0x10) { // only set latency if it's a packet just after a flush or resume
- int64_t rtp_timestamp_less_latency = monotonic_timestamp(nctohl(&packet[4]), conn);
- int64_t la = sync_rtp_timestamp - rtp_timestamp_less_latency + config.fixedLatencyOffset;
+ } 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(1, "New latency: %lld, sync latency: %lld, minimum latency: %lld, maximum "
- // "latency: %lld, fixed offset: %lld.",
- // 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);
+ }
}
}
- // need to clarify this.
-
- if (packet[0] & 0x10) {
- // if it's a packet right after a flush or resume
- sync_rtp_timestamp += 352; // add frame_size -- can't see a reference to this anywhere,
- // but it seems to get everything into sync.
- // it's as if the first sync after a flush or resume is the timing of the next packet
- // after the one whose RTP is given. Weird.
- }
-
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;
inet_ntop(conn->connection_ip_family, self_addr, conn->self_ip_string,
sizeof(conn->self_ip_string));
- debug(1, "Set up play connection from %s to self at %s on RTSP conversation thread %d.",
+ debug(2, "Set up play connection from %s to self at %s on RTSP conversation thread %d.",
conn->client_ip_string, conn->self_ip_string, conn->connection_number);
// set up a the record of the remote's control socket
playing_conn = NULL;
pthread_mutex_unlock(&play_lock);
}
- debug(1, "RTSP conversation thread %d terminated.", conn->connection_number);
+ debug(2, "RTSP conversation thread %d terminated.", conn->connection_number);
// please_shutdown = 0;
conn->running = 0;
return NULL;
projects / thirdparty / shairport-sync.git / commitdiff
