From 76ee6d5e4385cba38a5e10629a0113c00bc31635 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Mon, 26 Nov 2018 19:33:22 +0000 Subject: [PATCH 01/22] Add new watchdog thread for the player -- should be more reliable than the existing code. --- player.c | 72 +++++++++++++++++++++++++++++++++++++++++--------------- player.h | 5 +++- 2 files changed, 57 insertions(+), 20 deletions(-) diff --git a/player.c b/player.c index 8211c8dc..fe8a1447 100644 --- a/player.c +++ b/player.c @@ -114,6 +114,7 @@ uint64_t modulo_64_offset(uint64_t from, uint64_t to) { } void do_flush(uint32_t timestamp, rtsp_conn_info *conn); +void *player_watchdog_thread_code(void *arg); static void ab_resync(rtsp_conn_info *conn) { int i; @@ -781,25 +782,6 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { local_time_now = get_absolute_time_in_fp(); // type okay debug(3, "buffer_get_frame is iterating"); - // if config.timeout (default 120) seconds have elapsed since the last audio packet was - // received, then we should stop. - // config.timeout of zero means don't check..., but iTunes may be confused by a long gap - // followed by a resumption... - - if ((conn->time_of_last_audio_packet != 0) && (conn->stop == 0) && - (config.dont_check_timeout == 0)) { - uint64_t ct = config.timeout; // go from int to 64-bit int - // if (conn->packet_count>500) { //for testing -- about 4 seconds of play first - if ((local_time_now > conn->time_of_last_audio_packet) && - (local_time_now - conn->time_of_last_audio_packet >= ct << 32)) { - debug(1, "As Yeats almost said, \"Too long a silence / can make a stone of the heart\" " - "from RTSP conversation %d.", - conn->connection_number); - conn->stop = 1; - pthread_cancel(conn->thread); - // pthread_kill(conn->thread, SIGUSR1); - } - } int rco = get_requested_connection_state_to_output(); if (conn->connection_state_to_output != rco) { @@ -1449,6 +1431,12 @@ void player_thread_cleanup_handler(void *arg) { #endif debug(2, "Cancelling timing, control and audio threads..."); + debug(2, "Cancel watchdog thread."); + pthread_cancel(conn->player_watchdog_thread); + debug(2, "Join watchdog thread."); + pthread_join(conn->player_watchdog_thread, NULL); + debug(2, "Delete watchdog mutex."); + pthread_mutex_destroy(&conn->watchdog_mutex); debug(2, "Cancel timing thread."); pthread_cancel(conn->rtp_timing_thread); debug(2, "Join timing thread."); @@ -1742,6 +1730,10 @@ void *player_thread_func(void *arg) { pthread_create(&conn->rtp_control_thread, NULL, &rtp_control_receiver, (void *)conn); pthread_create(&conn->rtp_timing_thread, NULL, &rtp_timing_receiver, (void *)conn); + // create the watchdog mutex and start the watchdog thread; + pthread_mutex_init(&conn->watchdog_mutex, NULL); + pthread_create(&conn->player_watchdog_thread, NULL, &player_watchdog_thread_code, (void *)conn); + pthread_cleanup_push(player_thread_cleanup_handler, arg); // undo what's been done so far // stop looking elsewhere for DACP stuff @@ -2275,6 +2267,14 @@ void *player_thread_func(void *arg) { inframe->given_timestamp = 0; inframe->sequence_number = 0; + // update the watchdog + if ((config.dont_check_timeout == 0) && (config.timeout != 0)) { + uint64_t time_now = get_absolute_time_in_fp(); + debug_mutex_lock(&conn->watchdog_mutex, 1000, 1); + conn->watchdog_bark_time = time_now; + debug_mutex_unlock(&conn->watchdog_mutex, 3); + } + // debug(1,"Sync error %lld frames. Amount to stuff %d." ,sync_error,amount_to_stuff); // new stats calculation. We want a running average of sync error, drift, adjustment, @@ -2800,3 +2800,37 @@ int player_stop(rtsp_conn_info *conn) { return -1; } } + +void player_watchdog_thread_cleanup_handler(void *arg) { + rtsp_conn_info *conn = (rtsp_conn_info *)arg; + debug(2, "Connection %d: Watchdog Exit.", conn->connection_number); +} + +void *player_watchdog_thread_code(void *arg) { + pthread_cleanup_push(player_watchdog_thread_cleanup_handler, arg); + rtsp_conn_info *conn = (rtsp_conn_info *)arg; + do { + usleep(2000000); // check every two seconds + debug(3, "Connection %d: Check the player thread is doing something...", + conn->connection_number); + if ((config.dont_check_timeout == 0) && (config.timeout != 0)) { + debug_mutex_lock(&conn->watchdog_mutex, 1000, 1); + uint64_t last_watchdog_bark_time = conn->watchdog_bark_time; + debug_mutex_unlock(&conn->watchdog_mutex, 3); + if (last_watchdog_bark_time != 0) { + uint64_t time_since_last_bark = (get_absolute_time_in_fp() - last_watchdog_bark_time) >> 32; + uint64_t ct = config.timeout; // go from int to 64-bit int + + if (time_since_last_bark >= ct) { + debug(1, "Connection %d: As Yeats almost said, \"Too long a silence / can make a stone " + "of the heart\".", + conn->connection_number); + conn->stop = 1; + pthread_cancel(conn->thread); + } + } + } + } while (1); + pthread_cleanup_pop(0); // should never happen + pthread_exit(NULL); +} diff --git a/player.h b/player.h index 2f1a3284..deb787c6 100644 --- a/player.h +++ b/player.h @@ -85,7 +85,9 @@ typedef struct { int stop; int running; time_t playstart; - pthread_t thread, timer_requester, rtp_audio_thread, rtp_control_thread, rtp_timing_thread; + pthread_t thread, timer_requester, rtp_audio_thread, rtp_control_thread, rtp_timing_thread, + player_watchdog_thread; + int64_t watchdog_bark_time; // pthread_t *ptp; // buffers to delete on exit @@ -213,6 +215,7 @@ typedef struct { // request in flight at the same time pthread_mutex_t reference_time_mutex; + pthread_mutex_t watchdog_mutex; double local_to_remote_time_gradient; // if no drift, this would be exactly 1.0; likely it's // slightly above or below. From eaa98ea7d980384e09a3edfc3dab2872d915849a Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Tue, 27 Nov 2018 17:40:07 +0000 Subject: [PATCH 02/22] Quieten a few debug messages. --- audio_alsa.c | 13 ++++++++----- player.c | 26 +++++++++++++------------- rtp.c | 12 ++++++------ 3 files changed, 27 insertions(+), 24 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index 5ca4836c..2bd6efb8 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -874,7 +874,7 @@ int delay(long *the_delay) { if (alsa_handle == NULL) { return -ENODEV; } else { - pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 1); + pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 0); int derr; snd_pcm_state_t dac_state = snd_pcm_state(alsa_handle); if (dac_state == SND_PCM_STATE_RUNNING) { @@ -895,6 +895,8 @@ int delay(long *the_delay) { // there's nothing in the pipeline, so we can't measure frame rate. frame_index = 0; // we'll be starting over... measurement_data_is_valid = 0; + } else if (*the_delay > 10000) { + debug(1,"long delay: %ld.",*the_delay); } } } else { @@ -921,7 +923,7 @@ int delay(long *the_delay) { } } } - debug_mutex_unlock(&alsa_mutex, 3); + debug_mutex_unlock(&alsa_mutex, 0); pthread_cleanup_pop(0); // here, occasionally pretend there's a problem with pcm_get_delay() // if ((random() % 100000) < 3) // keep it pretty rare @@ -960,7 +962,7 @@ static int play(void *buf, int samples) { pthread_cleanup_pop(0); // release the mutex } if (ret == 0) { - pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 1); + pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 0); // snd_pcm_sframes_t current_delay = 0; int err, err2; if (snd_pcm_state(alsa_handle) == SND_PCM_STATE_XRUN) { @@ -980,6 +982,7 @@ static int play(void *buf, int samples) { if (samples == 0) debug(1, "empty buffer being passed to pcm_writei -- skipping it"); if ((samples != 0) && (buf != NULL)) { + debug(3,"write %d frames.",samples); err = alsa_pcm_write(alsa_handle, buf, samples); if (err < 0) { frame_index = 0; @@ -1044,7 +1047,7 @@ static int play(void *buf, int samples) { frame_index = 0; measurement_data_is_valid = 0; } - debug_mutex_unlock(&alsa_mutex, 3); + debug_mutex_unlock(&alsa_mutex, 0); pthread_cleanup_pop(0); // release the mutex } return ret; @@ -1065,7 +1068,7 @@ static void flush(void) { if ((derr = snd_pcm_hw_free(alsa_handle))) debug(1, "Error %d (\"%s\") freeing the output device hardware.", derr, snd_strerror(derr)); - + // flush also closes the device if ((derr = snd_pcm_close(alsa_handle))) debug(1, "Error %d (\"%s\") closing the output device.", derr, snd_strerror(derr)); diff --git a/player.c b/player.c index fe8a1447..3507db6b 100644 --- a/player.c +++ b/player.c @@ -443,7 +443,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in debug_mutex_unlock(&conn->flush_mutex, 3); } - debug_mutex_lock(&conn->ab_mutex, 30000, 1); + debug_mutex_lock(&conn->ab_mutex, 30000, 0); conn->packet_count++; conn->packet_count_since_flush++; conn->time_of_last_audio_packet = get_absolute_time_in_fp(); @@ -615,7 +615,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in } } } - debug_mutex_unlock(&conn->ab_mutex, 3); + debug_mutex_unlock(&conn->ab_mutex, 0); } int32_t rand_in_range(int32_t exclusive_range_limit) { @@ -759,7 +759,7 @@ static inline void process_sample(int32_t sample, char **outp, enum sps_format_t void buffer_get_frame_cleanup_handler(void *arg) { rtsp_conn_info *conn = (rtsp_conn_info *)arg; - debug_mutex_unlock(&conn->ab_mutex, 3); + debug_mutex_unlock(&conn->ab_mutex, 0); } // get the next frame, when available. return 0 if underrun/stream reset. @@ -770,7 +770,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { abuf_t *curframe = NULL; int notified_buffer_empty = 0; // diagnostic only - debug_mutex_lock(&conn->ab_mutex, 30000, 1); + debug_mutex_lock(&conn->ab_mutex, 30000, 0); int wait; long dac_delay = 0; // long because alsa returns a long @@ -780,7 +780,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { do { // get the time local_time_now = get_absolute_time_in_fp(); // type okay - debug(3, "buffer_get_frame is iterating"); + // debug(3, "buffer_get_frame is iterating"); int rco = get_requested_connection_state_to_output(); @@ -797,12 +797,12 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { if (config.output->is_running) if (config.output->is_running() != 0) { // if the back end isn't running for any reason debug(3, "not running"); - debug_mutex_lock(&conn->flush_mutex, 1000, 1); + debug_mutex_lock(&conn->flush_mutex, 1000, 0); conn->flush_requested = 1; - debug_mutex_unlock(&conn->flush_mutex, 3); + debug_mutex_unlock(&conn->flush_mutex, 0); } - debug_mutex_lock(&conn->flush_mutex, 1000, 1); + debug_mutex_lock(&conn->flush_mutex, 1000, 0); if (conn->flush_requested == 1) { if (config.output->flush) config.output->flush(); // no cancellation points @@ -812,7 +812,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { conn->time_since_play_started = 0; conn->flush_requested = 0; } - debug_mutex_unlock(&conn->flush_mutex, 3); + debug_mutex_unlock(&conn->flush_mutex, 0); if (conn->ab_synced) { curframe = conn->audio_buffer + BUFIDX(conn->ab_read); @@ -2270,9 +2270,9 @@ void *player_thread_func(void *arg) { // update the watchdog if ((config.dont_check_timeout == 0) && (config.timeout != 0)) { uint64_t time_now = get_absolute_time_in_fp(); - debug_mutex_lock(&conn->watchdog_mutex, 1000, 1); + debug_mutex_lock(&conn->watchdog_mutex, 1000, 0); conn->watchdog_bark_time = time_now; - debug_mutex_unlock(&conn->watchdog_mutex, 3); + debug_mutex_unlock(&conn->watchdog_mutex, 0); } // debug(1,"Sync error %lld frames. Amount to stuff %d." ,sync_error,amount_to_stuff); @@ -2814,9 +2814,9 @@ void *player_watchdog_thread_code(void *arg) { debug(3, "Connection %d: Check the player thread is doing something...", conn->connection_number); if ((config.dont_check_timeout == 0) && (config.timeout != 0)) { - debug_mutex_lock(&conn->watchdog_mutex, 1000, 1); + debug_mutex_lock(&conn->watchdog_mutex, 1000, 0); uint64_t last_watchdog_bark_time = conn->watchdog_bark_time; - debug_mutex_unlock(&conn->watchdog_mutex, 3); + debug_mutex_unlock(&conn->watchdog_mutex, 0); if (last_watchdog_bark_time != 0) { uint64_t time_since_last_bark = (get_absolute_time_in_fp() - last_watchdog_bark_time) >> 32; uint64_t ct = config.timeout; // go from int to 64-bit int diff --git a/rtp.c b/rtp.c index 0c97fc31..dba32390 100644 --- a/rtp.c +++ b/rtp.c @@ -1040,7 +1040,7 @@ void rtp_setup(SOCKADDR *local, SOCKADDR *remote, uint16_t cport, uint16_t tport void get_reference_timestamp_stuff(uint32_t *timestamp, uint64_t *timestamp_time, uint64_t *remote_timestamp_time, rtsp_conn_info *conn) { // types okay - debug_mutex_lock(&conn->reference_time_mutex, 1000, 1); + debug_mutex_lock(&conn->reference_time_mutex, 1000, 0); *timestamp = conn->reference_timestamp; *remote_timestamp_time = conn->remote_reference_timestamp_time; *timestamp_time = @@ -1048,7 +1048,7 @@ void get_reference_timestamp_stuff(uint32_t *timestamp, uint64_t *timestamp_time // if ((*timestamp == 0) && (*timestamp_time == 0)) { // debug(1,"Reference timestamp is invalid."); //} - debug_mutex_unlock(&conn->reference_time_mutex, 3); + debug_mutex_unlock(&conn->reference_time_mutex, 0); } void clear_reference_timestamp(rtsp_conn_info *conn) { @@ -1103,7 +1103,7 @@ int sanitised_source_rate_information(uint32_t *frames, uint64_t *time, rtsp_con // the reference timestamps are denominated in terms of the input rate int frame_to_local_time(uint32_t timestamp, uint64_t *time, rtsp_conn_info *conn) { - debug_mutex_lock(&conn->reference_time_mutex, 1000, 1); + debug_mutex_lock(&conn->reference_time_mutex, 1000, 0); int result = 0; uint64_t time_difference; uint32_t frame_difference; @@ -1135,12 +1135,12 @@ int frame_to_local_time(uint32_t timestamp, uint64_t *time, rtsp_conn_info *conn // on the specified fps. } *time = remote_time_of_timestamp - local_to_remote_time_difference_now(conn); - debug_mutex_unlock(&conn->reference_time_mutex, 3); + debug_mutex_unlock(&conn->reference_time_mutex, 0); return result; } int local_time_to_frame(uint64_t time, uint32_t *frame, rtsp_conn_info *conn) { - debug_mutex_lock(&conn->reference_time_mutex, 1000, 1); + debug_mutex_lock(&conn->reference_time_mutex, 1000, 0); int result = 0; uint64_t time_difference; @@ -1171,7 +1171,7 @@ int local_time_to_frame(uint64_t time, uint32_t *frame, rtsp_conn_info *conn) { // debug(1,"Frame interval is %" PRId64 " frames.",-frame_interval); *frame = (conn->reference_timestamp - frame_interval); } - debug_mutex_unlock(&conn->reference_time_mutex, 3); + debug_mutex_unlock(&conn->reference_time_mutex, 0); return result; } From b7ee743a0ee00df1a1c01b79cf3fc75c01f64dd0 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Tue, 27 Nov 2018 17:44:45 +0000 Subject: [PATCH 03/22] Quieten a few debug messages. --- audio_alsa.c | 2 -- 1 file changed, 2 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index 2bd6efb8..dc6f11d8 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -895,8 +895,6 @@ int delay(long *the_delay) { // there's nothing in the pipeline, so we can't measure frame rate. frame_index = 0; // we'll be starting over... measurement_data_is_valid = 0; - } else if (*the_delay > 10000) { - debug(1,"long delay: %ld.",*the_delay); } } } else { From 227c38a89c662d8659cbcb976cc26310b4396e3d Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Tue, 27 Nov 2018 22:03:56 +0000 Subject: [PATCH 04/22] Try to capture what happens after a write error. --- rtsp.c | 21 ++++++++++++--------- 1 file changed, 12 insertions(+), 9 deletions(-) diff --git a/rtsp.c b/rtsp.c index 99000174..cb26c576 100644 --- a/rtsp.c +++ b/rtsp.c @@ -425,13 +425,9 @@ static void debug_print_msg_content(int level, rtsp_message *msg) { void msg_free(rtsp_message *msg) { if (msg) { - int rc = pthread_mutex_lock(&reference_counter_lock); - if (rc) - debug(1, "Error %d locking reference counter lock during msg_free()", rc); + debug_mutex_lock(&reference_counter_lock,1000,3); msg->referenceCount--; - rc = pthread_mutex_unlock(&reference_counter_lock); - if (rc) - debug(1, "Error %d unlocking reference counter lock during msg_free()", rc); + debug_mutex_unlock(&reference_counter_lock,3); if (msg->referenceCount == 0) { unsigned int i; for (i = 0; i < msg->nheaders; i++) { @@ -1998,9 +1994,9 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { if (conn->player_thread) player_stop(conn); if (conn->fd > 0) { - // debug(1, "Connection %d: closing fd %d.", - // conn->connection_number,conn->fd); + debug(3, "Connection %d: closing fd %d.", conn->connection_number,conn->fd); close(conn->fd); + debug(3, "Connection %d: closed fd %d.", conn->connection_number,conn->fd); } if (conn->auth_nonce) { free(conn->auth_nonce); @@ -2025,6 +2021,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(3, "Connection %d: Checking play lock.", conn->connection_number); debug_mutex_lock(&playing_conn_lock, 1000000, 3); // get it if (playing_conn == conn) { debug(3, "Connection %d: Unlocking play lock.", conn->connection_number); @@ -2037,7 +2034,7 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { } void msg_cleanup_function(void *arg) { - // debug(1, "msg_cleanup_function called."); + debug(3, "msg_cleanup_function called."); msg_free((rtsp_message *)arg); } @@ -2131,6 +2128,8 @@ static void *rtsp_conversation_thread_func(void *pconn) { } debug(debug_level, "Connection %d: RTSP Response:", conn->connection_number); debug_print_msg_headers(debug_level, resp); + + /* fd_set writefds; FD_ZERO(&writefds); FD_SET(conn->fd, &writefds); @@ -2138,6 +2137,8 @@ static void *rtsp_conversation_thread_func(void *pconn) { memory_barrier(); } while (conn->stop == 0 && pselect(conn->fd + 1, NULL, &writefds, NULL, NULL, &pselect_sigset) <= 0); + */ + if (conn->stop == 0) { int err = msg_write_response(conn->fd, resp); if (err) { @@ -2145,6 +2146,8 @@ static void *rtsp_conversation_thread_func(void *pconn) { "connection.", conn->connection_number); conn->stop = 1; + if (debuglev >= 1) + debuglev = 3; // see what happens next } } pthread_cleanup_pop(1); From 4ab81ce0b76db062d4ce910515291e740e64edf3 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Tue, 27 Nov 2018 22:53:27 +0000 Subject: [PATCH 05/22] Add extra diagnostic to capture a meg_write_response error. --- rtsp.c | 14 +++++++++++--- 1 file changed, 11 insertions(+), 3 deletions(-) diff --git a/rtsp.c b/rtsp.c index cb26c576..478f20e6 100644 --- a/rtsp.c +++ b/rtsp.c @@ -692,9 +692,17 @@ int msg_write_response(int fd, rtsp_message *resp) { debug(1, "Attempted to write overlong RTSP packet 3"); return -3; } - if (write(fd, pkt, p - pkt) != p - pkt) { - debug(1, "Error writing an RTSP packet -- requested bytes not fully written."); - return -4; + ssize_t reply = write(fd, pkt, p - pkt); + if (reply == -1) { + char errorstring[1024]; + strerror_r(errno, (char *)errorstring, sizeof(errorstring)); + debug(1, "msg_write_response error %d: \"%s\".", + errno, (char *)errorstring); + return -4; + } + if (reply != p - pkt) { + debug(1, "msg_write_response error -- requested bytes not fully written."); + return -5; } return 0; } From 22f3e3e318d91d6e888f700bb2661dc3e32326cb Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Wed, 28 Nov 2018 17:18:03 +0000 Subject: [PATCH 06/22] Move watchdog to cover connection from start, not just from start of play. Start investigating UDP port allocation. Tidy up handling or RTSP write errors -- remove the pselect code from before a write. --- audio_alsa.c | 4 +-- common.c | 5 +++- player.c | 47 +--------------------------------- rtp.c | 9 +++++-- rtsp.c | 72 +++++++++++++++++++++++++++++++++++++++++++--------- shairport.c | 2 +- 6 files changed, 75 insertions(+), 64 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index dc6f11d8..00c33900 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -980,7 +980,7 @@ static int play(void *buf, int samples) { if (samples == 0) debug(1, "empty buffer being passed to pcm_writei -- skipping it"); if ((samples != 0) && (buf != NULL)) { - debug(3,"write %d frames.",samples); + debug(3, "write %d frames.", samples); err = alsa_pcm_write(alsa_handle, buf, samples); if (err < 0) { frame_index = 0; @@ -1066,7 +1066,7 @@ static void flush(void) { if ((derr = snd_pcm_hw_free(alsa_handle))) debug(1, "Error %d (\"%s\") freeing the output device hardware.", derr, snd_strerror(derr)); - + // flush also closes the device if ((derr = snd_pcm_close(alsa_handle))) debug(1, "Error %d (\"%s\") closing the output device.", derr, snd_strerror(derr)); diff --git a/common.c b/common.c index 0d76a4f4..76cf8204 100644 --- a/common.c +++ b/common.c @@ -96,7 +96,10 @@ sigset_t pselect_sigset; static uint16_t UDPPortIndex = 0; -void resetFreeUDPPort() { UDPPortIndex = 0; } +void resetFreeUDPPort() { + debug(1,"Resetting UDP Port Suggestion to %u",config.udp_port_base); + UDPPortIndex = 0; +} uint16_t nextFreeUDPPort() { if (UDPPortIndex == 0) diff --git a/player.c b/player.c index 3507db6b..4e2bfc4f 100644 --- a/player.c +++ b/player.c @@ -114,7 +114,6 @@ uint64_t modulo_64_offset(uint64_t from, uint64_t to) { } void do_flush(uint32_t timestamp, rtsp_conn_info *conn); -void *player_watchdog_thread_code(void *arg); static void ab_resync(rtsp_conn_info *conn) { int i; @@ -1431,12 +1430,6 @@ void player_thread_cleanup_handler(void *arg) { #endif debug(2, "Cancelling timing, control and audio threads..."); - debug(2, "Cancel watchdog thread."); - pthread_cancel(conn->player_watchdog_thread); - debug(2, "Join watchdog thread."); - pthread_join(conn->player_watchdog_thread, NULL); - debug(2, "Delete watchdog mutex."); - pthread_mutex_destroy(&conn->watchdog_mutex); debug(2, "Cancel timing thread."); pthread_cancel(conn->rtp_timing_thread); debug(2, "Join timing thread."); @@ -1730,10 +1723,6 @@ void *player_thread_func(void *arg) { pthread_create(&conn->rtp_control_thread, NULL, &rtp_control_receiver, (void *)conn); pthread_create(&conn->rtp_timing_thread, NULL, &rtp_timing_receiver, (void *)conn); - // create the watchdog mutex and start the watchdog thread; - pthread_mutex_init(&conn->watchdog_mutex, NULL); - pthread_create(&conn->player_watchdog_thread, NULL, &player_watchdog_thread_code, (void *)conn); - pthread_cleanup_push(player_thread_cleanup_handler, arg); // undo what's been done so far // stop looking elsewhere for DACP stuff @@ -2799,38 +2788,4 @@ int player_stop(rtsp_conn_info *conn) { // debuglev = dl; return -1; } -} - -void player_watchdog_thread_cleanup_handler(void *arg) { - rtsp_conn_info *conn = (rtsp_conn_info *)arg; - debug(2, "Connection %d: Watchdog Exit.", conn->connection_number); -} - -void *player_watchdog_thread_code(void *arg) { - pthread_cleanup_push(player_watchdog_thread_cleanup_handler, arg); - rtsp_conn_info *conn = (rtsp_conn_info *)arg; - do { - usleep(2000000); // check every two seconds - debug(3, "Connection %d: Check the player thread is doing something...", - conn->connection_number); - if ((config.dont_check_timeout == 0) && (config.timeout != 0)) { - debug_mutex_lock(&conn->watchdog_mutex, 1000, 0); - uint64_t last_watchdog_bark_time = conn->watchdog_bark_time; - debug_mutex_unlock(&conn->watchdog_mutex, 0); - if (last_watchdog_bark_time != 0) { - uint64_t time_since_last_bark = (get_absolute_time_in_fp() - last_watchdog_bark_time) >> 32; - uint64_t ct = config.timeout; // go from int to 64-bit int - - if (time_since_last_bark >= ct) { - debug(1, "Connection %d: As Yeats almost said, \"Too long a silence / can make a stone " - "of the heart\".", - conn->connection_number); - conn->stop = 1; - pthread_cancel(conn->thread); - } - } - } - } while (1); - pthread_cleanup_pop(0); // should never happen - pthread_exit(NULL); -} +} \ No newline at end of file diff --git a/rtp.c b/rtp.c index dba32390..1f908b0e 100644 --- a/rtp.c +++ b/rtp.c @@ -890,9 +890,14 @@ 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 " + char errorstring[1024]; + strerror_r(errno, (char *)errorstring, sizeof(errorstring)); + die("error %d: \"%s\". 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!"); + "check for restrictive firewall settings or a bad router! UDP base is %u, range is %u and " + "current suggestion is %u.", + errno, errorstring, config.udp_port_base, config.udp_port_range, desired_port); } uint16_t sport; diff --git a/rtsp.c b/rtsp.c index 478f20e6..beaaf8f7 100644 --- a/rtsp.c +++ b/rtsp.c @@ -253,6 +253,39 @@ int pc_queue_get_item(pc_queue *the_queue, void *the_stuff) { #endif +void player_watchdog_thread_cleanup_handler(void *arg) { + rtsp_conn_info *conn = (rtsp_conn_info *)arg; + debug(2, "Connection %d: Watchdog Exit.", conn->connection_number); +} + +void *player_watchdog_thread_code(void *arg) { + pthread_cleanup_push(player_watchdog_thread_cleanup_handler, arg); + rtsp_conn_info *conn = (rtsp_conn_info *)arg; + do { + usleep(2000000); // check every two seconds + debug(3, "Connection %d: Check the thread is doing something...", conn->connection_number); + if ((config.dont_check_timeout == 0) && (config.timeout != 0)) { + debug_mutex_lock(&conn->watchdog_mutex, 1000, 0); + uint64_t last_watchdog_bark_time = conn->watchdog_bark_time; + debug_mutex_unlock(&conn->watchdog_mutex, 0); + if (last_watchdog_bark_time != 0) { + uint64_t time_since_last_bark = (get_absolute_time_in_fp() - last_watchdog_bark_time) >> 32; + uint64_t ct = config.timeout; // go from int to 64-bit int + + if (time_since_last_bark >= ct) { + debug(1, "Connection %d: As Yeats almost said, \"Too long a silence / can make a stone " + "of the heart\".", + conn->connection_number); + conn->stop = 1; + pthread_cancel(conn->thread); + } + } + } + } while (1); + pthread_cleanup_pop(0); // should never happen + pthread_exit(NULL); +} + void ask_other_rtsp_conversation_threads_to_stop(pthread_t except_this_thread); void rtsp_request_shutdown_stream(void) { @@ -425,9 +458,9 @@ static void debug_print_msg_content(int level, rtsp_message *msg) { void msg_free(rtsp_message *msg) { if (msg) { - debug_mutex_lock(&reference_counter_lock,1000,3); + debug_mutex_lock(&reference_counter_lock, 1000, 3); msg->referenceCount--; - debug_mutex_unlock(&reference_counter_lock,3); + debug_mutex_unlock(&reference_counter_lock, 3); if (msg->referenceCount == 0) { unsigned int i; for (i = 0; i < msg->nheaders; i++) { @@ -695,10 +728,9 @@ int msg_write_response(int fd, rtsp_message *resp) { ssize_t reply = write(fd, pkt, p - pkt); if (reply == -1) { char errorstring[1024]; - strerror_r(errno, (char *)errorstring, sizeof(errorstring)); - debug(1, "msg_write_response error %d: \"%s\".", - errno, (char *)errorstring); - return -4; + strerror_r(errno, (char *)errorstring, sizeof(errorstring)); + debug(1, "msg_write_response error %d: \"%s\".", errno, (char *)errorstring); + return -4; } if (reply != p - pkt) { debug(1, "msg_write_response error -- requested bytes not fully written."); @@ -890,12 +922,14 @@ void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { "timing_port=%d;server_" "port=%d", conn->local_control_port, conn->local_timing_port, conn->local_audio_port); + msg_add_header(resp, "Transport", resphdr); msg_add_header(resp, "Session", "1"); resp->respcode = 200; + debug(1, "Connection %d: SETUP with UDP ports Control: %d, Timing: %d and Audio: %d.", conn->connection_number, conn->local_control_port, conn->local_timing_port, conn->local_audio_port); return; error: @@ -2002,9 +2036,9 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { if (conn->player_thread) player_stop(conn); if (conn->fd > 0) { - debug(3, "Connection %d: closing fd %d.", conn->connection_number,conn->fd); + debug(3, "Connection %d: closing fd %d.", conn->connection_number, conn->fd); close(conn->fd); - debug(3, "Connection %d: closed fd %d.", conn->connection_number,conn->fd); + debug(3, "Connection %d: closed fd %d.", conn->connection_number, conn->fd); } if (conn->auth_nonce) { free(conn->auth_nonce); @@ -2035,7 +2069,17 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { debug(3, "Connection %d: Unlocking play lock.", conn->connection_number); playing_conn = NULL; } + debug_mutex_unlock(&playing_conn_lock, 3); + debug(2, "Cancel watchdog thread."); + pthread_cancel(conn->player_watchdog_thread); + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); + debug(2, "Join watchdog thread."); + pthread_join(conn->player_watchdog_thread, NULL); + pthread_setcancelstate(oldState, NULL); + debug(2, "Delete watchdog mutex."); + pthread_mutex_destroy(&conn->watchdog_mutex); debug(2, "Connection %d: RTSP thread terminated.", conn->connection_number); conn->running = 0; @@ -2049,6 +2093,10 @@ void msg_cleanup_function(void *arg) { static void *rtsp_conversation_thread_func(void *pconn) { rtsp_conn_info *conn = pconn; + // create the watchdog mutex and start the watchdog thread; + pthread_mutex_init(&conn->watchdog_mutex, NULL); + pthread_create(&conn->player_watchdog_thread, NULL, &player_watchdog_thread_code, (void *)conn); + int rc = pthread_mutex_init(&conn->flush_mutex, NULL); if (rc) die("Connection %d: error %d initialising flush_mutex.", conn->connection_number, rc); @@ -2136,7 +2184,7 @@ static void *rtsp_conversation_thread_func(void *pconn) { } debug(debug_level, "Connection %d: RTSP Response:", conn->connection_number); debug_print_msg_headers(debug_level, resp); - + /* fd_set writefds; FD_ZERO(&writefds); @@ -2146,7 +2194,7 @@ static void *rtsp_conversation_thread_func(void *pconn) { } while (conn->stop == 0 && pselect(conn->fd + 1, NULL, &writefds, NULL, NULL, &pselect_sigset) <= 0); */ - + if (conn->stop == 0) { int err = msg_write_response(conn->fd, resp); if (err) { @@ -2154,8 +2202,8 @@ static void *rtsp_conversation_thread_func(void *pconn) { "connection.", conn->connection_number); conn->stop = 1; - if (debuglev >= 1) - debuglev = 3; // see what happens next + // if (debuglev >= 1) + // debuglev = 3; // see what happens next } } pthread_cleanup_pop(1); diff --git a/shairport.c b/shairport.c index c9212544..506f9feb 100644 --- a/shairport.c +++ b/shairport.c @@ -31,11 +31,11 @@ #include #include #include +#include #include #include #include #include -#include #include #include #include From 1cf28be647f20370de7ddb5d8c60b2753d2e5869 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Wed, 28 Nov 2018 19:39:11 +0000 Subject: [PATCH 07/22] Add SO_REUSEADDR to the UDP sockets. See if it makes any difference. --- rtp.c | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/rtp.c b/rtp.c index 1f908b0e..464bc303 100644 --- a/rtp.c +++ b/rtp.c @@ -858,6 +858,16 @@ static uint16_t bind_port(int ip_family, const char *self_ip_address, uint32_t s int local_socket = socket(ip_family, SOCK_DGRAM, IPPROTO_UDP); if (local_socket == -1) die("Could not allocate a socket."); + + int val = 1; + ret = setsockopt(local_socket, SOL_SOCKET, SO_REUSEADDR, &val, sizeof(val)); + if (ret < 0) { + char errorstring[1024]; + strerror_r(errno, (char *)errorstring, sizeof(errorstring)); + debug(1,"Error %d: \"%s\". Couldn't set SO_REUSEADDR"); + } + + SOCKADDR myaddr; int tryCount = 0; uint16_t desired_port; From 7bf22b426584a2e3cc136784588bb6845e1ef5ec Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Wed, 28 Nov 2018 19:49:12 +0000 Subject: [PATCH 08/22] Add some debug messages to closing the UDP ports. --- rtp.c | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/rtp.c b/rtp.c index 464bc303..c61be2ee 100644 --- a/rtp.c +++ b/rtp.c @@ -98,14 +98,14 @@ 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."); + debug(1, "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(1, "Audio Receiver Cleanup Successful."); } void *rtp_audio_receiver(void *arg) { @@ -242,11 +242,11 @@ 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(3, "shutdown control socket."); + debug(1, "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(1, "Control Receiver Cleanup Successful."); } void *rtp_control_receiver(void *arg) { @@ -563,11 +563,11 @@ 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(3, "shutdown timing socket."); + debug(1, "shutdown timing socket."); shutdown(conn->timing_socket, SHUT_RDWR); debug(3, "close timing socket."); close(conn->timing_socket); - debug(3, "Timing Receiver Cleanup Successful."); + debug(1, "Timing Receiver Cleanup Successful."); } void *rtp_timing_receiver(void *arg) { From c318796e5511686fdafbc0b445ada2eb30b38ae2 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Thu, 29 Nov 2018 11:37:56 +0000 Subject: [PATCH 09/22] Add an uncancellable usleep timer. Make the player and UDP thread cleanups uncancellable. --- common.c | 10 ++++++++++ common.h | 2 ++ player.c | 3 +++ rtp.c | 35 ++++++++++++++++++++++------------- rtsp.c | 28 ++++++++++++++++------------ 5 files changed, 53 insertions(+), 25 deletions(-) diff --git a/common.c b/common.c index 76cf8204..f815af91 100644 --- a/common.c +++ b/common.c @@ -94,6 +94,16 @@ volatile int debuglev = 0; sigset_t pselect_sigset; + +int usleep_uncancellable(useconds_t usec) { + int response; + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); + response = usleep_uncancellable(usec); + pthread_setcancelstate(oldState, NULL); + return response; +} + static uint16_t UDPPortIndex = 0; void resetFreeUDPPort() { diff --git a/common.h b/common.h index a043d0f7..59492c5f 100644 --- a/common.h +++ b/common.h @@ -330,5 +330,7 @@ char *get_version_string(); // mallocs a string space -- remember to free it aft void sps_nanosleep(const time_t sec, const long nanosec); // waits for this time, even through interruptions + +int usleep_uncancellable(useconds_t usec); #endif // _COMMON_H diff --git a/player.c b/player.c index 4e2bfc4f..57d7527b 100644 --- a/player.c +++ b/player.c @@ -1396,6 +1396,8 @@ void player_thread_initial_cleanup_handler(__attribute__((unused)) void *arg) { void player_thread_cleanup_handler(void *arg) { rtsp_conn_info *conn = (rtsp_conn_info *)arg; + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); debug(3, "Connection %d: player thread main loop exit via player_thread_cleanup_handler.", conn->connection_number); @@ -1465,6 +1467,7 @@ void player_thread_cleanup_handler(void *arg) { clear_reference_timestamp(conn); conn->rtp_running = 0; + pthread_setcancelstate(oldState, NULL); } void *player_thread_func(void *arg) { diff --git a/rtp.c b/rtp.c index c61be2ee..bfb32d75 100644 --- a/rtp.c +++ b/rtp.c @@ -98,14 +98,15 @@ uint64_t local_to_remote_time_difference_now(rtsp_conn_info *conn) { } void rtp_audio_receiver_cleanup_handler(void *arg) { - debug(1, "Audio Receiver Cleanup."); + 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."); + debug(3, "Close Audio Socket."); close(conn->audio_socket); - - debug(1, "Audio Receiver Cleanup Successful."); + debug(3, "Audio Receiver Cleanup Successful."); + usleep(20000); // microseconds + pthread_setcancelstate(oldState, NULL); } void *rtp_audio_receiver(void *arg) { @@ -240,13 +241,17 @@ 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(1, "shutdown control socket."); + debug(3, "Shut Down Control Socket."); shutdown(conn->control_socket, SHUT_RDWR); - debug(3, "close control socket."); + debug(3, "Close Control Socket."); close(conn->control_socket); - debug(1, "Control Receiver Cleanup Successful."); + debug(3, "Control Receiver Cleanup Successful."); + usleep(20000); // microseconds + pthread_setcancelstate(oldState, NULL); } void *rtp_control_receiver(void *arg) { @@ -559,15 +564,19 @@ void *rtp_timing_sender(void *arg) { } 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; + debug(3, "Cancel Timing Requester."); pthread_cancel(conn->timer_requester); + debug(3, "Join Timing Requester."); pthread_join(conn->timer_requester, NULL); - debug(1, "shutdown timing socket."); - shutdown(conn->timing_socket, SHUT_RDWR); - debug(3, "close timing socket."); + debug(3, "Close Timing Socket."); close(conn->timing_socket); - debug(1, "Timing Receiver Cleanup Successful."); + debug(3, "Timing Receiver Cleanup Successful."); + usleep(20000); // microseconds + pthread_setcancelstate(oldState, NULL); } void *rtp_timing_receiver(void *arg) { diff --git a/rtsp.c b/rtsp.c index beaaf8f7..2d1203d7 100644 --- a/rtsp.c +++ b/rtsp.c @@ -570,10 +570,12 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes if (nread < 0) { if (errno == EINTR) 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); + if (errno != ECONNRESET) { + 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); + } reply = rtsp_read_request_response_read_error; goto shutdown; } @@ -1577,7 +1579,7 @@ 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(2, "Connection %d: ANNOUNCE: already shutting down; waiting for it...", + 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) { @@ -2063,14 +2065,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(3, "Connection %d: Checking play lock.", conn->connection_number); - 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; - } - debug_mutex_unlock(&playing_conn_lock, 3); debug(2, "Cancel watchdog thread."); pthread_cancel(conn->player_watchdog_thread); int oldState; @@ -2081,6 +2076,15 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { debug(2, "Delete watchdog mutex."); pthread_mutex_destroy(&conn->watchdog_mutex); + + debug(3, "Connection %d: Checking play lock.", conn->connection_number); + 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; } From ca45d2ecbeea1eac2496bea6cff312f7c2ede571 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Thu, 29 Nov 2018 12:18:07 +0000 Subject: [PATCH 10/22] Clang formatted. --- common.c | 9 ++++----- common.h | 2 +- rtp.c | 11 +++++------ rtsp.c | 17 ++++++++--------- 4 files changed, 18 insertions(+), 21 deletions(-) diff --git a/common.c b/common.c index f815af91..d8fcbd44 100644 --- a/common.c +++ b/common.c @@ -94,10 +94,9 @@ volatile int debuglev = 0; sigset_t pselect_sigset; - int usleep_uncancellable(useconds_t usec) { - int response; - int oldState; + int response; + int oldState; pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); response = usleep_uncancellable(usec); pthread_setcancelstate(oldState, NULL); @@ -107,8 +106,8 @@ int usleep_uncancellable(useconds_t usec) { static uint16_t UDPPortIndex = 0; void resetFreeUDPPort() { - debug(1,"Resetting UDP Port Suggestion to %u",config.udp_port_base); - UDPPortIndex = 0; + debug(1, "Resetting UDP Port Suggestion to %u", config.udp_port_base); + UDPPortIndex = 0; } uint16_t nextFreeUDPPort() { diff --git a/common.h b/common.h index 59492c5f..ece21b1d 100644 --- a/common.h +++ b/common.h @@ -330,7 +330,7 @@ char *get_version_string(); // mallocs a string space -- remember to free it aft void sps_nanosleep(const time_t sec, const long nanosec); // waits for this time, even through interruptions - + int usleep_uncancellable(useconds_t usec); #endif // _COMMON_H diff --git a/rtp.c b/rtp.c index bfb32d75..61c69dd2 100644 --- a/rtp.c +++ b/rtp.c @@ -98,7 +98,7 @@ uint64_t local_to_remote_time_difference_now(rtsp_conn_info *conn) { } void rtp_audio_receiver_cleanup_handler(void *arg) { - int oldState; + int oldState; pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); debug(3, "Audio Receiver Cleanup."); rtsp_conn_info *conn = (rtsp_conn_info *)arg; @@ -564,13 +564,13 @@ void *rtp_timing_sender(void *arg) { } void rtp_timing_receiver_cleanup_handler(void *arg) { - int oldState; + int oldState; pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); debug(3, "Timing Receiver Cleanup."); rtsp_conn_info *conn = (rtsp_conn_info *)arg; debug(3, "Cancel Timing Requester."); pthread_cancel(conn->timer_requester); - debug(3, "Join Timing Requester."); + debug(3, "Join Timing Requester."); pthread_join(conn->timer_requester, NULL); debug(3, "Close Timing Socket."); close(conn->timing_socket); @@ -867,16 +867,15 @@ static uint16_t bind_port(int ip_family, const char *self_ip_address, uint32_t s int local_socket = socket(ip_family, SOCK_DGRAM, IPPROTO_UDP); if (local_socket == -1) die("Could not allocate a socket."); - + int val = 1; ret = setsockopt(local_socket, SOL_SOCKET, SO_REUSEADDR, &val, sizeof(val)); if (ret < 0) { char errorstring[1024]; strerror_r(errno, (char *)errorstring, sizeof(errorstring)); - debug(1,"Error %d: \"%s\". Couldn't set SO_REUSEADDR"); + debug(1, "Error %d: \"%s\". Couldn't set SO_REUSEADDR"); } - SOCKADDR myaddr; int tryCount = 0; uint16_t desired_port; diff --git a/rtsp.c b/rtsp.c index 2d1203d7..31af30f9 100644 --- a/rtsp.c +++ b/rtsp.c @@ -571,10 +571,10 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes if (errno == EINTR) continue; if (errno != ECONNRESET) { - 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); + 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); } reply = rtsp_read_request_response_read_error; goto shutdown; @@ -924,14 +924,15 @@ void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { "timing_port=%d;server_" "port=%d", conn->local_control_port, conn->local_timing_port, conn->local_audio_port); - msg_add_header(resp, "Transport", resphdr); msg_add_header(resp, "Session", "1"); resp->respcode = 200; - debug(1, "Connection %d: SETUP with UDP ports Control: %d, Timing: %d and Audio: %d.", conn->connection_number, conn->local_control_port, conn->local_timing_port, conn->local_audio_port); + debug(1, "Connection %d: SETUP with UDP ports Control: %d, Timing: %d and Audio: %d.", + conn->connection_number, conn->local_control_port, conn->local_timing_port, + conn->local_audio_port); return; error: @@ -2065,7 +2066,6 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { if (rc) debug(1, "Connection %d: error %d destroying flush_mutex.", conn->connection_number, rc); - debug(2, "Cancel watchdog thread."); pthread_cancel(conn->player_watchdog_thread); int oldState; @@ -2076,7 +2076,6 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { debug(2, "Delete watchdog mutex."); pthread_mutex_destroy(&conn->watchdog_mutex); - debug(3, "Connection %d: Checking play lock.", conn->connection_number); debug_mutex_lock(&playing_conn_lock, 1000000, 3); // get it if (playing_conn == conn) { @@ -2084,7 +2083,7 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { playing_conn = NULL; } debug_mutex_unlock(&playing_conn_lock, 3); - + debug(2, "Connection %d: RTSP thread terminated.", conn->connection_number); conn->running = 0; } From bcf9b1a84341e5e5d96cd6daca489518b387377a Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Thu, 29 Nov 2018 13:12:53 +0000 Subject: [PATCH 11/22] Quieten a debug message --- common.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/common.c b/common.c index d8fcbd44..8cbcd0d4 100644 --- a/common.c +++ b/common.c @@ -106,7 +106,7 @@ int usleep_uncancellable(useconds_t usec) { static uint16_t UDPPortIndex = 0; void resetFreeUDPPort() { - debug(1, "Resetting UDP Port Suggestion to %u", config.udp_port_base); + debug(3, "Resetting UDP Port Suggestion to %u", config.udp_port_base); UDPPortIndex = 0; } From fdd5ce430dd54801cfad32f343cc68a8c64452f0 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Thu, 29 Nov 2018 13:13:51 +0000 Subject: [PATCH 12/22] Check in SETUP and RECORD that the player is available, clean up setup code by removing gotos. --- rtsp.c | 272 +++++++++++++++++++++++++++++++-------------------------- 1 file changed, 149 insertions(+), 123 deletions(-) diff --git a/rtsp.c b/rtsp.c index 31af30f9..637938ef 100644 --- a/rtsp.c +++ b/rtsp.c @@ -253,6 +253,15 @@ int pc_queue_get_item(pc_queue *the_queue, void *the_stuff) { #endif +int have_player(rtsp_conn_info *conn) { + int response = 0; + debug_mutex_lock(&playing_conn_lock, 1000000, 3); + if (playing_conn == conn) // this connection definitely doesn't have the play lock + response = 1; + debug_mutex_unlock(&playing_conn_lock, 3); + return response; +} + void player_watchdog_thread_cleanup_handler(void *arg) { rtsp_conn_info *conn = (rtsp_conn_info *)arg; debug(2, "Connection %d: Watchdog Exit.", conn->connection_number); @@ -744,40 +753,47 @@ int msg_write_response(int fd, rtsp_message *resp) { void handle_record(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { debug(2, "Connection %d: RECORD", conn->connection_number); - if (conn->player_thread) - warn("Duplicate RECORD message -- ignored"); - else - player_play(conn); // the thread better be 0 + if (have_player(conn)) { - resp->respcode = 200; - // I think this is for telling the client what the absolute minimum latency - // actually is, - // and when the client specifies a latency, it should be added to this figure. + if (conn->player_thread) + warn("Duplicate RECORD message -- ignored"); + else + player_play(conn); // the thread better be 0 - // Thus, [the old version of] AirPlay's latency figure of 77175, when added to 11025 gives you - // exactly 88200 - // and iTunes' latency figure of 88553, when added to 11025 gives you 99578, - // pretty close to the 99400 we guessed. + resp->respcode = 200; + // I think this is for telling the client what the absolute minimum latency + // actually is, + // and when the client specifies a latency, it should be added to this figure. - msg_add_header(resp, "Audio-Latency", "11025"); + // Thus, [the old version of] AirPlay's latency figure of 77175, when added to 11025 gives you + // exactly 88200 + // and iTunes' latency figure of 88553, when added to 11025 gives you 99578, + // pretty close to the 99400 we guessed. - char *p; - uint32_t rtptime = 0; - char *hdr = msg_get_header(req, "RTP-Info"); + msg_add_header(resp, "Audio-Latency", "11025"); - if (hdr) { - // debug(1,"FLUSH message received: \"%s\".",hdr); - // get the rtp timestamp - p = strstr(hdr, "rtptime="); - if (p) { - p = strchr(p, '='); + char *p; + uint32_t rtptime = 0; + char *hdr = msg_get_header(req, "RTP-Info"); + + if (hdr) { + // debug(1,"FLUSH message received: \"%s\".",hdr); + // get the rtp timestamp + p = strstr(hdr, "rtptime="); if (p) { - rtptime = uatoi(p + 1); // unsigned integer -- up to 2^32-1 - // rtptime--; - // debug(1,"RTSP Flush Requested by handle_record: %u.",rtptime); - player_flush(rtptime, conn); + p = strchr(p, '='); + if (p) { + rtptime = uatoi(p + 1); // unsigned integer -- up to 2^32-1 + // rtptime--; + // debug(1,"RTSP Flush Requested by handle_record: %u.",rtptime); + player_flush(rtptime, conn); + } } } + } else { + warn("Connection %d RECORD received without having the player (no ANNOUNCE?)", + conn->connection_number); + resp->respcode = 451; } } @@ -839,109 +855,119 @@ void handle_flush(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { debug(3, "Connection %d: SETUP", conn->connection_number); - uint16_t cport, tport; - char *ar = msg_get_header(req, "Active-Remote"); - if (ar) { - debug(2, "Connection %d: SETUP -- Active-Remote string seen: \"%s\".", conn->connection_number, - ar); - // get the active remote - char *p; - conn->dacp_active_remote = strtoul(ar, &p, 10); + resp->respcode = 451; // invalid arguments -- expect them + + if (have_player(conn)) { + + uint16_t cport, tport; + + char *ar = msg_get_header(req, "Active-Remote"); + if (ar) { + debug(2, "Connection %d: SETUP -- Active-Remote string seen: \"%s\".", + conn->connection_number, ar); + // get the active remote + char *p; + conn->dacp_active_remote = strtoul(ar, &p, 10); #ifdef CONFIG_METADATA - send_metadata('ssnc', 'acre', ar, strlen(ar), req, 1); + send_metadata('ssnc', 'acre', ar, strlen(ar), req, 1); #endif - } else { - debug(2, "Connection %d: SETUP -- Note: no Active-Remote information the SETUP Record.", - conn->connection_number); - conn->dacp_active_remote = 0; - } - - ar = msg_get_header(req, "DACP-ID"); - if (ar) { - debug(2, "Connection %d: SETUP -- DACP-ID string seen: \"%s\".", conn->connection_number, ar); - if (conn->dacp_id) // this is in case SETUP was previously called - free(conn->dacp_id); - conn->dacp_id = strdup(ar); -#ifdef CONFIG_METADATA - send_metadata('ssnc', 'daid', ar, strlen(ar), req, 1); -#endif - } else { - debug(2, "Connection %d: SETUP doesn't include DACP-ID string information.", - conn->connection_number); - if (conn->dacp_id) // this is in case SETUP was previously called - free(conn->dacp_id); - conn->dacp_id = NULL; - } - - char *hdr = msg_get_header(req, "Transport"); - if (!hdr) { - debug(1, "Connection %d: SETUP doesn't contain a Transport header.", conn->connection_number); - goto error; - } - - char *p; - p = strstr(hdr, "control_port="); - if (!p) { - debug(1, "Connection %d: SETUP doesn't specify a control_port.", conn->connection_number); - goto error; - } - p = strchr(p, '=') + 1; - cport = atoi(p); - - p = strstr(hdr, "timing_port="); - if (!p) { - debug(1, "Connection %d: SETUP doesn't specify a timing_port.", conn->connection_number); - goto error; - } - p = strchr(p, '=') + 1; - tport = atoi(p); - - if (conn->rtp_running) { - if ((conn->remote_control_port != cport) || (conn->remote_timing_port != tport)) { - warn("Connection %d: Duplicate SETUP message with different control (old %u, new %u) or " - "timing (old %u, new " - "%u) ports! This is probably fatal!", - conn->connection_number, conn->remote_control_port, cport, conn->remote_timing_port, - tport); } else { - warn("Connection %d: Duplicate SETUP message with the same control (%u) and timing (%u) " - "ports. This is " - "probably not fatal.", - conn->connection_number, conn->remote_control_port, conn->remote_timing_port); + debug(2, "Connection %d: SETUP -- Note: no Active-Remote information the SETUP Record.", + conn->connection_number); + conn->dacp_active_remote = 0; } + + ar = msg_get_header(req, "DACP-ID"); + if (ar) { + debug(2, "Connection %d: SETUP -- DACP-ID string seen: \"%s\".", conn->connection_number, ar); + if (conn->dacp_id) // this is in case SETUP was previously called + free(conn->dacp_id); + conn->dacp_id = strdup(ar); +#ifdef CONFIG_METADATA + send_metadata('ssnc', 'daid', ar, strlen(ar), req, 1); +#endif + } else { + debug(2, "Connection %d: SETUP doesn't include DACP-ID string information.", + conn->connection_number); + if (conn->dacp_id) // this is in case SETUP was previously called + free(conn->dacp_id); + conn->dacp_id = NULL; + } + + char *hdr = msg_get_header(req, "Transport"); + if (hdr) { + char *p; + p = strstr(hdr, "control_port="); + if (p) { + p = strchr(p, '=') + 1; + cport = atoi(p); + + p = strstr(hdr, "timing_port="); + if (p) { + p = strchr(p, '=') + 1; + tport = atoi(p); + + if (conn->rtp_running) { + if ((conn->remote_control_port != cport) || (conn->remote_timing_port != tport)) { + warn("Connection %d: Duplicate SETUP message with different control (old %u, new %u) " + "or " + "timing (old %u, new " + "%u) ports! This is probably fatal!", + conn->connection_number, conn->remote_control_port, cport, + conn->remote_timing_port, tport); + } else { + warn("Connection %d: Duplicate SETUP message with the same control (%u) and timing " + "(%u) " + "ports. This is " + "probably not fatal.", + conn->connection_number, conn->remote_control_port, conn->remote_timing_port); + } + } else { + rtp_setup(&conn->local, &conn->remote, cport, tport, conn); + } + if (conn->local_audio_port != 0) { + + char resphdr[256] = ""; + snprintf(resphdr, sizeof(resphdr), + "RTP/AVP/" + "UDP;unicast;interleaved=0-1;mode=record;control_port=%d;" + "timing_port=%d;server_" + "port=%d", + conn->local_control_port, conn->local_timing_port, conn->local_audio_port); + + msg_add_header(resp, "Transport", resphdr); + + msg_add_header(resp, "Session", "1"); + + resp->respcode = 200; // it all worked out okay + debug(1, "Connection %d: SETUP with UDP ports Control: %d, Timing: %d and Audio: %d.", + conn->connection_number, conn->local_control_port, conn->local_timing_port, + conn->local_audio_port); + + } else { + debug(1, "Connection %d: SETUP seems to specify a null audio port.", + conn->connection_number); + } + } else { + debug(1, "Connection %d: SETUP doesn't specify a timing_port.", conn->connection_number); + } + } else { + debug(1, "Connection %d: SETUP doesn't specify a control_port.", conn->connection_number); + } + } else { + debug(1, "Connection %d: SETUP doesn't contain a Transport header.", conn->connection_number); + } + if (resp->respcode != 200) { + 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); + } + } else { - rtp_setup(&conn->local, &conn->remote, cport, tport, conn); + warn("Connection %d SETUP received without having the player (no ANNOUNCE?)", + conn->connection_number); } - if (conn->local_audio_port == 0) { - debug(1, "Connection %d: SETUP seems to specify a null audio port.", conn->connection_number); - goto error; - } - - char resphdr[256] = ""; - snprintf(resphdr, sizeof(resphdr), "RTP/AVP/" - "UDP;unicast;interleaved=0-1;mode=record;control_port=%d;" - "timing_port=%d;server_" - "port=%d", - conn->local_control_port, conn->local_timing_port, conn->local_audio_port); - - msg_add_header(resp, "Transport", resphdr); - - msg_add_header(resp, "Session", "1"); - - resp->respcode = 200; - debug(1, "Connection %d: SETUP with UDP ports Control: %d, Timing: %d and Audio: %d.", - conn->connection_number, conn->local_control_port, conn->local_timing_port, - conn->local_audio_port); - return; - -error: - warn("Connection %d: SETUP -- Error in setup request -- unlocking play lock.", - conn->connection_number); - 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 } /* @@ -2079,7 +2105,7 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { debug(3, "Connection %d: Checking play lock.", conn->connection_number); 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(2, "Connection %d: Unlocking play lock.", conn->connection_number); playing_conn = NULL; } debug_mutex_unlock(&playing_conn_lock, 3); From 1240c6efab7488ce6f7ced6e5be4025f3032d6fe Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Thu, 29 Nov 2018 15:32:06 +0000 Subject: [PATCH 13/22] Adds checks for posession of the player in order to handle flush, teardown requests. --- rtsp.c | 78 ++++++++++++++++++++++++++++++---------------------------- 1 file changed, 40 insertions(+), 38 deletions(-) diff --git a/rtsp.c b/rtsp.c index 637938ef..b643c7fe 100644 --- a/rtsp.c +++ b/rtsp.c @@ -752,11 +752,9 @@ int msg_write_response(int fd, rtsp_message *resp) { void handle_record(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { debug(2, "Connection %d: RECORD", conn->connection_number); - if (have_player(conn)) { - if (conn->player_thread) - warn("Duplicate RECORD message -- ignored"); + warn("Connection %d: RECORD: Duplicate RECORD message -- ignored", conn->connection_number); else player_play(conn); // the thread better be 0 @@ -809,59 +807,62 @@ void handle_options(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message * void handle_teardown(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message *req, rtsp_message *resp) { debug(2, "Connection %d: TEARDOWN", conn->connection_number); - // if (!rtsp_playing()) - // debug(1, "This RTSP connection thread (%d) doesn't think it's playing, but " - // "it's sending a response to teardown anyway",conn->connection_number); - resp->respcode = 200; - msg_add_header(resp, "Connection", "close"); - - debug(3, + if (have_player(conn)) { + resp->respcode = 200; + msg_add_header(resp, "Connection", "close"); + debug( + 3, "TEARDOWN: synchronously terminating the player thread of RTSP conversation thread %d (2).", conn->connection_number); - player_stop(conn); - debug(3, "TEARDOWN: successful termination of playing thread of RTSP conversation thread %d.", - conn->connection_number); + player_stop(conn); + debug(3, "TEARDOWN: successful termination of playing thread of RTSP conversation thread %d.", + conn->connection_number); + } else { + warn("Connection %d TEARDOWN received without having the player (no ANNOUNCE?)", + conn->connection_number); + resp->respcode = 451; + } } void handle_flush(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { debug(3, "Connection %d: FLUSH", conn->connection_number); - // if (!rtsp_playing()) - // debug(1, "This RTSP conversation thread (%d) doesn't think it's playing, but " - // "it's sending a response to flush anyway",conn->connection_number); - char *p = NULL; - uint32_t rtptime = 0; - char *hdr = msg_get_header(req, "RTP-Info"); + if (have_player(conn)) { + char *p = NULL; + uint32_t rtptime = 0; + char *hdr = msg_get_header(req, "RTP-Info"); - if (hdr) { - // debug(1,"FLUSH message received: \"%s\".",hdr); - // get the rtp timestamp - p = strstr(hdr, "rtptime="); - if (p) { - p = strchr(p, '='); - if (p) - rtptime = uatoi(p + 1); // unsigned integer -- up to 2^32-1 + if (hdr) { + // debug(1,"FLUSH message received: \"%s\".",hdr); + // get the rtp timestamp + p = strstr(hdr, "rtptime="); + if (p) { + p = strchr(p, '='); + if (p) + rtptime = uatoi(p + 1); // unsigned integer -- up to 2^32-1 + } } - } // debug(1,"RTSP Flush Requested: %u.",rtptime); #ifdef CONFIG_METADATA - if (p) - send_metadata('ssnc', 'flsr', p + 1, strlen(p + 1), req, 1); - else - send_metadata('ssnc', 'flsr', NULL, 0, NULL, 0); + if (p) + send_metadata('ssnc', 'flsr', p + 1, strlen(p + 1), req, 1); + else + send_metadata('ssnc', 'flsr', NULL, 0, NULL, 0); #endif - player_flush(rtptime, conn); // will not crash even it there is no player thread. - resp->respcode = 200; + player_flush(rtptime, conn); // will not crash even it there is no player thread. + resp->respcode = 200; + + } else { + warn("Connection %d FLUSH received without having the player (no ANNOUNCE?)", + conn->connection_number); + resp->respcode = 451; + } } void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { debug(3, "Connection %d: SETUP", conn->connection_number); - resp->respcode = 451; // invalid arguments -- expect them - if (have_player(conn)) { - uint16_t cport, tport; - char *ar = msg_get_header(req, "Active-Remote"); if (ar) { debug(2, "Connection %d: SETUP -- Active-Remote string seen: \"%s\".", @@ -959,6 +960,7 @@ void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { debug(1, "Connection %d: SETUP doesn't contain a Transport header.", conn->connection_number); } if (resp->respcode != 200) { + debug(1, "Connection %d: SETUP error -- releasing the player lock.", conn->connection_number); 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); From 4d4272c8baf4e2da8ca351ecd54a70999b362498 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Thu, 29 Nov 2018 15:36:18 +0000 Subject: [PATCH 14/22] Improve player watchdog, improve clearing down of ports, improve handling of write- and read-erroes on the RTSP channel. Improve code for holding and releasing the player. --- configure.ac | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/configure.ac b/configure.ac index 786ed9c4..5c2874e1 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.3d29], [mikebrady@eircom.net]) +AC_INIT([shairport-sync], [3.3d30], [mikebrady@eircom.net]) AM_INIT_AUTOMAKE AC_CONFIG_SRCDIR([shairport.c]) AC_CONFIG_HEADERS([config.h]) From 4a5b0009a4b03b8db3b3fab44e3a80ffc2123c1e Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Thu, 29 Nov 2018 17:13:12 +0000 Subject: [PATCH 15/22] Quieten a debug message --- rtp.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/rtp.c b/rtp.c index 61c69dd2..b8b1ea5b 100644 --- a/rtp.c +++ b/rtp.c @@ -1110,7 +1110,7 @@ int sanitised_source_rate_information(uint32_t *frames, uint64_t *time, rtsp_con double calculated_frame_rate = ((1.0 * local_frames) / local_time) * one_fp; if (((calculated_frame_rate / conn->input_rate) > 1.002) || ((calculated_frame_rate / conn->input_rate) < 0.998)) { - debug(1, "input frame rate out of bounds at %.2f fps.", calculated_frame_rate); + debug(2, "input frame rate out of bounds at %.2f fps.", calculated_frame_rate); result = 1; } else { *frames = local_frames; From f2a3ba00cc9b18a6cf7f73f9eea9972a26d86395 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Thu, 29 Nov 2018 17:14:40 +0000 Subject: [PATCH 16/22] Move cleanup push to start of RTSP initialisation. Take more care at startup and closedown to make stuff uncancellable. --- rtsp.c | 48 ++++++++++++++++++++++++++++++++++-------------- 1 file changed, 34 insertions(+), 14 deletions(-) diff --git a/rtsp.c b/rtsp.c index b643c7fe..f3831683 100644 --- a/rtsp.c +++ b/rtsp.c @@ -1591,7 +1591,7 @@ 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); + debug(3, "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 @@ -1608,8 +1608,8 @@ 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(1, "Connection %d ANNOUNCE is waiting for connection %d to shut down.", + conn->connection_number, 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.", @@ -2062,10 +2062,14 @@ authenticate: void rtsp_conversation_thread_cleanup_function(void *arg) { rtsp_conn_info *conn = (rtsp_conn_info *)arg; - // debug(1, "Connection %d: rtsp_conversation_thread_func_cleanup_function called.", - // conn->connection_number); + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); + + debug(3, "Connection %d: rtsp_conversation_thread_func_cleanup_function called.", + conn->connection_number); if (conn->player_thread) player_stop(conn); + if (conn->fd > 0) { debug(3, "Connection %d: closing fd %d.", conn->connection_number, conn->fd); close(conn->fd); @@ -2096,11 +2100,8 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { debug(2, "Cancel watchdog thread."); pthread_cancel(conn->player_watchdog_thread); - int oldState; - pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); debug(2, "Join watchdog thread."); pthread_join(conn->player_watchdog_thread, NULL); - pthread_setcancelstate(oldState, NULL); debug(2, "Delete watchdog mutex."); pthread_mutex_destroy(&conn->watchdog_mutex); @@ -2114,6 +2115,7 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { debug(2, "Connection %d: RTSP thread terminated.", conn->connection_number); conn->running = 0; + pthread_setcancelstate(oldState, NULL); } void msg_cleanup_function(void *arg) { @@ -2148,6 +2150,9 @@ static void *rtsp_conversation_thread_func(void *pconn) { die("Connection %d: error %d initialising flow control condition variable.", conn->connection_number, rc); + // nothing before this is cancellable + pthread_cleanup_push(rtsp_conversation_thread_cleanup_function, (void *)conn); + rtp_initialise(conn); char *hdr = NULL; @@ -2156,7 +2161,6 @@ static void *rtsp_conversation_thread_func(void *pconn) { int rtsp_read_request_attempt_count = 1; // 1 means exit immediately rtsp_message *req, *resp; - pthread_cleanup_push(rtsp_conversation_thread_cleanup_function, (void *)conn); while (conn->stop == 0) { int debug_level = 3; // for printing the request and response reply = rtsp_read_request(conn, &req); @@ -2232,6 +2236,12 @@ static void *rtsp_conversation_thread_func(void *pconn) { debug(1, "Connection %d: Unable to write an RTSP message response. Terminating the " "connection.", conn->connection_number); + struct linger so_linger; + so_linger.l_onoff = 1; // "true" + so_linger.l_linger = 0; + err = setsockopt(conn->fd, SOL_SOCKET, SO_LINGER, &so_linger, sizeof so_linger); + if (err) + debug(1, "Could not set the RTSP socket to abort due to a write error on closing."); conn->stop = 1; // if (debuglev >= 1) // debuglev = 3; // see what happens next @@ -2249,7 +2259,14 @@ 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)) + if (reply == rtsp_read_request_response_read_error) { + struct linger so_linger; + so_linger.l_onoff = 1; // "true" + so_linger.l_linger = 0; + int err = setsockopt(conn->fd, SOL_SOCKET, SO_LINGER, &so_linger, sizeof so_linger); + if (err) + debug(1, "Could not set the RTSP socket to abort due to a read error on closing."); + } // debuglev = 3; // see what happens next } else { if (reply == rtsp_read_request_response_channel_closed) @@ -2298,15 +2315,20 @@ static const char *format_address(struct sockaddr *fsa) { */ void rtsp_listen_loop_cleanup_handler(__attribute__((unused)) void *arg) { + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); debug(1, "rtsp_listen_loop_cleanup_handler called."); cancel_all_RTSP_threads(); int *sockfd = (int *)arg; mdns_unregister(); if (sockfd) free(sockfd); + pthread_setcancelstate(oldState, NULL); } void rtsp_listen_loop(void) { + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); struct addrinfo hints, *info, *p; char portstr[6]; int *sockfd = NULL; @@ -2405,9 +2427,7 @@ void rtsp_listen_loop(void) { mdns_register(); - // printf("Listening for connections."); - // shairport_startup_complete(); - + pthread_setcancelstate(oldState, NULL); int acceptfd; struct timeval tv; pthread_cleanup_push(rtsp_listen_loop_cleanup_handler, (void *)sockfd); @@ -2509,6 +2529,6 @@ void rtsp_listen_loop(void) { } } while (1); - pthread_cleanup_pop(0); + pthread_cleanup_pop(1); // should never happen debug(1, "Oops -- fell out of the RTSP select loop"); } From 0eac2b9cb3664235f8fb30481d48983553a14f77 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Thu, 29 Nov 2018 22:03:49 +0000 Subject: [PATCH 17/22] Move closing of ports to the player thread cleanup. They can be bound without the UDP threads ever having been called, so they must be closed when the player thread exits. --- player.c | 8 ++++++++ rtp.c | 33 ++++++--------------------------- 2 files changed, 14 insertions(+), 27 deletions(-) diff --git a/player.c b/player.c index 57d7527b..9c0482c7 100644 --- a/player.c +++ b/player.c @@ -1448,6 +1448,14 @@ void player_thread_cleanup_handler(void *arg) { pthread_join(conn->rtp_audio_thread, NULL); debug(2, "Audio thread terminated."); + debug(2, "Closing timing, control and audio sockets..."); + if (conn->control_socket) + close(conn->control_socket); + if (conn->timing_socket) + close(conn->timing_socket); + if (conn->audio_socket) + close(conn->audio_socket); + if (conn->outbuf) { free(conn->outbuf); conn->outbuf = NULL; diff --git a/rtp.c b/rtp.c index b8b1ea5b..0de094c6 100644 --- a/rtp.c +++ b/rtp.c @@ -97,16 +97,8 @@ uint64_t local_to_remote_time_difference_now(rtsp_conn_info *conn) { return conn->local_to_remote_time_difference + (uint64_t)(drift * (uint64_t)0x100000000); } -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, "Close Audio Socket."); - close(conn->audio_socket); - debug(3, "Audio Receiver Cleanup Successful."); - usleep(20000); // microseconds - pthread_setcancelstate(oldState, NULL); +void rtp_audio_receiver_cleanup_handler(__attribute__((unused)) void *arg) { + debug(3, "Audio Receiver Cleanup Done."); } void *rtp_audio_receiver(void *arg) { @@ -240,18 +232,8 @@ void *rtp_audio_receiver(void *arg) { pthread_exit(NULL); } -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, "Shut Down Control Socket."); - shutdown(conn->control_socket, SHUT_RDWR); - debug(3, "Close Control Socket."); - close(conn->control_socket); - debug(3, "Control Receiver Cleanup Successful."); - usleep(20000); // microseconds - pthread_setcancelstate(oldState, NULL); +void rtp_control_handler_cleanup_handler(__attribute__((unused)) void *arg) { + debug(3, "Control Receiver Cleanup Done."); } void *rtp_control_receiver(void *arg) { @@ -564,18 +546,15 @@ void *rtp_timing_sender(void *arg) { } 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; debug(3, "Cancel Timing Requester."); pthread_cancel(conn->timer_requester); + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); debug(3, "Join Timing Requester."); pthread_join(conn->timer_requester, NULL); - debug(3, "Close Timing Socket."); - close(conn->timing_socket); debug(3, "Timing Receiver Cleanup Successful."); - usleep(20000); // microseconds pthread_setcancelstate(oldState, NULL); } From a5c65ceced5671f3134ef378cd3202e0660eae17 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 30 Nov 2018 14:55:04 +0000 Subject: [PATCH 18/22] Move UDP port cloure to the RTSP thread, don't allow calls to mdns_* to be cancelled. Remove usage of (p)select in rtsp thread handling. --- player.c | 13 ++++--------- rtp.c | 16 +++++++++------- rtsp.c | 31 +++++++++++++++++++++++-------- 3 files changed, 36 insertions(+), 24 deletions(-) diff --git a/player.c b/player.c index 9c0482c7..cd9a9b8d 100644 --- a/player.c +++ b/player.c @@ -1448,14 +1448,6 @@ void player_thread_cleanup_handler(void *arg) { pthread_join(conn->rtp_audio_thread, NULL); debug(2, "Audio thread terminated."); - debug(2, "Closing timing, control and audio sockets..."); - if (conn->control_socket) - close(conn->control_socket); - if (conn->timing_socket) - close(conn->timing_socket); - if (conn->audio_socket) - close(conn->audio_socket); - if (conn->outbuf) { free(conn->outbuf); conn->outbuf = NULL; @@ -1736,7 +1728,9 @@ void *player_thread_func(void *arg) { pthread_cleanup_push(player_thread_cleanup_handler, arg); // undo what's been done so far -// stop looking elsewhere for DACP stuff + // stop looking elsewhere for DACP stuff + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); #ifdef CONFIG_DACP_CLIENT // debug(1, "Set dacp server info"); @@ -1753,6 +1747,7 @@ void *player_thread_func(void *arg) { // almost certainly, this has pthread cancellation points in it -- beware conn->dapo_private_storage = mdns_dacp_monitor(conn->dacp_id); #endif + pthread_setcancelstate(oldState, NULL); // set the default volume to whaterver it was before, as stored in the config airplay_volume debug(2, "Set initial volume to %f.", config.airplay_volume); diff --git a/rtp.c b/rtp.c index 0de094c6..1da6097f 100644 --- a/rtp.c +++ b/rtp.c @@ -847,13 +847,15 @@ static uint16_t bind_port(int ip_family, const char *self_ip_address, uint32_t s if (local_socket == -1) die("Could not allocate a socket."); - int val = 1; - ret = setsockopt(local_socket, SOL_SOCKET, SO_REUSEADDR, &val, sizeof(val)); - if (ret < 0) { - char errorstring[1024]; - strerror_r(errno, (char *)errorstring, sizeof(errorstring)); - debug(1, "Error %d: \"%s\". Couldn't set SO_REUSEADDR"); - } + /* + int val = 1; + ret = setsockopt(local_socket, SOL_SOCKET, SO_REUSEADDR, &val, sizeof(val)); + if (ret < 0) { + char errorstring[1024]; + strerror_r(errno, (char *)errorstring, sizeof(errorstring)); + debug(1, "Error %d: \"%s\". Couldn't set SO_REUSEADDR"); + } + */ SOCKADDR myaddr; int tryCount = 0; diff --git a/rtsp.c b/rtsp.c index f3831683..0b3625bd 100644 --- a/rtsp.c +++ b/rtsp.c @@ -555,18 +555,21 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes int msg_size = -1; while (msg_size < 0) { - fd_set readfds; - FD_ZERO(&readfds); - FD_SET(conn->fd, &readfds); - do { - memory_barrier(); - } while (conn->stop == 0 && - pselect(conn->fd + 1, &readfds, NULL, NULL, NULL, &pselect_sigset) <= 0); + /* +fd_set readfds; +FD_ZERO(&readfds); +FD_SET(conn->fd, &readfds); +do { + memory_barrier(); +} while (conn->stop == 0 && + pselect(conn->fd + 1, &readfds, NULL, NULL, NULL, &pselect_sigset) <= 0); +*/ if (conn->stop != 0) { debug(3, "RTSP conversation thread %d shutdown requested.", conn->connection_number); reply = rtsp_read_request_response_immediate_shutdown_requested; goto shutdown; } + nread = read(conn->fd, buf + inbuf, buflen - inbuf); if (nread == 0) { @@ -640,6 +643,8 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes warning_message_sent = 1; } } + + /* fd_set readfds; FD_ZERO(&readfds); FD_SET(conn->fd, &readfds); @@ -647,6 +652,8 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes memory_barrier(); } while (conn->stop == 0 && pselect(conn->fd + 1, &readfds, NULL, NULL, NULL, &pselect_sigset) <= 0); + */ + if (conn->stop != 0) { debug(1, "RTSP shutdown requested."); reply = rtsp_read_request_response_immediate_shutdown_requested; @@ -2070,6 +2077,14 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { if (conn->player_thread) player_stop(conn); + debug(3, "Closing timing, control and audio sockets..."); + if (conn->control_socket) + close(conn->control_socket); + if (conn->timing_socket) + close(conn->timing_socket); + if (conn->audio_socket) + close(conn->audio_socket); + if (conn->fd > 0) { debug(3, "Connection %d: closing fd %d.", conn->connection_number, conn->fd); close(conn->fd); @@ -2517,7 +2532,7 @@ void rtsp_listen_loop(void) { // conn->thread = rtsp_conversation_thread; // conn->stop = 0; // record's memory has been zeroed // conn->authorized = 0; // record's memory has been zeroed - fcntl(conn->fd, F_SETFL, O_NONBLOCK); + // fcntl(conn->fd, F_SETFL, O_NONBLOCK); ret = pthread_create(&conn->thread, NULL, rtsp_conversation_thread_func, conn); // also acts as a memory barrier From 2737222b0b5bb363e837821e89e47760655dae56 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sat, 1 Dec 2018 16:52:23 +0000 Subject: [PATCH 19/22] Fix a non-initialisation of parameters if no h/w mixer used. Add a few diagnostics, tidy up initial diagnostic message, add verbosity level and whether mixer used. --- audio_alsa.c | 10 +++++----- player.c | 12 +++++++++--- rtsp.c | 1 + shairport.c | 13 +++++++------ 4 files changed, 22 insertions(+), 14 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index 00c33900..372f84d1 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -70,7 +70,7 @@ audio_output audio_alsa = { .rate_info = &get_rate_information, .mute = NULL, // a function will be provided if it can, and is allowed to, do hardware mute .volume = NULL, // a function will be provided if it can do hardware volume - .parameters = ¶meters}; + .parameters = NULL}; // a function will be provided if it can do hardware volume static pthread_mutex_t alsa_mutex = PTHREAD_MUTEX_INITIALIZER; @@ -402,7 +402,7 @@ static int init(int argc, char **argv) { warn("Invalid audio argument: \"%s\" -- ignored", argv[optind]); } - debug(1, "alsa output device name is \"%s\".", alsa_out_dev); + debug(1, "alsa: output device name is \"%s\".", alsa_out_dev); if (hardware_mixer) { @@ -453,8 +453,8 @@ static int init(int argc, char **argv) { snd_ctl_elem_id_set_name(elem_id, alsa_mix_ctrl); if (snd_ctl_get_dB_range(ctl, elem_id, &alsa_mix_mindb, &alsa_mix_maxdb) == 0) { - debug(1, "Volume control \"%s\" has dB volume from %f to %f.", alsa_mix_ctrl, - (1.0 * alsa_mix_mindb) / 100.0, (1.0 * alsa_mix_maxdb) / 100.0); + debug(1, "alsa: hardware mixer \"%s\" selected, with dB volume from %f to %f.", + alsa_mix_ctrl, (1.0 * alsa_mix_mindb) / 100.0, (1.0 * alsa_mix_maxdb) / 100.0); has_softvol = 1; audio_alsa.volume = &volume; // insert the volume function now we know it can do dB stuff @@ -492,7 +492,7 @@ static int init(int argc, char **argv) { debug_mutex_unlock(&alsa_mutex, 3); // release the mutex pthread_cleanup_pop(0); } else { - // debug(1, "Has no mixer and thus no hardware mute."); + debug(1, "alsa: no hardware mixer selected."); } alsa_mix_handle = NULL; diff --git a/player.c b/player.c index cd9a9b8d..429a218d 100644 --- a/player.c +++ b/player.c @@ -1749,7 +1749,7 @@ void *player_thread_func(void *arg) { #endif pthread_setcancelstate(oldState, NULL); - // set the default volume to whaterver it was before, as stored in the config airplay_volume + // set the default volume to whatever it was before, as stored in the config airplay_volume debug(2, "Set initial volume to %f.", config.airplay_volume); player_volume(config.airplay_volume, conn); // will contain a cancellation point if asked to wait @@ -2778,8 +2778,14 @@ int player_stop(rtsp_conn_info *conn) { debug(2, "player_thread cancel..."); pthread_cancel(*conn->player_thread); debug(2, "player_thread join..."); - pthread_join(*conn->player_thread, NULL); - debug(2, "player_thread joined."); + if (pthread_join(*conn->player_thread, NULL) == -1) { + char errorstring[1024]; + strerror_r(errno, (char *)errorstring, sizeof(errorstring)); + debug(1, "Connection %d: error %d joining player thread: \"%s\".", conn->connection_number, + errno, (char *)errorstring); + } else { + debug(2, "player_thread joined."); + } free(conn->player_thread); conn->player_thread = NULL; #ifdef CONFIG_METADATA diff --git a/rtsp.c b/rtsp.c index 0b3625bd..a5079616 100644 --- a/rtsp.c +++ b/rtsp.c @@ -170,6 +170,7 @@ int send_ssnc_metadata(uint32_t code, char *data, uint32_t length, int block) { } void pc_queue_cleanup_handler(void *arg) { + // debug(1, "pc_queue_cleanup_handler called."); pc_queue *the_queue = (pc_queue *)arg; int rc = pthread_mutex_unlock(&the_queue->pc_queue_lock); if (rc) diff --git a/shairport.c b/shairport.c index 506f9feb..11f085b1 100644 --- a/shairport.c +++ b/shairport.c @@ -1483,13 +1483,18 @@ int main(int argc, char **argv) { char *version_dbs = get_version_string(); if (version_dbs) { - debug(1, "Version: \"%s\"", version_dbs); + debug(1, "software version: \"%s\"", version_dbs); free(version_dbs); } else { - debug(1, "Can't print the version information!"); + debug(1, "can't print the version information!"); } /* Print out options */ + debug(1, "log verbosity is %d.", debuglev); + 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); debug(1, "statistics_requester status is %d.", config.statistics_requested); debug(1, "daemon status is %d.", config.daemonise); debug(1, "deamon pid file path is \"%s\".", pid_file_proc()); @@ -1563,10 +1568,6 @@ 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 %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]; From 3644300db15292ad4cee3d2d6a85e2fb2e93259c Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sat, 1 Dec 2018 17:13:20 +0000 Subject: [PATCH 20/22] Fix a non-initialisation of parameters if no h/w mixer used. Add a few diagnostics, tidy up initial diagnostic message, add verbosity level and whether mixer used. --- configure.ac | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/configure.ac b/configure.ac index 5c2874e1..ca23c4e4 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.3d30], [mikebrady@eircom.net]) +AC_INIT([shairport-sync], [3.3d31], [mikebrady@eircom.net]) AM_INIT_AUTOMAKE AC_CONFIG_SRCDIR([shairport.c]) AC_CONFIG_HEADERS([config.h]) From 8c9b1590112e86054c9b68cd9643860ef85c24f0 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sun, 2 Dec 2018 18:13:20 +0000 Subject: [PATCH 21/22] Stop using an unsigned integer for time when we want to watch if it goes negative. Only release the playing_conn if we already own it! --- common.c | 4 ++-- rtsp.c | 14 ++++++++------ 2 files changed, 10 insertions(+), 8 deletions(-) diff --git a/common.c b/common.c index 8cbcd0d4..b2c920ad 100644 --- a/common.c +++ b/common.c @@ -1142,10 +1142,10 @@ int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time, // this is not pthread_cancellation safe because is contains a cancellation point int oldState; pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); - useconds_t time_to_wait = dally_time; + int time_to_wait = dally_time; int r = pthread_mutex_trylock(mutex); while ((r == EBUSY) && (time_to_wait > 0)) { - useconds_t st = time_to_wait; + int st = time_to_wait; if (st > 1000) st = 1000; sps_nanosleep(0, st * 1000); // this contains a cancellation point diff --git a/rtsp.c b/rtsp.c index a5079616..11266c7d 100644 --- a/rtsp.c +++ b/rtsp.c @@ -257,7 +257,7 @@ int pc_queue_get_item(pc_queue *the_queue, void *the_stuff) { int have_player(rtsp_conn_info *conn) { int response = 0; debug_mutex_lock(&playing_conn_lock, 1000000, 3); - if (playing_conn == conn) // this connection definitely doesn't have the play lock + if (playing_conn == conn) // this connection definitely has the play lock response = 1; debug_mutex_unlock(&playing_conn_lock, 3); return response; @@ -970,7 +970,8 @@ void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { if (resp->respcode != 200) { debug(1, "Connection %d: SETUP error -- releasing the player lock.", conn->connection_number); debug_mutex_lock(&playing_conn_lock, 1000000, 3); - playing_conn = NULL; // this connection definitely doesn't have the play lock + if (playing_conn == conn) // if we have the player + playing_conn = NULL; // let it go debug_mutex_unlock(&playing_conn_lock, 3); } @@ -1630,7 +1631,7 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag debug_mutex_unlock(&playing_conn_lock, 3); if (should_wait) { - useconds_t time_remaining = 3000000; + int time_remaining = 3000000; // must be signed, as it could go negative... while ((time_remaining > 0) && (have_the_player == 0)) { debug_mutex_lock(&playing_conn_lock, 1000000, 3); // get it @@ -1829,7 +1830,8 @@ out: 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; + if (playing_conn == conn) // if we managed to acquire it + playing_conn = NULL; // let it go debug_mutex_unlock(&playing_conn_lock, 3); } } @@ -2123,9 +2125,9 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { debug(3, "Connection %d: Checking play lock.", conn->connection_number); debug_mutex_lock(&playing_conn_lock, 1000000, 3); // get it - if (playing_conn == conn) { + if (playing_conn == conn) { // if it's ours debug(2, "Connection %d: Unlocking play lock.", conn->connection_number); - playing_conn = NULL; + playing_conn = NULL; // let it go } debug_mutex_unlock(&playing_conn_lock, 3); From 038dee01ba14f2f721f5c6e44796a601ece01870 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Mon, 3 Dec 2018 10:33:29 +0000 Subject: [PATCH 22/22] Fix an error caused by using an unsigned integer as a signed number. It may have been causing lots of conversation threads to wait for the (blocked) current playing thread to exit. --- configure.ac | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/configure.ac b/configure.ac index ca23c4e4..1fda52d5 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.3d31], [mikebrady@eircom.net]) +AC_INIT([shairport-sync], [3.3d32], [mikebrady@eircom.net]) AM_INIT_AUTOMAKE AC_CONFIG_SRCDIR([shairport.c]) AC_CONFIG_HEADERS([config.h])