From d0dda0b095e9b4b8ef7bb67ff81e4292f33e184a Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Tue, 29 May 2018 21:53:38 +0100 Subject: [PATCH 01/27] Increase debugging temporarily for a TEARDOWN. --- rtsp.c | 3 +++ 1 file changed, 3 insertions(+) diff --git a/rtsp.c b/rtsp.c index 4299167a..b0b4a0f3 100644 --- a/rtsp.c +++ b/rtsp.c @@ -717,6 +717,8 @@ static void handle_options(rtsp_conn_info *conn, __attribute__((unused)) rtsp_me static void handle_teardown(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message *req, rtsp_message *resp) { debug(2, "Connection %d: TEARDOWN", conn->connection_number); + int tdl = debuglev; + debuglev = 3; // 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); @@ -729,6 +731,7 @@ static void handle_teardown(rtsp_conn_info *conn, __attribute__((unused)) rtsp_m player_stop(conn); debug(3, "TEARDOWN: successful termination of playing thread of RTSP conversation thread %d.", conn->connection_number); + debuglev = tdl; } static void handle_flush(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { From ad1f5b9fa27e96ad20cc40298d6d782a5656cffa Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Tue, 29 May 2018 22:13:16 +0100 Subject: [PATCH 02/27] Increase debugging temporarily for a TEARDOWN. --- configure.ac | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/configure.ac b/configure.ac index 1808e0b7..ddb41d8a 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.2d56], [mikebrady@eircom.net]) +AC_INIT([shairport-sync], [3.2d57], [mikebrady@eircom.net]) AM_INIT_AUTOMAKE AC_CONFIG_SRCDIR([shairport.c]) AC_CONFIG_HEADERS([config.h]) From 0a10f0de8114820594029cb5d46f256068eacb1c Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Tue, 29 May 2018 22:18:35 +0100 Subject: [PATCH 03/27] Update RELEASENOTES.md --- RELEASENOTES.md | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/RELEASENOTES.md b/RELEASENOTES.md index fce8751c..628607b6 100644 --- a/RELEASENOTES.md +++ b/RELEASENOTES.md @@ -1,4 +1,10 @@ +Version 3.2d57 +==== + +**Bug Chasing** +* Debug messaging has been enhanced when a TEARDOWN message is received. + Version 3.2d56 ==== **Enhancement** From f018a18495abe40a30ec9f020031cfd1177a8aea Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Wed, 30 May 2018 15:00:37 +0100 Subject: [PATCH 04/27] Add yet more debugging to the TEARDOWN sequence. --- player.c | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/player.c b/player.c index 8e51c9c3..9e5dce1f 100644 --- a/player.c +++ b/player.c @@ -2679,11 +2679,15 @@ int player_play(rtsp_conn_info *conn) { } int player_stop(rtsp_conn_info *conn) { + debug(3,"player_stop"); pthread_rwlock_wrlock(&conn->player_thread_lock); + debug(3,"player_thread_lock acquired"); if (conn->player_thread) { + debug(3,"player_thread exists"); conn->player_thread_please_stop = 1; pthread_cond_signal(&conn->flowcontrol); // tell it to give up pthread_kill(*conn->player_thread, SIGUSR1); + debug(3,"player_thread signalled"); pthread_join(*conn->player_thread, NULL); free(conn->player_thread); conn->player_thread = NULL; From 1df8858f27cf3c742360847565cce28c92a49699 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Wed, 30 May 2018 15:29:58 +0100 Subject: [PATCH 05/27] Add yet more debugging to the TEARDOWN sequence. --- configure.ac | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/configure.ac b/configure.ac index ddb41d8a..7e97c929 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.2d57], [mikebrady@eircom.net]) +AC_INIT([shairport-sync], [3.2d58], [mikebrady@eircom.net]) AM_INIT_AUTOMAKE AC_CONFIG_SRCDIR([shairport.c]) AC_CONFIG_HEADERS([config.h]) From 2dab0b0816781bd2b03790e9f4189485364bd009 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Wed, 30 May 2018 16:15:41 +0100 Subject: [PATCH 06/27] Update RELEASENOTES.md --- RELEASENOTES.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/RELEASENOTES.md b/RELEASENOTES.md index 628607b6..5ece0a94 100644 --- a/RELEASENOTES.md +++ b/RELEASENOTES.md @@ -1,5 +1,5 @@ -Version 3.2d57 +Version 3.2d57 and 3.2d58 ==== **Bug Chasing** From 9e89eff303b1319fb15f25bdd612408c6c087ce6 Mon Sep 17 00:00:00 2001 From: fumitti Date: Fri, 1 Jun 2018 14:57:46 +0900 Subject: [PATCH 07/27] Update shairport-sync.conf remove mixed spaces --- scripts/shairport-sync.conf | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/scripts/shairport-sync.conf b/scripts/shairport-sync.conf index 74cbb4ff..2f7f1378 100644 --- a/scripts/shairport-sync.conf +++ b/scripts/shairport-sync.conf @@ -17,7 +17,7 @@ general = // output_backend = "alsa"; // Run "shairport-sync -h" to get a list of all output_backends, e.g. "alsa", "pipe", "stdout". The default is the first one. // 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_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. // 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 From 18b37ea25423b4c7a8067c1ce0780f8a321b8bef Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 1 Jun 2018 08:29:48 +0100 Subject: [PATCH 08/27] Replace all pthread_mutex_locks with debug_mutex_lock with a message and timer. Not really tested. --- audio_alsa.c | 16 ++++++++-------- common.c | 42 ++++++++++++++++++++++-------------------- common.h | 6 ++++++ player.c | 26 +++++++++++++------------- rtp.c | 10 +++++----- 5 files changed, 54 insertions(+), 46 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index 09903519..b1e4d1f8 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -166,7 +166,7 @@ void do_snd_mixer_selem_set_playback_dB_all(snd_mixer_elem_t *mix_elem, double v } static int init(int argc, char **argv) { - pthread_mutex_lock(&alsa_mutex); + debug_mutex_lock(&alsa_mutex, 1000, 1); // debug(2,"audio_alsa init called."); const char *str; int value; @@ -227,7 +227,7 @@ static int init(int argc, char **argv) { /* Get the mute_using_playback_switch setting. */ if (config_lookup_string(config.cfg, "alsa.mute_using_playback_switch", &str)) { inform("The alsa \"mute_using_playback_switch\" setting is deprecated. " - "Please use the \"use_hardware_mute_if_available\" setting instead."); + "Please use the \"use_hardware_mute_if_available\" setting instead."); if (strcasecmp(str, "no") == 0) config.alsa_use_hardware_mute = 0; else if (strcasecmp(str, "yes") == 0) @@ -817,7 +817,7 @@ int delay(long *the_delay) { if (alsa_handle == NULL) { return -ENODEV; } else { - pthread_mutex_lock(&alsa_mutex); + debug_mutex_lock(&alsa_mutex, 10000, 1); int derr; if (snd_pcm_state(alsa_handle) == SND_PCM_STATE_RUNNING) { *the_delay = 0; // just to see what happens @@ -855,7 +855,7 @@ static void play(void *buf, int samples) { // debug(3,"audio_alsa play called."); int ret = 0; if (alsa_handle == NULL) { - pthread_mutex_lock(&alsa_mutex); + debug_mutex_lock(&alsa_mutex, 10000, 1); ret = open_alsa_device(); if (ret == 0) { if (audio_alsa.volume) @@ -866,7 +866,7 @@ static void play(void *buf, int samples) { pthread_mutex_unlock(&alsa_mutex); } if (ret == 0) { - pthread_mutex_lock(&alsa_mutex); + debug_mutex_lock(&alsa_mutex, 10000, 1); // snd_pcm_sframes_t current_delay = 0; int err; if (snd_pcm_state(alsa_handle) == SND_PCM_STATE_XRUN) { @@ -903,7 +903,7 @@ static void play(void *buf, int samples) { static void flush(void) { // debug(2,"audio_alsa flush called."); - pthread_mutex_lock(&alsa_mutex); + debug_mutex_lock(&alsa_mutex, 10000, 1); int derr; do_mute(1); if (alsa_handle) { @@ -973,7 +973,7 @@ void do_volume(double vol) { // caller is assumed to have the alsa_mutex when us } void volume(double vol) { - pthread_mutex_lock(&alsa_mutex); + debug_mutex_lock(&alsa_mutex, 1000, 1); volume_set_request = 1; // an external request has been made to set the volume do_volume(vol); pthread_mutex_unlock(&alsa_mutex); @@ -999,7 +999,7 @@ static void linear_volume(double vol) { static void mute(int mute_state_requested) { // debug(1,"External Mute Request: %d",mute_state_requested); - pthread_mutex_lock(&alsa_mutex); + debug_mutex_lock(&alsa_mutex, 10000, 1); mute_request_pending = 1; overriding_mute_state_requested = mute_state_requested; do_mute(mute_state_requested); diff --git a/common.c b/common.c index e835ab67..41218609 100644 --- a/common.c +++ b/common.c @@ -795,17 +795,16 @@ uint64_t get_absolute_time_in_fp() { // can't use CLOCK_MONOTONIC_RAW as it's not implemented in OpenWrt clock_gettime(CLOCK_MONOTONIC, &tn); uint64_t tnfpsec = tn.tv_sec; - if (tnfpsec>0x100000000) + if (tnfpsec > 0x100000000) warn("clock_gettime seconds overflow!"); uint64_t tnfpnsec = tn.tv_nsec; - if (tnfpnsec>0x100000000) + if (tnfpnsec > 0x100000000) warn("clock_gettime nanoseconds seconds overflow!"); - tnfpsec = tnfpsec<<32; - tnfpnsec = tnfpnsec<<32; - tnfpnsec = tnfpnsec/1000000000; - - time_now_fp = - tnfpsec + tnfpnsec; // types okay + tnfpsec = tnfpsec << 32; + tnfpnsec = tnfpnsec << 32; + tnfpnsec = tnfpnsec / 1000000000; + + time_now_fp = tnfpsec + tnfpnsec; // types okay #endif #ifdef COMPILE_FOR_OSX uint64_t time_now_mach; @@ -1014,15 +1013,9 @@ void sps_nanosleep(const time_t sec, const long nanosec) { debug(1, "Error in sps_nanosleep of %d sec and %ld nanoseconds: %d.", sec, nanosec, errno); } -char *previous_debug_message = NULL; - int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time, const char *debugmessage, int debuglevel) { - if (previous_debug_message) - free(previous_debug_message); - previous_debug_message = strdup(debugmessage); - useconds_t time_to_wait = dally_time; int r = pthread_mutex_trylock(mutex); while ((r == EBUSY) && (time_to_wait > 0)) { @@ -1036,17 +1029,26 @@ int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time, if (r != 0) { char errstr[1000]; if (r == EBUSY) - debug(debuglevel, - "error EBUSY waiting for a mutex: \"%s\". Previous debug message was: \"%s\".", - debugmessage, previous_debug_message); + debug(debuglevel, "timeout at %d microseconds while waiting for a mutex: \"%s\".", dally_time, + debugmessage); else - debug(debuglevel, - "error %d: \"%s\" waiting for a mutex: \"%s\". Previous debug message was: \"%s\".", r, - strerror_r(r, errstr, sizeof(errstr)), debugmessage, previous_debug_message); + debug(debuglevel, "error %d: \"%s\" waiting for a mutex: \"%s\".", r, + strerror_r(r, errstr, sizeof(errstr)), debugmessage); } return r; } +int _debug_mutex_lock(pthread_mutex_t *mutex, useconds_t dally_time, const char *filename, + const int line, int debuglevel) { + char dstring[1000]; + memset(dstring, 0, sizeof(dstring)); + snprintf(dstring, sizeof(dstring), "%s%d", filename, line); + int result = sps_pthread_mutex_timedlock(mutex, dally_time, dstring, debuglevel); + if (result == EBUSY) + result = pthread_mutex_lock(mutex); + return result; +} + char *get_version_string() { char *version_string = malloc(200); if (version_string) { diff --git a/common.h b/common.h index e749d5f3..8878c390 100644 --- a/common.h +++ b/common.h @@ -264,6 +264,12 @@ extern sigset_t pselect_sigset; // wait for the specified time in microseconds -- it checks every 20 milliseconds int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time, const char *debugmessage, int debuglevel); +// wait for the specified time, checking every 20 milliseconds, and block if it can't acquire the +// lock +int _debug_mutex_lock(pthread_mutex_t *mutex, useconds_t dally_time, const char *filename, + const int line, int debuglevel); + +#define debug_mutex_lock(mu, t, d) _debug_mutex_lock(mu, t, __FILE__, __LINE__, d) char *get_version_string(); // mallocs a string space -- remember to free it afterwards diff --git a/player.c b/player.c index 9e5dce1f..e7767e4a 100644 --- a/player.c +++ b/player.c @@ -478,13 +478,13 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp // ignore a request to flush that has been made before the first packet... if (conn->packet_count == 0) { - pthread_mutex_lock(&conn->flush_mutex); + debug_mutex_lock(&conn->flush_mutex, 1000, 1); conn->flush_requested = 0; conn->flush_rtp_timestamp = 0; pthread_mutex_unlock(&conn->flush_mutex); } - pthread_mutex_lock(&conn->ab_mutex); + debug_mutex_lock(&conn->ab_mutex, 10000, 1); conn->packet_count++; conn->time_of_last_audio_packet = get_absolute_time_in_fp(); if (conn->connection_state_to_output) { // if we are supposed to be processing these packets @@ -787,13 +787,12 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { abuf_t *curframe = 0; int notified_buffer_empty = 0; // diagnostic only - pthread_mutex_lock(&conn->ab_mutex); + debug_mutex_lock(&conn->ab_mutex, 10000, 1); int wait; long dac_delay = 0; // long because alsa returns a long do { // get the time local_time_now = get_absolute_time_in_fp(); // type okay - // 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 @@ -818,13 +817,13 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { conn->connection_state_to_output = rco; // change happening if (conn->connection_state_to_output == 0) { // going off - pthread_mutex_lock(&conn->flush_mutex); + debug_mutex_lock(&conn->flush_mutex, 1000, 1); conn->flush_requested = 1; pthread_mutex_unlock(&conn->flush_mutex); } } - pthread_mutex_lock(&conn->flush_mutex); + debug_mutex_lock(&conn->flush_mutex, 1000, 1); if (conn->flush_requested == 1) { if (config.output->flush) config.output->flush(); @@ -1201,6 +1200,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { (!conn->player_thread_please_stop); if (wait) { + debug(3, "buffer_get_frame is iterating"); uint64_t time_to_wait_for_wakeup_fp = ((uint64_t)1 << 32) / conn->input_rate; // this is time period of one frame time_to_wait_for_wakeup_fp *= 4 * 352; // four full 352-frame packets @@ -1294,7 +1294,7 @@ static int stuff_buffer_basic_32(int32_t *inptr, int length, enum sps_format_t l stuffsamp = (rand() % (length - 2)) + 1; // ensure there's always a sample before and after the item - pthread_mutex_lock(&conn->vol_mutex); + debug_mutex_lock(&conn->vol_mutex, 1000, 1); for (i = 0; i < stuffsamp; i++) { // the whole frame, if no stuffing process_sample(*inptr++, &l_outptr, l_output_format, conn->fix_volume, dither, conn); process_sample(*inptr++, &l_outptr, l_output_format, conn->fix_volume, dither, conn); @@ -2582,7 +2582,7 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c // debug(1,"Software attenuation set to %f, i.e %f out of 65,536, for airplay volume of // %f",software_attenuation,temp_fix_volume,airplay_volume); - pthread_mutex_lock(&conn->vol_mutex); + debug_mutex_lock(&conn->vol_mutex, 1000, 1); conn->fix_volume = temp_fix_volume; pthread_mutex_unlock(&conn->vol_mutex); @@ -2617,7 +2617,7 @@ void player_volume(double airplay_volume, rtsp_conn_info *conn) { void do_flush(int64_t timestamp, rtsp_conn_info *conn) { debug(3, "Flush requested up to %u. It seems as if 0 is special.", timestamp); - pthread_mutex_lock(&conn->flush_mutex); + debug_mutex_lock(&conn->flush_mutex, 1000, 1); conn->flush_requested = 1; // if (timestamp!=0) conn->flush_rtp_timestamp = timestamp; // flush all packets up to (and including?) this @@ -2679,15 +2679,15 @@ int player_play(rtsp_conn_info *conn) { } int player_stop(rtsp_conn_info *conn) { - debug(3,"player_stop"); + debug(3, "player_stop"); pthread_rwlock_wrlock(&conn->player_thread_lock); - debug(3,"player_thread_lock acquired"); + debug(3, "player_thread_lock acquired"); if (conn->player_thread) { - debug(3,"player_thread exists"); + debug(3, "player_thread exists"); conn->player_thread_please_stop = 1; pthread_cond_signal(&conn->flowcontrol); // tell it to give up pthread_kill(*conn->player_thread, SIGUSR1); - debug(3,"player_thread signalled"); + debug(3, "player_thread signalled"); pthread_join(*conn->player_thread, NULL); free(conn->player_thread); conn->player_thread = NULL; diff --git a/rtp.c b/rtp.c index 01c7706d..01f71c3f 100644 --- a/rtp.c +++ b/rtp.c @@ -328,7 +328,7 @@ void *rtp_control_receiver(void *arg) { } } - pthread_mutex_lock(&conn->reference_time_mutex); + debug_mutex_lock(&conn->reference_time_mutex, 1000, 1); // this is for debugging // uint64_t old_remote_reference_time = conn->remote_reference_timestamp_time; @@ -812,8 +812,8 @@ void rtp_setup(SOCKADDR *local, SOCKADDR *remote, uint16_t cport, uint16_t tport inet_ntop(conn->connection_ip_family, self_addr, conn->self_ip_string, sizeof(conn->self_ip_string)); - debug(2, "Connection %d: SETUP -- Connection from %s to self at %s.", - conn->connection_number,conn->client_ip_string, conn->self_ip_string); + debug(2, "Connection %d: SETUP -- Connection from %s to self at %s.", conn->connection_number, + conn->client_ip_string, conn->self_ip_string); // set up a the record of the remote's control socket struct addrinfo hints; @@ -891,7 +891,7 @@ void rtp_setup(SOCKADDR *local, SOCKADDR *remote, uint16_t cport, uint16_t tport void get_reference_timestamp_stuff(int64_t *timestamp, uint64_t *timestamp_time, uint64_t *remote_timestamp_time, rtsp_conn_info *conn) { // types okay - pthread_mutex_lock(&conn->reference_time_mutex); + debug_mutex_lock(&conn->reference_time_mutex, 1000, 1); *timestamp = conn->reference_timestamp; *timestamp_time = conn->reference_timestamp_time; // if ((*timestamp == 0) && (*timestamp_time == 0)) { @@ -902,7 +902,7 @@ void get_reference_timestamp_stuff(int64_t *timestamp, uint64_t *timestamp_time, } void clear_reference_timestamp(rtsp_conn_info *conn) { - pthread_mutex_lock(&conn->reference_time_mutex); + debug_mutex_lock(&conn->reference_time_mutex, 1000, 1); conn->reference_timestamp = 0; conn->reference_timestamp_time = 0; pthread_mutex_unlock(&conn->reference_time_mutex); From 93f410599f79f1ddbed75b44f1cf7c59aeb83fcc Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 1 Jun 2018 09:28:28 +0100 Subject: [PATCH 09/27] Add debug_mutex_unlock code in place of a regular pthread_mutex_unlock in some places. --- audio_alsa.c | 58 ++++++++++++++++++++++++++-------------------------- common.c | 17 ++++++++++++++- common.h | 5 +++++ player.c | 22 ++++++++++---------- rtp.c | 6 +++--- 5 files changed, 64 insertions(+), 44 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index b1e4d1f8..e2a53ccd 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -219,7 +219,7 @@ static int init(int argc, char **argv) { else if (strcasecmp(str, "yes") == 0) config.no_sync = 1; else { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid disable_synchronization option choice \"%s\". It should be \"yes\" or \"no\""); } } @@ -233,7 +233,7 @@ static int init(int argc, char **argv) { else if (strcasecmp(str, "yes") == 0) config.alsa_use_hardware_mute = 1; else { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid mute_using_playback_switch option choice \"%s\". It should be \"yes\" or " "\"no\""); } @@ -246,7 +246,7 @@ static int init(int argc, char **argv) { else if (strcasecmp(str, "yes") == 0) config.alsa_use_hardware_mute = 1; else { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid use_hardware_mute_if_available option choice \"%s\". It should be \"yes\" or " "\"no\""); } @@ -269,7 +269,7 @@ static int init(int argc, char **argv) { else if (strcasecmp(str, "S8") == 0) config.output_format = SPS_FORMAT_S8; else { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid output format \"%s\". It should be \"U8\", \"S8\", \"S16\", \"S24\", " "\"S24_3LE\", \"S24_3BE\" or " "\"S32\"", @@ -288,7 +288,7 @@ static int init(int argc, char **argv) { config.output_rate = value; break; default: - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid output rate \"%d\". It should be a multiple of 44,100 up to 352,800", value); } } @@ -300,7 +300,7 @@ static int init(int argc, char **argv) { else if (strcasecmp(str, "yes") == 0) config.no_mmap = 0; else { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid use_mmap_if_available option choice \"%s\". It should be \"yes\" or \"no\""); } } @@ -309,7 +309,7 @@ static int init(int argc, char **argv) { set_period_size_request = 1; debug(1, "Value read for period size is %d.", value); if (value < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid alsa period size setting \"%d\". It " "must be greater than 0.", value); @@ -323,7 +323,7 @@ static int init(int argc, char **argv) { set_buffer_size_request = 1; debug(1, "Value read for buffer size is %d.", value); if (value < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid alsa buffer size setting \"%d\". It " "must be greater than 0.", value); @@ -362,13 +362,13 @@ static int init(int argc, char **argv) { break; default: help(); - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid audio option -%c specified", opt); } } if (optind < argc) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid audio argument: %s", argv[optind]); } @@ -412,11 +412,11 @@ static int init(int argc, char **argv) { alsa_mix_ctrl); if (snd_ctl_open(&ctl, alsa_mix_dev, 0) < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Cannot open control \"%s\"", alsa_mix_dev); } if (snd_ctl_elem_id_malloc(&elem_id) < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Cannot allocate memory for control \"%s\"", alsa_mix_dev); } snd_ctl_elem_id_set_interface(elem_id, SND_CTL_ELEM_IFACE_MIXER); @@ -462,7 +462,7 @@ static int init(int argc, char **argv) { } alsa_mix_handle = NULL; - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); return 0; } @@ -507,7 +507,7 @@ int open_alsa_device(void) { ret = snd_pcm_hw_params_any(alsa_handle, alsa_params); if (ret < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); ; die("audio_alsa: Broken configuration for device \"%s\": no configurations " "available", @@ -534,7 +534,7 @@ int open_alsa_device(void) { ret = snd_pcm_hw_params_set_access(alsa_handle, alsa_params, access); if (ret < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("audio_alsa: Access type not available for device \"%s\": %s", alsa_out_dev, snd_strerror(ret)); } @@ -562,20 +562,20 @@ int open_alsa_device(void) { sf = SND_PCM_FORMAT_S32; break; default: - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); sf = SND_PCM_FORMAT_S16; // this is just to quieten a compiler warning die("Unsupported output format at audio_alsa.c"); } ret = snd_pcm_hw_params_set_format(alsa_handle, alsa_params, sf); if (ret < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("audio_alsa: Sample format %d not available for device \"%s\": %s", sample_format, alsa_out_dev, snd_strerror(ret)); } ret = snd_pcm_hw_params_set_channels(alsa_handle, alsa_params, 2); if (ret < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("audio_alsa: Channels count (2) not available for device \"%s\": %s", alsa_out_dev, snd_strerror(ret)); } @@ -591,7 +591,7 @@ int open_alsa_device(void) { ret = snd_pcm_hw_params_set_period_size_near(alsa_handle, alsa_params, &period_size_requested, &dir); if (ret < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("audio_alsa: cannot set period size of %lu: %s", period_size_requested, snd_strerror(ret)); snd_pcm_uframes_t actual_period_size; @@ -607,7 +607,7 @@ int open_alsa_device(void) { debug(1, "Attempting to set the buffer size to %lu", buffer_size_requested); ret = snd_pcm_hw_params_set_buffer_size_near(alsa_handle, alsa_params, &buffer_size_requested); if (ret < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("audio_alsa: cannot set buffer size of %lu: %s", buffer_size_requested, snd_strerror(ret)); } @@ -621,19 +621,19 @@ int open_alsa_device(void) { ret = snd_pcm_hw_params(alsa_handle, alsa_params); if (ret < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("audio_alsa: Unable to set hw parameters for device \"%s\": %s.", alsa_out_dev, snd_strerror(ret)); } if (my_sample_rate != desired_sample_rate) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Can't set the D/A converter to %d.", desired_sample_rate); } ret = snd_pcm_hw_params_get_buffer_size(alsa_params, &actual_buffer_length); if (ret < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("audio_alsa: Unable to get hw buffer length for device \"%s\": %s.", alsa_out_dev, snd_strerror(ret)); } @@ -843,7 +843,7 @@ int delay(long *the_delay) { debug(1, "Error preparing after delay error: \"%s\".", snd_strerror(derr)); } } - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); // here, occasionally pretend there's a problem with pcm_get_delay() // if ((random() % 100000) < 3) // keep it pretty rare // reply = -EPERM; // pretend something bad has happened @@ -863,7 +863,7 @@ static void play(void *buf, int samples) { if (audio_alsa.mute) do_mute(0); } - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); } if (ret == 0) { debug_mutex_lock(&alsa_mutex, 10000, 1); @@ -897,7 +897,7 @@ static void play(void *buf, int samples) { debug(1, "Error preparing after play error: \"%s\".", snd_strerror(err)); } } - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); } } @@ -920,7 +920,7 @@ static void flush(void) { alsa_handle = NULL; } - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); } static void stop(void) { @@ -976,7 +976,7 @@ void volume(double vol) { debug_mutex_lock(&alsa_mutex, 1000, 1); volume_set_request = 1; // an external request has been made to set the volume do_volume(vol); - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); } /* @@ -1003,7 +1003,7 @@ static void mute(int mute_state_requested) { mute_request_pending = 1; overriding_mute_state_requested = mute_state_requested; do_mute(mute_state_requested); - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); } void do_mute(int mute_state_requested) { diff --git a/common.c b/common.c index 41218609..da2db747 100644 --- a/common.c +++ b/common.c @@ -1042,13 +1042,28 @@ int _debug_mutex_lock(pthread_mutex_t *mutex, useconds_t dally_time, const char const int line, int debuglevel) { char dstring[1000]; memset(dstring, 0, sizeof(dstring)); - snprintf(dstring, sizeof(dstring), "%s%d", filename, line); + snprintf(dstring, sizeof(dstring), "%s:%d", filename, line); + debug(3, "debug_mutex_lock at \"%s\".", dstring); int result = sps_pthread_mutex_timedlock(mutex, dally_time, dstring, debuglevel); if (result == EBUSY) result = pthread_mutex_lock(mutex); return result; } +int _debug_mutex_unlock(pthread_mutex_t *mutex, const char *filename, const int line, + int debuglevel) { + char dstring[1000]; + char errstr[512]; + memset(dstring, 0, sizeof(dstring)); + snprintf(dstring, sizeof(dstring), "%s:%d", filename, line); + debug(debuglevel, "debug_mutex_unlock at \"%s\".", dstring); + int r = pthread_mutex_unlock(mutex); + if (r != 0) + debug(1, "error %d: \"%s\" unlocking a mutex: \"%s\".", r, + strerror_r(r, errstr, sizeof(errstr)), dstring); + return r; +} + char *get_version_string() { char *version_string = malloc(200); if (version_string) { diff --git a/common.h b/common.h index 8878c390..87493cb1 100644 --- a/common.h +++ b/common.h @@ -271,6 +271,11 @@ int _debug_mutex_lock(pthread_mutex_t *mutex, useconds_t dally_time, const char #define debug_mutex_lock(mu, t, d) _debug_mutex_lock(mu, t, __FILE__, __LINE__, d) +int _debug_mutex_unlock(pthread_mutex_t *mutex, const char *filename, const int line, + int debuglevel); + +#define debug_mutex_unlock(mu, d) _debug_mutex_unlock(mu, __FILE__, __LINE__, d) + char *get_version_string(); // mallocs a string space -- remember to free it afterwards void sps_nanosleep(const time_t sec, diff --git a/player.c b/player.c index e7767e4a..7fbc45d5 100644 --- a/player.c +++ b/player.c @@ -481,10 +481,10 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp debug_mutex_lock(&conn->flush_mutex, 1000, 1); conn->flush_requested = 0; conn->flush_rtp_timestamp = 0; - pthread_mutex_unlock(&conn->flush_mutex); + debug_mutex_unlock(&conn->flush_mutex, 3); } - debug_mutex_lock(&conn->ab_mutex, 10000, 1); + debug_mutex_lock(&conn->ab_mutex, 40000, 1); conn->packet_count++; conn->time_of_last_audio_packet = get_absolute_time_in_fp(); if (conn->connection_state_to_output) { // if we are supposed to be processing these packets @@ -626,7 +626,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp if (rc) debug(1, "Error signalling flowcontrol."); } - pthread_mutex_unlock(&conn->ab_mutex); + debug_mutex_unlock(&conn->ab_mutex, 3); } else { debug( 1, @@ -787,7 +787,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { abuf_t *curframe = 0; int notified_buffer_empty = 0; // diagnostic only - debug_mutex_lock(&conn->ab_mutex, 10000, 1); + debug_mutex_lock(&conn->ab_mutex, 40000, 1); int wait; long dac_delay = 0; // long because alsa returns a long do { @@ -819,7 +819,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { if (conn->connection_state_to_output == 0) { // going off debug_mutex_lock(&conn->flush_mutex, 1000, 1); conn->flush_requested = 1; - pthread_mutex_unlock(&conn->flush_mutex); + debug_mutex_unlock(&conn->flush_mutex, 3); } } @@ -833,7 +833,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { conn->time_since_play_started = 0; conn->flush_requested = 0; } - pthread_mutex_unlock(&conn->flush_mutex); + debug_mutex_unlock(&conn->flush_mutex, 3); uint32_t flush_limit = 0; if (conn->ab_synced) { @@ -1232,7 +1232,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { if (conn->player_thread_please_stop) { debug(3, "buffer_get_frame exiting due to thread stop request."); - pthread_mutex_unlock(&conn->ab_mutex); + debug_mutex_unlock(&conn->ab_mutex, 3); return 0; } @@ -1246,7 +1246,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { curframe->ready = 0; curframe->resend_level = 0; conn->ab_read = SUCCESSOR(conn->ab_read); - pthread_mutex_unlock(&conn->ab_mutex); + debug_mutex_unlock(&conn->ab_mutex, 3); return curframe; } @@ -1324,7 +1324,7 @@ static int stuff_buffer_basic_32(int32_t *inptr, int length, enum sps_format_t l process_sample(*inptr++, &l_outptr, l_output_format, conn->fix_volume, dither, conn); } } - pthread_mutex_unlock(&conn->vol_mutex); + debug_mutex_unlock(&conn->vol_mutex, 3); conn->amountStuffed = tstuff; return length + tstuff; } @@ -2584,7 +2584,7 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c debug_mutex_lock(&conn->vol_mutex, 1000, 1); conn->fix_volume = temp_fix_volume; - pthread_mutex_unlock(&conn->vol_mutex); + debug_mutex_unlock(&conn->vol_mutex, 3); if (config.loudness) loudness_set_volume(software_attenuation / 100); @@ -2621,7 +2621,7 @@ void do_flush(int64_t timestamp, rtsp_conn_info *conn) { conn->flush_requested = 1; // if (timestamp!=0) conn->flush_rtp_timestamp = timestamp; // flush all packets up to (and including?) this - pthread_mutex_unlock(&conn->flush_mutex); + debug_mutex_unlock(&conn->flush_mutex, 3); conn->play_segment_reference_frame = 0; conn->play_number_after_flush = 0; #ifdef CONFIG_METADATA diff --git a/rtp.c b/rtp.c index 01f71c3f..e7ac0dbd 100644 --- a/rtp.c +++ b/rtp.c @@ -339,7 +339,7 @@ void *rtp_control_receiver(void *arg) { remote_time_of_sync - conn->local_to_remote_time_difference; conn->reference_timestamp = sync_rtp_timestamp; conn->latency_delayed_timestamp = rtp_timestamp_less_latency; - pthread_mutex_unlock(&conn->reference_time_mutex); + debug_mutex_unlock(&conn->reference_time_mutex, 3); // this is for debugging /* @@ -898,14 +898,14 @@ void get_reference_timestamp_stuff(int64_t *timestamp, uint64_t *timestamp_time, // debug(1,"Reference timestamp is invalid."); //} *remote_timestamp_time = conn->remote_reference_timestamp_time; - pthread_mutex_unlock(&conn->reference_time_mutex); + debug_mutex_unlock(&conn->reference_time_mutex, 3); } void clear_reference_timestamp(rtsp_conn_info *conn) { debug_mutex_lock(&conn->reference_time_mutex, 1000, 1); conn->reference_timestamp = 0; conn->reference_timestamp_time = 0; - pthread_mutex_unlock(&conn->reference_time_mutex); + debug_mutex_unlock(&conn->reference_time_mutex, 3); } void rtp_request_resend(seq_t first, uint32_t count, rtsp_conn_info *conn) { From d224f47e3796e6e7c45fd32556ea9e923b2a9046 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 1 Jun 2018 11:21:16 +0100 Subject: [PATCH 10/27] Remove unneeded volume control mutex, adjust some timings, add wait time to slow mutex locks. --- common.c | 8 +++++++- player.c | 16 +++------------- player.h | 1 - 3 files changed, 10 insertions(+), 15 deletions(-) diff --git a/common.c b/common.c index da2db747..ae87d6c4 100644 --- a/common.c +++ b/common.c @@ -1040,13 +1040,19 @@ int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time, int _debug_mutex_lock(pthread_mutex_t *mutex, useconds_t dally_time, const char *filename, const int line, int debuglevel) { + uint64_t time_at_start = get_absolute_time_in_fp(); char dstring[1000]; memset(dstring, 0, sizeof(dstring)); snprintf(dstring, sizeof(dstring), "%s:%d", filename, line); debug(3, "debug_mutex_lock at \"%s\".", dstring); int result = sps_pthread_mutex_timedlock(mutex, dally_time, dstring, debuglevel); - if (result == EBUSY) + if (result == EBUSY) { result = pthread_mutex_lock(mutex); + uint64_t time_delay = get_absolute_time_in_fp() - time_at_start; + uint64_t divisor = (uint64_t)1 << 32; + double delay = 1.0 * time_delay / divisor; + debug(debuglevel, "debug_mutex_lock at \"%s\" -- wait time: %0.9f sec.", dstring, delay); + } return result; } diff --git a/player.c b/player.c index 7fbc45d5..b2c35efc 100644 --- a/player.c +++ b/player.c @@ -1294,7 +1294,6 @@ static int stuff_buffer_basic_32(int32_t *inptr, int length, enum sps_format_t l stuffsamp = (rand() % (length - 2)) + 1; // ensure there's always a sample before and after the item - debug_mutex_lock(&conn->vol_mutex, 1000, 1); for (i = 0; i < stuffsamp; i++) { // the whole frame, if no stuffing process_sample(*inptr++, &l_outptr, l_output_format, conn->fix_volume, dither, conn); process_sample(*inptr++, &l_outptr, l_output_format, conn->fix_volume, dither, conn); @@ -1324,7 +1323,6 @@ static int stuff_buffer_basic_32(int32_t *inptr, int length, enum sps_format_t l process_sample(*inptr++, &l_outptr, l_output_format, conn->fix_volume, dither, conn); } } - debug_mutex_unlock(&conn->vol_mutex, 3); conn->amountStuffed = tstuff; return length + tstuff; } @@ -1437,9 +1435,6 @@ static void *player_thread_func(void *arg) { rc = pthread_mutex_init(&conn->flush_mutex, NULL); if (rc) debug(1, "Error initialising flush_mutex."); - rc = pthread_mutex_init(&conn->vol_mutex, NULL); - if (rc) - debug(1, "Error initialising vol_mutex."); // set the flowcontrol condition variable to wait on a monotonic clock #ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD pthread_condattr_t attr; @@ -2329,12 +2324,12 @@ static void *player_thread_func(void *arg) { mdns_dacp_dont_monitor(conn->dapo_private_storage); #endif - debug(3, "Requesting output device to stop."); + debug(3, "Connection %d: stopping output device.", conn->connection_number); if (config.output->stop) config.output->stop(); - debug(2, "Cancelling timing, control and audio threads"); + debug(2, "Cancelling timing, control and audio threads..."); pthread_cancel(rtp_timing_thread); pthread_cancel(rtp_control_thread); pthread_cancel(rtp_audio_thread); @@ -2362,10 +2357,6 @@ static void *player_thread_func(void *arg) { rc = pthread_mutex_destroy(&conn->ab_mutex); if (rc) debug(1, "Error destroying ab_mutex variable."); - rc = pthread_mutex_destroy(&conn->vol_mutex); - if (rc) - debug(1, "Error destroying vol_mutex variable."); - debug(2, "Connection %d: player thread terminated.", conn->connection_number); if (conn->dacp_id) { free(conn->dacp_id); @@ -2582,9 +2573,8 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c // debug(1,"Software attenuation set to %f, i.e %f out of 65,536, for airplay volume of // %f",software_attenuation,temp_fix_volume,airplay_volume); - debug_mutex_lock(&conn->vol_mutex, 1000, 1); conn->fix_volume = temp_fix_volume; - debug_mutex_unlock(&conn->vol_mutex, 3); + memory_barrier(); if (config.loudness) loudness_set_volume(software_attenuation / 100); diff --git a/player.h b/player.h index 793413ba..3274d648 100644 --- a/player.h +++ b/player.h @@ -106,7 +106,6 @@ typedef struct { // mutexes and condition variables pthread_cond_t flowcontrol; pthread_mutex_t ab_mutex, flush_mutex; - pthread_mutex_t vol_mutex; int fix_volume; uint32_t timestamp_epoch, last_timestamp, maximum_timestamp_interval; // timestamp_epoch of zero means not initialised, could start at 2 From b127e1a769bcf2d8a6c9c5108546b113271aa29d Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 1 Jun 2018 11:27:47 +0100 Subject: [PATCH 11/27] Monitor and time mutex locks and unlocks, add a diagnostic into the get_buffer loop. --- configure.ac | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/configure.ac b/configure.ac index 7e97c929..2ed89605 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.2d58], [mikebrady@eircom.net]) +AC_INIT([shairport-sync], [3.2d59], [mikebrady@eircom.net]) AM_INIT_AUTOMAKE AC_CONFIG_SRCDIR([shairport.c]) AC_CONFIG_HEADERS([config.h]) From 8e92da35b2a5f34dd9ca4f16f26b29a99a40fbd9 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 1 Jun 2018 11:58:31 +0100 Subject: [PATCH 12/27] move get_frame iteration message and enable error messaging if condwait timeout. --- player.c | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/player.c b/player.c index b2c35efc..95e6c2cb 100644 --- a/player.c +++ b/player.c @@ -793,6 +793,8 @@ 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"); + // 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 @@ -1200,7 +1202,6 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { (!conn->player_thread_please_stop); if (wait) { - debug(3, "buffer_get_frame is iterating"); uint64_t time_to_wait_for_wakeup_fp = ((uint64_t)1 << 32) / conn->input_rate; // this is time period of one frame time_to_wait_for_wakeup_fp *= 4 * 352; // four full 352-frame packets @@ -1214,10 +1215,10 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { struct timespec time_of_wakeup; time_of_wakeup.tv_sec = sec; time_of_wakeup.tv_nsec = nsec; - pthread_cond_timedwait(&conn->flowcontrol, &conn->ab_mutex, &time_of_wakeup); -// int rc = pthread_cond_timedwait(&flowcontrol,&ab_mutex,&time_of_wakeup); -// if (rc!=0) -// debug(1,"pthread_cond_timedwait returned error code %d.",rc); +// pthread_cond_timedwait(&conn->flowcontrol, &conn->ab_mutex, &time_of_wakeup); + int rc = pthread_cond_timedwait(&conn->flowcontrol,&conn->ab_mutex,&time_of_wakeup); + if (rc!=0) + debug(3,"pthread_cond_timedwait returned error code %d.",rc); #endif #ifdef COMPILE_FOR_OSX uint64_t sec = time_to_wait_for_wakeup_fp >> 32; From 497d49dda6fc439aadd0d8d8b8165cf716a52a80 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 1 Jun 2018 14:23:34 +0100 Subject: [PATCH 13/27] Move the resend requests to outside the ab_mutex lock and put a send timeout on the resend requester. --- player.c | 90 +++++++++++++++++++++++++++++--------------------------- rtp.c | 12 +++++++- 2 files changed, 58 insertions(+), 44 deletions(-) diff --git a/player.c b/player.c index 95e6c2cb..e5d8d995 100644 --- a/player.c +++ b/player.c @@ -484,7 +484,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp debug_mutex_unlock(&conn->flush_mutex, 3); } - debug_mutex_lock(&conn->ab_mutex, 40000, 1); + debug_mutex_lock(&conn->ab_mutex, 20000, 1); conn->packet_count++; conn->time_of_last_audio_packet = get_absolute_time_in_fp(); if (conn->connection_state_to_output) { // if we are supposed to be processing these packets @@ -526,37 +526,6 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp conn->latency, resend_interval); conn->resend_interval = resend_interval; } - if (!conn->ab_buffering) { - int j; - for (j = 1; j <= number_of_resend_attempts; j++) { - // check j times, after a short period of has elapsed, assuming 352 frames per packet - - int back_step = resend_interval * j; - - int32_t sd = seq_diff(conn->ab_read, conn->ab_write, conn->ab_read); - int k; - for (k = -2; k <= 2; k++) { - if ((back_step + k) < sd) { // if it's within the range of frames in use... - int item_to_check = (conn->ab_write - (back_step + k)) & 0xffff; - seq_t next = item_to_check; - abuf_t *check_buf = conn->audio_buffer + BUFIDX(next); - if ((!check_buf->ready) && - (check_buf->resend_level < - j)) { // prevent multiple requests from the same level of lookback - check_buf->resend_level = j; - if (config.disable_resend_requests == 0) { - rtp_request_resend(next, 1, conn); - if ((back_step + k + resend_interval) >= sd) - debug(2, "Last-ditch (#%d) resend request for packet %u in range %u to %u. " - "Looking back %d packets.", - j, next, conn->ab_read, conn->ab_write, back_step + k); - conn->resend_requests++; - } - } - } - } - } - } if (conn->ab_write == seqno) { // expected packet abuf = conn->audio_buffer + BUFIDX(seqno); @@ -621,16 +590,51 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp } // pthread_mutex_lock(&ab_mutex); + int rc = pthread_cond_signal(&conn->flowcontrol); + if (rc) + debug(1, "Error signalling flowcontrol."); + + // if it's at the expected time, do a look back for missing packets + // but release the ab_mutex when doing a resend + if (!conn->ab_buffering) { + int j; + for (j = 1; j <= number_of_resend_attempts; j++) { + // check j times, after a short period of has elapsed, assuming 352 frames per packet + + int back_step = resend_interval * j; + int k; + for (k = -2; k <= 2; k++) { + if ((back_step + k) < + seq_diff(conn->ab_read, conn->ab_write, + conn->ab_read)) { // if it's within the range of frames in use... + int item_to_check = (conn->ab_write - (back_step + k)) & 0xffff; + seq_t next = item_to_check; + abuf_t *check_buf = conn->audio_buffer + BUFIDX(next); + if ((!check_buf->ready) && + (check_buf->resend_level < + j)) { // prevent multiple requests from the same level of lookback + check_buf->resend_level = j; + if (config.disable_resend_requests == 0) { + if ((back_step + k + resend_interval) >= + seq_diff(conn->ab_read, conn->ab_write, conn->ab_read)) + debug(2, "Last-ditch (#%d) resend request for packet %u in range %u to %u. " + "Looking back %d packets.", + j, next, conn->ab_read, conn->ab_write, back_step + k); + debug_mutex_unlock(&conn->ab_mutex, 3); + rtp_request_resend(next, 1, conn); + conn->resend_requests++; + debug_mutex_lock(&conn->ab_mutex, 20000, 1); + } + } + } + } + } + } } - int rc = pthread_cond_signal(&conn->flowcontrol); - if (rc) - debug(1, "Error signalling flowcontrol."); } debug_mutex_unlock(&conn->ab_mutex, 3); } else { - debug( - 1, - "No player thread while adding a player_put_packet calle was made -- packet discarded."); + debug(1, "player_put_packet discarded packet %d because the player thread was gone."); } pthread_rwlock_unlock(&conn->player_thread_lock); } else { @@ -787,7 +791,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { abuf_t *curframe = 0; int notified_buffer_empty = 0; // diagnostic only - debug_mutex_lock(&conn->ab_mutex, 40000, 1); + debug_mutex_lock(&conn->ab_mutex, 20000, 1); int wait; long dac_delay = 0; // long because alsa returns a long do { @@ -1215,10 +1219,10 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { struct timespec time_of_wakeup; time_of_wakeup.tv_sec = sec; time_of_wakeup.tv_nsec = nsec; -// pthread_cond_timedwait(&conn->flowcontrol, &conn->ab_mutex, &time_of_wakeup); - int rc = pthread_cond_timedwait(&conn->flowcontrol,&conn->ab_mutex,&time_of_wakeup); - if (rc!=0) - debug(3,"pthread_cond_timedwait returned error code %d.",rc); + // pthread_cond_timedwait(&conn->flowcontrol, &conn->ab_mutex, &time_of_wakeup); + int rc = pthread_cond_timedwait(&conn->flowcontrol, &conn->ab_mutex, &time_of_wakeup); + if (rc != 0) + debug(3, "pthread_cond_timedwait returned error code %d.", rc); #endif #ifdef COMPILE_FOR_OSX uint64_t sec = time_to_wait_for_wakeup_fp >> 32; diff --git a/rtp.c b/rtp.c index e7ac0dbd..bb28be87 100644 --- a/rtp.c +++ b/rtp.c @@ -934,11 +934,21 @@ void rtp_request_resend(seq_t first, uint32_t count, rtsp_conn_info *conn) { resend_error_backoff_time)) { if ((config.diagnostic_drop_packet_fraction == 0.0) || (drand48() > config.diagnostic_drop_packet_fraction)) { + // put a time limit on the sendto + + struct timeval timeout; + timeout.tv_sec = 0; + timeout.tv_usec = 100000; + + if (setsockopt(conn->control_socket, SOL_SOCKET, SO_SNDTIMEO, (char *)&timeout, + sizeof(timeout)) < 0) + debug(1, "Can't set timeout on resend request socket."); + if (sendto(conn->control_socket, req, sizeof(req), 0, (struct sockaddr *)&conn->rtp_client_control_socket, msgsize) == -1) { char em[1024]; strerror_r(errno, em, sizeof(em)); - debug(1, "Error %d using send-to to an audio socket: \"%s\". Backing off for 1/16th of a " + debug(1, "Error %d using sendto to an audio socket: \"%s\". Backing off for 1/16th of a " "second.", errno, em); conn->rtp_time_of_last_resend_request_error_fp = time_of_sending_fp; From eee822b932cd46f2c1a87e5cf17fb862b0afa117 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 1 Jun 2018 16:00:20 +0100 Subject: [PATCH 14/27] add some more debugging messages. --- common.c | 11 +++++++---- player.c | 4 ++-- 2 files changed, 9 insertions(+), 6 deletions(-) diff --git a/common.c b/common.c index ae87d6c4..306b3c2f 100644 --- a/common.c +++ b/common.c @@ -1026,11 +1026,12 @@ int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time, time_to_wait -= st; r = pthread_mutex_trylock(mutex); } - if (r != 0) { + if ((r != 0) && (debugmessage != NULL)) { char errstr[1000]; if (r == EBUSY) - debug(debuglevel, "timeout at %d microseconds while waiting for a mutex: \"%s\".", dally_time, - debugmessage); + debug(debuglevel, + "waiting for a mutex, maximum expected time of %d microseconds exceeded \"%s\".", + dally_time, debugmessage); else debug(debuglevel, "error %d: \"%s\" waiting for a mutex: \"%s\".", r, strerror_r(r, errstr, sizeof(errstr)), debugmessage); @@ -1051,7 +1052,9 @@ int _debug_mutex_lock(pthread_mutex_t *mutex, useconds_t dally_time, const char uint64_t time_delay = get_absolute_time_in_fp() - time_at_start; uint64_t divisor = (uint64_t)1 << 32; double delay = 1.0 * time_delay / divisor; - debug(debuglevel, "debug_mutex_lock at \"%s\" -- wait time: %0.9f sec.", dstring, delay); + debug(debuglevel, + "debug_mutex_lock at \"%s\" expected max wait: %0.9f, actual wait: %0.9f sec.", dstring, + (1.0 * dally_time) / 1000000, delay); } return result; } diff --git a/player.c b/player.c index e5d8d995..ed844f6a 100644 --- a/player.c +++ b/player.c @@ -484,7 +484,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp debug_mutex_unlock(&conn->flush_mutex, 3); } - debug_mutex_lock(&conn->ab_mutex, 20000, 1); + debug_mutex_lock(&conn->ab_mutex, 30000, 1); conn->packet_count++; conn->time_of_last_audio_packet = get_absolute_time_in_fp(); if (conn->connection_state_to_output) { // if we are supposed to be processing these packets @@ -791,7 +791,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { abuf_t *curframe = 0; int notified_buffer_empty = 0; // diagnostic only - debug_mutex_lock(&conn->ab_mutex, 20000, 1); + debug_mutex_lock(&conn->ab_mutex, 30000, 1); int wait; long dac_delay = 0; // long because alsa returns a long do { From 6eab2d1617e1b7ce756d284bbeeadb3e4a346f4b Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sun, 3 Jun 2018 19:59:24 +0100 Subject: [PATCH 15/27] Use shutdown() before close() and separate out the cancel requests for the timing, control and audio threads, see if we can see anything. --- player.c | 11 ++++++++--- rtp.c | 9 +++++++++ 2 files changed, 17 insertions(+), 3 deletions(-) diff --git a/player.c b/player.c index ed844f6a..e05cebc1 100644 --- a/player.c +++ b/player.c @@ -2335,14 +2335,19 @@ static void *player_thread_func(void *arg) { config.output->stop(); debug(2, "Cancelling timing, control and audio threads..."); + debug(2, "Cancel timing thread."); pthread_cancel(rtp_timing_thread); - pthread_cancel(rtp_control_thread); - pthread_cancel(rtp_audio_thread); - debug(2, "Joining terminated threads."); + debug(2, "Join timing thread."); pthread_join(rtp_timing_thread, NULL); debug(2, "Timing thread terminated."); + debug(2, "Cancel control thread."); + pthread_cancel(rtp_control_thread); + debug(2, "Join control thread."); pthread_join(rtp_control_thread, NULL); debug(2, "Control thread terminated."); + debug(2, "Cancel audio thread."); + pthread_cancel(rtp_audio_thread); + debug(2, "Join audio thread."); pthread_join(rtp_audio_thread, NULL); debug(2, "Audio thread terminated."); clear_reference_timestamp(conn); diff --git a/rtp.c b/rtp.c index bb28be87..6a588b0b 100644 --- a/rtp.c +++ b/rtp.c @@ -68,6 +68,9 @@ void rtp_terminate(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."); + shutdown(conn->audio_socket,SHUT_RDWR); + debug(1,"close audio socket."); close(conn->audio_socket); debug(3, "Audio Receiver Cleanup Successful."); } @@ -188,6 +191,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."); + shutdown(conn->control_socket,SHUT_RDWR); + debug(1,"close control socket."); close(conn->control_socket); debug(3, "Control Receiver Cleanup Successful."); } @@ -471,6 +477,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."); + shutdown(conn->timing_socket,SHUT_RDWR); + debug(1,"close timing socket."); close(conn->timing_socket); debug(3, "Timing Receiver Cleanup Successful."); } From b5b1a69f91a2b903e5ab01b975b666850b81ef5b Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sun, 3 Jun 2018 19:59:54 +0100 Subject: [PATCH 16/27] Use shutdown() before close() and separate out the cancel requests for the timing, control and audio threads, see if we can see anything. --- configure.ac | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/configure.ac b/configure.ac index 2ed89605..0fb4a78d 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.2d59], [mikebrady@eircom.net]) +AC_INIT([shairport-sync], [3.2d60], [mikebrady@eircom.net]) AM_INIT_AUTOMAKE AC_CONFIG_SRCDIR([shairport.c]) AC_CONFIG_HEADERS([config.h]) From 78f4a24caa3672345794848c6bce39cd5dd0e5b1 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sun, 3 Jun 2018 20:05:10 +0100 Subject: [PATCH 17/27] Quieten the last-ditch message a bit. --- player.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/player.c b/player.c index e05cebc1..8337c329 100644 --- a/player.c +++ b/player.c @@ -617,7 +617,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp if (config.disable_resend_requests == 0) { if ((back_step + k + resend_interval) >= seq_diff(conn->ab_read, conn->ab_write, conn->ab_read)) - debug(2, "Last-ditch (#%d) resend request for packet %u in range %u to %u. " + debug(3, "Last-ditch (#%d) resend request for packet %u in range %u to %u. " "Looking back %d packets.", j, next, conn->ab_read, conn->ab_write, back_step + k); debug_mutex_unlock(&conn->ab_mutex, 3); From 370d70651bd91275492545f82bd974172a946a7d Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Tue, 5 Jun 2018 18:58:36 +0100 Subject: [PATCH 18/27] Add a pthread_cancel cleanup routine to put_packet to unlock that rw thread when cancelled. --- player.c | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/player.c b/player.c index 8337c329..a516aa0b 100644 --- a/player.c +++ b/player.c @@ -464,9 +464,16 @@ static void free_audio_buffers(rtsp_conn_info *conn) { free(conn->audio_buffer[i].data); } +void player_thread_lock_cleanup(void *arg) { + rtsp_conn_info *conn = (rtsp_conn_info *)arg; + debug(3,"Cleaning up player_thread_lock."); + pthread_rwlock_unlock(&conn->player_thread_lock); +} + void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp, uint8_t *data, int len, rtsp_conn_info *conn) { if (pthread_rwlock_tryrdlock(&conn->player_thread_lock) == 0) { + pthread_cleanup_push( player_thread_lock_cleanup, (void *)conn); if (conn->player_thread != NULL) { // all timestamps are done at the output rate @@ -636,7 +643,8 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp } else { debug(1, "player_put_packet discarded packet %d because the player thread was gone."); } - pthread_rwlock_unlock(&conn->player_thread_lock); + pthread_cleanup_pop( 1); + // pthread_rwlock_unlock(&conn->player_thread_lock); } else { debug(1, "player_put_packet discarded packet %d because the player thread was locked.", seqno); } From 1ca0b28e538ff56cb8c8c829aa4b14421f33c1bf Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Tue, 5 Jun 2018 19:07:10 +0100 Subject: [PATCH 19/27] Clean up player.c with clang_format. --- player.c | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/player.c b/player.c index a516aa0b..3a2b8dc0 100644 --- a/player.c +++ b/player.c @@ -466,14 +466,14 @@ static void free_audio_buffers(rtsp_conn_info *conn) { void player_thread_lock_cleanup(void *arg) { rtsp_conn_info *conn = (rtsp_conn_info *)arg; - debug(3,"Cleaning up player_thread_lock."); + debug(3, "Cleaning up player_thread_lock."); pthread_rwlock_unlock(&conn->player_thread_lock); } void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp, uint8_t *data, int len, rtsp_conn_info *conn) { if (pthread_rwlock_tryrdlock(&conn->player_thread_lock) == 0) { - pthread_cleanup_push( player_thread_lock_cleanup, (void *)conn); + pthread_cleanup_push(player_thread_lock_cleanup, (void *)conn); if (conn->player_thread != NULL) { // all timestamps are done at the output rate @@ -643,7 +643,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp } else { debug(1, "player_put_packet discarded packet %d because the player thread was gone."); } - pthread_cleanup_pop( 1); + pthread_cleanup_pop(1); // pthread_rwlock_unlock(&conn->player_thread_lock); } else { debug(1, "player_put_packet discarded packet %d because the player thread was locked.", seqno); From 86c9d0f6a71f96c9aede971820c89bf7e5e83bd1 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Tue, 5 Jun 2018 19:07:40 +0100 Subject: [PATCH 20/27] Add a pthread_cancel cleanup routine to put_packet to unlock that rw thread when cancelled. --- configure.ac | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/configure.ac b/configure.ac index 0fb4a78d..3d475874 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.2d60], [mikebrady@eircom.net]) +AC_INIT([shairport-sync], [3.2d61], [mikebrady@eircom.net]) AM_INIT_AUTOMAKE AC_CONFIG_SRCDIR([shairport.c]) AC_CONFIG_HEADERS([config.h]) From 7b0a05ad5c3376915a5e57a90b48efc604234e27 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 8 Jun 2018 00:45:22 +0200 Subject: [PATCH 21/27] Update RELEASENOTES.md --- RELEASENOTES.md | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/RELEASENOTES.md b/RELEASENOTES.md index 5ece0a94..9b552a18 100644 --- a/RELEASENOTES.md +++ b/RELEASENOTES.md @@ -1,9 +1,14 @@ - -Version 3.2d57 and 3.2d58 +Version 3.2d61 ==== +**Bug Fix** +* Add a pthread_cancel cleanup routine to put_packet to unlock the player rw thread when cancelled. Sincere thanks to [davidhq](https://github.com/davidhq) for help with this investigation. +Version 3.2d57, 3.2d58, 3.2d59, 3.2d60 +==== **Bug Chasing** * Debug messaging has been enhanced when a TEARDOWN message is received. +* Check both timed and untimed mutex locks and give estimates of how long to wait. Generate debug messages when appropriate. +* Unlock the ab_mutex when sending a resend request. Version 3.2d56 ==== From a4a2cafd6a5033f121ca059a4ad220b4504dc6ce Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 8 Jun 2018 00:46:08 +0200 Subject: [PATCH 22/27] Update RELEASENOTES.md --- RELEASENOTES.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/RELEASENOTES.md b/RELEASENOTES.md index 9b552a18..14c2013b 100644 --- a/RELEASENOTES.md +++ b/RELEASENOTES.md @@ -1,7 +1,7 @@ Version 3.2d61 ==== **Bug Fix** -* Add a pthread_cancel cleanup routine to put_packet to unlock the player rw thread when cancelled. Sincere thanks to [davidhq](https://github.com/davidhq) for help with this investigation. +* Add a pthread_cancel cleanup routine to put_packet to unlock the player rw thread when cancelled. Sincere thanks to [davidhq](https://github.com/davidhq) for help investigating this. Version 3.2d57, 3.2d58, 3.2d59, 3.2d60 ==== From daea84e32d60687764cfe94daa21fed5401df713 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Fri, 8 Jun 2018 00:46:31 +0200 Subject: [PATCH 23/27] Update RELEASENOTES.md --- RELEASENOTES.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/RELEASENOTES.md b/RELEASENOTES.md index 14c2013b..4658ccff 100644 --- a/RELEASENOTES.md +++ b/RELEASENOTES.md @@ -1,7 +1,7 @@ Version 3.2d61 ==== **Bug Fix** -* Add a pthread_cancel cleanup routine to put_packet to unlock the player rw thread when cancelled. Sincere thanks to [davidhq](https://github.com/davidhq) for help investigating this. +* Add a pthread_cancel cleanup routine to put_packet to unlock the player rw mutex when cancelled. Sincere thanks to [davidhq](https://github.com/davidhq) for help investigating this. Version 3.2d57, 3.2d58, 3.2d59, 3.2d60 ==== From f14389e455bcba7db02b638af499c22b17eac38c Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Mon, 11 Jun 2018 15:42:01 +0100 Subject: [PATCH 24/27] Quieten some debug messaging around TEARDOWN --- rtsp.c | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/rtsp.c b/rtsp.c index b0b4a0f3..9d4c83a3 100644 --- a/rtsp.c +++ b/rtsp.c @@ -717,8 +717,6 @@ static void handle_options(rtsp_conn_info *conn, __attribute__((unused)) rtsp_me static void handle_teardown(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message *req, rtsp_message *resp) { debug(2, "Connection %d: TEARDOWN", conn->connection_number); - int tdl = debuglev; - debuglev = 3; // 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); @@ -731,7 +729,6 @@ static void handle_teardown(rtsp_conn_info *conn, __attribute__((unused)) rtsp_m player_stop(conn); debug(3, "TEARDOWN: successful termination of playing thread of RTSP conversation thread %d.", conn->connection_number); - debuglev = tdl; } static void handle_flush(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { @@ -1883,7 +1880,7 @@ static void *rtsp_conversation_thread_func(void *pconn) { int debug_level = 3; // for printing the request and response reply = rtsp_read_request(conn, &req); if (reply == rtsp_read_request_response_ok) { - if (strcmp(req->method,"OPTIONS")!=0) + if (strcmp(req->method,"OPTIONS")!=0) // the options message is very common, so don't log it until level 3 debug_level=2; debug(debug_level, "RTSP thread %d received an RTSP Packet of type \"%s\":", conn->connection_number, req->method), From 69e0a4836e106037353fabc5f6664ca614f5820b Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Mon, 11 Jun 2018 20:18:05 +0100 Subject: [PATCH 25/27] Modify the RTSP write response code to output the entire response in one go. --- rtsp.c | 87 +++++++++++++++++++++++++++++++++------------------------- 1 file changed, 49 insertions(+), 38 deletions(-) diff --git a/rtsp.c b/rtsp.c index 9d4c83a3..0267e7f5 100644 --- a/rtsp.c +++ b/rtsp.c @@ -637,7 +637,7 @@ static void msg_write_response(int fd, rtsp_message *resp) { pktfree -= n; p += n; if (pktfree <= 1024) - die("Attempted to write overlong RTSP packet"); + die("Attempted to write overlong RTSP packet 1"); } // Here, if there's content, write the Content-Length header ... @@ -648,21 +648,22 @@ static void msg_write_response(int fd, rtsp_message *resp) { pktfree -= n; p += n; if (pktfree <= 1024) - die("Attempted to write overlong RTSP packet"); + die("Attempted to write overlong RTSP packet 2"); + debug(1, "Content is \"%s\"", resp->content); + memcpy(p, resp->content, resp->contentlength); + pktfree -= resp->contentlength; + p += resp->contentlength; } + n = snprintf(p, pktfree, "\r\n"); + pktfree -= n; + p += n; + + if (pktfree <= 1024) + die("Attempted to write overlong RTSP packet 3"); + if (write(fd, pkt, p - pkt) != p - pkt) debug(1, "Error writing an RTSP packet -- requested bytes not fully written."); - - // Here, if there's content, write it - if (resp->contentlength) { - debug(1, "Content is \"%s\"", resp->content); - if (write(fd, resp->content, resp->contentlength) != resp->contentlength) - debug(1, "Error writing RTSP content -- requested bytes not fully written."); - } - - if (write(fd, "\r\n", strlen("\r\n")) != strlen("\r\n")) - debug(1, "Error terminating RTSP content."); } static void handle_record(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { @@ -709,9 +710,10 @@ static void handle_options(rtsp_conn_info *conn, __attribute__((unused)) rtsp_me rtsp_message *resp) { debug(3, "Connection %d: OPTIONS", conn->connection_number); resp->respcode = 200; - msg_add_header(resp, "Public", "ANNOUNCE, SETUP, RECORD, " - "PAUSE, FLUSH, TEARDOWN, " - "OPTIONS, GET_PARAMETER, SET_PARAMETER"); + msg_add_header(resp, "Public", + "ANNOUNCE, SETUP, RECORD, " + "PAUSE, FLUSH, TEARDOWN, " + "OPTIONS, GET_PARAMETER, SET_PARAMETER"); } static void handle_teardown(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message *req, @@ -767,7 +769,8 @@ static void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message * char *ar = msg_get_header(req, "Active-Remote"); if (ar) { - debug(2, "Connection %d: SETUP -- Active-Remote string seen: \"%s\".", conn->connection_number, 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); @@ -775,13 +778,14 @@ static void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message * 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); + 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); + 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); @@ -789,7 +793,8 @@ static void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message * 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); + 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; @@ -797,14 +802,14 @@ static void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message * char *hdr = msg_get_header(req, "Transport"); if (!hdr) { - debug(1, "Connection %d: SETUP doesn't contain a Transport header.",conn->connection_number); + 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); + debug(1, "Connection %d: SETUP doesn't specify a control_port.", conn->connection_number); goto error; } p = strchr(p, '=') + 1; @@ -812,7 +817,7 @@ static void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message * p = strstr(hdr, "timing_port="); if (!p) { - debug(1, "Connection %d: SETUP doesn't specify a timing_port.",conn->connection_number); + debug(1, "Connection %d: SETUP doesn't specify a timing_port.", conn->connection_number); goto error; } p = strchr(p, '=') + 1; @@ -820,27 +825,31 @@ static void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message * 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); + 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); + 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) { - debug(1, "Connection %d: SETUP seems to specify a null audio port.",conn->connection_number); + 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", + 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); @@ -1358,7 +1367,7 @@ static void handle_set_parameter(rtsp_conn_info *conn, rtsp_message *req, rtsp_m char *ct = msg_get_header(req, "Content-Type"); if (ct) { -// debug(2, "SET_PARAMETER Content-Type:\"%s\".", ct); + // debug(2, "SET_PARAMETER Content-Type:\"%s\".", ct); #ifdef CONFIG_METADATA // It seems that the rtptime of the message is used as a kind of an ID that @@ -1880,11 +1889,13 @@ static void *rtsp_conversation_thread_func(void *pconn) { int debug_level = 3; // for printing the request and response reply = rtsp_read_request(conn, &req); if (reply == rtsp_read_request_response_ok) { - if (strcmp(req->method,"OPTIONS")!=0) // the options message is very common, so don't log it until level 3 - debug_level=2; - debug(debug_level, "RTSP thread %d received an RTSP Packet of type \"%s\":", conn->connection_number, + if (strcmp(req->method, "OPTIONS") != + 0) // the options message is very common, so don't log it until level 3 + debug_level = 2; + debug(debug_level, + "RTSP thread %d received an RTSP Packet of type \"%s\":", conn->connection_number, req->method), - debug_print_msg_headers(debug_level, req); + debug_print_msg_headers(debug_level, req); resp = msg_init(); resp->respcode = 400; From 7da3a02ac45746b63c32af373987264068ea9d8b Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Mon, 11 Jun 2018 20:18:38 +0100 Subject: [PATCH 26/27] Modify the RTSP write response code to output the entire response in one go. --- configure.ac | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/configure.ac b/configure.ac index 3d475874..5a98fa84 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.2d61], [mikebrady@eircom.net]) +AC_INIT([shairport-sync], [3.2d62], [mikebrady@eircom.net]) AM_INIT_AUTOMAKE AC_CONFIG_SRCDIR([shairport.c]) AC_CONFIG_HEADERS([config.h]) From 923e7f6734c0dafcad1a83f486ddc5720cd21ee4 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Tue, 12 Jun 2018 12:53:05 +0100 Subject: [PATCH 27/27] Change the type of the play argument from an array of shorts to a void pointer to comply with the otheres. Trivial. --- audio_pipe.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/audio_pipe.c b/audio_pipe.c index b81401c5..c080277d 100644 --- a/audio_pipe.c +++ b/audio_pipe.c @@ -54,7 +54,7 @@ static void start(__attribute__((unused)) int sample_rate, } } -static void play(short buf[], int samples) { +static void play(void *buf, int samples) { // if the file is not open, try to open it. char errorstring[1024]; if (fd == -1) {