From 23eb7d7038cad59fee8ea7cbbfc3bafd296d30c2 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Thu, 22 Nov 2018 10:08:00 +0000 Subject: [PATCH 01/13] Update shairport-sync.conf --- scripts/shairport-sync.conf | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/scripts/shairport-sync.conf b/scripts/shairport-sync.conf index 4697a6a3..42c085b0 100644 --- a/scripts/shairport-sync.conf +++ b/scripts/shairport-sync.conf @@ -107,9 +107,9 @@ pipe = // name = "/path/to/pipe"; // there is no default pipe name for the output }; -// These are no configuration file parameters for the "stdout" audio back end. No interpolation is done. +// There are no configuration file parameters for the "stdout" audio back end. No interpolation is done. -// These are no configuration file parameters for the "ao" audio back end. No interpolation is done. +// There are no configuration file parameters for the "ao" audio back end. No interpolation is done. // Static latency settings are deprecated and the settings have been removed. From 0e6835589ca9adcbf0dd6906132e59ec127de643 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Thu, 22 Nov 2018 21:57:54 +0000 Subject: [PATCH 02/13] Try making dropping and closing the DAC un-cancelable to stop the bcm DMA problem. Add some diagnostics. --- audio_alsa.c | 3 +++ player.c | 21 +++++++++++++++------ 2 files changed, 18 insertions(+), 6 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index ab3d172c..3039fa65 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -1051,6 +1051,8 @@ static int play(void *buf, int samples) { static void flush(void) { // debug(2,"audio_alsa flush called."); + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 1); int derr; do_mute(1); @@ -1072,6 +1074,7 @@ static void flush(void) { } debug_mutex_unlock(&alsa_mutex, 3); pthread_cleanup_pop(0); // release the mutex + pthread_setcancelstate(oldState, NULL); } static void stop(void) { diff --git a/player.c b/player.c index 8b16f3c1..751621e4 100644 --- a/player.c +++ b/player.c @@ -464,6 +464,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in conn->initial_reference_time = 0; conn->initial_reference_timestamp = 0; } else { + /* if ((conn->flush_rtp_timestamp != 0) && (modulo_32_offset(conn->flush_rtp_timestamp, actual_timestamp) > conn->input_rate / 5) && (modulo_32_offset(conn->flush_rtp_timestamp, actual_timestamp) < conn->input_rate)) { @@ -471,6 +472,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in debug(2, "Dropping flush request in player_put_packet"); conn->flush_rtp_timestamp = 0; } + */ abuf_t *abuf = 0; @@ -849,7 +851,10 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { debug(1, "Inconsistent sequence numbers detected"); } } - + + //if (conn->flush_rtp_timestamp != 0) + // debug(2,"flush_rtp_timestamp is %" PRIx32 " and curframe->given_timestamp is %" PRIx32 ".", conn->flush_rtp_timestamp , curframe->given_timestamp); + if ((conn->flush_rtp_timestamp != 0) && (curframe->given_timestamp != conn->flush_rtp_timestamp) && (modulo_32_offset(curframe->given_timestamp, conn->flush_rtp_timestamp) < @@ -945,11 +950,13 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { conn->first_packet_time_to_play = should_be_time; - if (local_time_now >= conn->first_packet_time_to_play) { + if (local_time_now > conn->first_packet_time_to_play) { + uint64_t lateness = local_time_now - conn->first_packet_time_to_play; + lateness = (lateness * 1000000) >> 32; // microseconds debug( 1, - "First packet is late! It should have played before now. Flushing 0.5 seconds"); - player_flush(conn->first_packet_timestamp + 5 * 4410 * conn->output_sample_ratio, + "First packet is %" PRIu64 " microseconds late! Flushing 0.5 seconds",lateness); + do_flush(conn->first_packet_timestamp + 5 * 4410, conn); } } @@ -978,8 +985,10 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { // dynamic adjustment int64_t filler_size = max_dac_delay; - if (local_time_now >= conn->first_packet_time_to_play) { - // debug(1,"Gone past starting time"); + if (local_time_now > conn->first_packet_time_to_play) { + uint64_t lateness = local_time_now - conn->first_packet_time_to_play; + lateness = (lateness * 1000000) >> 32; // microseconds + debug(1,"Gone past starting time by %" PRIu64 " microseconds.", lateness); have_sent_prefiller_silence = 1; conn->ab_buffering = 0; From 3709ac8180a1c7ee9d8c3eaf02c385b06d48fbd9 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 23 Nov 2018 08:53:27 +0000 Subject: [PATCH 03/13] experimental --- audio_alsa.c | 3 +- rtp.c | 46 +++++++++++----- rtsp.c | 151 ++++++++++++++++++++++++++++++--------------------- 3 files changed, 125 insertions(+), 75 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index 3039fa65..5ca4836c 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -489,7 +489,8 @@ static int init(int argc, char **argv) { } close_mixer(); } - pthread_cleanup_pop(1); // release the mutex + debug_mutex_unlock(&alsa_mutex, 3); // release the mutex + pthread_cleanup_pop(0); } else { // debug(1, "Has no mixer and thus no hardware mute."); } diff --git a/rtp.c b/rtp.c index 8995571f..92837e58 100644 --- a/rtp.c +++ b/rtp.c @@ -58,7 +58,7 @@ void rtp_initialise(rtsp_conn_info *conn) { } void rtp_terminate(rtsp_conn_info *conn) { - + conn->reference_timestamp = 0; // destroy the timer mutex int rc = pthread_mutex_destroy(&conn->reference_time_mutex); if (rc) @@ -125,9 +125,15 @@ void *rtp_audio_receiver(void *arg) { float stat_mean = 0.0; float stat_M2 = 0.0; + int frame_count = 0; ssize_t nread; while (1) { nread = recv(conn->audio_socket, packet, sizeof(packet), 0); + + frame_count++; + if (frame_count<10) + debug(1,"Recv'ed %d bytes. First two bytes are %02X,%02X ",nread,packet[0],packet[1]); + else { uint64_t local_time_now_fp = get_absolute_time_in_fp(); if (time_of_previous_packet_fp) { @@ -167,6 +173,19 @@ void *rtp_audio_receiver(void *arg) { // increment last_seqno and see if it's the same as the incoming seqno if (type == 0x60) { // regular audio data + + /* + char obf[4096]; + char *obfp = obf; + int obfc; + for (obfc=0;obfclocal_to_remote_time_difference) { // need a time packet to be interchanged @@ -585,10 +605,10 @@ void *rtp_timing_receiver(void *arg) { (drand48() > config.diagnostic_drop_packet_fraction)) { arrival_time = get_absolute_time_in_fp(); - // ssize_t plen = nread; + 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; @@ -597,8 +617,8 @@ void *rtp_timing_receiver(void *arg) { obfp+=2; }; *obfp=0; - //debug(1,"Timing Packet Received: \"%s\"",obf); - */ + 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; diff --git a/rtsp.c b/rtsp.c index 9f34c5d1..db6e99f4 100644 --- a/rtsp.c +++ b/rtsp.c @@ -89,7 +89,9 @@ enum rtsp_read_request_response { }; // Mike Brady's part... -static pthread_mutex_t play_lock = PTHREAD_MUTEX_INITIALIZER; + +// always lock use this when accessing the playing conn value +static pthread_mutex_t playing_conn_lock = PTHREAD_MUTEX_INITIALIZER; // every time we want to retain or release a reference count, lock it with this // if a reference count is read as zero, it means the it's being deallocated. @@ -279,8 +281,6 @@ void cancel_all_RTSP_threads(void) { for (i = 0; i < nconns; i++) { debug(1, "Connection %d: joining.", conns[i]->connection_number); pthread_join(conns[i]->thread, NULL); - if (conns[i] == playing_conn) - playing_conn = NULL; free(conns[i]); } } @@ -295,8 +295,6 @@ void cleanup_threads(void) { conns[i]->connection_number); pthread_join(conns[i]->thread, &retval); debug(3, "RTSP connection thread %d deleted...", conns[i]->connection_number); - if (conns[i] == playing_conn) - playing_conn = NULL; free(conns[i]); nconns--; if (nconns) @@ -461,7 +459,7 @@ int msg_handle_line(rtsp_message **pmsg, char *line) { char *sp, *p; sp = NULL; // this is to quieten a compiler warning - // debug(1, "received request: %s", line); + debug(1, "received request: %s", line); p = strtok_r(line, " ", &sp); if (!p) @@ -898,8 +896,9 @@ void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { error: warn("Connection %d: SETUP -- Error in setup request -- unlocking play lock.", conn->connection_number); - playing_conn = NULL; - pthread_mutex_unlock(&play_lock); + debug_mutex_lock(&playing_conn_lock, 1000000 , 3); + playing_conn = NULL; // this connection definitely doesn't have the play lock + debug_mutex_unlock(&playing_conn_lock, 3); resp->respcode = 451; // invalid arguments } @@ -1523,62 +1522,76 @@ static void handle_set_parameter(rtsp_conn_info *conn, rtsp_message *req, rtsp_m static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { debug(2, "Connection %d: ANNOUNCE", conn->connection_number); + + int have_the_player = 0; - - // interrupt session if permitted - if (pthread_mutex_trylock(&play_lock) == 0) { + int should_wait = 0; + + // try to become the current playing_conn + + debug_mutex_lock(&playing_conn_lock, 1000000 , 3); //get it + + if (playing_conn == NULL) { + playing_conn = conn; have_the_player = 1; - } else if ((playing_conn) && - (playing_conn->connection_number == conn->connection_number)) { // duplicate ANNOUNCE - warn("Duplicate ANNOUNCE, by the look of it!"); - have_the_player = 1; - } else { - int should_wait = 0; - - if (!playing_conn) - die("Non existent playing_conn with play_lock enabled."); - debug(1, "Connection %d: ANNOUNCE: already playing when checked by connection %d.", - playing_conn->connection_number, conn->connection_number); - if (playing_conn->stop) { - debug(1, "Connetion %d: ANNOUNCE: already shutting down; waiting for it...",playing_conn->connection_number); + } else if (playing_conn == conn) { + have_the_player = 1; + warn("Duplicate ANNOUNCE, by the look of it!"); + } else if (playing_conn->stop) { + debug(1, "Connection %d: ANNOUNCE: already shutting down; waiting for it...",playing_conn->connection_number); should_wait = 1; - } else if (config.allow_session_interruption == 1) { - // some thread has the player ... ask it to relinquish the thread - debug(1, "Connection %d: ANNOUNCE: asking playing connection %d to shut down.", + } else if (config.allow_session_interruption == 1) { + debug(1, "Connection %d: ANNOUNCE: asking playing connection %d to shut down.", conn->connection_number, playing_conn->connection_number); - if (playing_conn == conn) { - debug(1, "Connection %d: ANNOUNCE: asking to stop itself! Nothing done.",conn->connection_number); - } else { - player_stop(playing_conn); - playing_conn->stop = 1; - pthread_cancel(playing_conn->thread); // asking the RTSP thread to exit - should_wait = 1; - } - } + playing_conn->stop = 1; + pthread_cancel(playing_conn->thread); // asking the RTSP thread to exit + should_wait = 1; + } + debug_mutex_unlock(&playing_conn_lock, 3); - if (should_wait) { - useconds_t time_remaining = 3000000; + if (should_wait) { + useconds_t time_remaining = 3000000; - while ((time_remaining > 0) && (have_the_player == 0)) { - if (pthread_mutex_trylock(&play_lock) == 0) - have_the_player = 1; - else { + while ((time_remaining > 0) && (have_the_player == 0)) { + debug_mutex_lock(&playing_conn_lock, 1000000 , 3); //get it + if (playing_conn == NULL) { + playing_conn = conn; + have_the_player = 1; + } + debug_mutex_unlock(&playing_conn_lock, 3); + + if (have_the_player == 0) { usleep(100000); time_remaining -= 100000; } } - if (have_the_player == 1) { - debug(1, "Connection %d: ANNOUNCE got the player", conn->connection_number); - usleep(1000000); // this is just to let everything settle a bit - } else - debug(1, "Connection %d: ANNOUNCE failed to get the player", conn->connection_number); + + if (have_the_player == 1) { + debug(1, "Connection %d: ANNOUNCE got the player", conn->connection_number); + usleep(2000000); // this is just to let everything settle a bit + } else { + debug(1, "Connection %d: ANNOUNCE failed to get the player", conn->connection_number); } } if (have_the_player) { - playing_conn = conn; // the present connection is now playing debug(3, "RTSP conversation thread %d has acquired play lock.", conn->connection_number); + + { + char *cp = req->content; + int cp_left = req->contentlength; + while (cp_left > 1) { + if (strlen(cp) != 0) + warn(" %s", cp); + cp += strlen(cp) + 1; + cp_left -= strlen(cp) + 1; + } + } + + + resp->respcode = 456; // 456 - Header Field Not Valid for Resource + char *pssid = NULL; char *paesiv = NULL; char *prsaaeskey = NULL; char *pfmtp = NULL; @@ -1601,6 +1614,9 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag goto out; } + if (!strncmp(cp, "o=iTunes", 7)) + pssid = cp + 8; + if (!strncmp(cp, "a=fmtp:", 7)) pfmtp = cp + 7; @@ -1618,6 +1634,11 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag cp = next; } + + if (pssid) { + uint32_t ssid = uatoi(pssid); + debug(1, "Synchronisation Source Identifier: %08X,%u", ssid,ssid); + } if (pminlatency) { conn->minimum_latency = atoi(pminlatency); @@ -1719,10 +1740,11 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag out: if (resp->respcode != 200 && resp->respcode != 453) { - debug(1, "Error in handling ANNOUNCE on conversation thread %d. Unlocking the play lock.", + debug(1, "Connection %d: Error in handling ANNOUNCE. Unlocking the play lock.", conn->connection_number); + debug_mutex_lock(&playing_conn_lock, 1000000 , 3); //get it playing_conn = NULL; - pthread_mutex_unlock(&play_lock); + debug_mutex_unlock(&playing_conn_lock, 3); } } @@ -1970,26 +1992,19 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { // debug(1, "Connection %d: closing fd %d.", // conn->connection_number,conn->fd); close(conn->fd); + usleep(1000000); } if (conn->auth_nonce) { free(conn->auth_nonce); conn->auth_nonce = NULL; } rtp_terminate(conn); - if (playing_conn == conn) { - debug(3, "Connection %d: Unlocking play lock.", conn->connection_number); - playing_conn = NULL; - pthread_mutex_unlock(&play_lock); - } - + if (conn->dacp_id) { free(conn->dacp_id); conn->dacp_id = NULL; } - debug(2, "Connection %d: RTSP thread terminated.", conn->connection_number); - conn->running = 0; - // remove flow control and mutexes int rc = pthread_cond_destroy(&conn->flowcontrol); if (rc) @@ -2001,6 +2016,16 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { rc = pthread_mutex_destroy(&conn->flush_mutex); if (rc) debug(1, "Connection %d: error %d destroying flush_mutex.", conn->connection_number, rc); + + debug_mutex_lock(&playing_conn_lock, 1000000 , 3); //get it + if (playing_conn == conn) { + debug(1, "Connection %d: Unlocking play lock.", conn->connection_number); + playing_conn = NULL; + } + debug_mutex_unlock(&playing_conn_lock, 3); + + debug(2, "Connection %d: RTSP thread terminated.", conn->connection_number); + conn->running = 0; } void msg_cleanup_function(void *arg) { @@ -2109,6 +2134,8 @@ static void *rtsp_conversation_thread_func(void *pconn) { int err = msg_write_response(conn->fd, resp); if (err) { debug(1, "Connection %d: Unable to write an RTSP message response. Terminating the connection.", conn->connection_number); + if (debuglev != 0) + debuglev = 3; // see what happens next conn->stop = 1; } } @@ -2122,9 +2149,11 @@ static void *rtsp_conversation_thread_func(void *pconn) { (reply == rtsp_read_request_response_read_error)) { if (conn->player_thread) { rtsp_read_request_attempt_count--; - if (rtsp_read_request_attempt_count == 0) + if (rtsp_read_request_attempt_count == 0) { tstop = 1; - else { + if ((reply == rtsp_read_request_response_read_error) && (debuglev != 0)) + debuglev = 3; // see what happens next + } else { if (reply == rtsp_read_request_response_channel_closed) debug(2, "Connection %d: RTSP channel unexpectedly closed -- will try again %d time(s).", conn->connection_number, rtsp_read_request_attempt_count); From 093bf1dd46970a140a9199302bccb606930b0cf8 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 23 Nov 2018 13:29:09 +0000 Subject: [PATCH 04/13] Rotate usage of UDP ports if a session is interrupted. Avoids out-of-date packets landing in a new session. --- common.c | 17 +++++++++++++++++ common.h | 11 +++++++++++ player.c | 6 +++--- rtp.c | 25 ++++++++++++------------- rtsp.c | 22 ++++++++++++++-------- scripts/shairport-sync.conf | 2 +- shairport.c | 6 +++--- 7 files changed, 61 insertions(+), 28 deletions(-) diff --git a/common.c b/common.c index b0b34b3e..f735dba4 100644 --- a/common.c +++ b/common.c @@ -94,6 +94,23 @@ volatile int debuglev = 0; sigset_t pselect_sigset; +static uint16_t UDPPortIndex = 0; + +void resetFreeUDPPort() { + UDPPortIndex = 0; +} + +uint16_t nextFreeUDPPort() { + + if (UDPPortIndex == 0) + UDPPortIndex = config.udp_port_base; + else if (UDPPortIndex == (config.udp_port_base + config.udp_port_range)) + UDPPortIndex = config.udp_port_base; + else + UDPPortIndex++; + return UDPPortIndex; +} + int get_requested_connection_state_to_output() { return requested_connection_state_to_output; } void set_requested_connection_state_to_output(int v) { requested_connection_state_to_output = v; } diff --git a/common.h b/common.h index 0a84b725..a043d0f7 100644 --- a/common.h +++ b/common.h @@ -243,6 +243,17 @@ void r64arrayinit(); uint64_t ranarray64u(); int64_t ranarray64i(); +// if you are breaking in to a session, you need to avoid the ports of the current session +// if you are law-abiding, then you can reuse the ports. +// so, you can reset the free UDP ports minder when you're legit, and leave it otherwise + +// the downside of using different ports each time is that it might make the firewall +// rules a bit more complex, as they need to allow more than the minimum three ports. +// a range of 10 is suggested anyway + +void resetFreeUDPPort(); +uint16_t nextFreeUDPPort(); + volatile int debuglev; void die(const char *format, ...); void warn(const char *format, ...); diff --git a/player.c b/player.c index 751621e4..f1837573 100644 --- a/player.c +++ b/player.c @@ -457,7 +457,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in if ((conn->flush_rtp_timestamp != 0) && (actual_timestamp != conn->flush_rtp_timestamp) && (modulo_32_offset(actual_timestamp, conn->flush_rtp_timestamp) < conn->input_rate * 10)) { // if it's less than 10 seconds - debug(2, "Dropping flushed packet in player_put_packet, seqno %u, timestamp %" PRIu32 + debug(3, "Dropping flushed packet in player_put_packet, seqno %u, timestamp %" PRIu32 ", flushing to " "timestamp: %" PRIu32 ".", seqno, actual_timestamp, conn->flush_rtp_timestamp); @@ -859,7 +859,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { (curframe->given_timestamp != conn->flush_rtp_timestamp) && (modulo_32_offset(curframe->given_timestamp, conn->flush_rtp_timestamp) < conn->input_rate * 10)) { // if it's less than ten seconds - debug(2, "Dropping flushed packet in buffer_get_frame, seqno %u, timestamp %" PRIu32 + debug(3, "Dropping flushed packet in buffer_get_frame, seqno %u, timestamp %" PRIu32 ", flushing to " "timestamp: %" PRIu32 ".", curframe->sequence_number, curframe->given_timestamp, conn->flush_rtp_timestamp); @@ -874,7 +874,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { conn->input_rate / 5) && (modulo_32_offset(conn->flush_rtp_timestamp, curframe->given_timestamp) < conn->input_rate * 10)) { - debug(2, "Dropping flush request in buffer_get_frame"); + debug(3, "Dropping flush request in buffer_get_frame"); conn->flush_rtp_timestamp = 0; } } diff --git a/rtp.c b/rtp.c index 92837e58..4b71c0ee 100644 --- a/rtp.c +++ b/rtp.c @@ -129,11 +129,8 @@ void *rtp_audio_receiver(void *arg) { ssize_t nread; while (1) { nread = recv(conn->audio_socket, packet, sizeof(packet), 0); - + frame_count++; - if (frame_count<10) - debug(1,"Recv'ed %d bytes. First two bytes are %02X,%02X ",nread,packet[0],packet[1]); - else { uint64_t local_time_now_fp = get_absolute_time_in_fp(); if (time_of_previous_packet_fp) { @@ -200,8 +197,8 @@ void *rtp_audio_receiver(void *arg) { uint32_t actual_timestamp = ntohl(*(uint32_t *)(pktp + 4)); - uint32_t ssid = ntohl(*(uint32_t *)(pktp + 8)); - debug(1, "Audio packet SSID: %08X,%u", ssid,ssid); + // uint32_t ssid = ntohl(*(uint32_t *)(pktp + 8)); + // debug(1, "Audio packet SSID: %08X,%u", ssid,ssid); // if (packet[1]&0x10) // debug(1,"Audio packet Extension bit set."); @@ -229,7 +226,6 @@ void *rtp_audio_receiver(void *arg) { } else { debug(1, "Error receiving an audio packet."); } - } } /* @@ -605,10 +601,10 @@ void *rtp_timing_receiver(void *arg) { (drand48() > config.diagnostic_drop_packet_fraction)) { arrival_time = get_absolute_time_in_fp(); - ssize_t plen = nread; + // 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; @@ -618,7 +614,7 @@ void *rtp_timing_receiver(void *arg) { }; *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; @@ -855,14 +851,17 @@ void *rtp_timing_receiver(void *arg) { static uint16_t bind_port(int ip_family, const char *self_ip_address, uint32_t scope_id, int *sock) { // look for a port in the range, if any was specified. - uint16_t desired_port = config.udp_port_base; int ret = 0; int local_socket = socket(ip_family, SOCK_DGRAM, IPPROTO_UDP); if (local_socket == -1) die("Could not allocate a socket."); SOCKADDR myaddr; + int tryCount = 0; + uint16_t desired_port; do { + tryCount++; + desired_port = nextFreeUDPPort(); memset(&myaddr, 0, sizeof(myaddr)); if (ip_family == AF_INET) { struct sockaddr_in *sa = (struct sockaddr_in *)&myaddr; @@ -883,13 +882,13 @@ static uint16_t bind_port(int ip_family, const char *self_ip_address, uint32_t s #endif } while ((ret < 0) && (errno == EADDRINUSE) && (desired_port != 0) && - (++desired_port < config.udp_port_base + config.udp_port_range)); + (tryCount < config.udp_port_range)); // debug(1,"UDP port chosen: %d.",desired_port); if (ret < 0) { close(local_socket); - die("error: could not bind a UDP port! Check the udp_port_range is large enough (>= 10) or " + die("error: could not bind a UDP port! Check the udp_port_range is large enough -- it must be at least 3, and 10 or more is suggested -- or " "check for restrictive firewall settings or a bad router!"); } diff --git a/rtsp.c b/rtsp.c index db6e99f4..50bda29a 100644 --- a/rtsp.c +++ b/rtsp.c @@ -459,7 +459,7 @@ int msg_handle_line(rtsp_message **pmsg, char *line) { char *sp, *p; sp = NULL; // this is to quieten a compiler warning - debug(1, "received request: %s", line); + debug(3, "RTSP Message Received: \"%s\".", line); p = strtok_r(line, " ", &sp); if (!p) @@ -1525,7 +1525,7 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag int have_the_player = 0; - int should_wait = 0; + int should_wait = 0; // this will be true if you're trying to break in to the current session // try to become the current playing_conn @@ -1568,7 +1568,6 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag if (have_the_player == 1) { debug(1, "Connection %d: ANNOUNCE got the player", conn->connection_number); - usleep(2000000); // this is just to let everything settle a bit } else { debug(1, "Connection %d: ANNOUNCE failed to get the player", conn->connection_number); } @@ -1577,17 +1576,25 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag if (have_the_player) { debug(3, "RTSP conversation thread %d has acquired play lock.", conn->connection_number); + // now, if this new session did not break in, then it's okay to reset the next UDP ports + // to the start of the range + + if (should_wait == 0) { // will be zero if it didn't need to wait to break in + resetFreeUDPPort(); + } + + /* { char *cp = req->content; int cp_left = req->contentlength; while (cp_left > 1) { if (strlen(cp) != 0) - warn(" %s", cp); + debug(1,">>>>>> %s", cp); cp += strlen(cp) + 1; cp_left -= strlen(cp) + 1; } } - +*/ resp->respcode = 456; // 456 - Header Field Not Valid for Resource @@ -1637,7 +1644,7 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag if (pssid) { uint32_t ssid = uatoi(pssid); - debug(1, "Synchronisation Source Identifier: %08X,%u", ssid,ssid); + debug(3, "Synchronisation Source Identifier: %08X,%u", ssid,ssid); } if (pminlatency) { @@ -1992,7 +1999,6 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { // debug(1, "Connection %d: closing fd %d.", // conn->connection_number,conn->fd); close(conn->fd); - usleep(1000000); } if (conn->auth_nonce) { free(conn->auth_nonce); @@ -2019,7 +2025,7 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { debug_mutex_lock(&playing_conn_lock, 1000000 , 3); //get it if (playing_conn == conn) { - debug(1, "Connection %d: Unlocking play lock.", conn->connection_number); + debug(3, "Connection %d: Unlocking play lock.", conn->connection_number); playing_conn = NULL; } debug_mutex_unlock(&playing_conn_lock, 3); diff --git a/scripts/shairport-sync.conf b/scripts/shairport-sync.conf index 42c085b0..55ac4cbf 100644 --- a/scripts/shairport-sync.conf +++ b/scripts/shairport-sync.conf @@ -18,7 +18,7 @@ general = // mdns_backend = "avahi"; // Run "shairport-sync -h" to get a list of all mdns_backends. The default is the first one. // port = 5000; // Listen for service requests on this port // udp_port_base = 6001; // start allocating UDP ports from this port number when needed -// udp_port_range = 100; // look for free ports in this number of places, starting at the UDP port base. Allow at least 10, though only three are needed in a steady state. +// udp_port_range = 10; // look for free ports in this number of places, starting at the UDP port base. Allow at least 10, though only three are needed in a steady state. // drift_tolerance_in_seconds = 0.002; // allow a timing error of this number of seconds of drift away from exact synchronisation before attempting to correct it // resync_threshold_in_seconds = 0.050; // a synchronisation error greater than this number of seconds will cause resynchronisation; 0 disables it // ignore_volume_control = "no"; // set this to "yes" if you want the volume to be at 100% no matter what the source's volume control is set to. diff --git a/shairport.c b/shairport.c index 5e36e911..506f9feb 100644 --- a/shairport.c +++ b/shairport.c @@ -419,8 +419,8 @@ int parse_options(int argc, char **argv) { /* Get the udp port range setting. This is number of ports that will be tried for free ports , * starting at the port base. Only three ports are needed. */ if (config_lookup_int(config.cfg, "general.udp_port_range", &value)) { - if ((value < 0) || (value > 65535)) - die("Invalid port range \"%sd\". It should be between 0 and 65535, default is 100", + if ((value < 3) || (value > 65535)) + die("Invalid port range \"%sd\". It should be between 3 and 65535, default is 10", value); else config.udp_port_range = value; @@ -1234,7 +1234,7 @@ int main(int argc, char **argv) { 1); // we expect to be able to connect to the output device config.audio_backend_buffer_desired_length = 6615; // 0.15 seconds. config.udp_port_base = 6001; - config.udp_port_range = 100; + config.udp_port_range = 10; config.output_format = SPS_FORMAT_S16; // default config.output_rate = 44100; // default config.decoders_supported = From 4c5790de28b074376c628fd0acc70fd6bb38efe7 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 23 Nov 2018 13:39:23 +0000 Subject: [PATCH 05/13] Fix off-by-one error in UDP range counting --- common.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/common.c b/common.c index f735dba4..9b1a5538 100644 --- a/common.c +++ b/common.c @@ -104,7 +104,7 @@ uint16_t nextFreeUDPPort() { if (UDPPortIndex == 0) UDPPortIndex = config.udp_port_base; - else if (UDPPortIndex == (config.udp_port_base + config.udp_port_range)) + else if (UDPPortIndex == (config.udp_port_base + config.udp_port_range - 1)) UDPPortIndex = config.udp_port_base; else UDPPortIndex++; From 1e5219faa9a11c3c39c3fd140770d74bbfac0a12 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 23 Nov 2018 13:40:42 +0000 Subject: [PATCH 06/13] Fix bugs in interrupting an existing session, and use fresh ports if necessary. --- configure.ac | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/configure.ac b/configure.ac index efc335ce..786ed9c4 100644 --- a/configure.ac +++ b/configure.ac @@ -2,7 +2,7 @@ # Process this file with autoconf to produce a configure script. AC_PREREQ([2.50]) -AC_INIT([shairport-sync], [3.3d28], [mikebrady@eircom.net]) +AC_INIT([shairport-sync], [3.3d29], [mikebrady@eircom.net]) AM_INIT_AUTOMAKE AC_CONFIG_SRCDIR([shairport.c]) AC_CONFIG_HEADERS([config.h]) From ae1453f8aa5e7567c2df549c6817a094204903da Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 23 Nov 2018 13:57:34 +0000 Subject: [PATCH 07/13] Stop going to verbosity level 3 on occasion. It's not so useful now. --- player.c | 8 ++++---- rtsp.c | 6 ++---- 2 files changed, 6 insertions(+), 8 deletions(-) diff --git a/player.c b/player.c index f1837573..859e3d7f 100644 --- a/player.c +++ b/player.c @@ -2776,8 +2776,8 @@ int player_play(rtsp_conn_info *conn) { int player_stop(rtsp_conn_info *conn) { // note -- this may be called from another connection thread. - int dl = debuglev; - debuglev = 3; + //int dl = debuglev; + // debuglev = 3; debug(3, "player_stop"); if (conn->player_thread) { debug(2, "player_thread cancel..."); @@ -2791,12 +2791,12 @@ int player_stop(rtsp_conn_info *conn) { debug(2, "pend"); send_ssnc_metadata('pend', NULL, 0, 1); // contains cancellation points #endif - debuglev = dl; + // debuglev = dl; command_stop(); return 0; } else { debug(3, "Connection %d: player thread already deleted.", conn->connection_number); - debuglev = dl; + // debuglev = dl; return -1; } } diff --git a/rtsp.c b/rtsp.c index 50bda29a..b4d9d4df 100644 --- a/rtsp.c +++ b/rtsp.c @@ -2140,8 +2140,6 @@ static void *rtsp_conversation_thread_func(void *pconn) { int err = msg_write_response(conn->fd, resp); if (err) { debug(1, "Connection %d: Unable to write an RTSP message response. Terminating the connection.", conn->connection_number); - if (debuglev != 0) - debuglev = 3; // see what happens next conn->stop = 1; } } @@ -2157,8 +2155,8 @@ static void *rtsp_conversation_thread_func(void *pconn) { rtsp_read_request_attempt_count--; if (rtsp_read_request_attempt_count == 0) { tstop = 1; - if ((reply == rtsp_read_request_response_read_error) && (debuglev != 0)) - debuglev = 3; // see what happens next + // if ((reply == rtsp_read_request_response_read_error) && (debuglev != 0)) + // debuglev = 3; // see what happens next } else { if (reply == rtsp_read_request_response_channel_closed) debug(2, "Connection %d: RTSP channel unexpectedly closed -- will try again %d time(s).", From d93aeec50aaf3ed79ac2e10bfdda6a171c3a2236 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 23 Nov 2018 15:11:04 +0000 Subject: [PATCH 08/13] Quieten a few debug messages. --- player.c | 8 ++++---- rtp.c | 12 ++++++------ rtsp.c | 6 +++--- 3 files changed, 13 insertions(+), 13 deletions(-) diff --git a/player.c b/player.c index 859e3d7f..dcd2a93e 100644 --- a/player.c +++ b/player.c @@ -954,7 +954,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { uint64_t lateness = local_time_now - conn->first_packet_time_to_play; lateness = (lateness * 1000000) >> 32; // microseconds debug( - 1, + 3, "First packet is %" PRIu64 " microseconds late! Flushing 0.5 seconds",lateness); do_flush(conn->first_packet_timestamp + 5 * 4410, conn); @@ -988,7 +988,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { if (local_time_now > conn->first_packet_time_to_play) { uint64_t lateness = local_time_now - conn->first_packet_time_to_play; lateness = (lateness * 1000000) >> 32; // microseconds - debug(1,"Gone past starting time by %" PRIu64 " microseconds.", lateness); + debug(3,"Gone past starting time by %" PRIu64 " microseconds.", lateness); have_sent_prefiller_silence = 1; conn->ab_buffering = 0; @@ -1642,11 +1642,11 @@ void *player_thread_func(void *arg) { debug(3, "Output bit depth is %d.", output_bit_depth); if (conn->input_bit_depth > output_bit_depth) { - debug(1, "Dithering will be enabled because the input bit depth is greater than the output bit " + debug(3, "Dithering will be enabled because the input bit depth is greater than the output bit " "depth"); } if (conn->fix_volume != 0x10000) { - debug(1, "Dithering will be enabled because the output volume is being altered in software"); + debug(3, "Dithering will be enabled because the output volume is being altered in software"); } // we need an intermediate "transition" buffer diff --git a/rtp.c b/rtp.c index 4b71c0ee..4e5a98d6 100644 --- a/rtp.c +++ b/rtp.c @@ -100,9 +100,9 @@ uint64_t local_to_remote_time_difference_now(rtsp_conn_info *conn) { void rtp_audio_receiver_cleanup_handler(void *arg) { debug(3, "Audio Receiver Cleanup."); rtsp_conn_info *conn = (rtsp_conn_info *)arg; - debug(1, "shutdown audio socket."); + debug(3, "shutdown audio socket."); shutdown(conn->audio_socket, SHUT_RDWR); - debug(1, "close audio socket."); + debug(3, "close audio socket."); close(conn->audio_socket); debug(3, "Audio Receiver Cleanup Successful."); @@ -242,9 +242,9 @@ void *rtp_audio_receiver(void *arg) { void rtp_control_handler_cleanup_handler(void *arg) { debug(3, "Control Receiver Cleanup."); rtsp_conn_info *conn = (rtsp_conn_info *)arg; - debug(1, "shutdown control socket."); + debug(3, "shutdown control socket."); shutdown(conn->control_socket, SHUT_RDWR); - debug(1, "close control socket."); + debug(3, "close control socket."); close(conn->control_socket); debug(3, "Control Receiver Cleanup Successful."); } @@ -561,9 +561,9 @@ void rtp_timing_receiver_cleanup_handler(void *arg) { rtsp_conn_info *conn = (rtsp_conn_info *)arg; pthread_cancel(conn->timer_requester); pthread_join(conn->timer_requester, NULL); - debug(1, "shutdown timing socket."); + debug(3, "shutdown timing socket."); shutdown(conn->timing_socket, SHUT_RDWR); - debug(1, "close timing socket."); + debug(3, "close timing socket."); close(conn->timing_socket); debug(3, "Timing Receiver Cleanup Successful."); } diff --git a/rtsp.c b/rtsp.c index b4d9d4df..6d783c73 100644 --- a/rtsp.c +++ b/rtsp.c @@ -543,7 +543,7 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes continue; char errorstring[1024]; strerror_r(errno, (char *)errorstring, sizeof(errorstring)); - debug(1, "rtsp_read_request_response_read_error %d: \"%s\".", errno, (char *)errorstring); + debug(1, "Connection %d: rtsp_read_request_response_read_error %d: \"%s\".", conn->connection_number, errno, (char *)errorstring); reply = rtsp_read_request_response_read_error; goto shutdown; } @@ -2106,7 +2106,7 @@ static void *rtsp_conversation_thread_func(void *pconn) { } } if (method_selected == 0) { - debug(1, "Connection %d: Unrecognised and unhandled rtsp request \"%s\".", + debug(3, "Connection %d: Unrecognised and unhandled rtsp request \"%s\".", conn->connection_number, req->method); int y = req->contentlength; @@ -2123,7 +2123,7 @@ static void *rtsp_conversation_thread_func(void *pconn) { obfp += 2; }; *obfp = 0; - debug(1, "Content: \"%s\".", obf); + debug(3, "Content: \"%s\".", obf); } } } From dcd8fbc1eca09eb0210ebaa643025eca600034b2 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 23 Nov 2018 16:10:18 +0000 Subject: [PATCH 09/13] Remove some unnecessary test code from the debug messaging. --- common.c | 10 +--------- 1 file changed, 1 insertion(+), 9 deletions(-) diff --git a/common.c b/common.c index 9b1a5538..bf062edd 100644 --- a/common.c +++ b/common.c @@ -100,8 +100,7 @@ void resetFreeUDPPort() { UDPPortIndex = 0; } -uint16_t nextFreeUDPPort() { - +uint16_t nextFreeUDPPort() { if (UDPPortIndex == 0) UDPPortIndex = config.udp_port_base; else if (UDPPortIndex == (config.udp_port_base + config.udp_port_range - 1)) @@ -190,10 +189,6 @@ void debug(int level, const char *format, ...) { va_start(args, format); vsnprintf(s, sizeof(s), format, args); va_end(args); - int currentState; - pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, ¤tState); - if (currentState == PTHREAD_CANCEL_ENABLE) - daemon_log(LOG_DEBUG, "Warning -- cancellation is enabled before logging"); if ((config.debugger_show_elapsed_time) && (config.debugger_show_relative_time)) daemon_log(LOG_DEBUG, "|% 20.9f|% 20.9f|%s", tss, tsl, s); else if (config.debugger_show_relative_time) @@ -202,9 +197,6 @@ void debug(int level, const char *format, ...) { daemon_log(LOG_DEBUG, "% 20.9f|%s", tss, s); else daemon_log(LOG_DEBUG, "%s", s); - pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, ¤tState); - if (currentState == PTHREAD_CANCEL_ENABLE) - daemon_log(LOG_DEBUG, "Warning -- cancellation is enabled after logging"); pthread_setcancelstate(oldState, NULL); } From a932298d3a6deee479bf5e90d691843763f63fa9 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sat, 24 Nov 2018 11:06:20 +0000 Subject: [PATCH 10/13] Small correction to port selection logic. If a new sesion waits for an existing session to close that it hasn't interrupted, reset the ports base. Quieten some debug messages. --- rtsp.c | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/rtsp.c b/rtsp.c index 6d783c73..cd46598e 100644 --- a/rtsp.c +++ b/rtsp.c @@ -1526,6 +1526,7 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag int have_the_player = 0; int should_wait = 0; // this will be true if you're trying to break in to the current session + int interrupting_current_session = 0; // try to become the current playing_conn @@ -1538,14 +1539,15 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag have_the_player = 1; warn("Duplicate ANNOUNCE, by the look of it!"); } else if (playing_conn->stop) { - debug(1, "Connection %d: ANNOUNCE: already shutting down; waiting for it...",playing_conn->connection_number); + debug(2, "Connection %d: ANNOUNCE: already shutting down; waiting for it...",playing_conn->connection_number); should_wait = 1; } else if (config.allow_session_interruption == 1) { - debug(1, "Connection %d: ANNOUNCE: asking playing connection %d to shut down.", + debug(2, "Connection %d: ANNOUNCE: asking playing connection %d to shut down.", conn->connection_number, playing_conn->connection_number); playing_conn->stop = 1; - pthread_cancel(playing_conn->thread); // asking the RTSP thread to exit + interrupting_current_session = 1; should_wait = 1; + pthread_cancel(playing_conn->thread); // asking the RTSP thread to exit } debug_mutex_unlock(&playing_conn_lock, 3); @@ -1566,10 +1568,10 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag } } - if (have_the_player == 1) { - debug(1, "Connection %d: ANNOUNCE got the player", conn->connection_number); + if ((have_the_player == 1) && (interrupting_current_session == 1)) { + debug(2, "Connection %d: ANNOUNCE got the player", conn->connection_number); } else { - debug(1, "Connection %d: ANNOUNCE failed to get the player", conn->connection_number); + debug(2, "Connection %d: ANNOUNCE failed to get the player", conn->connection_number); } } @@ -1579,7 +1581,7 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag // now, if this new session did not break in, then it's okay to reset the next UDP ports // to the start of the range - if (should_wait == 0) { // will be zero if it didn't need to wait to break in + if (interrupting_current_session == 0) { // will be zero if it wasn't waiting to break in resetFreeUDPPort(); } From 998e7cea2cbededebca3d1524e25b7b6a4d06cf8 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sat, 24 Nov 2018 11:16:57 +0000 Subject: [PATCH 11/13] clang-format --- common.c | 20 +++++++-------- player.c | 44 ++++++++++++++++----------------- rtp.c | 25 ++++++++++--------- rtsp.c | 74 +++++++++++++++++++++++++++++--------------------------- 4 files changed, 84 insertions(+), 79 deletions(-) diff --git a/common.c b/common.c index bf062edd..0d76a4f4 100644 --- a/common.c +++ b/common.c @@ -96,18 +96,16 @@ sigset_t pselect_sigset; static uint16_t UDPPortIndex = 0; -void resetFreeUDPPort() { - UDPPortIndex = 0; -} +void resetFreeUDPPort() { UDPPortIndex = 0; } -uint16_t nextFreeUDPPort() { - if (UDPPortIndex == 0) - UDPPortIndex = config.udp_port_base; - else if (UDPPortIndex == (config.udp_port_base + config.udp_port_range - 1)) - UDPPortIndex = config.udp_port_base; - else - UDPPortIndex++; - return UDPPortIndex; +uint16_t nextFreeUDPPort() { + if (UDPPortIndex == 0) + UDPPortIndex = config.udp_port_base; + else if (UDPPortIndex == (config.udp_port_base + config.udp_port_range - 1)) + UDPPortIndex = config.udp_port_base; + else + UDPPortIndex++; + return UDPPortIndex; } int get_requested_connection_state_to_output() { return requested_connection_state_to_output; } diff --git a/player.c b/player.c index dcd2a93e..8211c8dc 100644 --- a/player.c +++ b/player.c @@ -464,15 +464,16 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in conn->initial_reference_time = 0; conn->initial_reference_timestamp = 0; } else { - /* - if ((conn->flush_rtp_timestamp != 0) && - (modulo_32_offset(conn->flush_rtp_timestamp, actual_timestamp) > conn->input_rate / 5) && - (modulo_32_offset(conn->flush_rtp_timestamp, actual_timestamp) < conn->input_rate)) { - // between 0.2 and 1 second - debug(2, "Dropping flush request in player_put_packet"); - conn->flush_rtp_timestamp = 0; - } - */ + /* + if ((conn->flush_rtp_timestamp != 0) && + (modulo_32_offset(conn->flush_rtp_timestamp, actual_timestamp) > conn->input_rate / 5) + && + (modulo_32_offset(conn->flush_rtp_timestamp, actual_timestamp) < conn->input_rate)) { + // between 0.2 and 1 second + debug(2, "Dropping flush request in player_put_packet"); + conn->flush_rtp_timestamp = 0; + } + */ abuf_t *abuf = 0; @@ -851,10 +852,11 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { debug(1, "Inconsistent sequence numbers detected"); } } - - //if (conn->flush_rtp_timestamp != 0) - // debug(2,"flush_rtp_timestamp is %" PRIx32 " and curframe->given_timestamp is %" PRIx32 ".", conn->flush_rtp_timestamp , curframe->given_timestamp); - + + // if (conn->flush_rtp_timestamp != 0) + // debug(2,"flush_rtp_timestamp is %" PRIx32 " and curframe->given_timestamp is %" PRIx32 + // ".", conn->flush_rtp_timestamp , curframe->given_timestamp); + if ((conn->flush_rtp_timestamp != 0) && (curframe->given_timestamp != conn->flush_rtp_timestamp) && (modulo_32_offset(curframe->given_timestamp, conn->flush_rtp_timestamp) < @@ -953,11 +955,9 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { if (local_time_now > conn->first_packet_time_to_play) { uint64_t lateness = local_time_now - conn->first_packet_time_to_play; lateness = (lateness * 1000000) >> 32; // microseconds - debug( - 3, - "First packet is %" PRIu64 " microseconds late! Flushing 0.5 seconds",lateness); - do_flush(conn->first_packet_timestamp + 5 * 4410, - conn); + debug(3, "First packet is %" PRIu64 " microseconds late! Flushing 0.5 seconds", + lateness); + do_flush(conn->first_packet_timestamp + 5 * 4410, conn); } } } @@ -988,7 +988,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { if (local_time_now > conn->first_packet_time_to_play) { uint64_t lateness = local_time_now - conn->first_packet_time_to_play; lateness = (lateness * 1000000) >> 32; // microseconds - debug(3,"Gone past starting time by %" PRIu64 " microseconds.", lateness); + debug(3, "Gone past starting time by %" PRIu64 " microseconds.", lateness); have_sent_prefiller_silence = 1; conn->ab_buffering = 0; @@ -2476,8 +2476,8 @@ void *player_thread_func(void *arg) { debug(1, "This should never be called."); pthread_cleanup_pop(1); // pop the cleanup handler -// debug(1, "This should never be called either."); -// pthread_cleanup_pop(1); // pop the initial cleanup handler + // debug(1, "This should never be called either."); + // pthread_cleanup_pop(1); // pop the initial cleanup handler pthread_exit(NULL); } @@ -2776,7 +2776,7 @@ int player_play(rtsp_conn_info *conn) { int player_stop(rtsp_conn_info *conn) { // note -- this may be called from another connection thread. - //int dl = debuglev; + // int dl = debuglev; // debuglev = 3; debug(3, "player_stop"); if (conn->player_thread) { diff --git a/rtp.c b/rtp.c index 4e5a98d6..0c97fc31 100644 --- a/rtp.c +++ b/rtp.c @@ -104,7 +104,7 @@ void rtp_audio_receiver_cleanup_handler(void *arg) { shutdown(conn->audio_socket, SHUT_RDWR); debug(3, "close audio socket."); close(conn->audio_socket); - + debug(3, "Audio Receiver Cleanup Successful."); } @@ -170,8 +170,8 @@ void *rtp_audio_receiver(void *arg) { // increment last_seqno and see if it's the same as the incoming seqno if (type == 0x60) { // regular audio data - - /* + + /* char obf[4096]; char *obfp = obf; int obfc; @@ -181,8 +181,8 @@ void *rtp_audio_receiver(void *arg) { }; *obfp=0; debug(1,"Audio Packet Received: \"%s\"",obf); - */ - + */ + if (last_seqno == -1) last_seqno = seqno; else { @@ -196,7 +196,7 @@ void *rtp_audio_receiver(void *arg) { } uint32_t actual_timestamp = ntohl(*(uint32_t *)(pktp + 4)); - + // uint32_t ssid = ntohl(*(uint32_t *)(pktp + 8)); // debug(1, "Audio packet SSID: %08X,%u", ssid,ssid); @@ -308,8 +308,10 @@ void *rtp_control_receiver(void *arg) { 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)); + 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 @@ -860,8 +862,8 @@ static uint16_t bind_port(int ip_family, const char *self_ip_address, uint32_t s int tryCount = 0; uint16_t desired_port; do { - tryCount++; - desired_port = nextFreeUDPPort(); + tryCount++; + desired_port = nextFreeUDPPort(); memset(&myaddr, 0, sizeof(myaddr)); if (ip_family == AF_INET) { struct sockaddr_in *sa = (struct sockaddr_in *)&myaddr; @@ -888,7 +890,8 @@ static uint16_t bind_port(int ip_family, const char *self_ip_address, uint32_t s if (ret < 0) { close(local_socket); - die("error: could not bind a UDP port! Check the udp_port_range is large enough -- it must be at least 3, and 10 or more is suggested -- or " + die("error: could not bind a UDP port! Check the udp_port_range is large enough -- it must be " + "at least 3, and 10 or more is suggested -- or " "check for restrictive firewall settings or a bad router!"); } diff --git a/rtsp.c b/rtsp.c index cd46598e..99000174 100644 --- a/rtsp.c +++ b/rtsp.c @@ -543,7 +543,8 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes continue; char errorstring[1024]; strerror_r(errno, (char *)errorstring, sizeof(errorstring)); - debug(1, "Connection %d: rtsp_read_request_response_read_error %d: \"%s\".", conn->connection_number, errno, (char *)errorstring); + debug(1, "Connection %d: rtsp_read_request_response_read_error %d: \"%s\".", + conn->connection_number, errno, (char *)errorstring); reply = rtsp_read_request_response_read_error; goto shutdown; } @@ -896,7 +897,7 @@ void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { error: warn("Connection %d: SETUP -- Error in setup request -- unlocking play lock.", conn->connection_number); - debug_mutex_lock(&playing_conn_lock, 1000000 , 3); + debug_mutex_lock(&playing_conn_lock, 1000000, 3); playing_conn = NULL; // this connection definitely doesn't have the play lock debug_mutex_unlock(&playing_conn_lock, 3); resp->respcode = 451; // invalid arguments @@ -1522,40 +1523,40 @@ static void handle_set_parameter(rtsp_conn_info *conn, rtsp_message *req, rtsp_m static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { debug(2, "Connection %d: ANNOUNCE", conn->connection_number); - - + int have_the_player = 0; int should_wait = 0; // this will be true if you're trying to break in to the current session int interrupting_current_session = 0; - + // try to become the current playing_conn - - debug_mutex_lock(&playing_conn_lock, 1000000 , 3); //get it - + + debug_mutex_lock(&playing_conn_lock, 1000000, 3); // get it + if (playing_conn == NULL) { playing_conn = conn; have_the_player = 1; } else if (playing_conn == conn) { - have_the_player = 1; - warn("Duplicate ANNOUNCE, by the look of it!"); + have_the_player = 1; + warn("Duplicate ANNOUNCE, by the look of it!"); } else if (playing_conn->stop) { - debug(2, "Connection %d: ANNOUNCE: already shutting down; waiting for it...",playing_conn->connection_number); - should_wait = 1; + debug(2, "Connection %d: ANNOUNCE: already shutting down; waiting for it...", + playing_conn->connection_number); + should_wait = 1; } else if (config.allow_session_interruption == 1) { debug(2, "Connection %d: ANNOUNCE: asking playing connection %d to shut down.", - conn->connection_number, playing_conn->connection_number); + conn->connection_number, playing_conn->connection_number); playing_conn->stop = 1; interrupting_current_session = 1; - should_wait = 1; + should_wait = 1; pthread_cancel(playing_conn->thread); // asking the RTSP thread to exit - } + } debug_mutex_unlock(&playing_conn_lock, 3); if (should_wait) { useconds_t time_remaining = 3000000; - + while ((time_remaining > 0) && (have_the_player == 0)) { - debug_mutex_lock(&playing_conn_lock, 1000000 , 3); //get it + debug_mutex_lock(&playing_conn_lock, 1000000, 3); // get it if (playing_conn == NULL) { playing_conn = conn; have_the_player = 1; @@ -1563,10 +1564,10 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag debug_mutex_unlock(&playing_conn_lock, 3); if (have_the_player == 0) { - usleep(100000); - time_remaining -= 100000; - } + usleep(100000); + time_remaining -= 100000; } + } if ((have_the_player == 1) && (interrupting_current_session == 1)) { debug(2, "Connection %d: ANNOUNCE got the player", conn->connection_number); @@ -1577,14 +1578,14 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag if (have_the_player) { debug(3, "RTSP conversation thread %d has acquired play lock.", conn->connection_number); - + // now, if this new session did not break in, then it's okay to reset the next UDP ports // to the start of the range - + if (interrupting_current_session == 0) { // will be zero if it wasn't waiting to break in - resetFreeUDPPort(); + resetFreeUDPPort(); } - + /* { char *cp = req->content; @@ -1597,8 +1598,7 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag } } */ - - + resp->respcode = 456; // 456 - Header Field Not Valid for Resource char *pssid = NULL; char *paesiv = NULL; @@ -1643,11 +1643,11 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag cp = next; } - + if (pssid) { uint32_t ssid = uatoi(pssid); - debug(3, "Synchronisation Source Identifier: %08X,%u", ssid,ssid); - } + debug(3, "Synchronisation Source Identifier: %08X,%u", ssid, ssid); + } if (pminlatency) { conn->minimum_latency = atoi(pminlatency); @@ -1751,7 +1751,7 @@ out: if (resp->respcode != 200 && resp->respcode != 453) { debug(1, "Connection %d: Error in handling ANNOUNCE. Unlocking the play lock.", conn->connection_number); - debug_mutex_lock(&playing_conn_lock, 1000000 , 3); //get it + debug_mutex_lock(&playing_conn_lock, 1000000, 3); // get it playing_conn = NULL; debug_mutex_unlock(&playing_conn_lock, 3); } @@ -2007,7 +2007,7 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { conn->auth_nonce = NULL; } rtp_terminate(conn); - + if (conn->dacp_id) { free(conn->dacp_id); conn->dacp_id = NULL; @@ -2025,7 +2025,7 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { if (rc) debug(1, "Connection %d: error %d destroying flush_mutex.", conn->connection_number, rc); - debug_mutex_lock(&playing_conn_lock, 1000000 , 3); //get it + debug_mutex_lock(&playing_conn_lock, 1000000, 3); // get it if (playing_conn == conn) { debug(3, "Connection %d: Unlocking play lock.", conn->connection_number); playing_conn = NULL; @@ -2141,7 +2141,9 @@ static void *rtsp_conversation_thread_func(void *pconn) { if (conn->stop == 0) { int err = msg_write_response(conn->fd, resp); if (err) { - debug(1, "Connection %d: Unable to write an RTSP message response. Terminating the connection.", conn->connection_number); + debug(1, "Connection %d: Unable to write an RTSP message response. Terminating the " + "connection.", + conn->connection_number); conn->stop = 1; } } @@ -2161,7 +2163,8 @@ static void *rtsp_conversation_thread_func(void *pconn) { // debuglev = 3; // see what happens next } else { if (reply == rtsp_read_request_response_channel_closed) - debug(2, "Connection %d: RTSP channel unexpectedly closed -- will try again %d time(s).", + debug(2, + "Connection %d: RTSP channel unexpectedly closed -- will try again %d time(s).", conn->connection_number, rtsp_read_request_attempt_count); if (reply == rtsp_read_request_response_read_error) debug(2, "Connection %d: RTSP channel read error -- will try again %d time(s).", @@ -2172,7 +2175,8 @@ static void *rtsp_conversation_thread_func(void *pconn) { tstop = 1; } } else { - debug(1, "Connection %d: rtsp_read_request error %d, packet ignored.", conn->connection_number, (int)reply); + debug(1, "Connection %d: rtsp_read_request error %d, packet ignored.", + conn->connection_number, (int)reply); } if (tstop) { debug(3, "Connection %d: Terminate RTSP connection.", conn->connection_number); From 57ae8ad846c4a9b5713a269e1def2cb7382e598f Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sat, 24 Nov 2018 11:35:16 +0000 Subject: [PATCH 12/13] Change order of header files (again?) to avoid OpenBSD compilation errors. --- shairport.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/shairport.c b/shairport.c index 506f9feb..c9212544 100644 --- a/shairport.c +++ b/shairport.c @@ -31,11 +31,11 @@ #include #include #include -#include #include #include #include #include +#include #include #include #include From 3b4654df7703c58d3d2fefa74c7543ed39851875 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sat, 24 Nov 2018 22:28:52 +0000 Subject: [PATCH 13/13] Make some alsa operation sequences un-cancellable. Make some cleanup sequences un-cancellable. --- audio_alsa.c | 33 ++++++++++++++++++++++++++++++--- rtp.c | 23 +++++++++++++++++++---- 2 files changed, 49 insertions(+), 7 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index 5ca4836c..24132fe6 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -405,6 +405,8 @@ static int init(int argc, char **argv) { debug(1, "alsa output device name is \"%s\".", alsa_out_dev); if (hardware_mixer) { + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable if (alsa_mix_dev == NULL) alsa_mix_dev = alsa_out_dev; @@ -491,6 +493,7 @@ static int init(int argc, char **argv) { } debug_mutex_unlock(&alsa_mutex, 3); // release the mutex pthread_cleanup_pop(0); + pthread_setcancelstate(oldState, NULL); } else { // debug(1, "Has no mixer and thus no hardware mute."); } @@ -504,7 +507,7 @@ static void deinit(void) { stop(); } -int open_alsa_device(void) { +int actual_open_alsa_device(void) { // the alsa mutex is already acquired when this is called const snd_pcm_uframes_t minimal_buffer_headroom = 352 * 2; // we accept this much headroom in the hardware buffer, but we'll @@ -851,6 +854,15 @@ int open_alsa_device(void) { return 0; } +int open_alsa_device(void) { + int result; + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable + result = actual_open_alsa_device(); + pthread_setcancelstate(oldState, NULL); + return result; +} + static void start(int i_sample_rate, int i_sample_format) { // debug(2,"audio_alsa start called."); if (i_sample_rate == 0) @@ -874,6 +886,8 @@ int delay(long *the_delay) { if (alsa_handle == NULL) { return -ENODEV; } else { + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 1); int derr; snd_pcm_state_t dac_state = snd_pcm_state(alsa_handle); @@ -926,6 +940,7 @@ int delay(long *the_delay) { // here, occasionally pretend there's a problem with pcm_get_delay() // if ((random() % 100000) < 3) // keep it pretty rare // reply = -EIO; // pretend something bad has happened + pthread_setcancelstate(oldState, NULL); return reply; } } @@ -945,10 +960,13 @@ int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played) { static int play(void *buf, int samples) { // debug(3,"audio_alsa play called."); + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable int ret = 0; if (alsa_handle == NULL) { + pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 1); - ret = open_alsa_device(); + ret = actual_open_alsa_device(); if (ret == 0) { if (audio_alsa.volume) do_volume(set_volume); @@ -1047,13 +1065,14 @@ static int play(void *buf, int samples) { debug_mutex_unlock(&alsa_mutex, 3); pthread_cleanup_pop(0); // release the mutex } + pthread_setcancelstate(oldState, NULL); return ret; } static void flush(void) { // debug(2,"audio_alsa flush called."); int oldState; - pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 1); int derr; do_mute(1); @@ -1094,6 +1113,8 @@ static void parameters(audio_parameters *info) { } void do_volume(double vol) { // caller is assumed to have the alsa_mutex when using this function + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable debug(3, "Setting volume db to %f.", vol); set_volume = vol; if (volume_set_request && (open_mixer() == 1)) { @@ -1125,6 +1146,7 @@ void do_volume(double vol) { // caller is assumed to have the alsa_mutex when us volume_set_request = 0; // any external request that has been made is now satisfied close_mixer(); } + pthread_setcancelstate(oldState, NULL); } void volume(double vol) { @@ -1165,6 +1187,9 @@ static void mute(int mute_state_requested) { void do_mute(int mute_state_requested) { + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable + // if a mute is requested now, then // if an external mute request is in place, leave everything muted // otherwise, if an external mute request is pending, action it @@ -1205,4 +1230,6 @@ void do_mute(int mute_state_requested) { } } mute_request_pending = 0; + + pthread_setcancelstate(oldState, NULL); } diff --git a/rtp.c b/rtp.c index 0c97fc31..afee1a4b 100644 --- a/rtp.c +++ b/rtp.c @@ -98,14 +98,16 @@ uint64_t local_to_remote_time_difference_now(rtsp_conn_info *conn) { } void rtp_audio_receiver_cleanup_handler(void *arg) { + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); debug(3, "Audio Receiver Cleanup."); rtsp_conn_info *conn = (rtsp_conn_info *)arg; debug(3, "shutdown audio socket."); shutdown(conn->audio_socket, SHUT_RDWR); debug(3, "close audio socket."); close(conn->audio_socket); - - debug(3, "Audio Receiver Cleanup Successful."); + debug(3, "Connection %d: Audio Receiver Cleanup.", conn->connection_number); + pthread_setcancelstate(oldState, NULL); } void *rtp_audio_receiver(void *arg) { @@ -240,13 +242,16 @@ void *rtp_audio_receiver(void *arg) { } void rtp_control_handler_cleanup_handler(void *arg) { + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); debug(3, "Control Receiver Cleanup."); rtsp_conn_info *conn = (rtsp_conn_info *)arg; debug(3, "shutdown control socket."); shutdown(conn->control_socket, SHUT_RDWR); debug(3, "close control socket."); close(conn->control_socket); - debug(3, "Control Receiver Cleanup Successful."); + debug(3, "Connection %d: Control Receiver Cleanup.", conn->connection_number); + pthread_setcancelstate(oldState, NULL); } void *rtp_control_receiver(void *arg) { @@ -495,7 +500,13 @@ void *rtp_control_receiver(void *arg) { pthread_exit(NULL); } +void rtp_timing_sender_cleanup_handler(void *arg) { + rtsp_conn_info *conn = (rtsp_conn_info *)arg; + debug(3, "Connection %d: Timing Sender Cleanup.", conn->connection_number); +} + void *rtp_timing_sender(void *arg) { + pthread_cleanup_push(rtp_timing_sender_cleanup_handler, arg); rtsp_conn_info *conn = (rtsp_conn_info *)arg; struct timing_request { char leader; @@ -555,10 +566,13 @@ void *rtp_timing_sender(void *arg) { usleep(3000000); } debug(3, "rtp_timing_sender thread interrupted. This should never happen."); + pthread_cleanup_pop(0); // don't execute anything here. pthread_exit(NULL); } void rtp_timing_receiver_cleanup_handler(void *arg) { + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); debug(3, "Timing Receiver Cleanup."); rtsp_conn_info *conn = (rtsp_conn_info *)arg; pthread_cancel(conn->timer_requester); @@ -567,7 +581,8 @@ void rtp_timing_receiver_cleanup_handler(void *arg) { shutdown(conn->timing_socket, SHUT_RDWR); debug(3, "close timing socket."); close(conn->timing_socket); - debug(3, "Timing Receiver Cleanup Successful."); + debug(3, "Connection %d: Timing Receiver Cleanup.", conn->connection_number); + pthread_setcancelstate(oldState, NULL); } void *rtp_timing_receiver(void *arg) {