From 1ee63bb2d22e05b045af746cffb93578150830ec Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Thu, 8 Nov 2018 11:25:24 +0000 Subject: [PATCH 01/14] Investigating alternate timing approaches. --- audio_alsa.c | 80 +++++++++++++++++++++++++++++++++++++++++++++++++--- 1 file changed, 76 insertions(+), 4 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index 48f6a650..37e6f1ca 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -74,11 +74,13 @@ audio_output audio_alsa = { static pthread_mutex_t alsa_mutex = PTHREAD_MUTEX_INITIALIZER; +static snd_output_t *output = NULL; static unsigned int desired_sample_rate; static enum sps_format_t sample_format; static snd_pcm_t *alsa_handle = NULL; static snd_pcm_hw_params_t *alsa_params = NULL; +static snd_pcm_sw_params_t *alsa_swparams = NULL; static snd_ctl_t *ctl = NULL; static snd_ctl_elem_id_t *elem_id = NULL; static snd_mixer_t *alsa_mix_handle = NULL; @@ -194,6 +196,9 @@ void do_snd_mixer_selem_set_playback_dB_all(snd_mixer_elem_t *mix_elem, double v } static int init(int argc, char **argv) { + snd_output_stdio_attach(&output, stdout, 0); + + // debug(2,"audio_alsa init called."); int response = 0; // this will be what we return to the caller. const char *str; @@ -502,6 +507,7 @@ static int init(int argc, char **argv) { static void deinit(void) { // debug(2,"audio_alsa deinit called."); stop(); + } int open_alsa_device(void) { @@ -536,7 +542,8 @@ int open_alsa_device(void) { return (-10); snd_pcm_hw_params_alloca(&alsa_params); - + snd_pcm_sw_params_alloca(&alsa_swparams); + ret = snd_pcm_hw_params_any(alsa_handle, alsa_params); if (ret < 0) { warn("audio_alsa: Broken configuration for device \"%s\": no configurations " @@ -691,7 +698,36 @@ int open_alsa_device(void) { snd_strerror(ret)); return -9; } + + ret = snd_pcm_sw_params_current(alsa_handle, alsa_swparams); + if (ret < 0) { + warn("audio_alsa: Unable to get current sw parameters for device \"%s\": %s.", alsa_out_dev, + snd_strerror(ret)); + return -10; + } + ret = snd_pcm_sw_params_set_tstamp_mode(alsa_handle, alsa_swparams, SND_PCM_TSTAMP_ENABLE); + if (ret < 0) { + warn("audio_alsa: Can't enable timestamp mode of device: \"%s\": %s.", alsa_out_dev, + snd_strerror(ret)); + return -11; + } + + ret = snd_pcm_sw_params_set_tstamp_type(alsa_handle, alsa_swparams, SND_PCM_TSTAMP_TYPE_MONOTONIC); + if (ret < 0) { + warn("audio_alsa: Can't set timestamp type of device: \"%s\": %s.", alsa_out_dev, + snd_strerror(ret)); + return -12; + } + + /* write the sw parameters */ + ret = snd_pcm_sw_params(alsa_handle, alsa_swparams); + if (ret < 0) { + warn("audio_alsa: Unable to set swparams_p of device: \"%s\": %s.", alsa_out_dev, + snd_strerror(ret)); + return -13; + } + if (actual_buffer_length < config.audio_backend_buffer_desired_length + minimal_buffer_headroom) { /* // the dac buffer is too small, so let's try to set it @@ -719,7 +755,7 @@ int open_alsa_device(void) { "length (%ld) you have chosen.", actual_buffer_length, config.audio_backend_buffer_desired_length); } - + if (alsa_characteristics_already_listed == 0) { alsa_characteristics_already_listed = 1; int log_level = 2; // the level at which debug information should be output @@ -867,6 +903,42 @@ static void start(int i_sample_rate, int i_sample_format) { measurement_data_is_valid = 0; } +int my_snd_pcm_delay(snd_pcm_t *pcm, snd_pcm_sframes_t *delayp) { + snd_pcm_status_t *alsa_snd_pcm_status; + snd_pcm_status_alloca(&alsa_snd_pcm_status); + + + struct timespec tn = {0,0}; + + snd_htimestamp_t snd_timestamp = {0,0}; //actually a struct timespec + snd_htimestamp_t audio_timestamp = {0,0}; //actually a struct timespec + snd_htimestamp_t driver_timestamp = {0,0}; //actually a struct timespec + if (snd_pcm_status(alsa_handle, alsa_snd_pcm_status) == 0) { + clock_gettime(CLOCK_MONOTONIC, &tn); + snd_pcm_status_get_htstamp(alsa_snd_pcm_status, &snd_timestamp); + + uint64_t t1 = tn.tv_sec * (uint64_t)1000000000 + tn.tv_nsec; + uint64_t t2 = snd_timestamp.tv_sec * (uint64_t)1000000000 + snd_timestamp.tv_nsec; + uint64_t delta = t1 - t2; + + + snd_pcm_status_get_audio_htstamp(alsa_snd_pcm_status, &audio_timestamp); + snd_pcm_status_get_driver_htstamp(alsa_snd_pcm_status, &driver_timestamp); + snd_pcm_sframes_t delay = snd_pcm_status_get_delay(alsa_snd_pcm_status); + debug(1,"Time now: %ld,%ld, Timestamp: %ld,%ld, delta: %" PRIu64 ", audio_timestamp: %ld,%ld, driver_timestamp: %ld,%ld, Delay: %ld.", + tn.tv_sec,tn.tv_nsec, + snd_timestamp.tv_sec,snd_timestamp.tv_nsec, + delta, + audio_timestamp.tv_sec,audio_timestamp.tv_nsec, + driver_timestamp.tv_sec,driver_timestamp.tv_nsec, + delay); + // snd_pcm_status_dump(alsa_snd_pcm_status, output); + + } + + return snd_pcm_delay(pcm, delayp); +} + int delay(long *the_delay) { // snd_pcm_sframes_t is a signed long -- hence the return of a "long" int reply = 0; @@ -879,7 +951,7 @@ int delay(long *the_delay) { snd_pcm_state_t dac_state = snd_pcm_state(alsa_handle); if (dac_state == SND_PCM_STATE_RUNNING) { *the_delay = 0; // just to see what happens - reply = snd_pcm_delay(alsa_handle, the_delay); + reply = my_snd_pcm_delay(alsa_handle, the_delay); if (reply != 0) { debug(1, "Error %d in delay(): \"%s\". Delay reported is %d frames.", reply, snd_strerror(reply), *the_delay); @@ -1000,7 +1072,7 @@ static int play(void *buf, int samples) { frame_index++; if ((frame_index == start_measurement_from_this_frame) || (frame_index % 32 == 0)) { long fl = 0; - err2 = snd_pcm_delay(alsa_handle, &fl); + err2 = my_snd_pcm_delay(alsa_handle, &fl); if (err2 != 0) { debug(1, "Error %d in delay in play(): \"%s\". Delay reported is %d frames.", err2, snd_strerror(err2), fl); From d90fec4a8c0e0e7d7a90ae095e2652ad85d9252c Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Thu, 8 Nov 2018 12:23:52 +0000 Subject: [PATCH 02/14] Prototype working estimated delay. --- audio_alsa.c | 74 +++++++++++++++++++++++++++++++++------------------- 1 file changed, 47 insertions(+), 27 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index 37e6f1ca..d26822bc 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -903,40 +903,60 @@ static void start(int i_sample_rate, int i_sample_format) { measurement_data_is_valid = 0; } -int my_snd_pcm_delay(snd_pcm_t *pcm, snd_pcm_sframes_t *delayp) { +int my_snd_pcm_delay(snd_pcm_t *pcm, snd_pcm_sframes_t *delayp) { + int ret; snd_pcm_status_t *alsa_snd_pcm_status; snd_pcm_status_alloca(&alsa_snd_pcm_status); - - + struct timespec tn = {0,0}; + snd_htimestamp_t update_timestamp = {0,0}; //actually a struct timespec - snd_htimestamp_t snd_timestamp = {0,0}; //actually a struct timespec - snd_htimestamp_t audio_timestamp = {0,0}; //actually a struct timespec - snd_htimestamp_t driver_timestamp = {0,0}; //actually a struct timespec - if (snd_pcm_status(alsa_handle, alsa_snd_pcm_status) == 0) { - clock_gettime(CLOCK_MONOTONIC, &tn); - snd_pcm_status_get_htstamp(alsa_snd_pcm_status, &snd_timestamp); - - uint64_t t1 = tn.tv_sec * (uint64_t)1000000000 + tn.tv_nsec; - uint64_t t2 = snd_timestamp.tv_sec * (uint64_t)1000000000 + snd_timestamp.tv_nsec; - uint64_t delta = t1 - t2; - - - snd_pcm_status_get_audio_htstamp(alsa_snd_pcm_status, &audio_timestamp); - snd_pcm_status_get_driver_htstamp(alsa_snd_pcm_status, &driver_timestamp); - snd_pcm_sframes_t delay = snd_pcm_status_get_delay(alsa_snd_pcm_status); - debug(1,"Time now: %ld,%ld, Timestamp: %ld,%ld, delta: %" PRIu64 ", audio_timestamp: %ld,%ld, driver_timestamp: %ld,%ld, Delay: %ld.", - tn.tv_sec,tn.tv_nsec, - snd_timestamp.tv_sec,snd_timestamp.tv_nsec, - delta, - audio_timestamp.tv_sec,audio_timestamp.tv_nsec, - driver_timestamp.tv_sec,driver_timestamp.tv_nsec, - delay); - // snd_pcm_status_dump(alsa_snd_pcm_status, output); + //snd_htimestamp_t audio_timestamp = {0,0}; //actually a struct timespec + //snd_htimestamp_t driver_timestamp = {0,0}; //actually a struct timespec + ret = snd_pcm_status(alsa_handle, alsa_snd_pcm_status); + if (ret) { + *delayp = 0; + return ret; } - return snd_pcm_delay(pcm, delayp); + snd_pcm_state_t state = snd_pcm_status_get_state(alsa_snd_pcm_status); + if (state != SND_PCM_STATE_RUNNING) { + *delayp = 0; + return -EIO; // might be a better code than this... + } + + clock_gettime(CLOCK_MONOTONIC, &tn); + snd_pcm_status_get_htstamp(alsa_snd_pcm_status, &update_timestamp); + + uint64_t t1 = tn.tv_sec * (uint64_t)1000000000 + tn.tv_nsec; + uint64_t t2 = update_timestamp.tv_sec * (uint64_t)1000000000 + update_timestamp.tv_nsec; + uint64_t delta = t1 - t2; + + //snd_pcm_status_get_audio_htstamp(alsa_snd_pcm_status, &audio_timestamp); + //snd_pcm_status_get_driver_htstamp(alsa_snd_pcm_status, &driver_timestamp); + snd_pcm_sframes_t delay = snd_pcm_status_get_delay(alsa_snd_pcm_status); + //debug(1,"Time now: %ld,%ld, Timestamp: %ld,%ld, delta: %.3f milliseconds, audio_timestamp: %ld,%ld, driver_timestamp: %ld,%ld, Delay: %ld.", + //tn.tv_sec,tn.tv_nsec, + //snd_timestamp.tv_sec,snd_timestamp.tv_nsec, + //(delta*1.0)/1000000, + //audio_timestamp.tv_sec,audio_timestamp.tv_nsec, + //driver_timestamp.tv_sec,driver_timestamp.tv_nsec, + //delay); + + uint64_t frames_played_since_last_interrupt = ((uint64_t)desired_sample_rate * delta)/1000000000; + snd_pcm_sframes_t frames_played_since_last_interrupt_sized = frames_played_since_last_interrupt; + + //debug(1,"Delta: %.3f, frames played in interval: %" PRIu64 ".",(delta*1.0)/1000000,frames_played_since_last_interrupt); + // snd_pcm_status_dump(alsa_snd_pcm_status, output); + snd_pcm_sframes_t reported_delay = 0; + snd_pcm_delay(pcm, &reported_delay); + if (reported_delay != delay) + debug(1,"Difference between reported delay and status delay is: %ld.",reported_delay-delay); + + *delayp = delay - frames_played_since_last_interrupt_sized; + return 0; + //return snd_pcm_delay(pcm, delayp); } int delay(long *the_delay) { From 3c00d14d2a10e8006b4d77d71d6cb4a2101683b1 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Thu, 8 Nov 2018 12:48:42 +0000 Subject: [PATCH 03/14] Refinements... --- audio_alsa.c | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index d26822bc..d067d4f5 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -914,12 +914,15 @@ int my_snd_pcm_delay(snd_pcm_t *pcm, snd_pcm_sframes_t *delayp) { //snd_htimestamp_t audio_timestamp = {0,0}; //actually a struct timespec //snd_htimestamp_t driver_timestamp = {0,0}; //actually a struct timespec - ret = snd_pcm_status(alsa_handle, alsa_snd_pcm_status); + ret = snd_pcm_status(pcm, alsa_snd_pcm_status); if (ret) { *delayp = 0; return ret; } + //snd_pcm_sframes_t reported_delay = 0; + //snd_pcm_delay(pcm, &reported_delay); + snd_pcm_state_t state = snd_pcm_status_get_state(alsa_snd_pcm_status); if (state != SND_PCM_STATE_RUNNING) { *delayp = 0; @@ -949,10 +952,8 @@ int my_snd_pcm_delay(snd_pcm_t *pcm, snd_pcm_sframes_t *delayp) { //debug(1,"Delta: %.3f, frames played in interval: %" PRIu64 ".",(delta*1.0)/1000000,frames_played_since_last_interrupt); // snd_pcm_status_dump(alsa_snd_pcm_status, output); - snd_pcm_sframes_t reported_delay = 0; - snd_pcm_delay(pcm, &reported_delay); - if (reported_delay != delay) - debug(1,"Difference between reported delay and status delay is: %ld.",reported_delay-delay); + //if (reported_delay != delay) + // debug(1,"Difference between reported delay and status delay is: %ld.",reported_delay-delay); *delayp = delay - frames_played_since_last_interrupt_sized; return 0; From cfd10647aad65314cbbde1ef5d959a57221d3090 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Thu, 8 Nov 2018 14:39:57 +0000 Subject: [PATCH 04/14] Make the changes to audio_alsa.c work back to alsa 1.0.28. --- audio_alsa.c | 44 +++++++------------------------------------- 1 file changed, 7 insertions(+), 37 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index d067d4f5..815f3423 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -712,20 +712,13 @@ int open_alsa_device(void) { snd_strerror(ret)); return -11; } - - ret = snd_pcm_sw_params_set_tstamp_type(alsa_handle, alsa_swparams, SND_PCM_TSTAMP_TYPE_MONOTONIC); - if (ret < 0) { - warn("audio_alsa: Can't set timestamp type of device: \"%s\": %s.", alsa_out_dev, - snd_strerror(ret)); - return -12; - } - + /* write the sw parameters */ ret = snd_pcm_sw_params(alsa_handle, alsa_swparams); if (ret < 0) { - warn("audio_alsa: Unable to set swparams_p of device: \"%s\": %s.", alsa_out_dev, + warn("audio_alsa: Unable to set software parameters of device: \"%s\": %s.", alsa_out_dev, snd_strerror(ret)); - return -13; + return -12; } if (actual_buffer_length < config.audio_backend_buffer_desired_length + minimal_buffer_headroom) { @@ -908,11 +901,8 @@ int my_snd_pcm_delay(snd_pcm_t *pcm, snd_pcm_sframes_t *delayp) { snd_pcm_status_t *alsa_snd_pcm_status; snd_pcm_status_alloca(&alsa_snd_pcm_status); - struct timespec tn = {0,0}; - snd_htimestamp_t update_timestamp = {0,0}; //actually a struct timespec - - //snd_htimestamp_t audio_timestamp = {0,0}; //actually a struct timespec - //snd_htimestamp_t driver_timestamp = {0,0}; //actually a struct timespec + struct timespec tn; // time now + snd_htimestamp_t update_timestamp; //actually a struct timespec ret = snd_pcm_status(pcm, alsa_snd_pcm_status); if (ret) { @@ -920,9 +910,6 @@ int my_snd_pcm_delay(snd_pcm_t *pcm, snd_pcm_sframes_t *delayp) { return ret; } - //snd_pcm_sframes_t reported_delay = 0; - //snd_pcm_delay(pcm, &reported_delay); - snd_pcm_state_t state = snd_pcm_status_get_state(alsa_snd_pcm_status); if (state != SND_PCM_STATE_RUNNING) { *delayp = 0; @@ -935,29 +922,12 @@ int my_snd_pcm_delay(snd_pcm_t *pcm, snd_pcm_sframes_t *delayp) { uint64_t t1 = tn.tv_sec * (uint64_t)1000000000 + tn.tv_nsec; uint64_t t2 = update_timestamp.tv_sec * (uint64_t)1000000000 + update_timestamp.tv_nsec; uint64_t delta = t1 - t2; - - //snd_pcm_status_get_audio_htstamp(alsa_snd_pcm_status, &audio_timestamp); - //snd_pcm_status_get_driver_htstamp(alsa_snd_pcm_status, &driver_timestamp); - snd_pcm_sframes_t delay = snd_pcm_status_get_delay(alsa_snd_pcm_status); - //debug(1,"Time now: %ld,%ld, Timestamp: %ld,%ld, delta: %.3f milliseconds, audio_timestamp: %ld,%ld, driver_timestamp: %ld,%ld, Delay: %ld.", - //tn.tv_sec,tn.tv_nsec, - //snd_timestamp.tv_sec,snd_timestamp.tv_nsec, - //(delta*1.0)/1000000, - //audio_timestamp.tv_sec,audio_timestamp.tv_nsec, - //driver_timestamp.tv_sec,driver_timestamp.tv_nsec, - //delay); - + uint64_t frames_played_since_last_interrupt = ((uint64_t)desired_sample_rate * delta)/1000000000; snd_pcm_sframes_t frames_played_since_last_interrupt_sized = frames_played_since_last_interrupt; - //debug(1,"Delta: %.3f, frames played in interval: %" PRIu64 ".",(delta*1.0)/1000000,frames_played_since_last_interrupt); - // snd_pcm_status_dump(alsa_snd_pcm_status, output); - //if (reported_delay != delay) - // debug(1,"Difference between reported delay and status delay is: %ld.",reported_delay-delay); - - *delayp = delay - frames_played_since_last_interrupt_sized; + *delayp = snd_pcm_status_get_delay(alsa_snd_pcm_status) - frames_played_since_last_interrupt_sized; return 0; - //return snd_pcm_delay(pcm, delayp); } int delay(long *the_delay) { From e7f70fba328bdcc88994b1963c1e85ffaba29af7 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Thu, 8 Nov 2018 14:43:52 +0000 Subject: [PATCH 05/14] Tidy up with clang-format --- audio_alsa.c | 89 +++++++++++++++++++++++++++------------------------- player.c | 30 +++++++++++------- shairport.c | 4 +-- 3 files changed, 66 insertions(+), 57 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index 815f3423..0a03957b 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -198,7 +198,6 @@ void do_snd_mixer_selem_set_playback_dB_all(snd_mixer_elem_t *mix_elem, double v static int init(int argc, char **argv) { snd_output_stdio_attach(&output, stdout, 0); - // debug(2,"audio_alsa init called."); int response = 0; // this will be what we return to the caller. const char *str; @@ -507,7 +506,6 @@ static int init(int argc, char **argv) { static void deinit(void) { // debug(2,"audio_alsa deinit called."); stop(); - } int open_alsa_device(void) { @@ -543,7 +541,7 @@ int open_alsa_device(void) { snd_pcm_hw_params_alloca(&alsa_params); snd_pcm_sw_params_alloca(&alsa_swparams); - + ret = snd_pcm_hw_params_any(alsa_handle, alsa_params); if (ret < 0) { warn("audio_alsa: Broken configuration for device \"%s\": no configurations " @@ -698,7 +696,7 @@ int open_alsa_device(void) { snd_strerror(ret)); return -9; } - + ret = snd_pcm_sw_params_current(alsa_handle, alsa_swparams); if (ret < 0) { warn("audio_alsa: Unable to get current sw parameters for device \"%s\": %s.", alsa_out_dev, @@ -712,15 +710,15 @@ int open_alsa_device(void) { snd_strerror(ret)); return -11; } - + /* write the sw parameters */ ret = snd_pcm_sw_params(alsa_handle, alsa_swparams); if (ret < 0) { warn("audio_alsa: Unable to set software parameters of device: \"%s\": %s.", alsa_out_dev, - snd_strerror(ret)); + snd_strerror(ret)); return -12; } - + if (actual_buffer_length < config.audio_backend_buffer_desired_length + minimal_buffer_headroom) { /* // the dac buffer is too small, so let's try to set it @@ -748,7 +746,7 @@ int open_alsa_device(void) { "length (%ld) you have chosen.", actual_buffer_length, config.audio_backend_buffer_desired_length); } - + if (alsa_characteristics_already_listed == 0) { alsa_characteristics_already_listed = 1; int log_level = 2; // the level at which debug information should be output @@ -896,38 +894,40 @@ static void start(int i_sample_rate, int i_sample_format) { measurement_data_is_valid = 0; } -int my_snd_pcm_delay(snd_pcm_t *pcm, snd_pcm_sframes_t *delayp) { - int ret; +int my_snd_pcm_delay(snd_pcm_t *pcm, snd_pcm_sframes_t *delayp) { + int ret; snd_pcm_status_t *alsa_snd_pcm_status; snd_pcm_status_alloca(&alsa_snd_pcm_status); - struct timespec tn; // time now - snd_htimestamp_t update_timestamp; //actually a struct timespec + struct timespec tn; // time now + snd_htimestamp_t update_timestamp; // actually a struct timespec ret = snd_pcm_status(pcm, alsa_snd_pcm_status); if (ret) { *delayp = 0; - return ret; + return ret; } - + snd_pcm_state_t state = snd_pcm_status_get_state(alsa_snd_pcm_status); if (state != SND_PCM_STATE_RUNNING) { *delayp = 0; - return -EIO; // might be a better code than this... + return -EIO; // might be a better code than this... } - + clock_gettime(CLOCK_MONOTONIC, &tn); snd_pcm_status_get_htstamp(alsa_snd_pcm_status, &update_timestamp); - - uint64_t t1 = tn.tv_sec * (uint64_t)1000000000 + tn.tv_nsec; - uint64_t t2 = update_timestamp.tv_sec * (uint64_t)1000000000 + update_timestamp.tv_nsec; + + uint64_t t1 = tn.tv_sec * (uint64_t)1000000000 + tn.tv_nsec; + uint64_t t2 = update_timestamp.tv_sec * (uint64_t)1000000000 + update_timestamp.tv_nsec; uint64_t delta = t1 - t2; - - uint64_t frames_played_since_last_interrupt = ((uint64_t)desired_sample_rate * delta)/1000000000; + + uint64_t frames_played_since_last_interrupt = + ((uint64_t)desired_sample_rate * delta) / 1000000000; snd_pcm_sframes_t frames_played_since_last_interrupt_sized = frames_played_since_last_interrupt; - - *delayp = snd_pcm_status_get_delay(alsa_snd_pcm_status) - frames_played_since_last_interrupt_sized; - return 0; + + *delayp = + snd_pcm_status_get_delay(alsa_snd_pcm_status) - frames_played_since_last_interrupt_sized; + return 0; } int delay(long *the_delay) { @@ -947,9 +947,9 @@ int delay(long *the_delay) { debug(1, "Error %d in delay(): \"%s\". Delay reported is %d frames.", reply, snd_strerror(reply), *the_delay); derr = snd_pcm_recover(alsa_handle, reply, 1); - if (derr < 0) - warn("Error %d -- could not clear an error after attempting delay(): \"%s\".", derr, - snd_strerror(derr)); + if (derr < 0) + warn("Error %d -- could not clear an error after attempting delay(): \"%s\".", derr, + snd_strerror(derr)); frame_index = 0; measurement_data_is_valid = 0; @@ -977,9 +977,10 @@ int delay(long *the_delay) { if ((derr = snd_pcm_prepare(alsa_handle))) { debug(1, "Error preparing after delay error: \"%s\".", snd_strerror(derr)); derr = snd_pcm_recover(alsa_handle, derr, 1); - if (derr < 0) - warn("Error %d -- could not clear an error after attempting to recover following a delay(): \"%s\".", derr, - snd_strerror(derr)); + if (derr < 0) + warn("Error %d -- could not clear an error after attempting to recover following a " + "delay(): \"%s\".", + derr, snd_strerror(derr)); } } } @@ -1028,10 +1029,10 @@ static int play(void *buf, int samples) { if (snd_pcm_state(alsa_handle) == SND_PCM_STATE_XRUN) { if ((err = snd_pcm_prepare(alsa_handle))) { debug(1, "Error preparing after underrun: \"%s\".", snd_strerror(err)); - err = snd_pcm_recover(alsa_handle, err, 1); - if (err < 0) - warn("Error %d -- could not clear an error after detecting underrun in play(): \"%s\".", err, - snd_strerror(err)); + err = snd_pcm_recover(alsa_handle, err, 1); + if (err < 0) + warn("Error %d -- could not clear an error after detecting underrun in play(): \"%s\".", + err, snd_strerror(err)); } frame_index = 0; // we'll be starting over measurement_data_is_valid = 0; @@ -1049,9 +1050,10 @@ static int play(void *buf, int samples) { debug(1, "Error %d writing %d samples in play(): \"%s\".", err, samples, snd_strerror(err)); err = snd_pcm_recover(alsa_handle, err, 1); - if (err < 0) - warn("Error %d -- could not clear an error after attempting to write %d samples in play(): \"%s\".", err, samples, - snd_strerror(err)); + if (err < 0) + warn("Error %d -- could not clear an error after attempting to write %d samples in " + "play(): \"%s\".", + err, samples, snd_strerror(err)); } if (frame_index == 0) { frames_sent_for_playing = samples; @@ -1068,9 +1070,9 @@ static int play(void *buf, int samples) { debug(1, "Error %d in delay in play(): \"%s\". Delay reported is %d frames.", err2, snd_strerror(err2), fl); err2 = snd_pcm_recover(alsa_handle, err2, 1); - if (err2 < 0) - warn("Error %d -- could not clear an error after checking delay in play(): \"%s\".", err2, - snd_strerror(err2)); + if (err2 < 0) + warn("Error %d -- could not clear an error after checking delay in play(): \"%s\".", + err2, snd_strerror(err2)); frame_index = 0; measurement_data_is_valid = 0; } else { @@ -1097,9 +1099,10 @@ static int play(void *buf, int samples) { if ((err = snd_pcm_prepare(alsa_handle))) { debug(1, "Error preparing after play error: \"%s\".", snd_strerror(err)); err2 = snd_pcm_recover(alsa_handle, err, 1); - if (err2 < 0) - warn("Error %d -- could not clear an error after reporting ALSA device in incorrect state for play: \"%s\".", err2, - snd_strerror(err2)); + if (err2 < 0) + warn("Error %d -- could not clear an error after reporting ALSA device in incorrect " + "state for play: \"%s\".", + err2, snd_strerror(err2)); } frame_index = 0; measurement_data_is_valid = 0; diff --git a/player.c b/player.c index 43461bf3..11bec280 100644 --- a/player.c +++ b/player.c @@ -454,7 +454,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in // now, if a flush_rtp_timestamp has been defined and the incoming timestamp is "before" it, // drop it… - if ((conn->flush_rtp_timestamp != 0) && (actual_timestamp != conn->flush_rtp_timestamp) && + if ((conn->flush_rtp_timestamp != 0) && (actual_timestamp != conn->flush_rtp_timestamp) && (modulo_32_offset(actual_timestamp, conn->flush_rtp_timestamp) < conn->input_rate * 10)) { // if it's less than 10 seconds debug(2, "Dropping flushed packet in player_put_packet, seqno %u, timestamp %" PRIu32 @@ -465,9 +465,9 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in conn->initial_reference_timestamp = 0; } else { if ((conn->flush_rtp_timestamp != 0) && - (modulo_32_offset(conn->flush_rtp_timestamp, actual_timestamp) > conn->input_rate/5) && + (modulo_32_offset(conn->flush_rtp_timestamp, actual_timestamp) > conn->input_rate / 5) && (modulo_32_offset(conn->flush_rtp_timestamp, actual_timestamp) < conn->input_rate)) { - // between 0.2 and 1 second + // between 0.2 and 1 second debug(2, "Dropping flush request in player_put_packet"); conn->flush_rtp_timestamp = 0; } @@ -851,7 +851,8 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { } } - if ((conn->flush_rtp_timestamp != 0) && (curframe->given_timestamp != conn->flush_rtp_timestamp) && + if ((conn->flush_rtp_timestamp != 0) && + (curframe->given_timestamp != conn->flush_rtp_timestamp) && (modulo_32_offset(curframe->given_timestamp, conn->flush_rtp_timestamp) < conn->input_rate * 10)) { // if it's less than ten seconds debug(2, "Dropping flushed packet in buffer_get_frame, seqno %u, timestamp %" PRIu32 @@ -866,8 +867,10 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { conn->initial_reference_timestamp = 0; } if ((conn->flush_rtp_timestamp != 0) && - (modulo_32_offset(conn->flush_rtp_timestamp, curframe->given_timestamp) > conn->input_rate / 5) && - (modulo_32_offset(conn->flush_rtp_timestamp, curframe->given_timestamp) < conn->input_rate * 10 )) { + (modulo_32_offset(conn->flush_rtp_timestamp, curframe->given_timestamp) > + conn->input_rate / 5) && + (modulo_32_offset(conn->flush_rtp_timestamp, curframe->given_timestamp) < + conn->input_rate * 10)) { debug(2, "Dropping flush request in buffer_get_frame"); conn->flush_rtp_timestamp = 0; } @@ -1912,8 +1915,8 @@ void *player_thread_func(void *arg) { int64_t rt, nt; rt = reference_timestamp; // uint32_t to int64_t nt = inframe->given_timestamp; // uint32_t to int64_t - rt = rt*conn->output_sample_ratio; - nt = nt*conn->output_sample_ratio; + rt = rt * conn->output_sample_ratio; + nt = nt * conn->output_sample_ratio; uint64_t local_time_now = get_absolute_time_in_fp(); // types okay // struct timespec tn; @@ -2062,14 +2065,17 @@ void *player_thread_func(void *arg) { // sync_error_out_of_bounds, sync_error); sync_error_out_of_bounds = 0; - int64_t filler_length = (int64_t)(config.resyncthreshold * config.output_rate); // number of samples + int64_t filler_length = + (int64_t)(config.resyncthreshold * config.output_rate); // number of samples if ((sync_error > 0) && (sync_error > filler_length)) { debug(2, "Large positive sync error: %" PRId64 ".", sync_error); frames_to_drop = sync_error / conn->output_sample_ratio; reset_input_flow_metrics(conn); } else if ((sync_error < 0) && ((-sync_error) > filler_length)) { - debug(2, "Large negative sync error: %" PRId64 " with should_be_frame_32 of %" PRIu32 - ", nt of %" PRId64 " and current_delay of %" PRId64 ".", sync_error, should_be_frame_32, nt, current_delay); + debug(2, + "Large negative sync error: %" PRId64 " with should_be_frame_32 of %" PRIu32 + ", nt of %" PRId64 " and current_delay of %" PRId64 ".", + sync_error, should_be_frame_32, nt, current_delay); int64_t silence_length = -sync_error; if (silence_length > (filler_length * 5)) silence_length = filler_length * 5; @@ -2077,7 +2083,7 @@ void *player_thread_func(void *arg) { char *long_silence = malloc(conn->output_bytes_per_frame * silence_length_sized); if (long_silence) { memset(long_silence, 0, conn->output_bytes_per_frame * silence_length_sized); - debug(2,"Play a silence of %d frames.",silence_length_sized); + debug(2, "Play a silence of %d frames.", silence_length_sized); config.output->play(long_silence, silence_length_sized); free(long_silence); } else { diff --git a/shairport.c b/shairport.c index d4a29410..5e36e911 100644 --- a/shairport.c +++ b/shairport.c @@ -25,8 +25,6 @@ * OTHER DEALINGS IN THE SOFTWARE. */ -#include -#include #include #include #include @@ -37,7 +35,9 @@ #include #include #include +#include #include +#include #include #include From 3b4654df7703c58d3d2fefa74c7543ed39851875 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sat, 24 Nov 2018 22:28:52 +0000 Subject: [PATCH 06/14] Make some alsa operation sequences un-cancellable. Make some cleanup sequences un-cancellable. --- audio_alsa.c | 33 ++++++++++++++++++++++++++++++--- rtp.c | 23 +++++++++++++++++++---- 2 files changed, 49 insertions(+), 7 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index 5ca4836c..24132fe6 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -405,6 +405,8 @@ static int init(int argc, char **argv) { debug(1, "alsa output device name is \"%s\".", alsa_out_dev); if (hardware_mixer) { + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable if (alsa_mix_dev == NULL) alsa_mix_dev = alsa_out_dev; @@ -491,6 +493,7 @@ static int init(int argc, char **argv) { } debug_mutex_unlock(&alsa_mutex, 3); // release the mutex pthread_cleanup_pop(0); + pthread_setcancelstate(oldState, NULL); } else { // debug(1, "Has no mixer and thus no hardware mute."); } @@ -504,7 +507,7 @@ static void deinit(void) { stop(); } -int open_alsa_device(void) { +int actual_open_alsa_device(void) { // the alsa mutex is already acquired when this is called const snd_pcm_uframes_t minimal_buffer_headroom = 352 * 2; // we accept this much headroom in the hardware buffer, but we'll @@ -851,6 +854,15 @@ int open_alsa_device(void) { return 0; } +int open_alsa_device(void) { + int result; + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable + result = actual_open_alsa_device(); + pthread_setcancelstate(oldState, NULL); + return result; +} + static void start(int i_sample_rate, int i_sample_format) { // debug(2,"audio_alsa start called."); if (i_sample_rate == 0) @@ -874,6 +886,8 @@ int delay(long *the_delay) { if (alsa_handle == NULL) { return -ENODEV; } else { + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 1); int derr; snd_pcm_state_t dac_state = snd_pcm_state(alsa_handle); @@ -926,6 +940,7 @@ int delay(long *the_delay) { // here, occasionally pretend there's a problem with pcm_get_delay() // if ((random() % 100000) < 3) // keep it pretty rare // reply = -EIO; // pretend something bad has happened + pthread_setcancelstate(oldState, NULL); return reply; } } @@ -945,10 +960,13 @@ int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played) { static int play(void *buf, int samples) { // debug(3,"audio_alsa play called."); + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable int ret = 0; if (alsa_handle == NULL) { + pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 1); - ret = open_alsa_device(); + ret = actual_open_alsa_device(); if (ret == 0) { if (audio_alsa.volume) do_volume(set_volume); @@ -1047,13 +1065,14 @@ static int play(void *buf, int samples) { debug_mutex_unlock(&alsa_mutex, 3); pthread_cleanup_pop(0); // release the mutex } + pthread_setcancelstate(oldState, NULL); return ret; } static void flush(void) { // debug(2,"audio_alsa flush called."); int oldState; - pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 1); int derr; do_mute(1); @@ -1094,6 +1113,8 @@ static void parameters(audio_parameters *info) { } void do_volume(double vol) { // caller is assumed to have the alsa_mutex when using this function + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable debug(3, "Setting volume db to %f.", vol); set_volume = vol; if (volume_set_request && (open_mixer() == 1)) { @@ -1125,6 +1146,7 @@ void do_volume(double vol) { // caller is assumed to have the alsa_mutex when us volume_set_request = 0; // any external request that has been made is now satisfied close_mixer(); } + pthread_setcancelstate(oldState, NULL); } void volume(double vol) { @@ -1165,6 +1187,9 @@ static void mute(int mute_state_requested) { void do_mute(int mute_state_requested) { + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable + // if a mute is requested now, then // if an external mute request is in place, leave everything muted // otherwise, if an external mute request is pending, action it @@ -1205,4 +1230,6 @@ void do_mute(int mute_state_requested) { } } mute_request_pending = 0; + + pthread_setcancelstate(oldState, NULL); } diff --git a/rtp.c b/rtp.c index 0c97fc31..afee1a4b 100644 --- a/rtp.c +++ b/rtp.c @@ -98,14 +98,16 @@ uint64_t local_to_remote_time_difference_now(rtsp_conn_info *conn) { } void rtp_audio_receiver_cleanup_handler(void *arg) { + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); debug(3, "Audio Receiver Cleanup."); rtsp_conn_info *conn = (rtsp_conn_info *)arg; debug(3, "shutdown audio socket."); shutdown(conn->audio_socket, SHUT_RDWR); debug(3, "close audio socket."); close(conn->audio_socket); - - debug(3, "Audio Receiver Cleanup Successful."); + debug(3, "Connection %d: Audio Receiver Cleanup.", conn->connection_number); + pthread_setcancelstate(oldState, NULL); } void *rtp_audio_receiver(void *arg) { @@ -240,13 +242,16 @@ void *rtp_audio_receiver(void *arg) { } void rtp_control_handler_cleanup_handler(void *arg) { + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); debug(3, "Control Receiver Cleanup."); rtsp_conn_info *conn = (rtsp_conn_info *)arg; debug(3, "shutdown control socket."); shutdown(conn->control_socket, SHUT_RDWR); debug(3, "close control socket."); close(conn->control_socket); - debug(3, "Control Receiver Cleanup Successful."); + debug(3, "Connection %d: Control Receiver Cleanup.", conn->connection_number); + pthread_setcancelstate(oldState, NULL); } void *rtp_control_receiver(void *arg) { @@ -495,7 +500,13 @@ void *rtp_control_receiver(void *arg) { pthread_exit(NULL); } +void rtp_timing_sender_cleanup_handler(void *arg) { + rtsp_conn_info *conn = (rtsp_conn_info *)arg; + debug(3, "Connection %d: Timing Sender Cleanup.", conn->connection_number); +} + void *rtp_timing_sender(void *arg) { + pthread_cleanup_push(rtp_timing_sender_cleanup_handler, arg); rtsp_conn_info *conn = (rtsp_conn_info *)arg; struct timing_request { char leader; @@ -555,10 +566,13 @@ void *rtp_timing_sender(void *arg) { usleep(3000000); } debug(3, "rtp_timing_sender thread interrupted. This should never happen."); + pthread_cleanup_pop(0); // don't execute anything here. pthread_exit(NULL); } void rtp_timing_receiver_cleanup_handler(void *arg) { + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); debug(3, "Timing Receiver Cleanup."); rtsp_conn_info *conn = (rtsp_conn_info *)arg; pthread_cancel(conn->timer_requester); @@ -567,7 +581,8 @@ void rtp_timing_receiver_cleanup_handler(void *arg) { shutdown(conn->timing_socket, SHUT_RDWR); debug(3, "close timing socket."); close(conn->timing_socket); - debug(3, "Timing Receiver Cleanup Successful."); + debug(3, "Connection %d: Timing Receiver Cleanup.", conn->connection_number); + pthread_setcancelstate(oldState, NULL); } void *rtp_timing_receiver(void *arg) { From 4bb29bc198541d5dacf7cb1ba9a2fcd82f2afe86 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Mon, 3 Dec 2018 16:52:32 +0000 Subject: [PATCH 07/14] Make sure that shared watchdog count is correctly updated in the rtsp_conn_info structure! --- player.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/player.h b/player.h index deb787c6..e2c6a4c8 100644 --- a/player.h +++ b/player.h @@ -87,7 +87,7 @@ typedef struct { time_t playstart; pthread_t thread, timer_requester, rtp_audio_thread, rtp_control_thread, rtp_timing_thread, player_watchdog_thread; - int64_t watchdog_bark_time; + volatile int64_t watchdog_bark_time; // pthread_t *ptp; // buffers to delete on exit From 60315b63c90944fb4d9da78e5608cfb92d3f01b7 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Mon, 3 Dec 2018 17:00:12 +0000 Subject: [PATCH 08/14] Try to ensure that any alsa command sequences are uncancellable. Leave a little time afterwards where possible. --- audio_alsa.c | 7 +++++-- rtsp.c | 16 ++++++++-------- 2 files changed, 13 insertions(+), 10 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index 98182989..c233a67b 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -506,7 +506,8 @@ static int init(int argc, char **argv) { } else { debug(1, "alsa: no hardware mixer selected."); } - + + usleep(200000); // see if it makes a difference alsa_mix_handle = NULL; return response; } @@ -883,7 +884,7 @@ int actual_open_alsa_device(void) { break; } } - + usleep(200000); // see if it makes a difference return 0; } @@ -910,6 +911,7 @@ static void start(int i_sample_rate, int i_sample_format) { frame_index = 0; measurement_data_is_valid = 0; + usleep(200000); // see if it makes a difference } //assuming pthread cancellation is disabled @@ -1163,6 +1165,7 @@ static void flush(void) { measurement_data_is_valid = 0; alsa_handle = NULL; } + usleep(200000); // see if it makes a difference debug_mutex_unlock(&alsa_mutex, 3); pthread_cleanup_pop(0); // release the mutex pthread_setcancelstate(oldState, NULL); diff --git a/rtsp.c b/rtsp.c index 11266c7d..81b380f0 100644 --- a/rtsp.c +++ b/rtsp.c @@ -265,7 +265,7 @@ int have_player(rtsp_conn_info *conn) { 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); + debug(1, "Connection %d: Watchdog Exit.", conn->connection_number); } void *player_watchdog_thread_code(void *arg) { @@ -2116,13 +2116,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); - debug(2, "Join watchdog thread."); - pthread_join(conn->player_watchdog_thread, NULL); - 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) { // if it's ours @@ -2131,6 +2124,13 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { } debug_mutex_unlock(&playing_conn_lock, 3); + 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, "Connection %d: RTSP thread terminated.", conn->connection_number); conn->running = 0; pthread_setcancelstate(oldState, NULL); From 78da7c453c8048b9b560d6d997072b7810cec48a Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Mon, 3 Dec 2018 18:01:54 +0000 Subject: [PATCH 09/14] Make the stop requester volatile, duh. --- player.h | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/player.h b/player.h index e2c6a4c8..7fea41fc 100644 --- a/player.h +++ b/player.h @@ -82,8 +82,8 @@ typedef struct { char *auth_nonce; // the session nonce, if needed stream_cfg stream; SOCKADDR remote, local; - int stop; - int running; + volatile int stop; + volatile int running; time_t playstart; pthread_t thread, timer_requester, rtp_audio_thread, rtp_control_thread, rtp_timing_thread, player_watchdog_thread; From 67d2a4b5d9455382519743dd747523ea3dc5f4c9 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Mon, 3 Dec 2018 18:42:49 +0000 Subject: [PATCH 10/14] Add a 30 second timout on the read function on an RTSP thread. --- rtsp.c | 22 ++++++++++++++-------- 1 file changed, 14 insertions(+), 8 deletions(-) diff --git a/rtsp.c b/rtsp.c index 81b380f0..8f0ec8c7 100644 --- a/rtsp.c +++ b/rtsp.c @@ -265,7 +265,7 @@ int have_player(rtsp_conn_info *conn) { void player_watchdog_thread_cleanup_handler(void *arg) { rtsp_conn_info *conn = (rtsp_conn_info *)arg; - debug(1, "Connection %d: Watchdog Exit.", conn->connection_number); + debug(2, "Connection %d: Watchdog Exit.", conn->connection_number); } void *player_watchdog_thread_code(void *arg) { @@ -2116,6 +2116,13 @@ 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); + debug(2, "Join watchdog thread."); + pthread_join(conn->player_watchdog_thread, NULL); + 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) { // if it's ours @@ -2124,13 +2131,6 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { } debug_mutex_unlock(&playing_conn_lock, 3); - 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, "Connection %d: RTSP thread terminated.", conn->connection_number); conn->running = 0; pthread_setcancelstate(oldState, NULL); @@ -2393,6 +2393,12 @@ void rtsp_listen_loop(void) { tv.tv_usec = 0; if (setsockopt(fd, SOL_SOCKET, SO_SNDTIMEO, (const char *)&tv, sizeof tv) == -1) debug(1, "Error %d setting send timeout for rtsp writeback.", errno); + + tv.tv_sec = 30; // 30 seconds read timeout + tv.tv_usec = 0; + if (setsockopt(fd, SOL_SOCKET, SO_RCVTIMEO, (const char *)&tv, sizeof tv) == -1) + debug(1, "Error %d setting send timeout for rtsp writeback.", errno); + #ifdef IPV6_V6ONLY // some systems don't support v4 access on v6 sockets, but some do. From 9ddef563ad8c7d5c603be5a31bc98ea101dccbec Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Tue, 4 Dec 2018 08:56:29 +0000 Subject: [PATCH 11/14] Shorten the delays to 100 ms --- audio_alsa.c | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index c233a67b..73f324a5 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -507,7 +507,7 @@ static int init(int argc, char **argv) { debug(1, "alsa: no hardware mixer selected."); } - usleep(200000); // see if it makes a difference + usleep(100000); // see if it makes a difference alsa_mix_handle = NULL; return response; } @@ -884,7 +884,7 @@ int actual_open_alsa_device(void) { break; } } - usleep(200000); // see if it makes a difference + usleep(100000); // see if it makes a difference return 0; } @@ -911,7 +911,7 @@ static void start(int i_sample_rate, int i_sample_format) { frame_index = 0; measurement_data_is_valid = 0; - usleep(200000); // see if it makes a difference + usleep(100000); // see if it makes a difference } //assuming pthread cancellation is disabled @@ -1165,7 +1165,7 @@ static void flush(void) { measurement_data_is_valid = 0; alsa_handle = NULL; } - usleep(200000); // see if it makes a difference + usleep(100000); // see if it makes a difference debug_mutex_unlock(&alsa_mutex, 3); pthread_cleanup_pop(0); // release the mutex pthread_setcancelstate(oldState, NULL); From 277d401d24438c563deef6aa870987c93ef58961 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Tue, 4 Dec 2018 17:25:15 +0000 Subject: [PATCH 12/14] Ensure watchdog always starts with the starting time of the thread. Add watchdog bark count. On the third bark, execute an unfixable error script if present. --- audio_alsa.c | 23 +++++++++-------------- common.c | 32 ++++++++++++++++++++++++++++++++ common.h | 3 ++- player.h | 5 +++-- rtsp.c | 32 +++++++++++++++++++++++--------- scripts/shairport-sync.conf | 1 + shairport.c | 5 +++++ 7 files changed, 75 insertions(+), 26 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index 73f324a5..a93ec1ae 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -136,8 +136,7 @@ static void help(void) { void set_alsa_out_dev(char *dev) { alsa_out_dev = dev; } - -//assuming pthread cancellation is disabled +// assuming pthread cancellation is disabled int open_mixer() { int response = 0; if (hardware_mixer) { @@ -181,7 +180,7 @@ int open_mixer() { return response; } -//assuming pthread cancellation is disabled +// assuming pthread cancellation is disabled void close_mixer() { if (alsa_mix_handle) { snd_mixer_close(alsa_mix_handle); @@ -189,7 +188,7 @@ void close_mixer() { } } -//assuming pthread cancellation is disabled +// assuming pthread cancellation is disabled void do_snd_mixer_selem_set_playback_dB_all(snd_mixer_elem_t *mix_elem, double vol) { if (snd_mixer_selem_set_playback_dB_all(mix_elem, vol, 0) != 0) { debug(1, "Can't set playback volume accurately to %f dB.", vol); @@ -200,7 +199,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) { - // for debugging + // for debugging snd_output_stdio_attach(&output, stdout, 0); // debug(2,"audio_alsa init called."); @@ -506,8 +505,7 @@ static int init(int argc, char **argv) { } else { debug(1, "alsa: no hardware mixer selected."); } - - usleep(100000); // see if it makes a difference + alsa_mix_handle = NULL; return response; } @@ -517,7 +515,7 @@ static void deinit(void) { stop(); } -//assuming pthread cancellation is disabled +// assuming pthread cancellation is disabled int actual_open_alsa_device(void) { // the alsa mutex is already acquired when this is called const snd_pcm_uframes_t minimal_buffer_headroom = @@ -884,11 +882,10 @@ int actual_open_alsa_device(void) { break; } } - usleep(100000); // see if it makes a difference return 0; } -int open_alsa_device(void) { +int open_alsa_device(void) { int result; int oldState; pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable @@ -911,10 +908,9 @@ static void start(int i_sample_rate, int i_sample_format) { frame_index = 0; measurement_data_is_valid = 0; - usleep(100000); // see if it makes a difference } -//assuming pthread cancellation is disabled +// assuming pthread cancellation is disabled int my_snd_pcm_delay(snd_pcm_t *pcm, snd_pcm_sframes_t *delayp) { int ret; snd_pcm_status_t *alsa_snd_pcm_status; @@ -1165,7 +1161,6 @@ static void flush(void) { measurement_data_is_valid = 0; alsa_handle = NULL; } - usleep(100000); // see if it makes a difference debug_mutex_unlock(&alsa_mutex, 3); pthread_cleanup_pop(0); // release the mutex pthread_setcancelstate(oldState, NULL); @@ -1303,6 +1298,6 @@ void do_mute(int mute_state_requested) { close_mixer(); } } - mute_request_pending = 0; + mute_request_pending = 0; pthread_setcancelstate(oldState, NULL); } diff --git a/common.c b/common.c index b2c920ad..264ef499 100644 --- a/common.c +++ b/common.c @@ -739,6 +739,38 @@ void command_start(void) { } } } +void command_execute(const char *command) { + // this has a cancellation point if waiting is enabled + if (command) { + /*Spawn a child to run the program.*/ + pid_t pid = fork(); + if (pid == 0) { /* child process */ + int argC; + char **argV; + if (poptParseArgvString(command, &argC, (const char ***)&argV) != + 0) // note that argV should be free()'d after use, but we expect this fork to exit + // eventually. + debug(1, "Can't decipher command arguments in \"%s\".", command); + else { + // debug(1,"Executing command %s",command); + execv(argV[0], argV); + warn("Execution of command \"%s\" failed to start", command); + debug(1, "Error executing command \"%s\".", command); + exit(127); /* only if execv fails */ + } + } else { + if (config.cmd_blocking) { /* pid!=0 means parent process and if blocking is true, wait for + process to finish */ + pid_t rc = waitpid(pid, 0, 0); /* wait for child to exit */ + if (rc != pid) { + warn("Execution of command \"%s\" returned an error.", command); + debug(1, "Command \"%s\" finished with error %d", command, errno); + } + } + // debug(1,"Continue after on-unfixable command"); + } + } +} void command_stop(void) { // this has a cancellation point if waiting is enabled diff --git a/common.h b/common.h index ece21b1d..a9f4ab7d 100644 --- a/common.h +++ b/common.h @@ -148,7 +148,7 @@ typedef struct { int debugger_show_relative_time; // in the debug message, display the time since the last one int statistics_requested, use_negotiated_latencies; enum playback_mode_type playback_mode; - char *cmd_start, *cmd_stop, *cmd_set_volume; + char *cmd_start, *cmd_stop, *cmd_set_volume, *cmd_unfixable; int cmd_blocking, cmd_start_returns_output; double tolerance; // allow this much drift before attempting to correct it enum stuffing_type packet_stuffing; @@ -296,6 +296,7 @@ int config_set_lookup_bool(config_t *cfg, char *where, int *dst); void command_start(void); void command_stop(void); +void command_execute(const char *command); void command_set_volume(double volume); int mkpath(const char *path, mode_t mode); diff --git a/player.h b/player.h index 7fea41fc..9346ef2b 100644 --- a/player.h +++ b/player.h @@ -84,11 +84,12 @@ typedef struct { SOCKADDR remote, local; volatile int stop; volatile int running; + volatile uint64_t watchdog_bark_time; + volatile int watchdog_barks; // number of times the watchdog has timed out and done something + time_t playstart; pthread_t thread, timer_requester, rtp_audio_thread, rtp_control_thread, rtp_timing_thread, player_watchdog_thread; - volatile int64_t watchdog_bark_time; - // pthread_t *ptp; // buffers to delete on exit signed short *tbuf; diff --git a/rtsp.c b/rtsp.c index 8f0ec8c7..158b3263 100644 --- a/rtsp.c +++ b/rtsp.c @@ -283,11 +283,25 @@ void *player_watchdog_thread_code(void *arg) { 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); + conn->watchdog_barks++; + if (conn->watchdog_barks == 1) { + 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); + } else if (conn->watchdog_barks == 3) { + if (config.cmd_unfixable) { + warn("Connection %d: An unfixable error has been detected. Executing the " + "\"run_this_if_an_unfixable_error_is_detected\" command.", + conn->connection_number); + command_execute(config.cmd_unfixable); + } else { + warn("Connection %d: An unfixable error has been detected. \"No " + "run_this_if_an_unfixable_error_is_detected\" command provided -- nothing done.", + conn->connection_number); + } + } } } } @@ -2144,7 +2158,8 @@ 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; + // create the watchdog mutex, initialise the watchdog time and start the watchdog thread; + conn->watchdog_bark_time = get_absolute_time_in_fp(); pthread_mutex_init(&conn->watchdog_mutex, NULL); pthread_create(&conn->player_watchdog_thread, NULL, &player_watchdog_thread_code, (void *)conn); @@ -2393,12 +2408,11 @@ void rtsp_listen_loop(void) { tv.tv_usec = 0; if (setsockopt(fd, SOL_SOCKET, SO_SNDTIMEO, (const char *)&tv, sizeof tv) == -1) debug(1, "Error %d setting send timeout for rtsp writeback.", errno); - + tv.tv_sec = 30; // 30 seconds read timeout tv.tv_usec = 0; - if (setsockopt(fd, SOL_SOCKET, SO_RCVTIMEO, (const char *)&tv, sizeof tv) == -1) + if (setsockopt(fd, SOL_SOCKET, SO_RCVTIMEO, (const char *)&tv, sizeof tv) == -1) debug(1, "Error %d setting send timeout for rtsp writeback.", errno); - #ifdef IPV6_V6ONLY // some systems don't support v4 access on v6 sockets, but some do. diff --git a/scripts/shairport-sync.conf b/scripts/shairport-sync.conf index 55ac4cbf..97431d79 100644 --- a/scripts/shairport-sync.conf +++ b/scripts/shairport-sync.conf @@ -53,6 +53,7 @@ sessioncontrol = { // run_this_before_play_begins = "/full/path/to/application and args"; // make sure the application has executable permission. If it's a script, include the shebang (#!/bin/...) on the first line // run_this_after_play_ends = "/full/path/to/application and args"; // make sure the application has executable permission. If it's a script, include the shebang (#!/bin/...) on the first line +// run_this_if_an_unfixable_error_is_detected = "/full/path/to/application and args"; // if a problem occurs that can't be cleared. It might restart the whole device. // wait_for_completion = "no"; // set to "yes" to get Shairport Sync to wait until the "run_this..." applications have terminated before continuing // allow_session_interruption = "no"; // set to "yes" to allow another device to interrupt Shairport Sync while it's playing from an existing audio source // session_timeout = 120; // wait for this number of seconds after a source disappears before terminating the session and becoming available again. diff --git a/shairport.c b/shairport.c index 11f085b1..65c0bd68 100644 --- a/shairport.c +++ b/shairport.c @@ -721,6 +721,11 @@ int parse_options(int argc, char **argv) { config.cmd_stop = (char *)str; } + if (config_lookup_string(config.cfg, + "sessioncontrol.run_this_if_an_unfixable_error_is_detected", &str)) { + config.cmd_unfixable = (char *)str; + } + if (config_lookup_string(config.cfg, "sessioncontrol.wait_for_completion", &str)) { if (strcasecmp(str, "no") == 0) config.cmd_blocking = 0; From b071d3983407e398320778fb709b023dbbc4b915 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Tue, 4 Dec 2018 17:25:40 +0000 Subject: [PATCH 13/14] Ensure watchdog always starts with the starting time of the thread. Add watchdog bark count. On the third bark, execute an unfixable error script if present. --- configure.ac | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/configure.ac b/configure.ac index 1fda52d5..82dc13fb 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.3d32], [mikebrady@eircom.net]) +AC_INIT([shairport-sync], [3.3d33], [mikebrady@eircom.net]) AM_INIT_AUTOMAKE AC_CONFIG_SRCDIR([shairport.c]) AC_CONFIG_HEADERS([config.h]) From a2e7cb34fb973d95e6f28763af12db7a1a2bb035 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Thu, 6 Dec 2018 14:46:57 +0000 Subject: [PATCH 14/14] The run_this_if_an_unfixable_error_is_detected script is definitely working and can restart the device. A sudoers entry is necessary to allow the shairport-sync user to 'sudo reboot --no-wall' without needing a password. --- configure.ac | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/configure.ac b/configure.ac index 82dc13fb..8f3248ab 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.3d33], [mikebrady@eircom.net]) +AC_INIT([shairport-sync], [3.3d34], [mikebrady@eircom.net]) AM_INIT_AUTOMAKE AC_CONFIG_SRCDIR([shairport.c]) AC_CONFIG_HEADERS([config.h])