From 98c45cbb1bee872d001b1221d2fd9872ad15d7b7 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Tue, 2 Nov 2021 09:15:04 +0000 Subject: [PATCH 01/40] Fix a bug that was causing a compiler warniong about a potentially uninitialised variable. --- rtsp.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/rtsp.c b/rtsp.c index 9e18a3b2..f1efb1cd 100644 --- a/rtsp.c +++ b/rtsp.c @@ -3784,7 +3784,7 @@ int send_metadata_to_queue(pc_queue *queue, uint32_t type, uint32_t code, char * int send_metadata(uint32_t type, uint32_t code, char *data, uint32_t length, rtsp_message *carrier, int block) { - int rc; + int rc = 0; if (config.metadata_enabled) { rc = send_metadata_to_queue(&metadata_queue, type, code, data, length, carrier, block); rc = From 99c663857313a23d307b8d3c48423bdfc9554379 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Sat, 6 Nov 2021 18:32:26 +0000 Subject: [PATCH 02/40] Ensure the frame rate calculator allows for silent frames added to disable standby. Clean up outmoded and unused stuff in audio_alsa.c. More to do. --- audio_alsa.c | 83 +++++++++++++++++++++------------------------------- player.c | 56 +++++++++++++++++++++++------------ player.h | 2 +- 3 files changed, 71 insertions(+), 70 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index f723cb7d..32f6c90f 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -60,7 +60,8 @@ static int play(void *buf, int samples); static void stop(void); static void flush(void); int delay(long *the_delay); -int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played); +int get_frames_sent_for_output(__attribute__ ((unused)) uint64_t *elapsed_time, uint64_t *frames_sent_to_dac); +// int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played); void *alsa_buffer_monitor_thread_code(void *arg); static void volume(double vol); @@ -88,7 +89,8 @@ audio_output audio_alsa = { .flush = &flush, .delay = &delay, .play = &play, - .rate_info = &get_rate_information, + .rate_info = &get_frames_sent_for_output, // will also include frames of silence sent to stop standby mode +// .rate_info = NULL, .mute = NULL, // a function will be provided if it can, and is allowed to, // do hardware mute .volume = NULL, // a function will be provided if it can do hardware volume @@ -239,22 +241,13 @@ int precision_delay_available() { return (precision_delay_available_status == YNDK_YES); } -// static int play_number; -// static int64_t accumulated_delay, accumulated_da_delay; int alsa_characteristics_already_listed = 0; static snd_pcm_uframes_t period_size_requested, buffer_size_requested; static int set_period_size_request, set_buffer_size_request; -static uint64_t measurement_start_time; -static uint64_t frames_played_at_measurement_start_time; - -static uint64_t measurement_time; -static uint64_t frames_played_at_measurement_time; - static uint64_t frames_sent_for_playing; -static uint64_t frame_index; -static int measurement_data_is_valid; +static int output_error_occurred; // set to true if an underrun or similar has occurred since last requested static void help(void) { printf(" -d output-device set the output device, default is \"default\".\n" @@ -1407,8 +1400,8 @@ static void start(__attribute__((unused)) int i_sample_rate, __attribute__((unused)) int i_sample_format) { debug(3, "audio_alsa start called."); - frame_index = 0; - measurement_data_is_valid = 0; + // frame_index = 0; + // measurement_data_is_valid = 0; stall_monitor_start_time = 0; stall_monitor_frame_count = 0; @@ -1430,8 +1423,8 @@ int standard_delay_and_status(snd_pcm_state_t *state, snd_pcm_sframes_t *delay, } else { // not running, thus no delay information, thus can't check for frame // rates - frame_index = 0; // we'll be starting over... - measurement_data_is_valid = 0; + // frame_index = 0; // we'll be starting over... + // measurement_data_is_valid = 0; *delay = 0; } @@ -1587,8 +1580,8 @@ int precision_delay_and_status(snd_pcm_state_t *state, snd_pcm_sframes_t *delay, // not running, thus no delay information, thus can't check for frame // rates - frame_index = 0; // we'll be starting over... - measurement_data_is_valid = 0; + // frame_index = 0; // we'll be starting over... + // measurement_data_is_valid = 0; } } else { debug(1, "alsa: can't get device's status."); @@ -1631,6 +1624,21 @@ int delay(long *the_delay) { return ret; } +int get_frames_sent_for_output(__attribute__ ((unused)) uint64_t *elapsed_time, uint64_t *frames_sent_to_dac) { + int ret = 0; + pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 0); + *frames_sent_to_dac = frames_sent_for_playing; + if (alsa_handle == NULL) + ret = ENODEV; + else + ret = output_error_occurred; // will be zero unless an error occurred + output_error_occurred = 0; // reset it. + debug_mutex_unlock(&alsa_mutex, 0); + pthread_cleanup_pop(0); + return ret; +} + +/* int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played) { // elapsed_time is in nanoseconds int response = 0; // zero means okay @@ -1644,6 +1652,7 @@ int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played) { } return response; } +*/ int do_play(void *buf, int samples) { // assuming the alsa_mutex has been acquired @@ -1671,34 +1680,9 @@ int do_play(void *buf, int samples) { ret = alsa_pcm_write(alsa_handle, buf, samples); if (ret == samples) { stall_monitor_frame_count += samples; - - if (frame_index == 0) { - frames_sent_for_playing = samples; - } else { - frames_sent_for_playing += samples; - } - - const uint64_t start_measurement_from_this_frame = - (2 * config.output_rate) / 352; // two seconds of frames - - frame_index++; - - if ((frame_index == start_measurement_from_this_frame) || - ((frame_index > start_measurement_from_this_frame) && (frame_index % 32 == 0))) { - - measurement_time = get_absolute_time_in_ns(); - frames_played_at_measurement_time = frames_sent_for_playing - my_delay - samples; - - if (frame_index == start_measurement_from_this_frame) { - // debug(1, "Start frame counting"); - frames_played_at_measurement_start_time = frames_played_at_measurement_time; - measurement_start_time = measurement_time; - measurement_data_is_valid = 1; - } - } + frames_sent_for_playing += samples; } else { - frame_index = 0; - measurement_data_is_valid = 0; + output_error_occurred = -ret; // note than an output error has occurred if (ret == -EPIPE) { /* underrun */ // It could be that the DAC was in the SND_PCM_STATE_XRUN state before @@ -1748,8 +1732,6 @@ int do_play(void *buf, int samples) { "alsa: device status returns fault status %d and SND_PCM_STATE_* " "%d for play.", ret, state); - frame_index = 0; - measurement_data_is_valid = 0; } pthread_setcancelstate(oldState, NULL); @@ -1774,7 +1756,8 @@ int do_open(int do_auto_setup) { // set accordingly // do_mute(0); // complete unmute } - + output_error_occurred = 0; + frames_sent_for_playing = 0; alsa_backend_state = abm_connected; // only do this if it really opened it. } } else { @@ -2005,8 +1988,8 @@ void *alsa_buffer_monitor_thread_code(__attribute__((unused)) void *arg) { "alsa_backend_state => abm_connected"); } else if ((alsa_backend_state == abm_connected) && (config.keep_dac_busy == 0)) { stall_monitor_start_time = 0; - frame_index = 0; - measurement_data_is_valid = 0; + // frame_index = 0; + // measurement_data_is_valid = 0; debug(2, "alsa: alsa_buffer_monitor_thread_code() -- closing the output " "device"); do_close(); diff --git a/player.c b/player.c index 6408a006..74c6eac2 100644 --- a/player.c +++ b/player.c @@ -1611,7 +1611,7 @@ void player_thread_cleanup_handler(void *arg) { int elapsedHours = rawSeconds / 3600; int elapsedMin = (rawSeconds / 60) % 60; int elapsedSec = rawSeconds % 60; - if (conn->frame_rate_status) + if (conn->frame_rate_valid) inform("Connection %d: Playback Stopped. Total playing time %02d:%02d:%02d. Input: %0.2f, " "output: %0.2f " "frames per second.", @@ -1714,6 +1714,12 @@ void player_thread_cleanup_handler(void *arg) { void *player_thread_func(void *arg) { rtsp_conn_info *conn = (rtsp_conn_info *)arg; + + uint64_t previous_frames_played; + uint64_t previous_frames_played_time; + int previous_frames_played_valid = 0; + + // pthread_cleanup_push(player_thread_initial_cleanup_handler, arg); conn->packet_count = 0; conn->packet_count_since_flush = 0; @@ -1866,7 +1872,7 @@ void *player_thread_func(void *arg) { conn->playstart = time(NULL); conn->frame_rate = 0.0; - conn->frame_rate_status = 0; + conn->frame_rate_valid = 0; conn->input_frame_rate = 0.0; conn->input_frame_rate_starting_point_is_valid = 0; @@ -2059,7 +2065,7 @@ void *player_thread_func(void *arg) { pthread_testcancel(); // allow a pthread_cancel request to take effect. abuf_t *inframe = buffer_get_frame(conn); // this has cancellation point(s), but it's not // guaranteed that they'll always be executed - + uint64_t local_time_now = get_absolute_time_in_ns(); // types okay if (inframe) { inbuf = inframe->data; inbuflength = inframe->length; @@ -2245,8 +2251,6 @@ void *player_thread_func(void *arg) { at_least_one_frame_seen = 1; - uint64_t local_time_now = get_absolute_time_in_ns(); // types okay - // This is the timing error for the next audio frame in the DAC, if applicable int64_t sync_error = 0; @@ -2780,21 +2784,32 @@ void *player_thread_func(void *arg) { conn->input_frame_rate = 0.0; } + uint64_t frames_sent_for_play; + int status = -1; if ((config.output->delay) && (config.no_sync == 0) && (config.output->rate_info)) { - uint64_t elapsed_play_time, frames_played; - if (config.output->rate_info(&elapsed_play_time, &frames_played) == 0) - conn->frame_rate_status = 1; - else - conn->frame_rate_status = 0; - if (conn->frame_rate_status) { - conn->frame_rate = - (1.0E9 * frames_played) / - elapsed_play_time; // an IEEE double calculation with two 64-bit integers - } else { - conn->frame_rate = 0.0; + uint64_t elapsed_play_time; // dummy + status = config.output->rate_info(&elapsed_play_time, &frames_sent_for_play); + uint64_t frames_played = frames_sent_for_play - play_samples - current_delay; + // If the status is zero, it means that there were no output problems since the + // last time the rate_info call was made. Thus, the frame rate should be valid. + if ((status == 0) && (previous_frames_played_valid)) { + uint64_t frames_played_in_this_interval = frames_played - previous_frames_played; + uint64_t interval = local_time_now - previous_frames_played_time; + conn->frame_rate = (1e9 * frames_played_in_this_interval) / interval; + conn->frame_rate_valid = 1; } + + // uncomment the if statement if your want to get as long a period for + // calculating the frame rate + // if ((status != 0) || (previous_frames_played_valid == 0)) { + // if we have just detected an outputting error, or if we have no + // starting information + previous_frames_played = frames_played; + previous_frames_played_time = local_time_now; + previous_frames_played_valid = 1; + // } } - + // we can now calculate running averages for sync error (frames), corrections (ppm), // insertions plus deletions (ppm), drift (ppm) double moving_average_sync_error = (1.0 * tsum_of_sync_errors) / number_of_statistics; @@ -2830,7 +2845,10 @@ void *player_thread_func(void *arg) { statistics_item("max buffers", "%*" PRIu32 "", 11, maximum_buffer_occupancy); statistics_item("nominal fps", "%*.2f", 11, conn->remote_frame_rate); statistics_item(" actual fps", "%*.2f", 11, conn->input_frame_rate); - statistics_item(" output fps", "%*.2f", 11, conn->frame_rate); + if (conn->frame_rate_valid) + statistics_item(" output fps", "%*.2f", 11, conn->frame_rate); + else + statistics_item(" output fps", " N/A"); statistics_item("source drift ppm", "%*.2f", 16, (conn->local_to_remote_time_gradient - 1.0) * 1000000); statistics_item("drift samples", "%*d", 13, @@ -2838,7 +2856,7 @@ void *player_thread_func(void *arg) { statistics_item( "estimated (unused) correction ppm", "%*.2f", strlen("estimated (unused) correction ppm"), - (conn->frame_rate > 0.0) + (conn->frame_rate_valid != 0) ? ((conn->frame_rate - conn->remote_frame_rate * conn->output_sample_ratio * conn->local_to_remote_time_gradient) * 1000000) / diff --git a/player.h b/player.h index effd8b12..d5719031 100644 --- a/player.h +++ b/player.h @@ -181,7 +181,7 @@ typedef struct { // for holding the output rate information until printed out at the end of a session double frame_rate; - int frame_rate_status; + int frame_rate_valid; // for holding input rate information until printed out at the end of a session From 04240708a948cfb8a8424bb7d8aceaef6359c2f8 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Mon, 8 Nov 2021 10:14:42 +0000 Subject: [PATCH 03/40] Try using the monotonic clock for checking output rate... --- common.c | 70 ++++++++++++++++++++++++++++++++++++++++++++------------ common.h | 1 + player.c | 24 +++++++++---------- player.h | 4 ++-- 4 files changed, 71 insertions(+), 28 deletions(-) diff --git a/common.c b/common.c index 866222c2..b1525a31 100644 --- a/common.c +++ b/common.c @@ -55,9 +55,9 @@ #endif #ifdef COMPILE_FOR_FREEBSD -#include -#include #include +#include +#include #endif #ifdef COMPILE_FOR_OSX @@ -1258,6 +1258,49 @@ uint64_t get_absolute_time_in_fp() { return time_now_fp; } +uint64_t get_monotonic_time_in_ns() { + uint64_t time_now_ns; + +#ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD + struct timespec tn; + // can't use CLOCK_MONOTONIC_RAW as it's not implemented in OpenWrt + // CLOCK_REALTIME because PTP uses it. + clock_gettime(CLOCK_MONOTONIC, &tn); + uint64_t tnnsec = tn.tv_sec; + tnnsec = tnnsec * 1000000000; + uint64_t tnjnsec = tn.tv_nsec; + time_now_ns = tnnsec + tnjnsec; +#endif + +#ifdef COMPILE_FOR_OSX + uint64_t time_now_mach; + uint64_t elapsedNano; + static mach_timebase_info_data_t sTimebaseInfo = {0, 0}; + + // this actually give you a monotonic clock + // see https://news.ycombinator.com/item?id=6303755 + time_now_mach = mach_absolute_time(); + + // If this is the first time we've run, get the timebase. + // We can use denom == 0 to indicate that sTimebaseInfo is + // uninitialised because it makes no sense to have a zero + // denominator in a fraction. + + if (sTimebaseInfo.denom == 0) { + debug(1, "Mac initialise timebase info."); + (void)mach_timebase_info(&sTimebaseInfo); + } + + // Do the maths. We hope that the multiplication doesn't + // overflow; the price you pay for working in fixed point. + + // this gives us nanoseconds + time_now_ns = time_now_mach * sTimebaseInfo.numer / sTimebaseInfo.denom; +#endif + + return time_now_ns; +} + uint64_t get_absolute_time_in_ns() { uint64_t time_now_ns; @@ -1277,6 +1320,7 @@ uint64_t get_absolute_time_in_ns() { uint64_t elapsedNano; static mach_timebase_info_data_t sTimebaseInfo = {0, 0}; + // this actually give you a monotonic clock time_now_mach = mach_absolute_time(); // If this is the first time we've run, get the timebase. @@ -1963,7 +2007,7 @@ int get_device_id(uint8_t *id, int int_length) { t = id; int found = 0; for (ifa = ifaddr; ifa != NULL; ifa = ifa->ifa_next) { - #ifdef AF_PACKET +#ifdef AF_PACKET if ((ifa->ifa_addr) && (ifa->ifa_addr->sa_family == AF_PACKET)) { struct sockaddr_ll *s = (struct sockaddr_ll *)ifa->ifa_addr; if ((strcmp(ifa->ifa_name, "lo") != 0) && (found == 0)) { @@ -1973,25 +2017,23 @@ int get_device_id(uint8_t *id, int int_length) { found = 1; } } - #else - #ifdef AF_LINK - struct sockaddr_dl * sdl = (struct sockaddr_dl *) ifa->ifa_addr; - if ((sdl) && (sdl->sdl_family == AF_LINK)) { +#else +#ifdef AF_LINK + struct sockaddr_dl *sdl = (struct sockaddr_dl *)ifa->ifa_addr; + if ((sdl) && (sdl->sdl_family == AF_LINK)) { if (sdl->sdl_type == IFT_ETHER) { char *s = LLADDR(sdl); for (i = 0; i < sdl->sdl_alen; i++) { - debug(1,"char %d: \"%c\".", i, *s); - *t++ = (uint8_t)*s++; - } + debug(1, "char %d: \"%c\".", i, *s); + *t++ = (uint8_t)*s++; + } found = 1; } } - #endif - #endif - +#endif +#endif } freeifaddrs(ifaddr); } return response; } - diff --git a/common.h b/common.h index 9c3496f6..199b3d41 100644 --- a/common.h +++ b/common.h @@ -381,6 +381,7 @@ double vol2attn(double vol, long max_db, long min_db); // return a time in nanoseconds // uint64_t get_absolute_time_in_fp(void); // obselete uint64_t get_absolute_time_in_ns(void); +uint64_t get_monotonic_time_in_ns(void); // to try and get precise FPS values // time at startup for debugging timing extern uint64_t ns_time_at_startup, ns_time_at_last_debug_message; diff --git a/player.c b/player.c index 74c6eac2..e19e6cab 100644 --- a/player.c +++ b/player.c @@ -1714,12 +1714,11 @@ void player_thread_cleanup_handler(void *arg) { void *player_thread_func(void *arg) { rtsp_conn_info *conn = (rtsp_conn_info *)arg; - + uint64_t previous_frames_played; uint64_t previous_frames_played_time; int previous_frames_played_valid = 0; - // pthread_cleanup_push(player_thread_initial_cleanup_handler, arg); conn->packet_count = 0; conn->packet_count_since_flush = 0; @@ -2787,6 +2786,7 @@ void *player_thread_func(void *arg) { uint64_t frames_sent_for_play; int status = -1; if ((config.output->delay) && (config.no_sync == 0) && (config.output->rate_info)) { + uint64_t monotonic_time_now = get_monotonic_time_in_ns(); uint64_t elapsed_play_time; // dummy status = config.output->rate_info(&elapsed_play_time, &frames_sent_for_play); uint64_t frames_played = frames_sent_for_play - play_samples - current_delay; @@ -2794,22 +2794,22 @@ void *player_thread_func(void *arg) { // last time the rate_info call was made. Thus, the frame rate should be valid. if ((status == 0) && (previous_frames_played_valid)) { uint64_t frames_played_in_this_interval = frames_played - previous_frames_played; - uint64_t interval = local_time_now - previous_frames_played_time; + uint64_t interval = monotonic_time_now - previous_frames_played_time; conn->frame_rate = (1e9 * frames_played_in_this_interval) / interval; conn->frame_rate_valid = 1; } - + // uncomment the if statement if your want to get as long a period for // calculating the frame rate // if ((status != 0) || (previous_frames_played_valid == 0)) { - // if we have just detected an outputting error, or if we have no - // starting information - previous_frames_played = frames_played; - previous_frames_played_time = local_time_now; - previous_frames_played_valid = 1; - // } + // if we have just detected an outputting error, or if we have no + // starting information + previous_frames_played = frames_played; + previous_frames_played_time = monotonic_time_now; + previous_frames_played_valid = 1; + //} } - + // we can now calculate running averages for sync error (frames), corrections (ppm), // insertions plus deletions (ppm), drift (ppm) double moving_average_sync_error = (1.0 * tsum_of_sync_errors) / number_of_statistics; @@ -2931,7 +2931,7 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c else sw_min_db = (sw_max_db - desired_sw_range); } else { - hw_min_db = hw_max_db - desired_range_db; + hw_min_db = hw_max_db - desired_range_db; } } } else { diff --git a/player.h b/player.h index d5719031..41cdc5bd 100644 --- a/player.h +++ b/player.h @@ -109,7 +109,6 @@ typedef enum { remote_control_stream } airplay_stream_c; // "c" for category - #ifdef CONFIG_AIRPLAY_2 typedef enum { ts_ntp, ts_ptp } timing_t; typedef enum { ap_1, ap_2 } airplay_t; @@ -296,7 +295,8 @@ typedef struct { clock_status_t clock_status; airplay_stream_c - airplay_stream_category; // is it a remote control stream or a normal "full service" stream? (will be unspecified if not build for AirPlay 2) + airplay_stream_category; // is it a remote control stream or a normal "full service" stream? + // (will be unspecified if not build for AirPlay 2) #ifdef CONFIG_AIRPLAY_2 char *airplay_gid; // UUID in the Bonjour advertisement -- if NULL, the group UUID is the same as From c0a3dacf304346d17efa3544dd8ca93c6ab5ede2 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Wed, 17 Nov 2021 10:35:21 +0000 Subject: [PATCH 04/40] Working to check for divide / mod by 0's --- activity_monitor.c | 4 +- audio_alsa.c | 63 ++++++----- audio_pw.c | 268 +++++++++++++++++++++------------------------ mdns.h | 2 +- player.c | 2 +- player.h | 2 +- ptp-utilities.c | 4 +- rtp.c | 28 ++--- rtsp.c | 60 ++++++---- shairport.c | 2 +- 10 files changed, 221 insertions(+), 214 deletions(-) diff --git a/activity_monitor.c b/activity_monitor.c index 2f5efddf..1d301c49 100644 --- a/activity_monitor.c +++ b/activity_monitor.c @@ -169,11 +169,11 @@ void *activity_monitor_thread_code(void *arg) { do { switch (state) { case am_inactive: - debug(2,"am_state: am_inactive"); + debug(2, "am_state: am_inactive"); while (player_state != ps_active) pthread_cond_wait(&activity_monitor_cv, &activity_monitor_mutex); state = am_active; - debug(2,"am_state: going active"); + debug(2, "am_state: going active"); break; case am_active: // debug(1,"am_state: am_active"); diff --git a/audio_alsa.c b/audio_alsa.c index 32f6c90f..a2126c36 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -60,7 +60,8 @@ static int play(void *buf, int samples); static void stop(void); static void flush(void); int delay(long *the_delay); -int get_frames_sent_for_output(__attribute__ ((unused)) uint64_t *elapsed_time, uint64_t *frames_sent_to_dac); +int get_frames_sent_for_output(__attribute__((unused)) uint64_t *elapsed_time, + uint64_t *frames_sent_to_dac); // int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played); void *alsa_buffer_monitor_thread_code(void *arg); @@ -89,8 +90,9 @@ audio_output audio_alsa = { .flush = &flush, .delay = &delay, .play = &play, - .rate_info = &get_frames_sent_for_output, // will also include frames of silence sent to stop standby mode -// .rate_info = NULL, + .rate_info = &get_frames_sent_for_output, // will also include frames of silence sent to stop + // standby mode + // .rate_info = NULL, .mute = NULL, // a function will be provided if it can, and is allowed to, // do hardware mute .volume = NULL, // a function will be provided if it can do hardware volume @@ -247,7 +249,8 @@ static snd_pcm_uframes_t period_size_requested, buffer_size_requested; static int set_period_size_request, set_buffer_size_request; static uint64_t frames_sent_for_playing; -static int output_error_occurred; // set to true if an underrun or similar has occurred since last requested +static int output_error_occurred; // set to true if an underrun or similar has occurred since last + // requested static void help(void) { printf(" -d output-device set the output device, default is \"default\".\n" @@ -432,7 +435,7 @@ int actual_open_alsa_device(int do_auto_setup) { char errorstring[1024]; strerror_r(-ret, (char *)errorstring, sizeof(errorstring)); die("alsa: error %d (\"%s\") opening alsa device \"%s\".", ret, (char *)errorstring, - alsa_out_dev); + alsa_out_dev); } return ret; } @@ -469,14 +472,14 @@ int actual_open_alsa_device(int do_auto_setup) { ret = snd_pcm_hw_params_set_access(alsa_handle, alsa_params, access); if (ret < 0) { die("audio_alsa: Access type not available for device \"%s\": %s", alsa_out_dev, - snd_strerror(ret)); + snd_strerror(ret)); return ret; } ret = snd_pcm_hw_params_set_channels(alsa_handle, alsa_params, 2); if (ret < 0) { die("audio_alsa: Channels count (2) not available for device \"%s\": %s", alsa_out_dev, - snd_strerror(ret)); + snd_strerror(ret)); return ret; } @@ -522,7 +525,7 @@ int actual_open_alsa_device(int do_auto_setup) { sps_format_description_string(config.output_format)); } else { die("audio_alsa: Could not automatically set the output format for device \"%s\": %s", - alsa_out_dev, snd_strerror(ret)); + alsa_out_dev, snd_strerror(ret)); return ret; } } @@ -532,8 +535,8 @@ int actual_open_alsa_device(int do_auto_setup) { config.output_rate; // this is the requested rate -- it'll be changed to the actual rate ret = snd_pcm_hw_params_set_rate_near(alsa_handle, alsa_params, &actual_sample_rate, &dir); if (ret < 0) { - die("audio_alsa: The frame rate of %i frames per second is not available for playback: %s", config.output_rate, - snd_strerror(ret)); + die("audio_alsa: The frame rate of %i frames per second is not available for playback: %s", + config.output_rate, snd_strerror(ret)); return ret; } } else { @@ -552,7 +555,9 @@ int actual_open_alsa_device(int do_auto_setup) { if (ret == 0) { speed_found = 1; if (actual_sample_rate != speeds[i]) - die("The output DAC can not be set to %d frames per second (fps). The nearest speed available is %d fps.", speeds[i], actual_sample_rate); + die("The output DAC can not be set to %d frames per second (fps). The nearest speed " + "available is %d fps.", + speeds[i], actual_sample_rate); } else { i++; } @@ -562,7 +567,7 @@ int actual_open_alsa_device(int do_auto_setup) { debug(1, "alsa: output speed chosen is %d.", config.output_rate); } else { die("audio_alsa: Could not automatically set the output rate for device \"%s\": %s", - alsa_out_dev, snd_strerror(ret)); + alsa_out_dev, snd_strerror(ret)); return ret; } } @@ -607,7 +612,7 @@ int actual_open_alsa_device(int do_auto_setup) { ret = snd_pcm_hw_params(alsa_handle, alsa_params); if (ret < 0) { die("audio_alsa: Unable to set hw parameters for device \"%s\": %s.", alsa_out_dev, - snd_strerror(ret)); + snd_strerror(ret)); return ret; } @@ -774,10 +779,11 @@ int actual_open_alsa_device(int do_auto_setup) { break; } - if (snd_pcm_hw_params_get_rate_numden(alsa_params, &uval, &uval2) == 0) + if ((snd_pcm_hw_params_get_rate_numden(alsa_params, &uval, &uval2) == 0) && (uval2 != 0)) + // watch for a divide by zero too! debug(log_level, " precise (rational) rate = %.3f frames per second (i.e. %u/%u).", uval, - uval2, ((double)uval) / uval2); - else + uval2, ((double)uval) / uval2); + else debug(log_level, " precise (rational) rate information unavailable."); snd_pcm_hw_params_get_period_time(alsa_params, &uval, &dir); @@ -1283,16 +1289,16 @@ static int init(int argc, char **argv) { warn("Invalid use_precision_timing option choice \"%s\". It should be " "\"yes\", \"auto\" or \"no\". " "It remains set to \"%s\".", - config.use_precision_timing == YNA_NO - ? "no" - : config.use_precision_timing == YNA_AUTO ? "auto" : "yes"); + config.use_precision_timing == YNA_NO ? "no" + : config.use_precision_timing == YNA_AUTO ? "auto" + : "yes"); } } debug(1, "alsa: disable_standby_mode is \"%s\".", - config.disable_standby_mode == disable_standby_off - ? "never" - : config.disable_standby_mode == disable_standby_always ? "always" : "auto"); + config.disable_standby_mode == disable_standby_off ? "never" + : config.disable_standby_mode == disable_standby_always ? "always" + : "auto"); debug(1, "alsa: disable_standby_mode_silence_threshold is %f seconds.", config.disable_standby_mode_silence_threshold); debug(1, "alsa: disable_standby_mode_silence_scan_interval is %f seconds.", @@ -1624,18 +1630,19 @@ int delay(long *the_delay) { return ret; } -int get_frames_sent_for_output(__attribute__ ((unused)) uint64_t *elapsed_time, uint64_t *frames_sent_to_dac) { +int get_frames_sent_for_output(__attribute__((unused)) uint64_t *elapsed_time, + uint64_t *frames_sent_to_dac) { int ret = 0; pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 0); *frames_sent_to_dac = frames_sent_for_playing; if (alsa_handle == NULL) ret = ENODEV; - else + else ret = output_error_occurred; // will be zero unless an error occurred - output_error_occurred = 0; // reset it. + output_error_occurred = 0; // reset it. debug_mutex_unlock(&alsa_mutex, 0); pthread_cleanup_pop(0); - return ret; + return ret; } /* @@ -1682,8 +1689,8 @@ int do_play(void *buf, int samples) { stall_monitor_frame_count += samples; frames_sent_for_playing += samples; } else { - output_error_occurred = -ret; // note than an output error has occurred - if (ret == -EPIPE) { /* underrun */ + output_error_occurred = -ret; // note than an output error has occurred + if (ret == -EPIPE) { /* underrun */ // It could be that the DAC was in the SND_PCM_STATE_XRUN state before // sending the samples to be output. If so, it will still be in diff --git a/audio_pw.c b/audio_pw.c index 58a5fd72..f25c0456 100644 --- a/audio_pw.c +++ b/audio_pw.c @@ -29,8 +29,8 @@ #include #include -#include #include +#include #include #include @@ -61,26 +61,26 @@ struct pw_data { } data; -static void on_core_info(__attribute__((unused)) void *userdata, const struct pw_core_info *info) -{ - debug(1, "pw: remote %"PRIu32" is named \"%s\"", info->id, info->name); +static void on_core_info(__attribute__((unused)) void *userdata, const struct pw_core_info *info) { + debug(1, "pw: remote %" PRIu32 " is named \"%s\"", info->id, info->name); } -static void on_core_error(__attribute__((unused)) void *userdata, uint32_t id, int seq, int res, const char *message) -{ - warn("pw: remote error: id=%"PRIu32" seq:%d res:%d (%s): %s", id, seq, res, spa_strerror(res), message); +static void on_core_error(__attribute__((unused)) void *userdata, uint32_t id, int seq, int res, + const char *message) { + warn("pw: remote error: id=%" PRIu32 " seq:%d res:%d (%s): %s", id, seq, res, spa_strerror(res), + message); } static const struct pw_core_events core_events = { - PW_VERSION_CORE_EVENTS, - .info = on_core_info, - .error = on_core_error, + PW_VERSION_CORE_EVENTS, + .info = on_core_info, + .error = on_core_error, }; -static void registry_event_global(__attribute__((unused)) void *userdata, uint32_t id, - __attribute__((unused)) uint32_t permissions, const char *type, __attribute__((unused)) uint32_t version, - const struct spa_dict *props) -{ +static void registry_event_global(__attribute__((unused)) void *userdata, uint32_t id, + __attribute__((unused)) uint32_t permissions, const char *type, + __attribute__((unused)) uint32_t version, + const struct spa_dict *props) { const struct spa_dict_item *item; const char *name, *media_class; @@ -91,49 +91,47 @@ static void registry_event_global(__attribute__((unused)) void *userdata, uint3 if (!name || !media_class) return; - debug(1, "pw: registry: id=%"PRIu32" type=%s name=\"%s\" media_class=\"%s\"", id, type, name, media_class); + debug(1, "pw: registry: id=%" PRIu32 " type=%s name=\"%s\" media_class=\"%s\"", id, type, name, + media_class); - spa_dict_for_each(item, props) { - debug(1, "pw: \t\t%s = \"%s\"", item->key, item->value); - } + spa_dict_for_each(item, props) { debug(1, "pw: \t\t%s = \"%s\"", item->key, item->value); } } } -static void registry_event_global_remove(__attribute__((unused)) void *userdata, uint32_t id) -{ - debug(1, "pw: registry: remove id=%"PRIu32"", id); +static void registry_event_global_remove(__attribute__((unused)) void *userdata, uint32_t id) { + debug(1, "pw: registry: remove id=%" PRIu32 "", id); } static const struct pw_registry_events registry_events = { - PW_VERSION_REGISTRY_EVENTS, - .global = registry_event_global, - .global_remove = registry_event_global_remove, + PW_VERSION_REGISTRY_EVENTS, + .global = registry_event_global, + .global_remove = registry_event_global_remove, }; -static void on_state_changed(void *userdata, enum pw_stream_state old, enum pw_stream_state state, const char *error) -{ +static void on_state_changed(void *userdata, enum pw_stream_state old, enum pw_stream_state state, + const char *error) { struct pw_data *pipewire = userdata; - debug(1, "pw: stream state changed %s -> %s", pw_stream_state_as_string(old), pw_stream_state_as_string(state)); + debug(1, "pw: stream state changed %s -> %s", pw_stream_state_as_string(old), + pw_stream_state_as_string(state)); if (state == PW_STREAM_STATE_STREAMING) - debug(1, "pw: stream node %"PRIu32"", pw_stream_get_node_id(pipewire->stream)); + debug(1, "pw: stream node %" PRIu32 "", pw_stream_get_node_id(pipewire->stream)); if (state == PW_STREAM_STATE_ERROR) - debug(1, "pw: stream node %"PRIu32" error: %s", pw_stream_get_node_id(pipewire->stream), error); + debug(1, "pw: stream node %" PRIu32 " error: %s", pw_stream_get_node_id(pipewire->stream), + error); pw_thread_loop_signal(pipewire->mainloop, 0); } -static void on_process(void *userdata) -{ +static void on_process(void *userdata) { struct pw_data *pipewire = userdata; pw_thread_loop_signal(pipewire->mainloop, 0); } -static void on_drained(void *userdata) -{ +static void on_drained(void *userdata) { struct pw_data *pipewire = userdata; pw_stream_set_active(pipewire->stream, false); @@ -142,10 +140,10 @@ static void on_drained(void *userdata) } static const struct pw_stream_events stream_events = { - PW_VERSION_STREAM_EVENTS, - .state_changed = on_state_changed, - .process = on_process, - .drained = on_drained, + PW_VERSION_STREAM_EVENTS, + .state_changed = on_state_changed, + .process = on_process, + .drained = on_drained, }; static void deinit() { @@ -157,7 +155,7 @@ static void deinit() { } if (data.registry) { - pw_proxy_destroy((struct pw_proxy*)data.registry); + pw_proxy_destroy((struct pw_proxy *)data.registry); data.registry = NULL; } @@ -182,10 +180,10 @@ static void deinit() { } } -static int init(__attribute__((unused)) int argc, __attribute__((unused)) char** argv) { +static int init(__attribute__((unused)) int argc, __attribute__((unused)) char **argv) { struct pw_loop *loop; - struct pw_properties* props; + struct pw_properties *props; // set up default values first config.audio_backend_buffer_desired_length = 0.35; @@ -197,13 +195,9 @@ static int init(__attribute__((unused)) int argc, __attribute__((unused)) char** debug(1, "pw: compiled with libpipewire %s", pw_get_headers_version()); debug(1, "pw: linked with libpipewire: %s", pw_get_library_version()); - data.props = pw_properties_new( - PW_KEY_MEDIA_TYPE, "Audio", - PW_KEY_MEDIA_CATEGORY, "Playback", - PW_KEY_MEDIA_ROLE, "Music", - PW_KEY_APP_NAME, "shairport-sync", - PW_KEY_NODE_NAME, "shairport-sync", - NULL); + data.props = pw_properties_new(PW_KEY_MEDIA_TYPE, "Audio", PW_KEY_MEDIA_CATEGORY, "Playback", + PW_KEY_MEDIA_ROLE, "Music", PW_KEY_APP_NAME, "shairport-sync", + PW_KEY_NODE_NAME, "shairport-sync", NULL); if (!data.props) { deinit(); @@ -268,77 +262,75 @@ static int init(__attribute__((unused)) int argc, __attribute__((unused)) char** static enum spa_audio_format sps_format_to_spa_format(sps_format_t sps_format) { switch (sps_format) { - case SPS_FORMAT_S8: - return SPA_AUDIO_FORMAT_S8; - case SPS_FORMAT_U8: - return SPA_AUDIO_FORMAT_U8; - case SPS_FORMAT_S16: - return SPA_AUDIO_FORMAT_S16; - case SPS_FORMAT_S16_LE: - return SPA_AUDIO_FORMAT_S16_LE; - case SPS_FORMAT_S16_BE: - return SPA_AUDIO_FORMAT_S16_BE; - case SPS_FORMAT_S24: - return SPA_AUDIO_FORMAT_S24_32; - case SPS_FORMAT_S24_LE: - return SPA_AUDIO_FORMAT_S24_32_LE; - case SPS_FORMAT_S24_BE: - return SPA_AUDIO_FORMAT_S24_32_BE; - case SPS_FORMAT_S24_3LE: - return SPA_AUDIO_FORMAT_S24_LE; - case SPS_FORMAT_S24_3BE: - return SPA_AUDIO_FORMAT_S24_BE; - case SPS_FORMAT_S32: - return SPA_AUDIO_FORMAT_S32; - case SPS_FORMAT_S32_LE: - return SPA_AUDIO_FORMAT_S32_LE; - case SPS_FORMAT_S32_BE: - return SPA_AUDIO_FORMAT_S32_BE; + case SPS_FORMAT_S8: + return SPA_AUDIO_FORMAT_S8; + case SPS_FORMAT_U8: + return SPA_AUDIO_FORMAT_U8; + case SPS_FORMAT_S16: + return SPA_AUDIO_FORMAT_S16; + case SPS_FORMAT_S16_LE: + return SPA_AUDIO_FORMAT_S16_LE; + case SPS_FORMAT_S16_BE: + return SPA_AUDIO_FORMAT_S16_BE; + case SPS_FORMAT_S24: + return SPA_AUDIO_FORMAT_S24_32; + case SPS_FORMAT_S24_LE: + return SPA_AUDIO_FORMAT_S24_32_LE; + case SPS_FORMAT_S24_BE: + return SPA_AUDIO_FORMAT_S24_32_BE; + case SPS_FORMAT_S24_3LE: + return SPA_AUDIO_FORMAT_S24_LE; + case SPS_FORMAT_S24_3BE: + return SPA_AUDIO_FORMAT_S24_BE; + case SPS_FORMAT_S32: + return SPA_AUDIO_FORMAT_S32; + case SPS_FORMAT_S32_LE: + return SPA_AUDIO_FORMAT_S32_LE; + case SPS_FORMAT_S32_BE: + return SPA_AUDIO_FORMAT_S32_BE; - case SPS_FORMAT_UNKNOWN: - case SPS_FORMAT_AUTO: - case SPS_FORMAT_INVALID: - default: - return SPA_AUDIO_FORMAT_S16; + case SPS_FORMAT_UNKNOWN: + case SPS_FORMAT_AUTO: + case SPS_FORMAT_INVALID: + default: + return SPA_AUDIO_FORMAT_S16; } } -static int spa_format_samplesize(enum spa_audio_format audio_format) -{ - switch(audio_format) { - case SPA_AUDIO_FORMAT_S8: - case SPA_AUDIO_FORMAT_U8: - return 1; - case SPA_AUDIO_FORMAT_S16: - return 2; - case SPA_AUDIO_FORMAT_S24: - return 3; - case SPA_AUDIO_FORMAT_S24_32: - case SPA_AUDIO_FORMAT_S32: - return 4; - default: - die("pw: unhandled spa_audio_format: %d", audio_format); - return -1; +static int spa_format_samplesize(enum spa_audio_format audio_format) { + switch (audio_format) { + case SPA_AUDIO_FORMAT_S8: + case SPA_AUDIO_FORMAT_U8: + return 1; + case SPA_AUDIO_FORMAT_S16: + return 2; + case SPA_AUDIO_FORMAT_S24: + return 3; + case SPA_AUDIO_FORMAT_S24_32: + case SPA_AUDIO_FORMAT_S32: + return 4; + default: + die("pw: unhandled spa_audio_format: %d", audio_format); + return -1; } } -static const char* spa_format_to_str(enum spa_audio_format audio_format) -{ - switch(audio_format) { - case SPA_AUDIO_FORMAT_U8: - return "u8"; - case SPA_AUDIO_FORMAT_S8: - return "s8"; - case SPA_AUDIO_FORMAT_S16: - return "s16"; - case SPA_AUDIO_FORMAT_S24: - case SPA_AUDIO_FORMAT_S24_32: - return "s24"; - case SPA_AUDIO_FORMAT_S32: - return "s32"; - default: - die("pw: unhandled spa_audio_format: %d", audio_format); - return "(invalid)"; +static const char *spa_format_to_str(enum spa_audio_format audio_format) { + switch (audio_format) { + case SPA_AUDIO_FORMAT_U8: + return "u8"; + case SPA_AUDIO_FORMAT_S8: + return "s8"; + case SPA_AUDIO_FORMAT_S16: + return "s16"; + case SPA_AUDIO_FORMAT_S24: + case SPA_AUDIO_FORMAT_S24_32: + return "s24"; + case SPA_AUDIO_FORMAT_S32: + return "s32"; + default: + die("pw: unhandled spa_audio_format: %d", audio_format); + return "(invalid)"; } } @@ -368,13 +360,11 @@ static void start(int sample_rate, int sample_format) { debug(1, "pw: format: %s", spa_format_to_str(data.format)); debug(1, "pw: samplesize: %d", spa_format_samplesize(data.format)); debug(1, "pw: stride: %d", data.stride); - debug(1, "pw: latency: %d samples (%.3fs)", nom, (double)nom/data.rate); + if (data.rate != 0) + debug(1, "pw: latency: %d samples (%.3fs)", nom, (double)nom / data.rate); - info = SPA_AUDIO_INFO_RAW_INIT( - .flags = SPA_AUDIO_FLAG_NONE, - .format = data.format, - .rate = data.rate, - .channels = data.channels); + info = SPA_AUDIO_INFO_RAW_INIT(.flags = SPA_AUDIO_FLAG_NONE, .format = data.format, + .rate = data.rate, .channels = data.channels); params[0] = spa_format_audio_raw_build(&pod_builder, SPA_PARAM_EnumFormat, &info); @@ -385,15 +375,13 @@ static void start(int sample_rate, int sample_format) { die("pw: pw_stream_new() failed: %m"); } - debug(1, "pw: connecting stream: target_id=%"PRIu32"", PW_ID_ANY); + debug(1, "pw: connecting stream: target_id=%" PRIu32 "", PW_ID_ANY); pw_stream_add_listener(data.stream, &data.stream_listener, &stream_events, &data); - ret = pw_stream_connect(data.stream, - PW_DIRECTION_OUTPUT, - PW_ID_ANY, - PW_STREAM_FLAG_INACTIVE | PW_STREAM_FLAG_AUTOCONNECT | PW_STREAM_FLAG_MAP_BUFFERS, - params, 1); + ret = pw_stream_connect( + data.stream, PW_DIRECTION_OUTPUT, PW_ID_ANY, + PW_STREAM_FLAG_INACTIVE | PW_STREAM_FLAG_AUTOCONNECT | PW_STREAM_FLAG_MAP_BUFFERS, params, 1); if (ret < 0) { deinit(); @@ -408,12 +396,12 @@ static void start(int sample_rate, int sample_format) { debug(1, "pw: stream properties:"); pstate = NULL; while ((key = pw_properties_iterate(props, &pstate)) != NULL && - (val = pw_properties_get(props, key)) != NULL) { + (val = pw_properties_get(props, key)) != NULL) { debug(1, "pw: \t%s = \"%s\"", key, val); } } - while(1) { + while (1) { enum pw_stream_state stream_state = pw_stream_get_state(data.stream, NULL); if (stream_state == PW_STREAM_STATE_PAUSED) break; @@ -483,19 +471,17 @@ static int play(void *buf, int samples) { return 0; } -audio_output audio_pw = { - .name = "pw", - .help = NULL, - .init = &init, - .deinit = &deinit, - .prepare = NULL, - .start = &start, - .stop = &stop, - .is_running = NULL, - .flush = &flush, - .delay = NULL, - .play = &play, - .volume = NULL, - .parameters = NULL, - .mute = NULL -}; +audio_output audio_pw = {.name = "pw", + .help = NULL, + .init = &init, + .deinit = &deinit, + .prepare = NULL, + .start = &start, + .stop = &stop, + .is_running = NULL, + .flush = &flush, + .delay = NULL, + .play = &play, + .volume = NULL, + .parameters = NULL, + .mute = NULL}; diff --git a/mdns.h b/mdns.h index d43b9513..f69179ef 100644 --- a/mdns.h +++ b/mdns.h @@ -20,7 +20,7 @@ typedef struct { char *name; int (*mdns_register)(char *ap1name, char *ap2name, int port, char **txt_records, char **secondary_txt_records); - int (*mdns_update)(char **txt_records, char **secondary_txt_records); + int (*mdns_update)(char **txt_records, char **secondary_txt_records); void (*mdns_unregister)(void); void (*mdns_dacp_monitor_start)(); void (*mdns_dacp_monitor_set_id)(const char *); diff --git a/player.c b/player.c index 67a0c086..07ee1123 100644 --- a/player.c +++ b/player.c @@ -1732,7 +1732,7 @@ void *player_thread_func(void *arg) { conn->flush_rtp_timestamp = 0; // it seems this number has a special significance -- it seems to // be used as a null operand, so we'll use it like that too conn->fix_volume = 0x10000; - + #ifdef CONFIG_AIRPLAY_2 conn->ap2_flush_requested = 0; conn->ap2_flush_from_valid = 0; diff --git a/player.h b/player.h index 41cdc5bd..526572ef 100644 --- a/player.h +++ b/player.h @@ -170,7 +170,7 @@ typedef struct { player_watchdog_thread; // buffers to delete on exit - signed short *tbuf; + int32_t *tbuf; int32_t *sbuf; char *outbuf; diff --git a/ptp-utilities.c b/ptp-utilities.c index 0f80e913..7019187e 100644 --- a/ptp-utilities.c +++ b/ptp-utilities.c @@ -33,8 +33,8 @@ #include #include #ifdef COMPILE_FOR_FREEBSD -#include #include +#include #endif #define __STDC_FORMAT_MACROS #include "common.h" @@ -86,7 +86,7 @@ int ptp_get_clock_info(uint64_t *actual_clock_id, uint64_t *time_of_sample, uint if (actual_clock_id != NULL) *actual_clock_id = nqptp_data.master_clock_id; if (time_of_sample != NULL) - *time_of_sample = nqptp_data.local_time; + *time_of_sample = nqptp_data.local_time; if (raw_offset != NULL) *raw_offset = nqptp_data.local_to_master_time_offset; if (mastership_start_time != NULL) diff --git a/rtp.c b/rtp.c index db8ff2f0..41b07371 100644 --- a/rtp.c +++ b/rtp.c @@ -290,8 +290,8 @@ void *rtp_control_receiver(void *arg) { obfp += 2; }; *obfp = 0; - - + + // get raw timestamp information // I think that a good way to understand these timestamps is that // (1) the rtlt below is the timestamp of the frame that should be playing at the @@ -302,19 +302,19 @@ void *rtp_control_receiver(void *arg) { // Thus, (3) the latency can be calculated by subtracting the second from the // first. // There must be more to it -- there something missing. - + // In addition, it seems that if the value of the short represented by the second // pair of bytes in the packet is 7 // then an extra time lag is expected to be added, presumably by // the AirPort Express. - + // Best guess is that this delay is 11,025 frames. - + uint32_t rtlt = nctohl(&packet[4]); // raw timestamp less latency uint32_t rt = nctohl(&packet[16]); // raw timestamp - + uint32_t fl = nctohs(&packet[2]); // - + debug(1,"Sync Packet of %d bytes received: \"%s\", flags: %d, timestamps %u and %u, giving a latency of %d frames.",plen,obf,fl,rt,rtlt,rt-rtlt); //debug(1,"Monotonic timestamps are: %" PRId64 " and %" PRId64 " @@ -1564,7 +1564,8 @@ void rtp_ap2_control_handler_cleanup_handler(void *arg) { rtsp_conn_info *conn = (rtsp_conn_info *)arg; debug(2, "Connection %d: AP2 Control Receiver Cleanup.", conn->connection_number); close(conn->ap2_control_socket); - debug(2, "Connection %d: UDP control port %u closed.", conn->connection_number, conn->local_ap2_control_port); + debug(2, "Connection %d: UDP control port %u closed.", conn->connection_number, + conn->local_ap2_control_port); conn->ap2_control_socket = 0; conn->ap2_remote_control_socket_addr_length = 0; // indicates to the control receiver thread that the socket address need to be @@ -2030,7 +2031,8 @@ void rtp_buffered_audio_cleanup_handler(__attribute__((unused)) void *arg) { debug(2, "Buffered Audio Receiver Cleanup Start."); rtsp_conn_info *conn = (rtsp_conn_info *)arg; close(conn->buffered_audio_socket); - debug(2, "Connection %d: TCP Buffered Audio port closed: %u.", conn->connection_number, conn->local_buffered_audio_port); + debug(2, "Connection %d: TCP Buffered Audio port closed: %u.", conn->connection_number, + conn->local_buffered_audio_port); conn->buffered_audio_socket = 0; debug(2, "Buffered Audio Receiver Cleanup Done."); } @@ -2119,10 +2121,10 @@ void *rtp_buffered_audio_processor(void *arg) { // (does nothing if called twice during the course of one program execution) // deprecated in ffmpeg 4.0 and later... but still needed in ffmpeg 3.6 / ubuntu 18 - #pragma GCC diagnostic push - #pragma GCC diagnostic ignored "-Wdeprecated-declarations" +#pragma GCC diagnostic push +#pragma GCC diagnostic ignored "-Wdeprecated-declarations" avcodec_register_all(); - #pragma GCC diagnostic pop +#pragma GCC diagnostic pop AVCodec *codec = avcodec_find_decoder(AV_CODEC_ID_AAC); if (codec == NULL) { @@ -2221,7 +2223,7 @@ void *rtp_buffered_audio_processor(void *arg) { ssize_t data_remaining; uint32_t seq_no; // audio packet number // uint32_t previous_seq_no = 0; - int new_buffer_needed; + int new_buffer_needed = 0; ssize_t nread; int finished = 0; diff --git a/rtsp.c b/rtsp.c index f1efb1cd..5f9fa9ab 100644 --- a/rtsp.c +++ b/rtsp.c @@ -655,7 +655,8 @@ void cancel_all_RTSP_threads(airplay_stream_c stream_category, int except_this_o debug_mutex_lock(&conns_lock, 1000000, 3); int i; for (i = 0; i < nconns; i++) { - if ((conns[i] != NULL) && (conns[i]->running != 0) && (conns[i]->connection_number != except_this_one) && + if ((conns[i] != NULL) && (conns[i]->running != 0) && + (conns[i]->connection_number != except_this_one) && ((stream_category == unspecified_stream_category) || (stream_category == conns[i]->airplay_stream_category))) { pthread_cancel(conns[i]->thread); @@ -663,7 +664,8 @@ void cancel_all_RTSP_threads(airplay_stream_c stream_category, int except_this_o } } for (i = 0; i < nconns; i++) { - if ((conns[i] != NULL) && (conns[i]->running != 0) && (conns[i]->connection_number != except_this_one) && + if ((conns[i] != NULL) && (conns[i]->running != 0) && + (conns[i]->connection_number != except_this_one) && ((stream_category == unspecified_stream_category) || (stream_category == conns[i]->airplay_stream_category))) { pthread_join(conns[i]->thread, NULL); @@ -1303,7 +1305,8 @@ int msg_write_response(rtsp_conn_info *conn, rtsp_message *resp) { char *string; }; - struct response_t responses[] = {{200, "OK"}, {400, "Bad Request"}, {403, "Unauthorized"}, {501, "Not Implemented"}}; + struct response_t responses[] = { + {200, "OK"}, {400, "Bad Request"}, {403, "Unauthorized"}, {501, "Not Implemented"}}; int found = 0; char *respcode_text = "Unauthorized"; for (i = 0; i < sizeof(responses) / sizeof(struct response_t); i++) { @@ -1662,13 +1665,14 @@ void handle_flushbuffered(rtsp_conn_info *conn, rtsp_message *req, rtsp_message } void handle_setrate(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { - debug(3, "Connection %d: SETRATE %s : Content-Length %d", conn->connection_number, - req->path, req->contentlength); + debug(3, "Connection %d: SETRATE %s : Content-Length %d", conn->connection_number, req->path, + req->contentlength); debug_log_rtsp_message(2, "SETRATE request -- unimplemented", req); resp->respcode = 501; // Not Implemented } -void handle_unimplemented_ap1(__attribute((unused)) rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { +void handle_unimplemented_ap1(__attribute((unused)) rtsp_conn_info *conn, rtsp_message *req, + rtsp_message *resp) { debug_log_rtsp_message(1, "request not recognised for AirPlay 1 operation", req); resp->respcode = 501; } @@ -1783,8 +1787,9 @@ void handle_get(__attribute((unused)) rtsp_conn_info *conn, __attribute((unused) req->contentlength); resp->respcode = 500; } -void handle_post(__attribute((unused)) rtsp_conn_info *conn, __attribute((unused)) rtsp_message *req, - __attribute((unused)) rtsp_message *resp) { +void handle_post(__attribute((unused)) rtsp_conn_info *conn, + __attribute((unused)) rtsp_message *req, + __attribute((unused)) rtsp_message *resp) { debug(1, "Connection %d: POST %s Content-Length %d", conn->connection_number, req->path, req->contentlength); resp->respcode = 500; @@ -2321,7 +2326,7 @@ void teardown_phase_one(rtsp_conn_info *conn) { // this can be called more than once on the same connection -- // by the player itself but also by the play seesion being killed if (conn->player_thread) { - player_stop(conn); // this nulls the player_thread + player_stop(conn); // this nulls the player_thread activity_monitor_signify_activity(0); // inactive, and should be after command_stop() } if (conn->session_key) { @@ -2347,7 +2352,8 @@ void teardown_phase_two(rtsp_conn_info *conn) { if (conn->event_socket) { close(conn->event_socket); conn->event_socket = 0; - debug(2, "Connection %d: closing TCP event port %u.", conn->connection_number, conn->local_event_port); + debug(2, "Connection %d: closing TCP event port %u.", conn->connection_number, + conn->local_event_port); } // if we are closing a PTP stream only, do this @@ -2365,7 +2371,6 @@ void teardown_phase_two(rtsp_conn_info *conn) { } } - void handle_teardown_2(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message *req, rtsp_message *resp) { @@ -2661,7 +2666,8 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) conn->connection_number, err); } - debug(2, "Connection %d: TCP PTP event port opened: %u.", conn->connection_number, conn->local_event_port); + debug(2, "Connection %d: TCP PTP event port opened: %u.", conn->connection_number, + conn->local_event_port); if (conn->rtp_event_thread != NULL) debug(1, "previous rtp_event_thread allocation not freed, it seems."); @@ -2707,7 +2713,8 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) conn->connection_number, err); } - debug(1, "Connection %d: TCP Remote Control event port opened: %u.", conn->connection_number, conn->local_event_port); + debug(1, "Connection %d: TCP Remote Control event port opened: %u.", + conn->connection_number, conn->local_event_port); if (conn->rtp_event_thread != NULL) debug(1, "previous rtp_event_thread allocation not freed, it seems."); conn->rtp_event_thread = malloc(sizeof(pthread_t)); @@ -2759,7 +2766,8 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) if (err) { die("Error %d: could not find a UDP port to use as an ap2_control port", err); } - debug(2, "Connection %d: UDP control port opened: %u.", conn->connection_number, conn->local_ap2_control_port); + debug(2, "Connection %d: UDP control port opened: %u.", conn->connection_number, + conn->local_ap2_control_port); pthread_create(&conn->rtp_ap2_control_thread, NULL, &rtp_ap2_control_receiver, (void *)conn); @@ -2829,7 +2837,8 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) if (err) { die("Error %d: could not find a UDP port to use as a realtime_audio port", err); } - debug(2, "Connection %d: UDP realtime audio port opened: %u.", conn->connection_number, conn->local_realtime_audio_port); + debug(2, "Connection %d: UDP realtime audio port opened: %u.", conn->connection_number, + conn->local_realtime_audio_port); pthread_create(&conn->rtp_realtime_audio_thread, NULL, &rtp_realtime_audio_receiver, (void *)conn); @@ -2892,7 +2901,8 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) conn->connection_number, err); } - debug(2, "Connection %d: TCP Buffered Audio port opened: %u.", conn->connection_number, conn->local_buffered_audio_port); + debug(2, "Connection %d: TCP Buffered Audio port opened: %u.", conn->connection_number, + conn->local_buffered_audio_port); // hack. conn->max_frames_per_packet = 352; // number of audio frames per packet. @@ -3117,7 +3127,8 @@ void handle_set_parameter_parameter(rtsp_conn_info *conn, rtsp_message *req, conn->initial_airplay_volume = volume; conn->initial_airplay_volume_set = 1; } - } else if (strncmp(cp, "progress: ", strlen("progress: ")) == 0) { // this can be sent even when metadata is not solicited + } else if (strncmp(cp, "progress: ", strlen("progress: ")) == + 0) { // this can be sent even when metadata is not solicited #ifdef CONFIG_METADATA char *progress = cp + strlen("progress: "); @@ -3126,8 +3137,7 @@ void handle_set_parameter_parameter(rtsp_conn_info *conn, rtsp_message *req, send_ssnc_metadata('prgr', progress, strlen(progress), 1); #endif - } else - { + } else { debug(1, "Connection %d, unrecognised parameter: \"%s\" (%d)\n", conn->connection_number, cp, strlen(cp)); } @@ -3381,6 +3391,8 @@ void metadata_multicast_process(uint32_t type, uint32_t code, char *data, uint32 // ("ssnc", "chnk", packet_ix, packet_counts, packet_tag, packet_type, chunked_data) uint32_t chunk_ix = 0; + if (config.metadata_sockmsglength == 24) + die("A divide by zero almost occurred (config.metadata_sockmsglength = 24)."); uint32_t chunk_total = length / (config.metadata_sockmsglength - 24); if (chunk_total * (config.metadata_sockmsglength - 24) < length) { chunk_total++; @@ -3673,7 +3685,8 @@ void metadata_init(void) { if (pthread_create(&metadata_thread, NULL, metadata_thread_function, NULL) != 0) debug(1, "Failed to create metadata thread!"); - if (pthread_create(&metadata_multicast_thread, NULL, metadata_multicast_thread_function, NULL) != 0) + if (pthread_create(&metadata_multicast_thread, NULL, metadata_multicast_thread_function, + NULL) != 0) debug(1, "Failed to create metadata multicast thread!"); } #ifdef CONFIG_METADATA_HUB @@ -4513,8 +4526,6 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { close(conn->audio_socket); } - - if (conn->fd > 0) { debug(3, "Connection %d terminating: closing fd %d.", conn->connection_number, conn->fd); close(conn->fd); @@ -4674,7 +4685,9 @@ static void *rtsp_conversation_thread_func(void *pconn) { } } if (method_selected == 0) { - debug(1, "Connection %d: Unrecognised and unhandled rtsp request \"%s\". HTTP Response Code 501 (\"Not Implemented\") returned.", + debug(1, + "Connection %d: Unrecognised and unhandled rtsp request \"%s\". HTTP Response Code " + "501 (\"Not Implemented\") returned.", conn->connection_number, req->method); int y = req->contentlength; @@ -4693,7 +4706,6 @@ static void *rtsp_conversation_thread_func(void *pconn) { *obfp = 0; debug(1, "Content: \"%s\".", obf); } - } } debug(debug_level, "Connection %d: RTSP Response:", conn->connection_number); diff --git a/shairport.c b/shairport.c index edcb5e10..4afcd86f 100644 --- a/shairport.c +++ b/shairport.c @@ -1920,7 +1920,7 @@ int main(int argc, char **argv) { /* Version check should be the very first call because it makes sure that important subsystems are initialized. #define NEED_LIBGCRYPT_VERSION to the minimum required version. */ - + #define NEED_LIBGCRYPT_VERSION "1.5.4" if (!gcry_check_version(NEED_LIBGCRYPT_VERSION)) { From 5f8e6e3989b55134c9894db100bf297f81d47f0e Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Sat, 20 Nov 2021 12:14:23 +0000 Subject: [PATCH 05/40] attempt to increase the precision of the FPS timing --- audio.h | 4 +- audio_alsa.c | 45 +++++++++- player.c | 228 ++++++++++++++++++++++++++------------------------- 3 files changed, 162 insertions(+), 115 deletions(-) diff --git a/audio.h b/audio.h index 3413250c..f6ddcd9e 100644 --- a/audio.h +++ b/audio.h @@ -39,8 +39,8 @@ typedef struct { // will change dynamically, so keep watching it. Implemented in ALSA only. // returns a negative error code if there's a problem int (*delay)(long *the_delay); // snd_pcm_sframes_t is a signed long - int (*rate_info)(uint64_t *elapsed_time, - uint64_t *frames_played); // use this to get the true rate of the DAC + int (*rate_info)(uint64_t *measurement_time, uint64_t *delay, + uint64_t *frames_sent_to_dac); // use this to get the true rate of the DAC // may be NULL, in which case soft volume is applied void (*volume)(double vol); diff --git a/audio_alsa.c b/audio_alsa.c index a2126c36..0e4268ed 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -60,8 +60,7 @@ static int play(void *buf, int samples); static void stop(void); static void flush(void); int delay(long *the_delay); -int get_frames_sent_for_output(__attribute__((unused)) uint64_t *elapsed_time, - uint64_t *frames_sent_to_dac); +int play_stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac); // int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played); void *alsa_buffer_monitor_thread_code(void *arg); @@ -90,7 +89,7 @@ audio_output audio_alsa = { .flush = &flush, .delay = &delay, .play = &play, - .rate_info = &get_frames_sent_for_output, // will also include frames of silence sent to stop + .rate_info = &play_stats, // will also include frames of silence sent to stop // standby mode // .rate_info = NULL, .mute = NULL, // a function will be provided if it can, and is allowed to, @@ -1630,6 +1629,46 @@ int delay(long *the_delay) { return ret; } +int play_stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac) { + // returns 0 if the device is in a valid state -- SND_PCM_STATE_RUNNING or + // SND_PCM_STATE_PREPARED + // or SND_PCM_STATE_DRAINING + // and returns the actual delay if running or 0 if prepared in *the_delay + + // otherwise return an error code + // the error code could be a Unix errno code or a snderror code, or + // the sps_extra_code_output_stalled or the + // sps_extra_code_output_state_cannot_make_ready codes + int ret = 0; + *the_delay = 0; + + int oldState; + + snd_pcm_state_t state; + snd_pcm_sframes_t my_delay = 0; // this initialisation is to silence a clang warning + + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable + pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 0); + + if (alsa_handle == NULL) { + ret = ENODEV; + } else { + *the_time = get_absolute_time_in_ns(); + ret = delay_and_status(&state, &my_delay, NULL); + } + if (ret == 0) + ret = output_error_occurred; // will be zero unless an error like an underrun occurred + output_error_occurred = 0; // reset it. + if (frames_sent_to_dac != NULL) + *frames_sent_to_dac = frames_sent_for_playing; + debug_mutex_unlock(&alsa_mutex, 0); + pthread_cleanup_pop(0); + pthread_setcancelstate(oldState, NULL); + uint64_t hd = my_delay; // note: snd_pcm_sframes_t is a long + *the_delay = hd; + return ret; +} + int get_frames_sent_for_output(__attribute__((unused)) uint64_t *elapsed_time, uint64_t *frames_sent_to_dac) { int ret = 0; diff --git a/player.c b/player.c index 07ee1123..c6e360e8 100644 --- a/player.c +++ b/player.c @@ -2287,6 +2287,124 @@ void *player_thread_func(void *arg) { if (conn->buffer_occupancy > maximum_buffer_occupancy) maximum_buffer_occupancy = conn->buffer_occupancy; + + + // now, before outputting anything to the output device, check the stats + + if (play_number % print_interval == 0) { + + // here, calculate the input and output frame rates, where possible, even if statistics + // have not been requested + // this is to calculate them in case they are needed by the D-Bus interface or elsewhere. + + if (conn->input_frame_rate_starting_point_is_valid) { + uint64_t elapsed_reception_time, frames_received; + elapsed_reception_time = + conn->frames_inward_measurement_time - conn->frames_inward_measurement_start_time; + frames_received = conn->frames_inward_frames_received_at_measurement_time - + conn->frames_inward_frames_received_at_measurement_start_time; + conn->input_frame_rate = + (1.0E9 * frames_received) / + elapsed_reception_time; // an IEEE double calculation with two 64-bit integers + } else { + conn->input_frame_rate = 0.0; + } + + int stats_status = -1; + if ((config.output->delay) && (config.no_sync == 0) && (config.output->rate_info)) { + uint64_t frames_sent_for_play; + uint64_t measurement_time; + uint64_t actual_delay; + stats_status = config.output->rate_info(&measurement_time, &actual_delay, &frames_sent_for_play); + // debug(1,"actual_delay: %" PRIu64 ", frames_sent_for_play: %" PRIu64 ", frames_played: %" PRIu64 ".", actual_delay, frames_sent_for_play, frames_sent_for_play - actual_delay); + uint64_t frames_played = frames_sent_for_play - actual_delay; + // If the status is zero, it means that there were no output problems since the + // last time the rate_info call was made. Thus, the frame rate should be valid. + if ((stats_status == 0) && (previous_frames_played_valid)) { + uint64_t frames_played_in_this_interval = frames_played - previous_frames_played; + uint64_t interval = measurement_time - previous_frames_played_time; + // debug(1,"frames_played_in_this_interval: %" PRIu64 ", interval: %" PRIu64 ".", frames_played_in_this_interval, interval); + conn->frame_rate = (1e9 * frames_played_in_this_interval) / interval; + conn->frame_rate_valid = 1; + } + + // uncomment the if statement if your want to get as long a period for + // calculating the frame rate as possible without an output break or error + // if ((status != 0) || (previous_frames_played_valid == 0)) { + // if we have just detected an outputting error, or if we have no + // starting information + if (stats_status != 0) + conn->frame_rate_valid = 0; + previous_frames_played = frames_played; + previous_frames_played_time = measurement_time; + previous_frames_played_valid = 1; + // } + } + + // we can now calculate running averages for sync error (frames), corrections (ppm), + // insertions plus deletions (ppm), drift (ppm) + double moving_average_sync_error = (1.0 * tsum_of_sync_errors) / number_of_statistics; + double moving_average_correction = (1.0 * tsum_of_corrections) / number_of_statistics; + double moving_average_insertions_plus_deletions = + (1.0 * tsum_of_insertions_and_deletions) / number_of_statistics; + // double moving_average_drift = (1.0 * tsum_of_drifts) / number_of_statistics; + // if ((play_number/print_interval)%20==0) + // figure out which statistics profile to use, depending on the kind of stream + + if (config.statistics_requested) { + + if (at_least_one_frame_seen) { + do { + line_of_stats[0] = '\0'; + statistics_column = 0; + was_a_previous_column = 0; + statistics_item("sync error ms", "%*.2f", 13, + 1000 * moving_average_sync_error / config.output_rate); + statistics_item("net sync ppm", "%*.1f", 12, + moving_average_correction * 1000000 / + (352 * conn->output_sample_ratio)); + statistics_item("all sync ppm", "%*.1f", 12, + moving_average_insertions_plus_deletions * 1000000 / + (352 * conn->output_sample_ratio)); + statistics_item(" packets", "%*d", 11, play_number); + statistics_item("missing", "%*" PRIu64 "", 7, conn->missing_packets); + statistics_item(" late", "%*" PRIu64 "", 6, conn->late_packets); + statistics_item("too late", "%*" PRIu64 "", 8, conn->too_late_packets); + statistics_item("resend reqs", "%*" PRIu64 "", 11, conn->resend_requests); + statistics_item("min DAC queue", "%*" PRIu64 "", 13, minimum_dac_queue_size); + statistics_item("min buffers", "%*" PRIu32 "", 11, minimum_buffer_occupancy); + statistics_item("max buffers", "%*" PRIu32 "", 11, maximum_buffer_occupancy); + statistics_item("nominal fps", "%*.2f", 11, conn->remote_frame_rate); + statistics_item(" actual fps", "%*.2f", 11, conn->input_frame_rate); + if (conn->frame_rate_valid) + statistics_item(" output fps", "%*.2f", 11, conn->frame_rate); + else + statistics_item(" output fps", " N/A"); + statistics_item("source drift ppm", "%*.2f", 16, + (conn->local_to_remote_time_gradient - 1.0) * 1000000); + statistics_item("drift samples", "%*d", 13, + conn->local_to_remote_time_gradient_sample_count); + statistics_item( + "estimated (unused) correction ppm", "%*.2f", + strlen("estimated (unused) correction ppm"), + (conn->frame_rate_valid != 0) + ? ((conn->frame_rate - conn->remote_frame_rate * conn->output_sample_ratio * + conn->local_to_remote_time_gradient) * + 1000000) / + conn->frame_rate + : 0.0); + statistics_row++; + inform(line_of_stats); + } while (statistics_row < 2); + } else { + inform("No frames received in the last sampling interval."); + } + } + minimum_dac_queue_size = UINT64_MAX; // hack reset + maximum_buffer_occupancy = INT32_MIN; // can't be less than this + minimum_buffer_occupancy = INT32_MAX; // can't be more than this + at_least_one_frame_seen = 0; + } // here, we want to check (a) if we are meant to do synchronisation, // (b) if we have a delay procedure, (c) if we can get the delay. @@ -2771,116 +2889,6 @@ void *player_thread_func(void *arg) { number_of_statistics++; } } - if (play_number % print_interval == 0) { - - // here, calculate the input and output frame rates, where possible, even if statistics - // have not been requested - // this is to calculate them in case they are needed by the D-Bus interface or elsewhere. - - if (conn->input_frame_rate_starting_point_is_valid) { - uint64_t elapsed_reception_time, frames_received; - elapsed_reception_time = - conn->frames_inward_measurement_time - conn->frames_inward_measurement_start_time; - frames_received = conn->frames_inward_frames_received_at_measurement_time - - conn->frames_inward_frames_received_at_measurement_start_time; - conn->input_frame_rate = - (1.0E9 * frames_received) / - elapsed_reception_time; // an IEEE double calculation with two 64-bit integers - } else { - conn->input_frame_rate = 0.0; - } - - uint64_t frames_sent_for_play; - int status = -1; - if ((config.output->delay) && (config.no_sync == 0) && (config.output->rate_info)) { - uint64_t monotonic_time_now = get_monotonic_time_in_ns(); - uint64_t elapsed_play_time; // dummy - status = config.output->rate_info(&elapsed_play_time, &frames_sent_for_play); - uint64_t frames_played = frames_sent_for_play - play_samples - current_delay; - // If the status is zero, it means that there were no output problems since the - // last time the rate_info call was made. Thus, the frame rate should be valid. - if ((status == 0) && (previous_frames_played_valid)) { - uint64_t frames_played_in_this_interval = frames_played - previous_frames_played; - uint64_t interval = monotonic_time_now - previous_frames_played_time; - conn->frame_rate = (1e9 * frames_played_in_this_interval) / interval; - conn->frame_rate_valid = 1; - } - - // uncomment the if statement if your want to get as long a period for - // calculating the frame rate - // if ((status != 0) || (previous_frames_played_valid == 0)) { - // if we have just detected an outputting error, or if we have no - // starting information - previous_frames_played = frames_played; - previous_frames_played_time = monotonic_time_now; - previous_frames_played_valid = 1; - //} - } - - // we can now calculate running averages for sync error (frames), corrections (ppm), - // insertions plus deletions (ppm), drift (ppm) - double moving_average_sync_error = (1.0 * tsum_of_sync_errors) / number_of_statistics; - double moving_average_correction = (1.0 * tsum_of_corrections) / number_of_statistics; - double moving_average_insertions_plus_deletions = - (1.0 * tsum_of_insertions_and_deletions) / number_of_statistics; - // double moving_average_drift = (1.0 * tsum_of_drifts) / number_of_statistics; - // if ((play_number/print_interval)%20==0) - // figure out which statistics profile to use, depending on the kind of stream - - if (config.statistics_requested) { - - if (at_least_one_frame_seen) { - do { - line_of_stats[0] = '\0'; - statistics_column = 0; - was_a_previous_column = 0; - statistics_item("sync error ms", "%*.2f", 13, - 1000 * moving_average_sync_error / config.output_rate); - statistics_item("net sync ppm", "%*.1f", 12, - moving_average_correction * 1000000 / - (352 * conn->output_sample_ratio)); - statistics_item("all sync ppm", "%*.1f", 12, - moving_average_insertions_plus_deletions * 1000000 / - (352 * conn->output_sample_ratio)); - statistics_item(" packets", "%*d", 11, play_number); - statistics_item("missing", "%*" PRIu64 "", 7, conn->missing_packets); - statistics_item(" late", "%*" PRIu64 "", 6, conn->late_packets); - statistics_item("too late", "%*" PRIu64 "", 8, conn->too_late_packets); - statistics_item("resend reqs", "%*" PRIu64 "", 11, conn->resend_requests); - statistics_item("min DAC queue", "%*" PRIu64 "", 13, minimum_dac_queue_size); - statistics_item("min buffers", "%*" PRIu32 "", 11, minimum_buffer_occupancy); - statistics_item("max buffers", "%*" PRIu32 "", 11, maximum_buffer_occupancy); - statistics_item("nominal fps", "%*.2f", 11, conn->remote_frame_rate); - statistics_item(" actual fps", "%*.2f", 11, conn->input_frame_rate); - if (conn->frame_rate_valid) - statistics_item(" output fps", "%*.2f", 11, conn->frame_rate); - else - statistics_item(" output fps", " N/A"); - statistics_item("source drift ppm", "%*.2f", 16, - (conn->local_to_remote_time_gradient - 1.0) * 1000000); - statistics_item("drift samples", "%*d", 13, - conn->local_to_remote_time_gradient_sample_count); - statistics_item( - "estimated (unused) correction ppm", "%*.2f", - strlen("estimated (unused) correction ppm"), - (conn->frame_rate_valid != 0) - ? ((conn->frame_rate - conn->remote_frame_rate * conn->output_sample_ratio * - conn->local_to_remote_time_gradient) * - 1000000) / - conn->frame_rate - : 0.0); - statistics_row++; - inform(line_of_stats); - } while (statistics_row < 2); - } else { - inform("No frames received in the last sampling interval."); - } - } - minimum_dac_queue_size = UINT64_MAX; // hack reset - maximum_buffer_occupancy = INT32_MIN; // can't be less than this - minimum_buffer_occupancy = INT32_MAX; // can't be more than this - at_least_one_frame_seen = 0; - } } } } From cd9da86fc30de35cc5f32640c9a2a83f787ed8ce Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Sat, 20 Nov 2021 13:59:16 +0000 Subject: [PATCH 06/40] Add a 'stats' function to the audio back ends to replace the 'rate_info' function. Zero all except the alsa back end. --- audio.h | 2 +- audio_alsa.c | 6 +++--- audio_ao.c | 1 + audio_dummy.c | 1 + audio_jack.c | 1 + audio_pa.c | 1 + audio_pipe.c | 1 + audio_pw.c | 1 + audio_sndio.c | 1 + audio_soundio.c | 1 + audio_stdout.c | 1 + player.c | 8 ++++---- 12 files changed, 17 insertions(+), 8 deletions(-) diff --git a/audio.h b/audio.h index f6ddcd9e..ad574adb 100644 --- a/audio.h +++ b/audio.h @@ -39,7 +39,7 @@ typedef struct { // will change dynamically, so keep watching it. Implemented in ALSA only. // returns a negative error code if there's a problem int (*delay)(long *the_delay); // snd_pcm_sframes_t is a signed long - int (*rate_info)(uint64_t *measurement_time, uint64_t *delay, + int (*stats)(uint64_t *measurement_time, uint64_t *delay, uint64_t *frames_sent_to_dac); // use this to get the true rate of the DAC // may be NULL, in which case soft volume is applied diff --git a/audio_alsa.c b/audio_alsa.c index 0e4268ed..3fcbde66 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -60,7 +60,7 @@ static int play(void *buf, int samples); static void stop(void); static void flush(void); int delay(long *the_delay); -int play_stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac); +int stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac); // int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played); void *alsa_buffer_monitor_thread_code(void *arg); @@ -89,7 +89,7 @@ audio_output audio_alsa = { .flush = &flush, .delay = &delay, .play = &play, - .rate_info = &play_stats, // will also include frames of silence sent to stop + .stats = &stats, // will also include frames of silence sent to stop // standby mode // .rate_info = NULL, .mute = NULL, // a function will be provided if it can, and is allowed to, @@ -1629,7 +1629,7 @@ int delay(long *the_delay) { return ret; } -int play_stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac) { +int stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac) { // returns 0 if the device is in a valid state -- SND_PCM_STATE_RUNNING or // SND_PCM_STATE_PREPARED // or SND_PCM_STATE_DRAINING diff --git a/audio_ao.c b/audio_ao.c index 38953b69..40a94fdc 100644 --- a/audio_ao.c +++ b/audio_ao.c @@ -135,6 +135,7 @@ audio_output audio_ao = {.name = "ao", .is_running = NULL, .flush = NULL, .delay = NULL, + .stats = NULL, .play = &play, .volume = NULL, .parameters = NULL, diff --git a/audio_dummy.c b/audio_dummy.c index 5d16bf95..70ea755e 100644 --- a/audio_dummy.c +++ b/audio_dummy.c @@ -58,6 +58,7 @@ audio_output audio_dummy = {.name = "dummy", .is_running = NULL, .flush = NULL, .delay = NULL, + .stats = NULL, .play = &play, .volume = NULL, .parameters = NULL, diff --git a/audio_jack.c b/audio_jack.c index 21c3e543..e87e16a3 100644 --- a/audio_jack.c +++ b/audio_jack.c @@ -63,6 +63,7 @@ audio_output audio_jack = {.name = "jack", .is_running = NULL, .flush = &jack_flush, .delay = &jack_delay, + .stats = NULL, .play = &play, .volume = NULL, .parameters = NULL, diff --git a/audio_pa.c b/audio_pa.c index 951860be..9d37bc60 100644 --- a/audio_pa.c +++ b/audio_pa.c @@ -315,6 +315,7 @@ audio_output audio_pa = {.name = "pa", .is_running = NULL, .flush = &flush, .delay = &pa_delay, + .stats = NULL, .play = &play, .volume = NULL, .parameters = NULL, diff --git a/audio_pipe.c b/audio_pipe.c index a7925fbc..fcece96b 100644 --- a/audio_pipe.c +++ b/audio_pipe.c @@ -151,6 +151,7 @@ audio_output audio_pipe = {.name = "pipe", .is_running = NULL, .flush = NULL, .delay = NULL, + .stats = NULL, .play = &play, .volume = NULL, .parameters = NULL, diff --git a/audio_pw.c b/audio_pw.c index f25c0456..52e6a882 100644 --- a/audio_pw.c +++ b/audio_pw.c @@ -481,6 +481,7 @@ audio_output audio_pw = {.name = "pw", .is_running = NULL, .flush = &flush, .delay = NULL, + .stats = NULL, .play = &play, .volume = NULL, .parameters = NULL, diff --git a/audio_sndio.c b/audio_sndio.c index f8582c8a..e32c1f4d 100644 --- a/audio_sndio.c +++ b/audio_sndio.c @@ -49,6 +49,7 @@ audio_output audio_sndio = {.name = "sndio", .is_running = NULL, .flush = &flush, .delay = &delay, + .stats = NULL, .play = &play, .volume = NULL, .parameters = NULL, diff --git a/audio_soundio.c b/audio_soundio.c index 501c6db2..28108a9f 100644 --- a/audio_soundio.c +++ b/audio_soundio.c @@ -216,6 +216,7 @@ audio_output audio_soundio = {.name = "soundio", .is_running = NULL, .flush = &flush, .delay = NULL, + .stats = NULL, .play = &play, .volume = NULL, .parameters = ¶meters, diff --git a/audio_stdout.c b/audio_stdout.c index 8b37883e..61fdc744 100644 --- a/audio_stdout.c +++ b/audio_stdout.c @@ -84,6 +84,7 @@ audio_output audio_stdout = {.name = "stdout", .is_running = NULL, .flush = NULL, .delay = NULL, + .stats = NULL, .play = &play, .volume = NULL, .parameters = NULL, diff --git a/player.c b/player.c index c6e360e8..bc2956e0 100644 --- a/player.c +++ b/player.c @@ -2019,7 +2019,7 @@ void *player_thread_func(void *arg) { } } else { #endif - if (config.output->delay) { + if (config.output->stats) { if (config.no_sync == 0) statistics_print_profile = ap1_synced_statistics_print_profile; else @@ -2311,15 +2311,15 @@ void *player_thread_func(void *arg) { } int stats_status = -1; - if ((config.output->delay) && (config.no_sync == 0) && (config.output->rate_info)) { + if ((config.output->delay) && (config.no_sync == 0) && (config.output->stats)) { uint64_t frames_sent_for_play; uint64_t measurement_time; uint64_t actual_delay; - stats_status = config.output->rate_info(&measurement_time, &actual_delay, &frames_sent_for_play); + stats_status = config.output->stats(&measurement_time, &actual_delay, &frames_sent_for_play); // debug(1,"actual_delay: %" PRIu64 ", frames_sent_for_play: %" PRIu64 ", frames_played: %" PRIu64 ".", actual_delay, frames_sent_for_play, frames_sent_for_play - actual_delay); uint64_t frames_played = frames_sent_for_play - actual_delay; // If the status is zero, it means that there were no output problems since the - // last time the rate_info call was made. Thus, the frame rate should be valid. + // last time the stats call was made. Thus, the frame rate should be valid. if ((stats_status == 0) && (previous_frames_played_valid)) { uint64_t frames_played_in_this_interval = frames_played - previous_frames_played; uint64_t interval = measurement_time - previous_frames_played_time; From 1797b4164b94f479fdf39474cc0ab2347312a999 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Sat, 20 Nov 2021 14:18:13 +0000 Subject: [PATCH 07/40] Check for the stats function before allowing expanded stats info. --- player.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/player.c b/player.c index bc2956e0..a8fd3a54 100644 --- a/player.c +++ b/player.c @@ -1999,7 +1999,7 @@ void *player_thread_func(void *arg) { #ifdef CONFIG_AIRPLAY_2 if (conn->airplay_type == ap_2) { if (conn->airplay_stream_type == realtime_stream) { - if (config.output->delay) { + if (config.output->stats) { if (config.no_sync == 0) statistics_print_profile = ap2_realtime_synced_stream_statistics_print_profile; else @@ -2008,7 +2008,7 @@ void *player_thread_func(void *arg) { statistics_print_profile = ap2_realtime_nodelay_stream_statistics_print_profile; } } else { - if (config.output->delay) { + if (config.output->stats) { if (config.no_sync == 0) statistics_print_profile = ap2_buffered_synced_stream_statistics_print_profile; else From 881a5ca25e2ed899cc25d65f47412a3f7d5042b5 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Sat, 20 Nov 2021 15:11:57 +0000 Subject: [PATCH 08/40] Don't display output FPS, as it's not clear how accurate it is... --- player.c | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/player.c b/player.c index a8fd3a54..41010643 100644 --- a/player.c +++ b/player.c @@ -1545,7 +1545,9 @@ int *statistics_print_profile; // these arrays specify which of the statistics specified by the statistics_item calls will actually // be printed -- 1 means print, 0 means skip -int ap1_synced_statistics_print_profile[] = {1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1}; + +// don't display output fps -- not sure how accurate it is (change item 14 and 17 to 1 to restore) +int ap1_synced_statistics_print_profile[] = {1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 0, 1, 1, 0}; int ap1_nosync_statistics_print_profile[] = {1, 0, 0, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 0, 1, 1, 0}; int ap1_nodelay_statistics_print_profile[] = {0, 0, 0, 1, 1, 1, 1, 1, 0, 1, 1, 1, 1, 0, 1, 1, 0}; @@ -1556,8 +1558,9 @@ int ap2_realtime_nosync_stream_statistics_print_profile[] = {1, 0, 0, 1, 1, 1, 1 int ap2_realtime_nodelay_stream_statistics_print_profile[] = {0, 0, 0, 1, 1, 1, 1, 1, 0, 1, 1, 0, 0, 0, 0, 0, 0}; +// don't display output fps -- not sure how accurate it is (change item 14 1 to restore) int ap2_buffered_synced_stream_statistics_print_profile[] = {1, 1, 1, 1, 0, 0, 0, 0, 1, - 1, 1, 0, 0, 1, 0, 0, 0}; + 1, 1, 0, 0, 0, 0, 0, 0}; int ap2_buffered_nosync_stream_statistics_print_profile[] = {1, 0, 0, 1, 0, 0, 0, 0, 1, 1, 1, 0, 0, 0, 0, 0, 0}; int ap2_buffered_nodelay_stream_statistics_print_profile[] = {0, 0, 0, 1, 0, 0, 0, 0, 0, From 14bfba27242545c7c3aa426528da730ab05a7e05 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Sun, 21 Nov 2021 21:47:32 +0000 Subject: [PATCH 09/40] Add code to check divisions and mods for a potrntial divide by zero problem. MAy cause SPS to terminate but leave a log message. --- audio.h | 2 +- audio_alsa.c | 12 +-- audio_sndio.c | 7 ++ audio_soundio.c | 2 + common.c | 26 ++++-- dacp.c | 14 +-- player.c | 244 +++++++++++++++++++++++++++--------------------- player.h | 1 + rtp.c | 16 +++- shairport.c | 15 ++- 10 files changed, 208 insertions(+), 131 deletions(-) diff --git a/audio.h b/audio.h index ad574adb..25742d7b 100644 --- a/audio.h +++ b/audio.h @@ -40,7 +40,7 @@ typedef struct { // returns a negative error code if there's a problem int (*delay)(long *the_delay); // snd_pcm_sframes_t is a signed long int (*stats)(uint64_t *measurement_time, uint64_t *delay, - uint64_t *frames_sent_to_dac); // use this to get the true rate of the DAC + uint64_t *frames_sent_to_dac); // use this to get the true rate of the DAC // may be NULL, in which case soft volume is applied void (*volume)(double vol); diff --git a/audio_alsa.c b/audio_alsa.c index 3fcbde66..caaad899 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -89,9 +89,9 @@ audio_output audio_alsa = { .flush = &flush, .delay = &delay, .play = &play, - .stats = &stats, // will also include frames of silence sent to stop - // standby mode - // .rate_info = NULL, + .stats = &stats, // will also include frames of silence sent to stop + // standby mode + // .rate_info = NULL, .mute = NULL, // a function will be provided if it can, and is allowed to, // do hardware mute .volume = NULL, // a function will be provided if it can do hardware volume @@ -781,8 +781,8 @@ int actual_open_alsa_device(int do_auto_setup) { if ((snd_pcm_hw_params_get_rate_numden(alsa_params, &uval, &uval2) == 0) && (uval2 != 0)) // watch for a divide by zero too! debug(log_level, " precise (rational) rate = %.3f frames per second (i.e. %u/%u).", uval, - uval2, ((double)uval) / uval2); - else + uval2, ((double)uval) / uval2); + else debug(log_level, " precise (rational) rate information unavailable."); snd_pcm_hw_params_get_period_time(alsa_params, &uval, &dir); @@ -1570,7 +1570,7 @@ int precision_delay_and_status(snd_pcm_state_t *state, snd_pcm_sframes_t *delay, ((uint64_t)frames_played_since_last_interrupt_sized != frames_played_since_last_interrupt)) debug(1, - "overflow resizing frames_played_since_last_interrupt % " PRIx64 + "overflow resizing frames_played_since_last_interrupt %" PRIx64 " to frames_played_since_last_interrupt %lx.", frames_played_since_last_interrupt, frames_played_since_last_interrupt_sized); delay_temp = delay_temp - frames_played_since_last_interrupt_sized; diff --git a/audio_sndio.c b/audio_sndio.c index e32c1f4d..f710e200 100644 --- a/audio_sndio.c +++ b/audio_sndio.c @@ -204,12 +204,19 @@ static int init(int argc, char **argv) { framesize = par.bps * par.pchan; config.output_rate = par.rate; + if (par.rate == 0) { + die("sndio: par.rate set to zero."); + } + config.audio_backend_buffer_desired_length = 1.0 * par.bufsz / par.rate; config.audio_backend_latency_offset = 0; sio_onmove(hdl, onmove_cb, NULL); pthread_mutex_unlock(&sndio_mutex); + if (framesize == 0) { + die("sndio: framesize set to zero."); + } return 0; } diff --git a/audio_soundio.c b/audio_soundio.c index 28108a9f..ccf44bf7 100644 --- a/audio_soundio.c +++ b/audio_soundio.c @@ -22,6 +22,8 @@ static void write_callback(struct SoundIoOutStream *outstream, int frame_count_m char *read_ptr = soundio_ring_buffer_read_ptr(ring_buffer); int fill_bytes = soundio_ring_buffer_fill_count(ring_buffer); + if (outstream->bytes_per_frame == 0) + die("soundio: outstream->bytes_per_frame is zero."); int fill_count = fill_bytes / outstream->bytes_per_frame; debug(3, diff --git a/common.c b/common.c index b1525a31..a947be41 100644 --- a/common.c +++ b/common.c @@ -1187,6 +1187,8 @@ double vol2attn(double vol, long max_db, long min_db) { int i; for (i = 0; i < order; i++) { if (vol <= lines[i][0]) { + if ((-30 - lines[i][0]) == 0.0) + die("(-30 - lines[%d][0]) == 0.0!", i); double tvol = lines[i][1] * (vol - lines[i][0]) / (-30 - lines[i][0]); // debug(1,"On line %d, end point of %f, input vol %f yields output vol // %f.",i,lines[i][1],vol,tvol); @@ -1246,8 +1248,10 @@ uint64_t get_absolute_time_in_fp() { // Do the maths. We hope that the multiplication doesn't // overflow; the price you pay for working in fixed point. - // this gives us nanoseconds - uint64_t time_now_ns = time_now_mach * sTimebaseInfo.numer / sTimebaseInfo.denom; + if (sTimebaseInfo.denom == 0) + die("could not initialise Mac timebase info in get_absolute_time_in_fp().") + // this gives us nanoseconds + uint64_t time_now_ns = time_now_mach * sTimebaseInfo.numer / sTimebaseInfo.denom; // take the units and shift them to the upper half of the fp, and take the nanoseconds, shift them // to the upper half and then divide the result to 1000000000 @@ -1291,11 +1295,14 @@ uint64_t get_monotonic_time_in_ns() { (void)mach_timebase_info(&sTimebaseInfo); } - // Do the maths. We hope that the multiplication doesn't - // overflow; the price you pay for working in fixed point. + if (sTimebaseInfo.denom == 0) + die("could not initialise Mac timebase info in get_monotonic_time_in_ns().") - // this gives us nanoseconds - time_now_ns = time_now_mach * sTimebaseInfo.numer / sTimebaseInfo.denom; + // Do the maths. We hope that the multiplication doesn't + // overflow; the price you pay for working in fixed point. + + // this gives us nanoseconds + time_now_ns = time_now_mach * sTimebaseInfo.numer / sTimebaseInfo.denom; #endif return time_now_ns; @@ -1336,8 +1343,11 @@ uint64_t get_absolute_time_in_ns() { // Do the maths. We hope that the multiplication doesn't // overflow; the price you pay for working in fixed point. - // this gives us nanoseconds - time_now_ns = time_now_mach * sTimebaseInfo.numer / sTimebaseInfo.denom; + if (sTimebaseInfo.denom == 0) + die("could not initialise Mac timebase info in get_absolute_time_in_ns().") + + // this gives us nanoseconds + time_now_ns = time_now_mach * sTimebaseInfo.numer / sTimebaseInfo.denom; #endif return time_now_ns; diff --git a/dacp.c b/dacp.c index 35dbabd0..ef2297e2 100644 --- a/dacp.c +++ b/dacp.c @@ -1351,12 +1351,14 @@ int dacp_set_volume(int32_t vo) { machine_number, highest_other_volume); // set the overall volume to the highest one } - int32_t desired_relative_volume = - (vo * 100 + (highest_other_volume / 2)) / highest_other_volume; - debug(2, "Set our speaker volume relative to the highest volume."); - http_response = dacp_set_speaker_volume( - machine_number, - desired_relative_volume); // set the overall volume to the highest one + if (highest_other_volume != 0) { + int32_t desired_relative_volume = + (vo * 100 + (highest_other_volume / 2)) / highest_other_volume; + debug(2, "Set our speaker volume relative to the highest volume."); + http_response = dacp_set_speaker_volume( + machine_number, + desired_relative_volume); // set the overall volume to the highest one + } } } } diff --git a/player.c b/player.c index 41010643..7a66a1b3 100644 --- a/player.c +++ b/player.c @@ -235,7 +235,10 @@ int audio_packet_decode(short *dest, int *destlen, uint8_t *buf, int len, rtsp_c reply = -1; // output packet is the wrong size } - *destlen = outsize / conn->input_bytes_per_frame; + if (conn->input_bytes_per_frame != 0) + *destlen = outsize / conn->input_bytes_per_frame; + else + die("Unexpectedly, conn->input_bytes_per_frame is zero."); if ((outsize % conn->input_bytes_per_frame) != 0) debug(1, "Number of audio frames (%d) does not correspond exactly to the number of bytes (%d) " @@ -1354,6 +1357,8 @@ static inline int32_t mean_32(int32_t a, int32_t b) { // stuff: 1 means add 1; 0 means do nothing; -1 means remove 1 static int stuff_buffer_basic_32(int32_t *inptr, int length, sps_format_t l_output_format, char *outptr, int stuff, int dither, rtsp_conn_info *conn) { + if (length < 3) + die("buffer length expected to be 3 or more, but is %d!", length); int tstuff = stuff; char *l_outptr = outptr; if ((stuff > 1) || (stuff < -1) || (length < 100)) { @@ -1465,7 +1470,10 @@ int stuff_buffer_soxr_32(int32_t *inptr, int32_t *scratchBuffer, int length, longest_soxr_execution_time = soxr_execution_time; stat_n += 1; double stat_delta = soxr_execution_time - stat_mean; - stat_mean += stat_delta / stat_n; + if (stat_n != 0) + stat_mean += stat_delta / stat_n; + else + warn("calculation error for stat_n"); stat_M2 += stat_delta * (soxr_execution_time - stat_mean); int i; @@ -2071,6 +2079,17 @@ void *player_thread_func(void *arg) { debug(2, "Play begin"); while (1) { + + // check a few parameters to ensure they are non-zero + if (config.output_rate == 0) + debug(1, "config.output_rate is zero!"); + if (conn->output_sample_ratio == 0) + debug(1, "conn->output_sample_ratio is zero!"); + if (conn->input_rate == 0) + debug(1, "conn->input_rate is zero!"); + if (conn->input_bytes_per_frame == 0) + debug(1, "conn->input_bytes_per_frame is zero!"); + pthread_testcancel(); // allow a pthread_cancel request to take effect. abuf_t *inframe = buffer_get_frame(conn); // this has cancellation point(s), but it's not // guaranteed that they'll always be executed @@ -2290,50 +2309,56 @@ void *player_thread_func(void *arg) { if (conn->buffer_occupancy > maximum_buffer_occupancy) maximum_buffer_occupancy = conn->buffer_occupancy; - - + // now, before outputting anything to the output device, check the stats - - if (play_number % print_interval == 0) { - // here, calculate the input and output frame rates, where possible, even if statistics - // have not been requested - // this is to calculate them in case they are needed by the D-Bus interface or elsewhere. + if (play_number % print_interval == 0) { - if (conn->input_frame_rate_starting_point_is_valid) { - uint64_t elapsed_reception_time, frames_received; - elapsed_reception_time = - conn->frames_inward_measurement_time - conn->frames_inward_measurement_start_time; - frames_received = conn->frames_inward_frames_received_at_measurement_time - - conn->frames_inward_frames_received_at_measurement_start_time; - conn->input_frame_rate = - (1.0E9 * frames_received) / - elapsed_reception_time; // an IEEE double calculation with two 64-bit integers - } else { - conn->input_frame_rate = 0.0; - } + // here, calculate the input and output frame rates, where possible, even if statistics + // have not been requested + // this is to calculate them in case they are needed by the D-Bus interface or + // elsewhere. - int stats_status = -1; - if ((config.output->delay) && (config.no_sync == 0) && (config.output->stats)) { - uint64_t frames_sent_for_play; - uint64_t measurement_time; - uint64_t actual_delay; - stats_status = config.output->stats(&measurement_time, &actual_delay, &frames_sent_for_play); - // debug(1,"actual_delay: %" PRIu64 ", frames_sent_for_play: %" PRIu64 ", frames_played: %" PRIu64 ".", actual_delay, frames_sent_for_play, frames_sent_for_play - actual_delay); - uint64_t frames_played = frames_sent_for_play - actual_delay; - // If the status is zero, it means that there were no output problems since the - // last time the stats call was made. Thus, the frame rate should be valid. - if ((stats_status == 0) && (previous_frames_played_valid)) { - uint64_t frames_played_in_this_interval = frames_played - previous_frames_played; - uint64_t interval = measurement_time - previous_frames_played_time; - // debug(1,"frames_played_in_this_interval: %" PRIu64 ", interval: %" PRIu64 ".", frames_played_in_this_interval, interval); - conn->frame_rate = (1e9 * frames_played_in_this_interval) / interval; - conn->frame_rate_valid = 1; + if (conn->input_frame_rate_starting_point_is_valid) { + uint64_t elapsed_reception_time, frames_received; + elapsed_reception_time = + conn->frames_inward_measurement_time - conn->frames_inward_measurement_start_time; + frames_received = conn->frames_inward_frames_received_at_measurement_time - + conn->frames_inward_frames_received_at_measurement_start_time; + conn->input_frame_rate = + (1.0E9 * frames_received) / + elapsed_reception_time; // an IEEE double calculation with two 64-bit integers + } else { + conn->input_frame_rate = 0.0; } - // uncomment the if statement if your want to get as long a period for - // calculating the frame rate as possible without an output break or error - // if ((status != 0) || (previous_frames_played_valid == 0)) { + int stats_status = -1; + if ((config.output->delay) && (config.no_sync == 0) && (config.output->stats)) { + uint64_t frames_sent_for_play; + uint64_t measurement_time; + uint64_t actual_delay; + stats_status = + config.output->stats(&measurement_time, &actual_delay, &frames_sent_for_play); + // debug(1,"actual_delay: %" PRIu64 ", frames_sent_for_play: %" PRIu64 ", + // frames_played: %" PRIu64 ".", actual_delay, frames_sent_for_play, + // frames_sent_for_play - actual_delay); + uint64_t frames_played = frames_sent_for_play - actual_delay; + // If the status is zero, it means that there were no output problems since the + // last time the stats call was made. Thus, the frame rate should be valid. + if ((stats_status == 0) && (previous_frames_played_valid)) { + uint64_t frames_played_in_this_interval = frames_played - previous_frames_played; + uint64_t interval = measurement_time - previous_frames_played_time; + // debug(1,"frames_played_in_this_interval: %" PRIu64 ", interval: %" PRIu64 ".", + // frames_played_in_this_interval, interval); + if (interval != 0) { + conn->frame_rate = (1e9 * frames_played_in_this_interval) / interval; + conn->frame_rate_valid = 1; + } + } + + // uncomment the if statement if your want to get as long a period for + // calculating the frame rate as possible without an output break or error + // if ((status != 0) || (previous_frames_played_valid == 0)) { // if we have just detected an outputting error, or if we have no // starting information if (stats_status != 0) @@ -2341,73 +2366,80 @@ void *player_thread_func(void *arg) { previous_frames_played = frames_played; previous_frames_played_time = measurement_time; previous_frames_played_valid = 1; - // } - } - - // we can now calculate running averages for sync error (frames), corrections (ppm), - // insertions plus deletions (ppm), drift (ppm) - double moving_average_sync_error = (1.0 * tsum_of_sync_errors) / number_of_statistics; - double moving_average_correction = (1.0 * tsum_of_corrections) / number_of_statistics; - double moving_average_insertions_plus_deletions = - (1.0 * tsum_of_insertions_and_deletions) / number_of_statistics; - // double moving_average_drift = (1.0 * tsum_of_drifts) / number_of_statistics; - // if ((play_number/print_interval)%20==0) - // figure out which statistics profile to use, depending on the kind of stream - - if (config.statistics_requested) { - - if (at_least_one_frame_seen) { - do { - line_of_stats[0] = '\0'; - statistics_column = 0; - was_a_previous_column = 0; - statistics_item("sync error ms", "%*.2f", 13, - 1000 * moving_average_sync_error / config.output_rate); - statistics_item("net sync ppm", "%*.1f", 12, - moving_average_correction * 1000000 / - (352 * conn->output_sample_ratio)); - statistics_item("all sync ppm", "%*.1f", 12, - moving_average_insertions_plus_deletions * 1000000 / - (352 * conn->output_sample_ratio)); - statistics_item(" packets", "%*d", 11, play_number); - statistics_item("missing", "%*" PRIu64 "", 7, conn->missing_packets); - statistics_item(" late", "%*" PRIu64 "", 6, conn->late_packets); - statistics_item("too late", "%*" PRIu64 "", 8, conn->too_late_packets); - statistics_item("resend reqs", "%*" PRIu64 "", 11, conn->resend_requests); - statistics_item("min DAC queue", "%*" PRIu64 "", 13, minimum_dac_queue_size); - statistics_item("min buffers", "%*" PRIu32 "", 11, minimum_buffer_occupancy); - statistics_item("max buffers", "%*" PRIu32 "", 11, maximum_buffer_occupancy); - statistics_item("nominal fps", "%*.2f", 11, conn->remote_frame_rate); - statistics_item(" actual fps", "%*.2f", 11, conn->input_frame_rate); - if (conn->frame_rate_valid) - statistics_item(" output fps", "%*.2f", 11, conn->frame_rate); - else - statistics_item(" output fps", " N/A"); - statistics_item("source drift ppm", "%*.2f", 16, - (conn->local_to_remote_time_gradient - 1.0) * 1000000); - statistics_item("drift samples", "%*d", 13, - conn->local_to_remote_time_gradient_sample_count); - statistics_item( - "estimated (unused) correction ppm", "%*.2f", - strlen("estimated (unused) correction ppm"), - (conn->frame_rate_valid != 0) - ? ((conn->frame_rate - conn->remote_frame_rate * conn->output_sample_ratio * - conn->local_to_remote_time_gradient) * - 1000000) / - conn->frame_rate - : 0.0); - statistics_row++; - inform(line_of_stats); - } while (statistics_row < 2); - } else { - inform("No frames received in the last sampling interval."); + // } } + + // we can now calculate running averages for sync error (frames), corrections (ppm), + // insertions plus deletions (ppm), drift (ppm) + double moving_average_sync_error = 0.0; + double moving_average_correction = 0.0; + double moving_average_insertions_plus_deletions = 0.0; + if (number_of_statistics == 0) { + debug(1, "number_of_statistics is zero!"); + } else { + moving_average_sync_error = (1.0 * tsum_of_sync_errors) / number_of_statistics; + moving_average_correction = (1.0 * tsum_of_corrections) / number_of_statistics; + moving_average_insertions_plus_deletions = + (1.0 * tsum_of_insertions_and_deletions) / number_of_statistics; + // double moving_average_drift = (1.0 * tsum_of_drifts) / number_of_statistics; + } + // if ((play_number/print_interval)%20==0) + // figure out which statistics profile to use, depending on the kind of stream + + if (config.statistics_requested) { + + if (at_least_one_frame_seen) { + do { + line_of_stats[0] = '\0'; + statistics_column = 0; + was_a_previous_column = 0; + statistics_item("sync error ms", "%*.2f", 13, + 1000 * moving_average_sync_error / config.output_rate); + statistics_item("net sync ppm", "%*.1f", 12, + moving_average_correction * 1000000 / + (352 * conn->output_sample_ratio)); + statistics_item("all sync ppm", "%*.1f", 12, + moving_average_insertions_plus_deletions * 1000000 / + (352 * conn->output_sample_ratio)); + statistics_item(" packets", "%*d", 11, play_number); + statistics_item("missing", "%*" PRIu64 "", 7, conn->missing_packets); + statistics_item(" late", "%*" PRIu64 "", 6, conn->late_packets); + statistics_item("too late", "%*" PRIu64 "", 8, conn->too_late_packets); + statistics_item("resend reqs", "%*" PRIu64 "", 11, conn->resend_requests); + statistics_item("min DAC queue", "%*" PRIu64 "", 13, minimum_dac_queue_size); + statistics_item("min buffers", "%*" PRIu32 "", 11, minimum_buffer_occupancy); + statistics_item("max buffers", "%*" PRIu32 "", 11, maximum_buffer_occupancy); + statistics_item("nominal fps", "%*.2f", 11, conn->remote_frame_rate); + statistics_item(" actual fps", "%*.2f", 11, conn->input_frame_rate); + if (conn->frame_rate_valid) + statistics_item(" output fps", "%*.2f", 11, conn->frame_rate); + else + statistics_item(" output fps", " N/A"); + statistics_item("source drift ppm", "%*.2f", 16, + (conn->local_to_remote_time_gradient - 1.0) * 1000000); + statistics_item("drift samples", "%*d", 13, + conn->local_to_remote_time_gradient_sample_count); + statistics_item("estimated (unused) correction ppm", "%*.2f", + strlen("estimated (unused) correction ppm"), + (conn->frame_rate_valid != 0) + ? ((conn->frame_rate - + conn->remote_frame_rate * conn->output_sample_ratio * + conn->local_to_remote_time_gradient) * + 1000000) / + conn->frame_rate + : 0.0); + statistics_row++; + inform(line_of_stats); + } while (statistics_row < 2); + } else { + inform("No frames received in the last sampling interval."); + } + } + minimum_dac_queue_size = UINT64_MAX; // hack reset + maximum_buffer_occupancy = INT32_MIN; // can't be less than this + minimum_buffer_occupancy = INT32_MAX; // can't be more than this + at_least_one_frame_seen = 0; } - minimum_dac_queue_size = UINT64_MAX; // hack reset - maximum_buffer_occupancy = INT32_MIN; // can't be less than this - minimum_buffer_occupancy = INT32_MAX; // can't be more than this - at_least_one_frame_seen = 0; - } // here, we want to check (a) if we are meant to do synchronisation, // (b) if we have a delay procedure, (c) if we can get the delay. @@ -2737,7 +2769,7 @@ void *player_thread_func(void *arg) { #ifdef CONFIG_SOXR if ((current_delay < conn->dac_buffer_queue_minimum_length) || (config.packet_stuffing == ST_basic) || - (config.soxr_delay_index == 0) || // not computed yet + (config.soxr_delay_index == 0) || // not computed ((config.packet_stuffing == ST_auto) && (config.soxr_delay_index > config.soxr_delay_threshold)) // if the CPU is deemed too slow diff --git a/player.h b/player.h index 526572ef..b08a379e 100644 --- a/player.h +++ b/player.h @@ -30,6 +30,7 @@ #include "audio.h" #define time_ping_history_power_of_two 7 +// this must now be zero, otherwise bad things will happen #define time_ping_history \ (1 << time_ping_history_power_of_two) // 2^7 is 128. At 1 per three seconds, approximately six // minutes of records diff --git a/rtp.c b/rtp.c index 41b07371..a79e0bbd 100644 --- a/rtp.c +++ b/rtp.c @@ -154,7 +154,7 @@ void *rtp_audio_receiver(void *arg) { float stat_delta = time_interval_us - stat_mean; stat_mean += stat_delta / stat_n; stat_M2 += stat_delta * (time_interval_us - stat_mean); - if (stat_n % 2500 == 0) { + if ((stat_n != 1) && (stat_n % 2500 == 0)) { debug(2, "Packet reception interval stats: mean, standard deviation and max for the last " "2,500 packets in microseconds: %10.1f, %10.1f, %10.1f.", @@ -650,6 +650,8 @@ void *rtp_timing_receiver(void *arg) { double log_of_multiplier = log10(diffusion_expansion_factor) / time_ping_history; double multiplier = pow(10, log_of_multiplier); uint64_t dispersion_factor = (uint64_t)(multiplier * 100); + if (dispersion_factor == 0) + die("dispersion factor is zero!"); // debug(1,"dispersion factor is %" PRIu64 ".", dispersion_factor); // uint64_t first_local_to_remote_time_difference_time; @@ -1029,6 +1031,8 @@ const int use_nominal_rate = 0; // specify whether to use the nominal input rate int sanitised_source_rate_information(uint32_t *frames, uint64_t *time, rtsp_conn_info *conn) { int result = 1; + if (conn->input_rate == 0) + die("conn->input_rate is zero!"); uint32_t fs = conn->input_rate; *frames = fs; // default value to return *time = 1000000000; // default value to return @@ -1051,7 +1055,11 @@ int sanitised_source_rate_information(uint32_t *frames, uint64_t *time, rtsp_con result = 1; } else { *frames = local_frames; + if (local_frames == 0) + die("local_frames is zero!"); *time = local_time; + if (local_time == 0) + die("local_time is zero!"); result = 0; } } @@ -1469,6 +1477,8 @@ int frame_to_ptp_local_time(uint32_t timestamp, uint64_t *time, rtsp_conn_info * int32_t frame_difference = timestamp - anchor_rtptime; int64_t time_difference = frame_difference; time_difference = time_difference * 1000000000; + if (conn->input_rate == 0) + die("conn->input_rate is zero!"); time_difference = time_difference / conn->input_rate; uint64_t ltime = anchor_local_time + time_difference; *time = ltime; @@ -2246,6 +2256,10 @@ void *rtp_buffered_audio_processor(void *arg) { double requested_lead_time = 0.3; // normal lead time minimum reset_buffer(conn); // in case there is any garbage in the player // int not_first_time_out = 0; + + // quick check of parameters + if (conn->input_bytes_per_frame == 0) + die("conn->input_bytes_per_frame is zero!"); do { int flush_is_delayed = 0; int flush_newly_requested = 0; diff --git a/shairport.c b/shairport.c index 4afcd86f..9b7648e3 100644 --- a/shairport.c +++ b/shairport.c @@ -202,15 +202,24 @@ void *soxr_time_check(__attribute__((unused)) void *arg) { double soxr_execution_time_ns = (get_absolute_time_in_ns() - soxr_start_time) * 1.0; // free(outbuffer); // free(inbuffer); - config.soxr_delay_index = (int)(0.9 + soxr_execution_time_ns / (number_of_iterations * 1000000)); + if (number_of_iterations != 0) { + config.soxr_delay_index = + (int)(0.9 + soxr_execution_time_ns / (number_of_iterations * 1000000)); + } else { + debug(1, "No soxr-timing iterations performed, so \"basic\" iteration will be used."); + config.soxr_delay_index = 0; // used as a flag + } debug(2, "soxr_delay_index: %d.", config.soxr_delay_index); if ((config.packet_stuffing == ST_soxr) && (config.soxr_delay_index > config.soxr_delay_threshold)) inform("Note: this device may be too slow for \"soxr\" interpolation. Consider choosing the " "\"basic\" or \"auto\" interpolation setting."); if (config.packet_stuffing == ST_auto) - debug(1, "\"%s\" interpolation has been chosen.", - config.soxr_delay_index <= config.soxr_delay_threshold ? "soxr" : "basic"); + debug( + 1, "\"%s\" interpolation has been chosen.", + ((config.soxr_delay_index != 0) && (config.soxr_delay_index <= config.soxr_delay_threshold)) + ? "soxr" + : "basic"); pthread_exit(NULL); } From ce39f00a0b9496a1945967e3b4014753e40f6b1e Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Thu, 25 Nov 2021 17:42:48 +0000 Subject: [PATCH 10/40] Don't overwrite service files if they already exist. --- Makefile.am | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/Makefile.am b/Makefile.am index dd8a1bac..c8d53440 100644 --- a/Makefile.am +++ b/Makefile.am @@ -230,13 +230,13 @@ if INSTALL_SYSTEMV getent group shairport-sync &>/dev/null || groupadd -r shairport-sync >/dev/null getent passwd shairport-sync &> /dev/null || useradd -r -M -g shairport-sync -s /usr/bin/nologin -G audio shairport-sync >/dev/null [ -e $(DESTDIR)$(sysconfdir)/init.d ] || mkdir -p $(DESTDIR)$(sysconfdir)/init.d - cp scripts/shairport-sync $(DESTDIR)$(sysconfdir)/init.d/ + [ -e $(DESTDIR)$(sysconfdir)/init.d/shairport-sync ] || cp scripts/shairport-sync $(DESTDIR)$(sysconfdir)/init.d/ endif if INSTALL_SYSTEMD getent group shairport-sync &>/dev/null || groupadd -r shairport-sync >/dev/null getent passwd shairport-sync &> /dev/null || useradd -r -M -g shairport-sync -s /usr/bin/nologin -G audio shairport-sync >/dev/null [ -e $(DESTDIR)$(systemdsystemunitdir) ] || mkdir -p $(DESTDIR)$(systemdsystemunitdir) - cp scripts/shairport-sync.service $(DESTDIR)$(systemdsystemunitdir) + [ -e $(DESTDIR)$(systemdsystemunitdir)/shairport-sync.service ] || cp scripts/shairport-sync.service $(DESTDIR)$(systemdsystemunitdir) endif if INSTALL_FREEBSD_SERVICE # Choose a uid and gid of 801 completely arbitrarity, except that it should be below 1000. FreeBSD doesn't seem to allow you to say "an ID in the range of..." @@ -244,9 +244,9 @@ if INSTALL_FREEBSD_SERVICE pw showuser shairport-sync > /dev/null 2>&1 || pw adduser -c "shairport-sync unprivileged user" -n shairport-sync -u 801 -s /usr/sbin/nologin -d /nonexistent > /dev/null 2>&1 [ -e /var/run/shairport-sync ] || mkdir -p /var/run/shairport-sync chown shairport-sync:shairport-sync /var/run/shairport-sync - cp scripts/shairport-sync.freebsd /usr/local/etc/rc.d/shairport_sync + [ -e /usr/local/etc/rc.d/shairport_sync ] || cp scripts/shairport-sync.freebsd /usr/local/etc/rc.d/shairport_sync chmod 555 /usr/local/etc/rc.d/shairport_sync endif if INSTALL_CYGWIN_SERVICE - cp scripts/shairport-sync-config /usr/local/bin + [ -e /usr/local/bin/shairport-sync-config ] || cp scripts/shairport-sync-config /usr/local/bin endif From 87d887f4125d681e5969c94f703f4c93d0518a34 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Thu, 25 Nov 2021 18:13:56 +0000 Subject: [PATCH 11/40] Remove the commas in the statistics logs -- easier to get into a spreadsheet. --- player.c | 24 ++++++++++++------------ 1 file changed, 12 insertions(+), 12 deletions(-) diff --git a/player.c b/player.c index 7a66a1b3..824aa871 100644 --- a/player.c +++ b/player.c @@ -1555,7 +1555,7 @@ int *statistics_print_profile; // be printed -- 1 means print, 0 means skip // don't display output fps -- not sure how accurate it is (change item 14 and 17 to 1 to restore) -int ap1_synced_statistics_print_profile[] = {1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 0, 1, 1, 0}; +int ap1_synced_statistics_print_profile[] = {1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1}; int ap1_nosync_statistics_print_profile[] = {1, 0, 0, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 0, 1, 1, 0}; int ap1_nodelay_statistics_print_profile[] = {0, 0, 0, 1, 1, 1, 1, 1, 0, 1, 1, 1, 1, 0, 1, 1, 0}; @@ -1568,7 +1568,7 @@ int ap2_realtime_nodelay_stream_statistics_print_profile[] = {0, 0, 0, 1, 1, 1, // don't display output fps -- not sure how accurate it is (change item 14 1 to restore) int ap2_buffered_synced_stream_statistics_print_profile[] = {1, 1, 1, 1, 0, 0, 0, 0, 1, - 1, 1, 0, 0, 0, 0, 0, 0}; + 1, 1, 0, 0, 1, 0, 0, 0}; int ap2_buffered_nosync_stream_statistics_print_profile[] = {1, 0, 0, 1, 0, 0, 0, 0, 1, 1, 1, 0, 0, 0, 0, 0, 0}; int ap2_buffered_nodelay_stream_statistics_print_profile[] = {0, 0, 0, 1, 0, 0, 0, 0, 0, @@ -1577,7 +1577,7 @@ int ap2_buffered_nodelay_stream_statistics_print_profile[] = {0, 0, 0, 1, 0, 0, void statistics_item(const char *heading, const char *format, ...) { if (statistics_print_profile[statistics_column] == 1) { // include this column? if (was_a_previous_column != 0) - strcat(line_of_stats, ", "); + strcat(line_of_stats, " "); if (statistics_row == 0) { strcat(line_of_stats, heading); } else { @@ -2358,15 +2358,15 @@ void *player_thread_func(void *arg) { // uncomment the if statement if your want to get as long a period for // calculating the frame rate as possible without an output break or error - // if ((status != 0) || (previous_frames_played_valid == 0)) { - // if we have just detected an outputting error, or if we have no - // starting information - if (stats_status != 0) - conn->frame_rate_valid = 0; - previous_frames_played = frames_played; - previous_frames_played_time = measurement_time; - previous_frames_played_valid = 1; - // } + if ((stats_status != 0) || (previous_frames_played_valid == 0)) { + // if we have just detected an outputting error, or if we have no + // starting information + if (stats_status != 0) + conn->frame_rate_valid = 0; + previous_frames_played = frames_played; + previous_frames_played_time = measurement_time; + previous_frames_played_valid = 1; + } } // we can now calculate running averages for sync error (frames), corrections (ppm), From 136071a62180c5d5215678d6d00638240f1321bd Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Fri, 26 Nov 2021 15:17:27 +0000 Subject: [PATCH 12/40] change stats to report non-zero if output has just opened or if there has been any discontinuity in play from previous time. --- audio_alsa.c | 46 +++++++++++++++++----------------------------- 1 file changed, 17 insertions(+), 29 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index caaad899..0910b9e7 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -248,8 +248,12 @@ static snd_pcm_uframes_t period_size_requested, buffer_size_requested; static int set_period_size_request, set_buffer_size_request; static uint64_t frames_sent_for_playing; -static int output_error_occurred; // set to true if an underrun or similar has occurred since last - // requested + + // set to true if there has been a discontinuity between the last reported frames_sent_for_playing + // and the present reported frames_sent_for_playing + // Not that it will be set when the device is opened, as any previous figures for frames_sent_for_playing + // (which Shairport Sync might hold) would be invalid. +static int frames_sent_break_occurred; static void help(void) { printf(" -d output-device set the output device, default is \"default\".\n" @@ -1632,13 +1636,10 @@ int delay(long *the_delay) { int stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac) { // returns 0 if the device is in a valid state -- SND_PCM_STATE_RUNNING or // SND_PCM_STATE_PREPARED - // or SND_PCM_STATE_DRAINING - // and returns the actual delay if running or 0 if prepared in *the_delay - - // otherwise return an error code - // the error code could be a Unix errno code or a snderror code, or - // the sps_extra_code_output_stalled or the - // sps_extra_code_output_state_cannot_make_ready codes + // or SND_PCM_STATE_DRAINING. + // returns the actual delay if running or 0 if prepared in *the_delay + // returns the present value of frames_sent_for_playing + // otherwise return a non-zero value int ret = 0; *the_delay = 0; @@ -1657,8 +1658,10 @@ int stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac) ret = delay_and_status(&state, &my_delay, NULL); } if (ret == 0) - ret = output_error_occurred; // will be zero unless an error like an underrun occurred - output_error_occurred = 0; // reset it. + ret = frames_sent_break_occurred; // will be zero unless an error like an underrun occurred + else + ret = 1; // just indicate there was some kind of a break + frames_sent_break_occurred = 0; // reset it. if (frames_sent_to_dac != NULL) *frames_sent_to_dac = frames_sent_for_playing; debug_mutex_unlock(&alsa_mutex, 0); @@ -1668,22 +1671,6 @@ int stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac) *the_delay = hd; return ret; } - -int get_frames_sent_for_output(__attribute__((unused)) uint64_t *elapsed_time, - uint64_t *frames_sent_to_dac) { - int ret = 0; - pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 0); - *frames_sent_to_dac = frames_sent_for_playing; - if (alsa_handle == NULL) - ret = ENODEV; - else - ret = output_error_occurred; // will be zero unless an error occurred - output_error_occurred = 0; // reset it. - debug_mutex_unlock(&alsa_mutex, 0); - pthread_cleanup_pop(0); - return ret; -} - /* int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played) { // elapsed_time is in nanoseconds @@ -1728,7 +1715,7 @@ int do_play(void *buf, int samples) { stall_monitor_frame_count += samples; frames_sent_for_playing += samples; } else { - output_error_occurred = -ret; // note than an output error has occurred + frames_sent_break_occurred = 1; // note than an output error has occurred if (ret == -EPIPE) { /* underrun */ // It could be that the DAC was in the SND_PCM_STATE_XRUN state before @@ -1802,7 +1789,8 @@ int do_open(int do_auto_setup) { // set accordingly // do_mute(0); // complete unmute } - output_error_occurred = 0; + frames_sent_break_occurred = 1; // there is a discontinuity with + // any previously-reported frame count frames_sent_for_playing = 0; alsa_backend_state = abm_connected; // only do this if it really opened it. } From b9d3abfa2421143788f2474aeaed7aeaca73e034 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Fri, 26 Nov 2021 15:18:27 +0000 Subject: [PATCH 13/40] Add some debug messages to help check the output rate calculations. --- player.c | 14 ++++++-------- 1 file changed, 6 insertions(+), 8 deletions(-) diff --git a/player.c b/player.c index 824aa871..e568cc87 100644 --- a/player.c +++ b/player.c @@ -2332,27 +2332,25 @@ void *player_thread_func(void *arg) { conn->input_frame_rate = 0.0; } - int stats_status = -1; + int stats_status = 0; if ((config.output->delay) && (config.no_sync == 0) && (config.output->stats)) { uint64_t frames_sent_for_play; uint64_t measurement_time; uint64_t actual_delay; stats_status = config.output->stats(&measurement_time, &actual_delay, &frames_sent_for_play); - // debug(1,"actual_delay: %" PRIu64 ", frames_sent_for_play: %" PRIu64 ", - // frames_played: %" PRIu64 ".", actual_delay, frames_sent_for_play, - // frames_sent_for_play - actual_delay); + debug(1,"status: %d, actual_delay: %" PRIu64 ", frames_sent_for_play: %" PRIu64 ", frames_played: %" PRIu64 ".", stats_status, actual_delay, frames_sent_for_play, frames_sent_for_play - actual_delay); uint64_t frames_played = frames_sent_for_play - actual_delay; // If the status is zero, it means that there were no output problems since the // last time the stats call was made. Thus, the frame rate should be valid. - if ((stats_status == 0) && (previous_frames_played_valid)) { + if ((stats_status == 0) && (previous_frames_played_valid != 0)) { uint64_t frames_played_in_this_interval = frames_played - previous_frames_played; - uint64_t interval = measurement_time - previous_frames_played_time; - // debug(1,"frames_played_in_this_interval: %" PRIu64 ", interval: %" PRIu64 ".", - // frames_played_in_this_interval, interval); + int64_t interval = measurement_time - previous_frames_played_time; if (interval != 0) { conn->frame_rate = (1e9 * frames_played_in_this_interval) / interval; conn->frame_rate_valid = 1; + debug(1,"frames_played_in_this_interval: %" PRIu64 ", interval: %" PRId64 ", rate: %f.", + frames_played_in_this_interval, interval, conn->frame_rate); } } From 7890188dcfaa307819211d1970013f472399a0cd Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Fri, 26 Nov 2021 18:01:36 +0000 Subject: [PATCH 14/40] Quieten some debug messages. --- player.c | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/player.c b/player.c index e568cc87..0991167c 100644 --- a/player.c +++ b/player.c @@ -2339,7 +2339,7 @@ void *player_thread_func(void *arg) { uint64_t actual_delay; stats_status = config.output->stats(&measurement_time, &actual_delay, &frames_sent_for_play); - debug(1,"status: %d, actual_delay: %" PRIu64 ", frames_sent_for_play: %" PRIu64 ", frames_played: %" PRIu64 ".", stats_status, actual_delay, frames_sent_for_play, frames_sent_for_play - actual_delay); + // debug(1,"status: %d, actual_delay: %" PRIu64 ", frames_sent_for_play: %" PRIu64 ", frames_played: %" PRIu64 ".", stats_status, actual_delay, frames_sent_for_play, frames_sent_for_play - actual_delay); uint64_t frames_played = frames_sent_for_play - actual_delay; // If the status is zero, it means that there were no output problems since the // last time the stats call was made. Thus, the frame rate should be valid. @@ -2349,8 +2349,8 @@ void *player_thread_func(void *arg) { if (interval != 0) { conn->frame_rate = (1e9 * frames_played_in_this_interval) / interval; conn->frame_rate_valid = 1; - debug(1,"frames_played_in_this_interval: %" PRIu64 ", interval: %" PRId64 ", rate: %f.", - frames_played_in_this_interval, interval, conn->frame_rate); + //debug(1,"frames_played_in_this_interval: %" PRIu64 ", interval: %" PRId64 ", rate: %f.", + // frames_played_in_this_interval, interval, conn->frame_rate); } } From dc5b8f1a1171b18e704283f98c3dd2bf8e4a08ca Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Fri, 26 Nov 2021 18:02:23 +0000 Subject: [PATCH 15/40] Clang format --- audio_alsa.c | 16 ++++++++-------- player.c | 7 +++++-- 2 files changed, 13 insertions(+), 10 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index 0910b9e7..f2e0b131 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -249,10 +249,10 @@ static int set_period_size_request, set_buffer_size_request; static uint64_t frames_sent_for_playing; - // set to true if there has been a discontinuity between the last reported frames_sent_for_playing - // and the present reported frames_sent_for_playing - // Not that it will be set when the device is opened, as any previous figures for frames_sent_for_playing - // (which Shairport Sync might hold) would be invalid. +// set to true if there has been a discontinuity between the last reported frames_sent_for_playing +// and the present reported frames_sent_for_playing +// Not that it will be set when the device is opened, as any previous figures for +// frames_sent_for_playing (which Shairport Sync might hold) would be invalid. static int frames_sent_break_occurred; static void help(void) { @@ -1660,8 +1660,8 @@ int stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac) if (ret == 0) ret = frames_sent_break_occurred; // will be zero unless an error like an underrun occurred else - ret = 1; // just indicate there was some kind of a break - frames_sent_break_occurred = 0; // reset it. + ret = 1; // just indicate there was some kind of a break + frames_sent_break_occurred = 0; // reset it. if (frames_sent_to_dac != NULL) *frames_sent_to_dac = frames_sent_for_playing; debug_mutex_unlock(&alsa_mutex, 0); @@ -1716,7 +1716,7 @@ int do_play(void *buf, int samples) { frames_sent_for_playing += samples; } else { frames_sent_break_occurred = 1; // note than an output error has occurred - if (ret == -EPIPE) { /* underrun */ + if (ret == -EPIPE) { /* underrun */ // It could be that the DAC was in the SND_PCM_STATE_XRUN state before // sending the samples to be output. If so, it will still be in @@ -1790,7 +1790,7 @@ int do_open(int do_auto_setup) { // do_mute(0); // complete unmute } frames_sent_break_occurred = 1; // there is a discontinuity with - // any previously-reported frame count + // any previously-reported frame count frames_sent_for_playing = 0; alsa_backend_state = abm_connected; // only do this if it really opened it. } diff --git a/player.c b/player.c index 0991167c..5e6e4133 100644 --- a/player.c +++ b/player.c @@ -2339,7 +2339,9 @@ void *player_thread_func(void *arg) { uint64_t actual_delay; stats_status = config.output->stats(&measurement_time, &actual_delay, &frames_sent_for_play); - // debug(1,"status: %d, actual_delay: %" PRIu64 ", frames_sent_for_play: %" PRIu64 ", frames_played: %" PRIu64 ".", stats_status, actual_delay, frames_sent_for_play, frames_sent_for_play - actual_delay); + // debug(1,"status: %d, actual_delay: %" PRIu64 ", frames_sent_for_play: %" PRIu64 ", + // frames_played: %" PRIu64 ".", stats_status, actual_delay, frames_sent_for_play, + // frames_sent_for_play - actual_delay); uint64_t frames_played = frames_sent_for_play - actual_delay; // If the status is zero, it means that there were no output problems since the // last time the stats call was made. Thus, the frame rate should be valid. @@ -2349,7 +2351,8 @@ void *player_thread_func(void *arg) { if (interval != 0) { conn->frame_rate = (1e9 * frames_played_in_this_interval) / interval; conn->frame_rate_valid = 1; - //debug(1,"frames_played_in_this_interval: %" PRIu64 ", interval: %" PRId64 ", rate: %f.", + // debug(1,"frames_played_in_this_interval: %" PRIu64 ", interval: %" PRId64 ", + // rate: %f.", // frames_played_in_this_interval, interval, conn->frame_rate); } } From 56bef8e7ddf01e9d76860fafb65b6d7330c186b1 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Sun, 28 Nov 2021 16:08:48 +0000 Subject: [PATCH 16/40] Use CLOCK_MONOLITHIC_RAW to avoid NTP effects, report raw and corrected timing from audio_alsa. Clean up statistics. Stop watchdog timing out AP2 sessions. CLean up some debug messages. --- activity_monitor.c | 2 +- audio.h | 3 +- audio_alsa.c | 12 ++-- common.c | 122 ++++++++++++++++++++++------------------- common.h | 9 ++- dacp.c | 2 +- nqptp-shm-structures.h | 2 +- player.c | 75 +++++++++++++++---------- player.h | 3 +- rtp.c | 2 +- rtsp.c | 4 ++ 11 files changed, 137 insertions(+), 99 deletions(-) diff --git a/activity_monitor.c b/activity_monitor.c index 1d301c49..deeab2b6 100644 --- a/activity_monitor.c +++ b/activity_monitor.c @@ -187,7 +187,7 @@ void *activity_monitor_thread_code(void *arg) { uint64_t time_to_wait_for_wakeup_ns = (uint64_t)(config.active_state_timeout * 1000000000); #ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD - uint64_t time_of_wakeup_ns = get_absolute_time_in_ns() + time_to_wait_for_wakeup_ns; + uint64_t time_of_wakeup_ns = get_realtime_in_ns() + time_to_wait_for_wakeup_ns; sec = time_of_wakeup_ns / 1000000000; nsec = time_of_wakeup_ns % 1000000000; time_for_wait.tv_sec = sec; diff --git a/audio.h b/audio.h index 25742d7b..5ff14195 100644 --- a/audio.h +++ b/audio.h @@ -39,7 +39,8 @@ typedef struct { // will change dynamically, so keep watching it. Implemented in ALSA only. // returns a negative error code if there's a problem int (*delay)(long *the_delay); // snd_pcm_sframes_t is a signed long - int (*stats)(uint64_t *measurement_time, uint64_t *delay, + int (*stats)(uint64_t *raw_measurement_time, uint64_t *corrected_measurement_time, + uint64_t *delay, uint64_t *frames_sent_to_dac); // use this to get the true rate of the DAC // may be NULL, in which case soft volume is applied diff --git a/audio_alsa.c b/audio_alsa.c index f2e0b131..a007c419 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -60,8 +60,9 @@ static int play(void *buf, int samples); static void stop(void); static void flush(void); int delay(long *the_delay); -int stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac); -// int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played); +int stats(uint64_t *raw_measurement_time, uint64_t *corrected_measurement_time, uint64_t *the_delay, + uint64_t *frames_sent_to_dac); + void *alsa_buffer_monitor_thread_code(void *arg); static void volume(double vol); @@ -1633,7 +1634,8 @@ int delay(long *the_delay) { return ret; } -int stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac) { +int stats(uint64_t *raw_measurement_time, uint64_t *corrected_measurement_time, uint64_t *the_delay, + uint64_t *frames_sent_to_dac) { // returns 0 if the device is in a valid state -- SND_PCM_STATE_RUNNING or // SND_PCM_STATE_PREPARED // or SND_PCM_STATE_DRAINING. @@ -1654,7 +1656,9 @@ int stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac) if (alsa_handle == NULL) { ret = ENODEV; } else { - *the_time = get_absolute_time_in_ns(); + *raw_measurement_time = + get_absolute_time_in_ns(); // this is not conditioned ("disciplined") by NTP + *corrected_measurement_time = get_monotonic_time_in_ns(); // this is ("disciplined") by NTP ret = delay_and_status(&state, &my_delay, NULL); } if (ret == 0) diff --git a/common.c b/common.c index a947be41..bbe36780 100644 --- a/common.c +++ b/common.c @@ -1210,58 +1210,6 @@ double vol2attn(double vol, long max_db, long min_db) { return vol_setting; } -uint64_t get_absolute_time_in_fp() { - uint64_t time_now_fp; -#ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD - struct timespec tn; - // 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) - warn("clock_gettime seconds overflow!"); - uint64_t tnfpnsec = tn.tv_nsec; - 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 -#endif -#ifdef COMPILE_FOR_OSX - uint64_t time_now_mach; - uint64_t elapsedNano; - static mach_timebase_info_data_t sTimebaseInfo = {0, 0}; - - time_now_mach = mach_absolute_time(); - - // If this is the first time we've run, get the timebase. - // We can use denom == 0 to indicate that sTimebaseInfo is - // uninitialised because it makes no sense to have a zero - // denominator in a fraction. - - if (sTimebaseInfo.denom == 0) { - debug(1, "Mac initialise timebase info."); - (void)mach_timebase_info(&sTimebaseInfo); - } - - // Do the maths. We hope that the multiplication doesn't - // overflow; the price you pay for working in fixed point. - - if (sTimebaseInfo.denom == 0) - die("could not initialise Mac timebase info in get_absolute_time_in_fp().") - // this gives us nanoseconds - uint64_t time_now_ns = time_now_mach * sTimebaseInfo.numer / sTimebaseInfo.denom; - - // take the units and shift them to the upper half of the fp, and take the nanoseconds, shift them - // to the upper half and then divide the result to 1000000000 - time_now_fp = - ((time_now_ns / 1000000000) << 32) + (((time_now_ns % 1000000000) << 32) / 1000000000); - -#endif - return time_now_fp; -} - uint64_t get_monotonic_time_in_ns() { uint64_t time_now_ns; @@ -1308,10 +1256,57 @@ uint64_t get_monotonic_time_in_ns() { return time_now_ns; } -uint64_t get_absolute_time_in_ns() { +// all these clock things are now in macOS now since 10.13 (September 2017). Must update... +uint64_t get_monotonic_raw_time_in_ns() { + // CLOCK_MONOTONIC_RAW in FreeBSD etc, monotonic in MacOSX uint64_t time_now_ns; #ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD + struct timespec tn; + clock_gettime(CLOCK_MONOTONIC_RAW, &tn); + uint64_t tnnsec = tn.tv_sec; + tnnsec = tnnsec * 1000000000; + uint64_t tnjnsec = tn.tv_nsec; + time_now_ns = tnnsec + tnjnsec; +#endif + +#ifdef COMPILE_FOR_OSX + uint64_t time_now_mach; + uint64_t elapsedNano; + static mach_timebase_info_data_t sTimebaseInfo = {0, 0}; + + // this actually give you a monotonic clock + // see https://news.ycombinator.com/item?id=6303755 + time_now_mach = mach_absolute_time(); + + // If this is the first time we've run, get the timebase. + // We can use denom == 0 to indicate that sTimebaseInfo is + // uninitialised because it makes no sense to have a zero + // denominator in a fraction. + + if (sTimebaseInfo.denom == 0) { + debug(1, "Mac initialise timebase info."); + (void)mach_timebase_info(&sTimebaseInfo); + } + + if (sTimebaseInfo.denom == 0) + die("could not initialise Mac timebase info in get_monotonic_time_in_ns().") + + // Do the maths. We hope that the multiplication doesn't + // overflow; the price you pay for working in fixed point. + + // this gives us nanoseconds + time_now_ns = time_now_mach * sTimebaseInfo.numer / sTimebaseInfo.denom; +#endif + + return time_now_ns; +} + +#ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD +// Not defined for macOS +uint64_t get_realtime_in_ns() { + uint64_t time_now_ns; + struct timespec tn; // can't use CLOCK_MONOTONIC_RAW as it's not implemented in OpenWrt // CLOCK_REALTIME because PTP uses it. @@ -1320,6 +1315,21 @@ uint64_t get_absolute_time_in_ns() { tnnsec = tnnsec * 1000000000; uint64_t tnjnsec = tn.tv_nsec; time_now_ns = tnnsec + tnjnsec; + return time_now_ns; +} +#endif + +uint64_t get_absolute_time_in_ns() { + // CLOCK_MONOTONIC_RAW in FreeBSD etc, monotonic in MacOSX + uint64_t time_now_ns; + +#ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD + struct timespec tn; + clock_gettime(CLOCK_MONOTONIC_RAW, &tn); + uint64_t tnnsec = tn.tv_sec; + tnnsec = tnnsec * 1000000000; + uint64_t tnjnsec = tn.tv_nsec; + time_now_ns = tnnsec + tnjnsec; #endif #ifdef COMPILE_FOR_OSX @@ -1521,8 +1531,8 @@ int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time, pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); struct timespec timeoutTime; - uint64_t wait_until_time = dally_time * 1000; // to nanoseconds - uint64_t start_time = get_absolute_time_in_ns(); // this is from CLOCK_REALTIME + uint64_t wait_until_time = dally_time * 1000; // to nanoseconds + uint64_t start_time = get_realtime_in_ns(); // this is from CLOCK_REALTIME wait_until_time = wait_until_time + start_time; uint64_t wait_until_sec = wait_until_time / 1000000000; uint64_t wait_until_nsec = wait_until_time % 1000000000; @@ -1530,7 +1540,7 @@ int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time, timeoutTime.tv_nsec = wait_until_nsec; int r = pthread_mutex_timedlock(mutex, &timeoutTime); - uint64_t et = get_absolute_time_in_ns() - start_time; + uint64_t et = get_realtime_in_ns() - start_time; if ((debuglevel != 0) && (r != 0) && (debugmessage != NULL)) { char errstr[1000]; diff --git a/common.h b/common.h index 199b3d41..d9be0327 100644 --- a/common.h +++ b/common.h @@ -379,9 +379,12 @@ double flat_vol2attn(double vol, long max_db, long min_db); double vol2attn(double vol, long max_db, long min_db); // return a time in nanoseconds -// uint64_t get_absolute_time_in_fp(void); // obselete -uint64_t get_absolute_time_in_ns(void); -uint64_t get_monotonic_time_in_ns(void); // to try and get precise FPS values +#ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD +// Not defined for macOS +uint64_t get_realtime_in_ns(void); +#endif +uint64_t get_absolute_time_in_ns(void); // monotonic_raw or monotonic +uint64_t get_monotonic_time_in_ns(void); // NTP-disciplined // time at startup for debugging timing extern uint64_t ns_time_at_startup, ns_time_at_last_debug_message; diff --git a/dacp.c b/dacp.c index ef2297e2..d6964133 100644 --- a/dacp.c +++ b/dacp.c @@ -529,7 +529,7 @@ void *dacp_monitor_thread_code(__attribute__((unused)) void *na) { (uint64_t)(1000000000 * config.missing_port_dacp_scan_interval_seconds); #ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD - uint64_t time_of_wakeup_ns = get_absolute_time_in_ns() + time_to_wait_for_wakeup_ns; + uint64_t time_of_wakeup_ns = get_realtime_in_ns() + time_to_wait_for_wakeup_ns; uint64_t sec = time_of_wakeup_ns / 1000000000; uint64_t nsec = time_of_wakeup_ns % 1000000000; #endif diff --git a/nqptp-shm-structures.h b/nqptp-shm-structures.h index 36c8a813..f4db8c6e 100644 --- a/nqptp-shm-structures.h +++ b/nqptp-shm-structures.h @@ -22,7 +22,7 @@ #define STORAGE_ID "/nqptp" #define MAX_CLOCKS 32 -#define NQPTP_SHM_STRUCTURES_VERSION 5 +#define NQPTP_SHM_STRUCTURES_VERSION 6 #define NQPTP_CONTROL_PORT 9000 // the control port will accept a UDP packet with the first letter being: diff --git a/player.c b/player.c index 5e6e4133..9b0b86ca 100644 --- a/player.c +++ b/player.c @@ -1299,7 +1299,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { time_to_wait_for_wakeup_ns /= 3; // two thirds of a packet time #ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD - uint64_t time_of_wakeup_ns = local_time_now + time_to_wait_for_wakeup_ns; + uint64_t time_of_wakeup_ns = get_realtime_in_ns() + time_to_wait_for_wakeup_ns; uint64_t sec = time_of_wakeup_ns / 1000000000; uint64_t nsec = time_of_wakeup_ns % 1000000000; @@ -1552,30 +1552,31 @@ int was_a_previous_column; int *statistics_print_profile; // these arrays specify which of the statistics specified by the statistics_item calls will actually -// be printed -- 1 means print, 0 means skip +// be printed -- 2 means print, 1 means print only in a debug mode, 0 means skip // don't display output fps -- not sure how accurate it is (change item 14 and 17 to 1 to restore) -int ap1_synced_statistics_print_profile[] = {1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1}; -int ap1_nosync_statistics_print_profile[] = {1, 0, 0, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 0, 1, 1, 0}; -int ap1_nodelay_statistics_print_profile[] = {0, 0, 0, 1, 1, 1, 1, 1, 0, 1, 1, 1, 1, 0, 1, 1, 0}; +int ap1_synced_statistics_print_profile[] = {2, 2, 2, 1, 2, 1, 1, 2, 1, 1, 1, 1, 1, 2, 2, 1, 1}; +int ap1_nosync_statistics_print_profile[] = {2, 0, 0, 1, 2, 1, 1, 2, 1, 1, 1, 1, 1, 0, 0, 1, 0}; +int ap1_nodelay_statistics_print_profile[] = {0, 0, 0, 1, 2, 1, 1, 2, 0, 1, 1, 1, 1, 0, 0, 1, 0}; -int ap2_realtime_synced_stream_statistics_print_profile[] = {1, 1, 1, 1, 1, 1, 1, 1, 1, - 1, 1, 0, 0, 1, 0, 0, 0}; -int ap2_realtime_nosync_stream_statistics_print_profile[] = {1, 0, 0, 1, 1, 1, 1, 1, 1, - 1, 1, 0, 0, 0, 0, 0, 0}; -int ap2_realtime_nodelay_stream_statistics_print_profile[] = {0, 0, 0, 1, 1, 1, 1, 1, 0, - 1, 1, 0, 0, 0, 0, 0, 0}; +int ap2_realtime_synced_stream_statistics_print_profile[] = {2, 2, 2, 1, 2, 1, 1, 2, 1, + 1, 1, 1, 1, 2, 2, 0, 0}; +int ap2_realtime_nosync_stream_statistics_print_profile[] = {2, 0, 0, 1, 2, 1, 1, 2, 1, + 1, 1, 1, 1, 0, 0, 0, 0}; +int ap2_realtime_nodelay_stream_statistics_print_profile[] = {0, 0, 0, 1, 2, 1, 1, 2, 0, + 1, 1, 1, 1, 0, 0, 0, 0}; // don't display output fps -- not sure how accurate it is (change item 14 1 to restore) -int ap2_buffered_synced_stream_statistics_print_profile[] = {1, 1, 1, 1, 0, 0, 0, 0, 1, - 1, 1, 0, 0, 1, 0, 0, 0}; -int ap2_buffered_nosync_stream_statistics_print_profile[] = {1, 0, 0, 1, 0, 0, 0, 0, 1, +int ap2_buffered_synced_stream_statistics_print_profile[] = {2, 2, 2, 1, 0, 0, 0, 0, 1, + 1, 1, 0, 0, 2, 2, 0, 0}; +int ap2_buffered_nosync_stream_statistics_print_profile[] = {2, 0, 0, 1, 0, 0, 0, 0, 1, 1, 1, 0, 0, 0, 0, 0, 0}; int ap2_buffered_nodelay_stream_statistics_print_profile[] = {0, 0, 0, 1, 0, 0, 0, 0, 0, 1, 1, 0, 0, 0, 0, 0, 0}; void statistics_item(const char *heading, const char *format, ...) { - if (statistics_print_profile[statistics_column] == 1) { // include this column? + if (((statistics_print_profile[statistics_column] == 1) && (debuglev != 0)) || + (statistics_print_profile[statistics_column] == 2)) { // include this column? if (was_a_previous_column != 0) strcat(line_of_stats, " "); if (statistics_row == 0) { @@ -1624,10 +1625,10 @@ void player_thread_cleanup_handler(void *arg) { int elapsedSec = rawSeconds % 60; if (conn->frame_rate_valid) inform("Connection %d: Playback Stopped. Total playing time %02d:%02d:%02d. Input: %0.2f, " - "output: %0.2f " + " Output: %0.2f (raw), %0.2f (corrected) " "frames per second.", conn->connection_number, elapsedHours, elapsedMin, elapsedSec, conn->input_frame_rate, - conn->frame_rate); + conn->raw_frame_rate, conn->corrected_frame_rate); else inform("Connection %d: Playback Stopped. Total playing time %02d:%02d:%02d. Input: %0.2f " "frames per second.", @@ -1727,7 +1728,8 @@ void *player_thread_func(void *arg) { rtsp_conn_info *conn = (rtsp_conn_info *)arg; uint64_t previous_frames_played; - uint64_t previous_frames_played_time; + uint64_t previous_raw_measurement_time; + uint64_t previous_corrected_measurement_time; int previous_frames_played_valid = 0; // pthread_cleanup_push(player_thread_initial_cleanup_handler, arg); @@ -1888,7 +1890,8 @@ void *player_thread_func(void *arg) { conn->playstart = time(NULL); - conn->frame_rate = 0.0; + conn->raw_frame_rate = 0.0; + conn->corrected_frame_rate = 0.0; conn->frame_rate_valid = 0; conn->input_frame_rate = 0.0; @@ -2335,10 +2338,12 @@ void *player_thread_func(void *arg) { int stats_status = 0; if ((config.output->delay) && (config.no_sync == 0) && (config.output->stats)) { uint64_t frames_sent_for_play; - uint64_t measurement_time; + uint64_t raw_measurement_time; + uint64_t corrected_measurement_time; uint64_t actual_delay; stats_status = - config.output->stats(&measurement_time, &actual_delay, &frames_sent_for_play); + config.output->stats(&raw_measurement_time, &corrected_measurement_time, + &actual_delay, &frames_sent_for_play); // debug(1,"status: %d, actual_delay: %" PRIu64 ", frames_sent_for_play: %" PRIu64 ", // frames_played: %" PRIu64 ".", stats_status, actual_delay, frames_sent_for_play, // frames_sent_for_play - actual_delay); @@ -2347,9 +2352,13 @@ void *player_thread_func(void *arg) { // last time the stats call was made. Thus, the frame rate should be valid. if ((stats_status == 0) && (previous_frames_played_valid != 0)) { uint64_t frames_played_in_this_interval = frames_played - previous_frames_played; - int64_t interval = measurement_time - previous_frames_played_time; - if (interval != 0) { - conn->frame_rate = (1e9 * frames_played_in_this_interval) / interval; + int64_t raw_interval = raw_measurement_time - previous_raw_measurement_time; + int64_t corrected_interval = + corrected_measurement_time - previous_corrected_measurement_time; + if (raw_interval != 0) { + conn->raw_frame_rate = (1e9 * frames_played_in_this_interval) / raw_interval; + conn->corrected_frame_rate = + (1e9 * frames_played_in_this_interval) / corrected_interval; conn->frame_rate_valid = 1; // debug(1,"frames_played_in_this_interval: %" PRIu64 ", interval: %" PRId64 ", // rate: %f.", @@ -2365,7 +2374,8 @@ void *player_thread_func(void *arg) { if (stats_status != 0) conn->frame_rate_valid = 0; previous_frames_played = frames_played; - previous_frames_played_time = measurement_time; + previous_raw_measurement_time = raw_measurement_time; + previous_corrected_measurement_time = corrected_measurement_time; previous_frames_played_valid = 1; } } @@ -2411,15 +2421,19 @@ void *player_thread_func(void *arg) { statistics_item("min buffers", "%*" PRIu32 "", 11, minimum_buffer_occupancy); statistics_item("max buffers", "%*" PRIu32 "", 11, maximum_buffer_occupancy); statistics_item("nominal fps", "%*.2f", 11, conn->remote_frame_rate); - statistics_item(" actual fps", "%*.2f", 11, conn->input_frame_rate); - if (conn->frame_rate_valid) - statistics_item(" output fps", "%*.2f", 11, conn->frame_rate); - else - statistics_item(" output fps", " N/A"); + statistics_item("received fps", "%*.2f", 12, conn->input_frame_rate); + if (conn->frame_rate_valid) { + statistics_item("output fps (r)", "%*.2f", 14, conn->raw_frame_rate); + statistics_item("output fps (c)", "%*.2f", 14, conn->corrected_frame_rate); + } else { + statistics_item("output fps (r)", " N/A"); + statistics_item("output fps (c)", " N/A"); + } statistics_item("source drift ppm", "%*.2f", 16, (conn->local_to_remote_time_gradient - 1.0) * 1000000); statistics_item("drift samples", "%*d", 13, conn->local_to_remote_time_gradient_sample_count); + /* statistics_item("estimated (unused) correction ppm", "%*.2f", strlen("estimated (unused) correction ppm"), (conn->frame_rate_valid != 0) @@ -2429,6 +2443,7 @@ void *player_thread_func(void *arg) { 1000000) / conn->frame_rate : 0.0); + */ statistics_row++; inform(line_of_stats); } while (statistics_row < 2); diff --git a/player.h b/player.h index b08a379e..d37f00c7 100644 --- a/player.h +++ b/player.h @@ -180,7 +180,8 @@ typedef struct { stats_t *statistics; // for holding the output rate information until printed out at the end of a session - double frame_rate; + double raw_frame_rate; + double corrected_frame_rate; int frame_rate_valid; // for holding input rate information until printed out at the end of a session diff --git a/rtp.c b/rtp.c index a79e0bbd..5b79ff4b 100644 --- a/rtp.c +++ b/rtp.c @@ -1762,7 +1762,7 @@ void rtp_realtime_audio_cleanup_handler(__attribute__((unused)) void *arg) { debug(2, "Realtime Audio Receiver Cleanup Start."); rtsp_conn_info *conn = (rtsp_conn_info *)arg; close(conn->realtime_audio_socket); - debug(1, "Connection %d: closing realtime audio port %u", conn->local_realtime_audio_port); + debug(2, "Connection %d: closing realtime audio port %u", conn->local_realtime_audio_port); conn->realtime_audio_socket = 0; debug(2, "Realtime Audio Receiver Cleanup Done."); } diff --git a/rtsp.c b/rtsp.c index 5f9fa9ab..079ad14d 100644 --- a/rtsp.c +++ b/rtsp.c @@ -583,7 +583,11 @@ void *player_watchdog_thread_code(void *arg) { do { usleep(2000000); // check every two seconds // debug(3, "Connection %d: Check the thread is doing something...", conn->connection_number); +#ifdef CONFIG_AIRPLAY_2 + if ((config.dont_check_timeout == 0) && (config.timeout != 0) && (conn->airplay_type == ap_1)) { +#else if ((config.dont_check_timeout == 0) && (config.timeout != 0)) { +#endif debug_mutex_lock(&conn->watchdog_mutex, 1000, 0); uint64_t last_watchdog_bark_time = conn->watchdog_bark_time; debug_mutex_unlock(&conn->watchdog_mutex, 0); From e3faba141c24bdbec191c46010c7d394453a9969 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Sun, 28 Nov 2021 21:51:26 +0000 Subject: [PATCH 17/40] log statsistics headers whenever verbosity goes on or off or whenever statistics are requested --- dbus-service.c | 4 ++++ player.h | 1 + 2 files changed, 5 insertions(+) diff --git a/dbus-service.c b/dbus-service.c index bbd5dcd4..05dd9726 100644 --- a/dbus-service.c +++ b/dbus-service.c @@ -423,6 +423,8 @@ gboolean notify_statistics_callback(ShairportSyncDiagnostics *skeleton, // debug(1, "\"notify_statistics_callback\" called."); if (shairport_sync_diagnostics_get_statistics(skeleton)) { debug(1, ">> start logging statistics"); + if (config.statistics_requested == 0) + statistics_row = 0; // redraw the header line config.statistics_requested = 1; } else { debug(1, ">> stop logging statistics"); @@ -437,6 +439,8 @@ gboolean notify_verbosity_callback(ShairportSyncDiagnostics *skeleton, if ((th >= 0) && (th <= 3)) { if (th == 0) debug(1, ">> log verbosity set to %d.", th); + if (((debuglev == 0) && (th != 0)) || ((debuglev != 0) && (th == 0))) + statistics_row = 0; // if the debug level changes, redraw the header line debuglev = th; debug(1, ">> log verbosity set to %d.", th); } else { diff --git a/player.h b/player.h index d37f00c7..edf80837 100644 --- a/player.h +++ b/player.h @@ -410,6 +410,7 @@ typedef struct { } rtsp_conn_info; extern pthread_mutex_t playing_conn_lock; +extern int statistics_row; // will be reset to zero when debug level changes or statistics enabled void reset_buffer(rtsp_conn_info *conn); From 7b8e293f8b4c8ea3a7d7aeb148ffed6b10d44288 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Wed, 1 Dec 2021 09:01:31 +0000 Subject: [PATCH 18/40] Change behaviour after an unrecoverable error -- if not handled, exit Shairport Sync. --- player.c | 2 +- rtsp.c | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/player.c b/player.c index 9b0b86ca..e9fa556a 100644 --- a/player.c +++ b/player.c @@ -1168,7 +1168,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { if (config.cmd_unfixable) { command_execute(config.cmd_unfixable, "output_device_stalled", 1); } else { - warn("an unrecoverable error, \"output_device_stalled\", has been " + die("an unrecoverable error, \"output_device_stalled\", has been " "detected.", conn->connection_number); } diff --git a/rtsp.c b/rtsp.c index 079ad14d..ae650a6a 100644 --- a/rtsp.c +++ b/rtsp.c @@ -611,7 +611,7 @@ void *player_watchdog_thread_code(void *arg) { conn->unfixable_error_reported = 1; command_execute(config.cmd_unfixable, "unable_to_cancel_play_session", 1); } else { - warn("an unrecoverable error, \"unable_to_cancel_play_session\", has been detected.", + die("an unrecoverable error, \"unable_to_cancel_play_session\", has been detected.", conn->connection_number); } } From b3526c54726c627b9e083ed0eed9b770bca3f829 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Wed, 1 Dec 2021 17:58:22 +0000 Subject: [PATCH 19/40] Use PKG_CHECK_MODULES to find libavcodec, to make it work with Fedora 35 (?) --- configure.ac | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/configure.ac b/configure.ac index e0dcb10f..7f31e167 100644 --- a/configure.ac +++ b/configure.ac @@ -413,7 +413,9 @@ if test "x$with_airplay_2" = "xyes" ; then # PKG_CHECK_MODULES([libgcrypt], [libgcrypt],[CFLAGS="${libgcrypt_CFLAGS} ${CFLAGS}" LIBS="${libgcrypt_LIBS} ${LIBS}"],[AC_MSG_ERROR(AirPlay 2 support requires libgcrypt -- libgcrypt-dev suggested)]) # AC_CHECK_LIB([sodium], [sodium_init], ,[AC_MSG_ERROR([AirPlay 2 support requires libsodium -- libsodium-dev suggested])]) AC_CHECK_LIB([avutil],[av_malloc], [], [AC_MSG_ERROR([Airplay 2 support requires libavutil -- libavutil-dev suggested])]) - AC_CHECK_LIB([avcodec],[avcodec_find_encoder], [], [AC_MSG_ERROR([AirPlay 2 support requires libavcodec -- libavcodec-dev suggested])]) + PKG_CHECK_MODULES([libavcodec], [libavcodec],[CFLAGS="${libavcodec_CFLAGS} ${CFLAGS}" LIBS="${libavcodec_LIBS} ${LIBS}"],[ + AC_MSG_ERROR(AirPlay 2 support requires libavcodec -- libavcodec-dev suggested)]) +# AC_CHECK_LIB([avcodec],[avcodec_find_encoder], [], [AC_MSG_ERROR([AirPlay 2 support requires libavcodec -- libavcodec-dev suggested])]) AC_CHECK_LIB([avformat],[avformat_new_stream], [], [AC_MSG_ERROR([AirPlay 2 support requires libavformat -- libavformat-dev suggested])]) AC_CHECK_LIB([swresample],[swr_convert], [], [AC_MSG_ERROR([AirPlay 2 support requires libswresample -- libswresample-dev suggested])]) AC_CHECK_LIB([uuid],[uuid_generate], [], [AC_MSG_ERROR([AirPlay 2 support requires the uuid library -- uuid-dev suggested])]) From 60f830bc7541e374dc87d72cc956452c924a7a75 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Thu, 2 Dec 2021 11:16:00 +0000 Subject: [PATCH 20/40] Tidy up the statistics printout table and stop outputting (non existent) nominal fps for AP2 Realtime Streams. --- player.c | 28 +++++++++++----------------- 1 file changed, 11 insertions(+), 17 deletions(-) diff --git a/player.c b/player.c index e9fa556a..257d2ee8 100644 --- a/player.c +++ b/player.c @@ -1554,25 +1554,19 @@ int *statistics_print_profile; // these arrays specify which of the statistics specified by the statistics_item calls will actually // be printed -- 2 means print, 1 means print only in a debug mode, 0 means skip -// don't display output fps -- not sure how accurate it is (change item 14 and 17 to 1 to restore) -int ap1_synced_statistics_print_profile[] = {2, 2, 2, 1, 2, 1, 1, 2, 1, 1, 1, 1, 1, 2, 2, 1, 1}; -int ap1_nosync_statistics_print_profile[] = {2, 0, 0, 1, 2, 1, 1, 2, 1, 1, 1, 1, 1, 0, 0, 1, 0}; -int ap1_nodelay_statistics_print_profile[] = {0, 0, 0, 1, 2, 1, 1, 2, 0, 1, 1, 1, 1, 0, 0, 1, 0}; +// clang-format off +int ap1_synced_statistics_print_profile[] = {2, 2, 2, 1, 2, 1, 1, 2, 1, 1, 1, 1, 1, 2, 2, 1, 1}; +int ap1_nosync_statistics_print_profile[] = {2, 0, 0, 1, 2, 1, 1, 2, 1, 1, 1, 1, 1, 0, 0, 1, 0}; +int ap1_nodelay_statistics_print_profile[] = {0, 0, 0, 1, 2, 1, 1, 2, 0, 1, 1, 1, 1, 0, 0, 1, 0}; -int ap2_realtime_synced_stream_statistics_print_profile[] = {2, 2, 2, 1, 2, 1, 1, 2, 1, - 1, 1, 1, 1, 2, 2, 0, 0}; -int ap2_realtime_nosync_stream_statistics_print_profile[] = {2, 0, 0, 1, 2, 1, 1, 2, 1, - 1, 1, 1, 1, 0, 0, 0, 0}; -int ap2_realtime_nodelay_stream_statistics_print_profile[] = {0, 0, 0, 1, 2, 1, 1, 2, 0, - 1, 1, 1, 1, 0, 0, 0, 0}; +int ap2_realtime_synced_stream_statistics_print_profile[] = {2, 2, 2, 1, 2, 1, 1, 2, 1, 1, 1, 0, 1, 2, 2, 0, 0}; +int ap2_realtime_nosync_stream_statistics_print_profile[] = {2, 0, 0, 1, 2, 1, 1, 2, 1, 1, 1, 0, 1, 0, 0, 0, 0}; +int ap2_realtime_nodelay_stream_statistics_print_profile[] = {0, 0, 0, 1, 2, 1, 1, 2, 0, 1, 1, 0, 1, 0, 0, 0, 0}; -// don't display output fps -- not sure how accurate it is (change item 14 1 to restore) -int ap2_buffered_synced_stream_statistics_print_profile[] = {2, 2, 2, 1, 0, 0, 0, 0, 1, - 1, 1, 0, 0, 2, 2, 0, 0}; -int ap2_buffered_nosync_stream_statistics_print_profile[] = {2, 0, 0, 1, 0, 0, 0, 0, 1, - 1, 1, 0, 0, 0, 0, 0, 0}; -int ap2_buffered_nodelay_stream_statistics_print_profile[] = {0, 0, 0, 1, 0, 0, 0, 0, 0, - 1, 1, 0, 0, 0, 0, 0, 0}; +int ap2_buffered_synced_stream_statistics_print_profile[] = {2, 2, 2, 1, 0, 0, 0, 0, 1, 1, 1, 0, 0, 2, 2, 0, 0}; +int ap2_buffered_nosync_stream_statistics_print_profile[] = {2, 0, 0, 1, 0, 0, 0, 0, 1, 1, 1, 0, 0, 0, 0, 0, 0}; +int ap2_buffered_nodelay_stream_statistics_print_profile[] = {0, 0, 0, 1, 0, 0, 0, 0, 0, 1, 1, 0, 0, 0, 0, 0, 0}; +// clang-format on void statistics_item(const char *heading, const char *format, ...) { if (((statistics_print_profile[statistics_column] == 1) && (debuglev != 0)) || From d32544d9047e3c3286819c93a56acd9a387c67bd Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Thu, 2 Dec 2021 11:17:59 +0000 Subject: [PATCH 21/40] Set the timing peer list as soon as a SETPEERS message is received -- don't wait until play is about to begin. Not sure if it works universally yet. --- rtsp.c | 15 ++++++++------- 1 file changed, 8 insertions(+), 7 deletions(-) diff --git a/rtsp.c b/rtsp.c index ae650a6a..ba03359f 100644 --- a/rtsp.c +++ b/rtsp.c @@ -1756,7 +1756,7 @@ void handle_setrateanchori(rtsp_conn_info *conn, rtsp_message *req, rtsp_message if ((rate & 1) != 0) { // keep this outside the flush_mutex lock if (conn->ap2_timing_peer_list_message) { - ptp_send_control_message_string(conn->ap2_timing_peer_list_message); + // ptp_send_control_message_string(conn->ap2_timing_peer_list_message); } else { debug(1, "Connection %d: No timing peer list!", conn->connection_number); } @@ -2290,10 +2290,10 @@ void handle_setpeers(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp free(conn->ap2_timing_peer_list_message); conn->ap2_timing_peer_list_message = strdup(timing_list_message); // if this rtsp thread is playing... - if (try_to_hold_play_lock(conn) == 0) { + // if (try_to_hold_play_lock(conn) == 0) { ptp_send_control_message_string(conn->ap2_timing_peer_list_message); - release_hold_on_play_lock(conn); - } + // release_hold_on_play_lock(conn); + // } } plist_free(addresses_array); resp->respcode = 200; @@ -2876,10 +2876,11 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) conn->input_bit_depth = conn->stream.fmtp[3]; conn->input_bytes_per_frame = conn->input_num_channels * ((conn->input_bit_depth + 7) / 8); debug(2, "Realtime Stream Play"); - if (conn->ap2_timing_peer_list_message) - ptp_send_control_message_string(conn->ap2_timing_peer_list_message); - else + if (conn->ap2_timing_peer_list_message) { + // ptp_send_control_message_string(conn->ap2_timing_peer_list_message); + } else { debug(1, "No timing peer list!"); + } activity_monitor_signify_activity(1); player_prepare_to_play(conn); player_play(conn); From 231d5242d782483a44176b8e1efddb9ca4b2be0c Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Thu, 2 Dec 2021 11:19:52 +0000 Subject: [PATCH 22/40] clang format only --- player.c | 4 ++-- rtsp.c | 6 +++--- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/player.c b/player.c index 257d2ee8..36c7aabf 100644 --- a/player.c +++ b/player.c @@ -1169,8 +1169,8 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { command_execute(config.cmd_unfixable, "output_device_stalled", 1); } else { die("an unrecoverable error, \"output_device_stalled\", has been " - "detected.", - conn->connection_number); + "detected.", + conn->connection_number); } } } else { diff --git a/rtsp.c b/rtsp.c index ba03359f..45efd8cf 100644 --- a/rtsp.c +++ b/rtsp.c @@ -612,7 +612,7 @@ void *player_watchdog_thread_code(void *arg) { command_execute(config.cmd_unfixable, "unable_to_cancel_play_session", 1); } else { die("an unrecoverable error, \"unable_to_cancel_play_session\", has been detected.", - conn->connection_number); + conn->connection_number); } } } @@ -2291,8 +2291,8 @@ void handle_setpeers(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp conn->ap2_timing_peer_list_message = strdup(timing_list_message); // if this rtsp thread is playing... // if (try_to_hold_play_lock(conn) == 0) { - ptp_send_control_message_string(conn->ap2_timing_peer_list_message); - // release_hold_on_play_lock(conn); + ptp_send_control_message_string(conn->ap2_timing_peer_list_message); + // release_hold_on_play_lock(conn); // } } plist_free(addresses_array); From 41f55ac1cb4b371ac8dec4155ffabcccc6facd51 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Mon, 6 Dec 2021 18:03:42 +0000 Subject: [PATCH 23/40] Stop clearing the timing peer list and stop removing the anchor clock info. --- player.c | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/player.c b/player.c index 36c7aabf..da98c55b 100644 --- a/player.c +++ b/player.c @@ -383,6 +383,10 @@ void reset_buffer(rtsp_conn_info *conn) { debug_mutex_lock(&conn->ab_mutex, 30000, 0); ab_resync(conn); debug_mutex_unlock(&conn->ab_mutex, 0); + if (config.output->flush) { + config.output->flush(); // no cancellation points +// debug(1, "reset_buffer: flush output device."); + } } void get_audio_buffer_size_and_occupancy(unsigned int *size, unsigned int *occupancy, @@ -1687,7 +1691,7 @@ void player_thread_cleanup_handler(void *arg) { debug(3, "Audio thread terminated."); #ifdef CONFIG_AIRPLAY_2 } - ptp_send_control_message_string("T"); // remove all timing peers to force the master to 0 + // ptp_send_control_message_string("T"); // remove all timing peers to force the master to 0 #endif if (conn->outbuf) { @@ -1711,7 +1715,7 @@ void player_thread_cleanup_handler(void *arg) { if (conn->stream.type == ast_apple_lossless) terminate_decoders(conn); - reset_anchor_info(conn); + // reset_anchor_info(conn); release_play_lock(conn); conn->rtp_running = 0; pthread_setcancelstate(oldState, NULL); @@ -1747,7 +1751,7 @@ void *player_thread_func(void *arg) { conn->ap2_play_enabled = 0; #endif - reset_anchor_info(conn); + // reset_anchor_info(conn); if (conn->stream.type == ast_apple_lossless) init_alac_decoder((int32_t *)&conn->stream.fmtp, From fa20d88c1c2b46391a6de88f187fd8c816bd7806 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Mon, 6 Dec 2021 18:08:35 +0000 Subject: [PATCH 24/40] Remember to add some exta fields later... --- plists/get_info_response.xml | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/plists/get_info_response.xml b/plists/get_info_response.xml index 7a3b7a05..b45e3bad 100644 --- a/plists/get_info_response.xml +++ b/plists/get_info_response.xml @@ -60,7 +60,8 @@ 366.0 statusFlags 4 - txtAirPlay - + + From be4807fff205b7022d7fed2bc27b29ce1f1d38fa Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Mon, 6 Dec 2021 18:09:29 +0000 Subject: [PATCH 25/40] Wait for that mutex for longer. (Don't know why yet...) --- ptp-utilities.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/ptp-utilities.c b/ptp-utilities.c index 7019187e..fa1c6407 100644 --- a/ptp-utilities.c +++ b/ptp-utilities.c @@ -68,7 +68,7 @@ int get_nqptp_data(struct shm_structure *nqptp_data) { int ptp_get_clock_info(uint64_t *actual_clock_id, uint64_t *time_of_sample, uint64_t *raw_offset, uint64_t *mastership_start_time) { int response = clock_ok; - pthread_cleanup_debug_mutex_lock(&ptp_access_mutex, 20000, 1); + pthread_cleanup_debug_mutex_lock(&ptp_access_mutex, 50000, 1); if (actual_clock_id != NULL) *actual_clock_id = 0; if (raw_offset != NULL) From 0b21373c0e5ba8e565bf420ed2ad8eb79f23d491 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Mon, 6 Dec 2021 18:13:20 +0000 Subject: [PATCH 26/40] Skip some invalid AAC packets, don't decode outdated frames, wait for timing information to be valid. --- rtp.c | 61 ++++++++++++++++++++++++++++++++++++++++++++++------------- 1 file changed, 48 insertions(+), 13 deletions(-) diff --git a/rtp.c b/rtp.c index 5b79ff4b..d3bf06c4 100644 --- a/rtp.c +++ b/rtp.c @@ -1310,7 +1310,7 @@ int get_ptp_anchor_local_time_info(rtsp_conn_info *conn, uint32_t *anchorRTP, // if the master clock and the anchor clock are the same // wait at least this time before using the new master clock // note that mastershipo may be backdated - if (duration_of_mastership < 1500000000) { + if (duration_of_mastership < 100000000) { debug(3, "master not old enough yet: %f ms", 0.000001 * duration_of_mastership); response = clock_not_ready; } else if ((duration_of_mastership > 5000000000) || @@ -1400,6 +1400,7 @@ int get_ptp_anchor_local_time_info(rtsp_conn_info *conn, uint32_t *anchorRTP, } } } else { + // debug(1, "anchor_remote_info_is_valid not valid"); response = clock_no_anchor_info; // no anchor information } } @@ -2253,7 +2254,14 @@ void *rtp_buffered_audio_processor(void *arg) { int streaming_has_started = 0; int play_enabled = 0; uint32_t flush_from_timestamp; - double requested_lead_time = 0.3; // normal lead time minimum + double requested_lead_time = 0.0; // normal lead time minimum -- maybe it should be about 0.1 + + // wait until our timing information is valid + + // debug(1,"rtp_buffered_audio_processor ready."); + while (have_ptp_timing_information(conn) == 0) + usleep(1000); + reset_buffer(conn); // in case there is any garbage in the player // int not_first_time_out = 0; @@ -2519,28 +2527,42 @@ void *rtp_buffered_audio_processor(void *arg) { // to decipher it first // debug(1,"seq_no %u, timestamp %u", seq_no, timestamp); + uint64_t local_should_be_time = 0; + int have_time_information = frame_to_local_time(timestamp, &local_should_be_time, conn); + int64_t local_lead_time = 0; + int64_t requested_lead_time_ns = (int64_t)(requested_lead_time * 1000000000); + requested_lead_time_ns = (int64_t)(-300000000); + int outdated = 0; + if (have_time_information == 0) { + local_lead_time = local_should_be_time - get_absolute_time_in_ns(); + outdated = (local_lead_time < requested_lead_time_ns); + // if (outdated != 0) + // debug(1,"Frame is outdated %d if lead_time %" PRId64 " is less than requested lead time %" PRId64 " ns.", outdated, local_lead_time, requested_lead_time_ns); + } else { + debug(1,"Timing information not valid"); + // outdated = 1; + } + + if ((flush_requested) && (seq_no >= flushUntilSeq)) { - uint64_t should_be_time; - if ((frame_to_local_time(timestamp, &should_be_time, conn) == 0) && (play_enabled)) { + if ((have_time_information == 0) && (play_enabled)) { // play enabled will be off when this is a full flush and the anchor information is not // valid - int64_t lead_time = should_be_time - get_absolute_time_in_ns(); - debug(1, + debug(2, "flush completed to seq: %u, flushUntilTS; %u with rtptime: %u, lead time: " "0x%" PRIx64 " nanoseconds, i.e. %f sec.", - seq_no, flushUntilTS, timestamp, lead_time, lead_time * 0.000000001); + seq_no, flushUntilTS, timestamp, local_lead_time, local_lead_time * 0.000000001); } else { debug(2, "flush completed to seq: %u with rtptime: %u.", seq_no, timestamp); } } - - if (((flush_requested != 0) && (seq_no == flushUntilSeq)) || - ((flush_requested == 0) && (new_buffer_needed))) { - + // if we are here because of a flush request, it must be the case that // flushing the pcm buffer wasn't enough, as the request would have been turned off by now // so we better indicate that the pcm buffer is empty and its contents invalid - if (flush_requested) { + + // also, if the incomgin frame is outdated, set pcm_buffer_occupancy to 0; + if ((flush_requested) || (outdated)){ pcm_buffer_occupancy = 0; } @@ -2556,6 +2578,11 @@ void *rtp_buffered_audio_processor(void *arg) { //} } + + if (((flush_requested != 0) && (seq_no == flushUntilSeq)) || + ((flush_requested == 0) && (new_buffer_needed))) { + + unsigned char nonce[12]; memset(nonce, 0, sizeof(nonce)); memcpy(nonce + 4, packet + nread - 8, @@ -2596,6 +2623,7 @@ void *rtp_buffered_audio_processor(void *arg) { data_remaining = aac_packet_length; int ret = 0; // there can be more than one av packet (? terminology) in a block + int frame_within_block = 0; while (data_remaining > 0) { if (decoded_frame == NULL) { decoded_frame = av_frame_alloc(); @@ -2608,14 +2636,20 @@ void *rtp_buffered_audio_processor(void *arg) { if (ret < 0) { debug(1, "error while parsing deciphered audio packet."); } else { + frame_within_block++; data_to_process += ret; data_remaining -= ret; // debug(1, "frame found"); // now pass each packet to be decoded if (pkt->size) { + //if (0) { + if (pkt->size <= 7) { // no idea about this... + debug(1,"malformed AAC packet skipped."); + } else { ret = avcodec_send_packet(codec_context, pkt); + if (ret < 0) { - debug(1, "error sending packet to decoder"); + debug(1, "error sending frame %d of size %d to decoder, blocks_read: %u, blocks_read_since_flush: %u.", frame_within_block, pkt->size, blocks_read, blocks_read_since_flush); } else { while (ret >= 0) { ret = avcodec_receive_frame(codec_context, decoded_frame); @@ -2672,6 +2706,7 @@ void *rtp_buffered_audio_processor(void *arg) { } } } + } } if (decoded_frame == NULL) debug(1, "decoded_frame is NULL"); From 3b9f2e1c53ede54dcbfba551bc534d2efd43c557 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Mon, 6 Dec 2021 18:14:23 +0000 Subject: [PATCH 27/40] Don't ask for cover art if not asking for metadata too. Duh. --- shairport.c | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/shairport.c b/shairport.c index 9b7648e3..b1faf5c9 100644 --- a/shairport.c +++ b/shairport.c @@ -1807,11 +1807,12 @@ int main(int argc, char **argv) { #ifdef CONFIG_METADATA // If we are asking for metadata, turn on the relevant bits - if (config.metadata_enabled != 0) + if (config.metadata_enabled != 0) { config.airplay_features |= (1 << 17) | (1 << 16); // 16 is progress, 17 is text - // If we are asking for artwork, turn on the relevant bit - if (config.get_coverart) - config.airplay_features |= (1 << 15); // 15 is artwork + // If we are asking for artwork, turn on the relevant bit + if (config.get_coverart) + config.airplay_features |= (1 << 15); // 15 is artwork + } #endif debug(1, "Features: 0x%" PRIx64 ".", config.airplay_features); From 1e2136821337dd73f4ac563e0ff6f3ff5790a92c Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Mon, 6 Dec 2021 18:16:57 +0000 Subject: [PATCH 28/40] Add txtAirPlay data to info response. Don't pause long RTSP message reception. --- rtsp.c | 127 +++++++++++++++++++++++++++++++++++++++++++++++++-------- 1 file changed, 110 insertions(+), 17 deletions(-) diff --git a/rtsp.c b/rtsp.c index 45efd8cf..6c0da18f 100644 --- a/rtsp.c +++ b/rtsp.c @@ -185,6 +185,39 @@ typedef struct { #ifdef CONFIG_AIRPLAY_2 +int add_pstring_to_malloc(const char *s, void **allocation, size_t *size) { + int response = 0; + void *p = *allocation; + if (p == NULL) { + p = malloc(strlen(s) + 1); + if (p == NULL) { + debug(1, "error allocating memory"); + } else { + *allocation = p; + *size = *size + strlen(s) + 1; + uint8_t *b = (uint8_t *)p; + *b = strlen(s); + p = p+1; + memcpy(p,s,strlen(s)); + response = 1; + } + } else { + p = realloc(p, *size + strlen(s) + 1); + if (p == NULL) { // assuming we never allocate a zero byte space + debug(1, "error reallocating memory"); + } else { + *allocation = p; + uint8_t *b = (uint8_t *)p + *size; + *b = strlen(s); + p = p + *size + 1; + memcpy(p,s,strlen(s)); + *size = *size + strlen(s) + 1; + response = 1; + } + } + return response; +} + static void pkString_make(char *str, size_t str_size, const char *device_id) { uint8_t public_key[32]; if (str_size < 2 * sizeof(public_key) + 1) { @@ -1139,6 +1172,8 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes enum rtsp_read_request_response reply = rtsp_read_request_response_ok; ssize_t buflen = 4096; + if ((config.metadata_enabled != 0) && (config.get_coverart != 0)) + buflen = 1024 * 256; // big enough for typical picture data, which will be base64 encoded int release_buffer = 0; // on exit, don't deallocate the buffer if everything was okay char *buf = malloc(buflen + 1); // add a NUL at the end if (!buf) { @@ -1228,7 +1263,7 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes get_absolute_time_in_ns() + ((uint64_t)15000000000); // i.e. fifteen seconds from now int warning_message_sent = 0; - const size_t max_read_chunk = 1024 * 1024 / 16; + // const size_t max_read_chunk = 1024 * 1024 / 16; while (inbuf < msg_size) { // we are going to read the stream in chunks and time how long it takes to @@ -1255,9 +1290,9 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes goto shutdown; } size_t read_chunk = msg_size - inbuf; - if (read_chunk > max_read_chunk) - read_chunk = max_read_chunk; - usleep(80000); // wait about 80 milliseconds between reads of up to max_read_chunk + //if (read_chunk > max_read_chunk) + // read_chunk = max_read_chunk; + // usleep(80000); // wait about 80 milliseconds between reads of up to max_read_chunk nread = read_from_rtsp_connection(conn, buf + inbuf, read_chunk); if (!nread) { reply = rtsp_read_request_response_error; @@ -1476,7 +1511,7 @@ void handle_record(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) void handle_get_info(__attribute((unused)) rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { - + debug_log_rtsp_message(2, "GET /info:", req); if (rtsp_message_contains_plist(req)) { // it's stage one // get version of AirPlay -- it might be too old. Not using it yet. char *hdr = msg_get_header(req, "User-Agent"); @@ -1519,6 +1554,43 @@ void handle_get_info(__attribute((unused)) rtsp_conn_info *conn, rtsp_message *r if (response_plist == NULL) { debug(1, "GET /info Stage 1: response plist not created from XML!"); } else { + void *qualifier_response_data = NULL; + size_t qualifier_response_data_length = 0; + if (add_pstring_to_malloc("acl=0", &qualifier_response_data, &qualifier_response_data_length) == 0) + debug(1, "Problem"); + if (add_pstring_to_malloc(deviceIdString, &qualifier_response_data, &qualifier_response_data_length) == 0) + debug(1, "Problem"); + if (add_pstring_to_malloc(featuresString, &qualifier_response_data, &qualifier_response_data_length) == 0) + debug(1, "Problem"); + if (add_pstring_to_malloc("rsf=0x0", &qualifier_response_data, &qualifier_response_data_length) == 0) + debug(1, "Problem"); + if (add_pstring_to_malloc("flags=0x4", &qualifier_response_data, &qualifier_response_data_length) == 0) + debug(1, "Problem"); + if (add_pstring_to_malloc("model=Shairport Sync", &qualifier_response_data, &qualifier_response_data_length) == 0) + debug(1, "Problem"); + if (add_pstring_to_malloc("manufacturer=", &qualifier_response_data, &qualifier_response_data_length) == 0) + debug(1, "Problem"); + if (add_pstring_to_malloc("serialNumber=", &qualifier_response_data, &qualifier_response_data_length) == 0) + debug(1, "Problem"); + if (add_pstring_to_malloc("protovers=1.1", &qualifier_response_data, &qualifier_response_data_length) == 0) + debug(1, "Problem"); + if (add_pstring_to_malloc("srcvers=366.0", &qualifier_response_data, &qualifier_response_data_length) == 0) + debug(1, "Problem"); + if (add_pstring_to_malloc(piString, &qualifier_response_data, &qualifier_response_data_length) == 0) + debug(1, "Problem"); + if (add_pstring_to_malloc(gidString, &qualifier_response_data, &qualifier_response_data_length) == 0) + debug(1, "Problem"); + if (add_pstring_to_malloc("gcgl=0", &qualifier_response_data, &qualifier_response_data_length) == 0) + debug(1, "Problem"); + snprintf(pkString, sizeof(pkString), "pk="); + pkString_make(pkString + strlen("pk="), sizeof(pkString) - strlen("pk="), + config.airplay_device_id); + if (add_pstring_to_malloc(pkString, &qualifier_response_data, &qualifier_response_data_length) == 0) + debug(1, "Problem"); + // debug(1,"qualifier_response_data_length: %u.", qualifier_response_data_length); + + plist_dict_set_item(response_plist, "txtAirPlay", plist_new_data(qualifier_response_data, qualifier_response_data_length)); + plist_dict_set_item(response_plist, "features", plist_new_uint(config.airplay_features)); plist_dict_set_item(response_plist, "statusFlags", plist_new_uint(config.airplay_statusflags)); @@ -1526,15 +1598,16 @@ void handle_get_info(__attribute((unused)) rtsp_conn_info *conn, rtsp_message *r plist_dict_set_item(response_plist, "pi", plist_new_string(config.airplay_pi)); plist_dict_set_item(response_plist, "name", plist_new_string(config.service_name)); char *vs = get_version_string(); - plist_dict_set_item(response_plist, "model", plist_new_string(vs)); +// plist_dict_set_item(response_plist, "model", plist_new_string(vs)); + plist_dict_set_item(response_plist, "model", plist_new_string("Shairport Sync")); free(vs); - char pkString[128]; - pkString_make(pkString, sizeof(pkString), config.airplay_device_id); - plist_dict_set_item(response_plist, "pk", plist_new_string(pkString)); + //pkString_make(pkString, sizeof(pkString), config.airplay_device_id); + //plist_dict_set_item(response_plist, "pk", plist_new_string(pkString)); plist_to_bin(response_plist, &resp->content, &resp->contentlength); if (resp->contentlength == 0) debug(1, "GET /info Stage 1: response bplist not created!"); plist_free(response_plist); + free(qualifier_response_data); } msg_add_header(resp, "Content-Type", "application/x-apple-binary-plist"); debug_log_rtsp_message(2, "GET /info Stage 1 Response:", resp); @@ -1554,11 +1627,11 @@ void handle_get_info(__attribute((unused)) rtsp_conn_info *conn, rtsp_message *r plist_dict_set_item(response_plist, "pi", plist_new_string(config.airplay_pi)); plist_dict_set_item(response_plist, "name", plist_new_string(config.service_name)); char *vs = get_version_string(); - plist_dict_set_item(response_plist, "model", plist_new_string(vs)); + // plist_dict_set_item(response_plist, "model", plist_new_string(vs)); + plist_dict_set_item(response_plist, "model", plist_new_string("Shairport Sync")); free(vs); - char pkString[128]; - pkString_make(pkString, sizeof(pkString), config.airplay_device_id); - plist_dict_set_item(response_plist, "pk", plist_new_string(pkString)); + // pkString_make(pkString, sizeof(pkString), config.airplay_device_id); + // plist_dict_set_item(response_plist, "pk", plist_new_string(pkString)); plist_to_bin(response_plist, &resp->content, &resp->contentlength); plist_free(response_plist); msg_add_header(resp, "Content-Type", "application/x-apple-binary-plist"); @@ -1702,12 +1775,12 @@ void handle_setrateanchori(rtsp_conn_info *conn, rtsp_message *req, rtsp_message } uint64_t networkTimeSecs; plist_get_uint_val(item, &networkTimeSecs); - debug(2, "anchor networkTimeSecs is 0x%" PRIx64 ".", networkTimeSecs); + debug(2, "anchor networkTimeSecs is %" PRIu64 ".", networkTimeSecs); item = plist_dict_get_item(messagePlist, "networkTimeFrac"); uint64_t networkTimeFrac; plist_get_uint_val(item, &networkTimeFrac); - debug(2, "anchor networkTimeFrac is 0x%" PRIx64 ".", networkTimeFrac); + debug(2, "anchor networkTimeFrac is 0%" PRIu64 ".", networkTimeFrac); // it looks like the networkTimeFrac is a fraction where the msb is work 1/2, the // next 1/4 and so on // now, convert the network time and fraction into nanoseconds @@ -1718,7 +1791,7 @@ void handle_setrateanchori(rtsp_conn_info *conn, rtsp_message *req, rtsp_message networkTimeSecs = networkTimeSecs * 1000000000; // turn the whole seconds into ns uint64_t anchorTimeNanoseconds = networkTimeSecs + networkTimeFrac; - debug(2, "anchorTimeNanoseconds looks like 0x%" PRIx64 ".", anchorTimeNanoseconds); + debug(2, "anchorTimeNanoseconds looks like %" PRIu64 ".", anchorTimeNanoseconds); item = plist_dict_get_item(messagePlist, "rtpTime"); uint64_t rtpTime; @@ -2158,7 +2231,27 @@ void handle_configure(rtsp_conn_info *conn __attribute__((unused)), void handle_feedback(__attribute__((unused)) rtsp_conn_info *conn, __attribute__((unused)) rtsp_message *req, - __attribute__((unused)) rtsp_message *resp) {} + __attribute__((unused)) rtsp_message *resp) { + /* not finished yet + plist_t payload_plist = plist_new_dict(); + plist_dict_set_item(payload_plist, "type", plist_new_uint(103)); + plist_dict_set_item(payload_plist, "sr", plist_new_real(44100.0)); + + plist_t array_plist = plist_new_array(); + plist_array_append_item(array_plist, payload_plist); + + plist_t response_plist = plist_new_dict(); + plist_dict_set_item(response_plist, "streams",array_plist); + + plist_to_bin(response_plist, &resp->content, &resp->contentlength); + plist_free(response_plist); + // plist_free(array_plist); + // plist_free(payload_plist); + + msg_add_header(resp, "Content-Type", "application/x-apple-binary-plist"); + debug_log_rtsp_message(2, "FEEDBACK response:", resp); + */ +} void handle_command(__attribute__((unused)) rtsp_conn_info *conn, rtsp_message *req, __attribute__((unused)) rtsp_message *resp) { From 70821f81278abbf204ec9353b2808f8cad8bffec Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Mon, 6 Dec 2021 18:45:25 +0000 Subject: [PATCH 29/40] Clang Format --- player.c | 4 +- rtp.c | 170 ++++++++++++++++++++++++++++--------------------------- rtsp.c | 75 ++++++++++++++---------- 3 files changed, 133 insertions(+), 116 deletions(-) diff --git a/player.c b/player.c index da98c55b..6e1ee80d 100644 --- a/player.c +++ b/player.c @@ -384,8 +384,8 @@ void reset_buffer(rtsp_conn_info *conn) { ab_resync(conn); debug_mutex_unlock(&conn->ab_mutex, 0); if (config.output->flush) { - config.output->flush(); // no cancellation points -// debug(1, "reset_buffer: flush output device."); + config.output->flush(); // no cancellation points + // debug(1, "reset_buffer: flush output device."); } } diff --git a/rtp.c b/rtp.c index d3bf06c4..f80e32ae 100644 --- a/rtp.c +++ b/rtp.c @@ -2255,14 +2255,14 @@ void *rtp_buffered_audio_processor(void *arg) { int play_enabled = 0; uint32_t flush_from_timestamp; double requested_lead_time = 0.0; // normal lead time minimum -- maybe it should be about 0.1 - + // wait until our timing information is valid - + // debug(1,"rtp_buffered_audio_processor ready."); while (have_ptp_timing_information(conn) == 0) usleep(1000); - - reset_buffer(conn); // in case there is any garbage in the player + + reset_buffer(conn); // in case there is any garbage in the player // int not_first_time_out = 0; // quick check of parameters @@ -2532,17 +2532,17 @@ void *rtp_buffered_audio_processor(void *arg) { int64_t local_lead_time = 0; int64_t requested_lead_time_ns = (int64_t)(requested_lead_time * 1000000000); requested_lead_time_ns = (int64_t)(-300000000); - int outdated = 0; + int outdated = 0; if (have_time_information == 0) { local_lead_time = local_should_be_time - get_absolute_time_in_ns(); outdated = (local_lead_time < requested_lead_time_ns); // if (outdated != 0) - // debug(1,"Frame is outdated %d if lead_time %" PRId64 " is less than requested lead time %" PRId64 " ns.", outdated, local_lead_time, requested_lead_time_ns); + // debug(1,"Frame is outdated %d if lead_time %" PRId64 " is less than requested lead time + // %" PRId64 " ns.", outdated, local_lead_time, requested_lead_time_ns); } else { - debug(1,"Timing information not valid"); + debug(1, "Timing information not valid"); // outdated = 1; } - if ((flush_requested) && (seq_no >= flushUntilSeq)) { if ((have_time_information == 0) && (play_enabled)) { @@ -2556,33 +2556,31 @@ void *rtp_buffered_audio_processor(void *arg) { debug(2, "flush completed to seq: %u with rtptime: %u.", seq_no, timestamp); } } - - // if we are here because of a flush request, it must be the case that - // flushing the pcm buffer wasn't enough, as the request would have been turned off by now - // so we better indicate that the pcm buffer is empty and its contents invalid - - // also, if the incomgin frame is outdated, set pcm_buffer_occupancy to 0; - if ((flush_requested) || (outdated)){ - pcm_buffer_occupancy = 0; - } - // decode the block and add it to or put it in the pcm buffer + // if we are here because of a flush request, it must be the case that + // flushing the pcm buffer wasn't enough, as the request would have been turned off by now + // so we better indicate that the pcm buffer is empty and its contents invalid - if (pcm_buffer_occupancy == 0) { - // they should match and the read point should be zero - // if ((blocks_read != 0) && (pcm_buffer_read_point_rtptime != timestamp)) { - // debug(2, "set pcm_buffer_read_point_rtptime from %u to %u.", - // pcm_buffer_read_point_rtptime, timestamp); - pcm_buffer_read_point_rtptime = timestamp; - pcm_buffer_read_point = 0; - //} - } + // also, if the incomgin frame is outdated, set pcm_buffer_occupancy to 0; + if ((flush_requested) || (outdated)) { + pcm_buffer_occupancy = 0; + } + // decode the block and add it to or put it in the pcm buffer + + if (pcm_buffer_occupancy == 0) { + // they should match and the read point should be zero + // if ((blocks_read != 0) && (pcm_buffer_read_point_rtptime != timestamp)) { + // debug(2, "set pcm_buffer_read_point_rtptime from %u to %u.", + // pcm_buffer_read_point_rtptime, timestamp); + pcm_buffer_read_point_rtptime = timestamp; + pcm_buffer_read_point = 0; + //} + } if (((flush_requested != 0) && (seq_no == flushUntilSeq)) || ((flush_requested == 0) && (new_buffer_needed))) { - unsigned char nonce[12]; memset(nonce, 0, sizeof(nonce)); memcpy(nonce + 4, packet + nread - 8, @@ -2642,71 +2640,75 @@ void *rtp_buffered_audio_processor(void *arg) { // debug(1, "frame found"); // now pass each packet to be decoded if (pkt->size) { - //if (0) { + // if (0) { if (pkt->size <= 7) { // no idea about this... - debug(1,"malformed AAC packet skipped."); + debug(1, "malformed AAC packet skipped."); } else { - ret = avcodec_send_packet(codec_context, pkt); - - if (ret < 0) { - debug(1, "error sending frame %d of size %d to decoder, blocks_read: %u, blocks_read_since_flush: %u.", frame_within_block, pkt->size, blocks_read, blocks_read_since_flush); - } else { - while (ret >= 0) { - ret = avcodec_receive_frame(codec_context, decoded_frame); - if (ret == AVERROR(EAGAIN) || ret == AVERROR_EOF) - break; - else if (ret < 0) { - debug(1, "error %d during decoding", ret); - } else { - av_samples_alloc(&pcm_audio, &dst_linesize, codec_context->channels, - decoded_frame->nb_samples, av_format, 1); - // remember to free pcm_audio - ret = swr_convert(swr, &pcm_audio, decoded_frame->nb_samples, - (const uint8_t **)decoded_frame->extended_data, - decoded_frame->nb_samples); - dst_bufsize = av_samples_get_buffer_size( - &dst_linesize, codec_context->channels, ret, av_format, 1); - // debug(1,"generated %d bytes of PCM", dst_bufsize); - // copy the PCM audio into the PCM buffer. - // make sure it's big enough first + ret = avcodec_send_packet(codec_context, pkt); - // also, check it if needs to be truncated but to an impending delayed - // flush_is_delayed - if (flush_is_delayed) { - // see if the flush_from_timestamp is in the buffer - int32_t samples_remaining = - (flush_from_timestamp - pcm_buffer_read_point_rtptime); - if ((samples_remaining > 0) && - ((samples_remaining * conn->input_bytes_per_frame) < dst_bufsize)) { - debug(2, - "samples remaining before flush: %d, number of samples %d. " - "flushFromTS: %u, pcm_buffer_read_point_rtptime: %u.", - samples_remaining, dst_bufsize / conn->input_bytes_per_frame, - flush_from_timestamp, pcm_buffer_read_point_rtptime); - dst_bufsize = samples_remaining * conn->input_bytes_per_frame; - } - } - if ((pcm_buffer_size - pcm_buffer_occupancy) < dst_bufsize) { - debug(1, - "pcm_buffer_read_point (frames): %u, pcm_buffer_occupancy " - "(frames): %u", - pcm_buffer_read_point / conn->input_bytes_per_frame, - pcm_buffer_occupancy / conn->input_bytes_per_frame); - pcm_buffer_size = dst_bufsize + pcm_buffer_occupancy; - debug(1, "fatal error! pcm buffer too small at %d bytes.", - pcm_buffer_size); + if (ret < 0) { + debug(1, + "error sending frame %d of size %d to decoder, blocks_read: %u, " + "blocks_read_since_flush: %u.", + frame_within_block, pkt->size, blocks_read, blocks_read_since_flush); + } else { + while (ret >= 0) { + ret = avcodec_receive_frame(codec_context, decoded_frame); + if (ret == AVERROR(EAGAIN) || ret == AVERROR_EOF) + break; + else if (ret < 0) { + debug(1, "error %d during decoding", ret); } else { - memcpy(pcm_buffer + pcm_buffer_occupancy, pcm_audio, dst_bufsize); - pcm_buffer_occupancy += dst_bufsize; + av_samples_alloc(&pcm_audio, &dst_linesize, codec_context->channels, + decoded_frame->nb_samples, av_format, 1); + // remember to free pcm_audio + ret = swr_convert(swr, &pcm_audio, decoded_frame->nb_samples, + (const uint8_t **)decoded_frame->extended_data, + decoded_frame->nb_samples); + dst_bufsize = av_samples_get_buffer_size( + &dst_linesize, codec_context->channels, ret, av_format, 1); + // debug(1,"generated %d bytes of PCM", dst_bufsize); + // copy the PCM audio into the PCM buffer. + // make sure it's big enough first + + // also, check it if needs to be truncated but to an impending delayed + // flush_is_delayed + if (flush_is_delayed) { + // see if the flush_from_timestamp is in the buffer + int32_t samples_remaining = + (flush_from_timestamp - pcm_buffer_read_point_rtptime); + if ((samples_remaining > 0) && + ((samples_remaining * conn->input_bytes_per_frame) < + dst_bufsize)) { + debug(2, + "samples remaining before flush: %d, number of samples %d. " + "flushFromTS: %u, pcm_buffer_read_point_rtptime: %u.", + samples_remaining, dst_bufsize / conn->input_bytes_per_frame, + flush_from_timestamp, pcm_buffer_read_point_rtptime); + dst_bufsize = samples_remaining * conn->input_bytes_per_frame; + } + } + if ((pcm_buffer_size - pcm_buffer_occupancy) < dst_bufsize) { + debug(1, + "pcm_buffer_read_point (frames): %u, pcm_buffer_occupancy " + "(frames): %u", + pcm_buffer_read_point / conn->input_bytes_per_frame, + pcm_buffer_occupancy / conn->input_bytes_per_frame); + pcm_buffer_size = dst_bufsize + pcm_buffer_occupancy; + debug(1, "fatal error! pcm buffer too small at %d bytes.", + pcm_buffer_size); + } else { + memcpy(pcm_buffer + pcm_buffer_occupancy, pcm_audio, dst_bufsize); + pcm_buffer_occupancy += dst_bufsize; + } + // debug(1,"decoded %d samples", decoded_frame->nb_samples); + // memcpy(sampleBuffer,outputBuffer16,dst_bufsize); + av_freep(&pcm_audio); } - // debug(1,"decoded %d samples", decoded_frame->nb_samples); - // memcpy(sampleBuffer,outputBuffer16,dst_bufsize); - av_freep(&pcm_audio); } } } } - } } if (decoded_frame == NULL) debug(1, "decoded_frame is NULL"); diff --git a/rtsp.c b/rtsp.c index 6c0da18f..177a4b81 100644 --- a/rtsp.c +++ b/rtsp.c @@ -197,8 +197,8 @@ int add_pstring_to_malloc(const char *s, void **allocation, size_t *size) { *size = *size + strlen(s) + 1; uint8_t *b = (uint8_t *)p; *b = strlen(s); - p = p+1; - memcpy(p,s,strlen(s)); + p = p + 1; + memcpy(p, s, strlen(s)); response = 1; } } else { @@ -210,7 +210,7 @@ int add_pstring_to_malloc(const char *s, void **allocation, size_t *size) { uint8_t *b = (uint8_t *)p + *size; *b = strlen(s); p = p + *size + 1; - memcpy(p,s,strlen(s)); + memcpy(p, s, strlen(s)); *size = *size + strlen(s) + 1; response = 1; } @@ -1173,8 +1173,8 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes enum rtsp_read_request_response reply = rtsp_read_request_response_ok; ssize_t buflen = 4096; if ((config.metadata_enabled != 0) && (config.get_coverart != 0)) - buflen = 1024 * 256; // big enough for typical picture data, which will be base64 encoded - int release_buffer = 0; // on exit, don't deallocate the buffer if everything was okay + buflen = 1024 * 256; // big enough for typical picture data, which will be base64 encoded + int release_buffer = 0; // on exit, don't deallocate the buffer if everything was okay char *buf = malloc(buflen + 1); // add a NUL at the end if (!buf) { warn("Connection %d: rtsp_read_request: can't get a buffer.", conn->connection_number); @@ -1290,7 +1290,7 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes goto shutdown; } size_t read_chunk = msg_size - inbuf; - //if (read_chunk > max_read_chunk) + // if (read_chunk > max_read_chunk) // read_chunk = max_read_chunk; // usleep(80000); // wait about 80 milliseconds between reads of up to max_read_chunk nread = read_from_rtsp_connection(conn, buf + inbuf, read_chunk); @@ -1556,41 +1556,56 @@ void handle_get_info(__attribute((unused)) rtsp_conn_info *conn, rtsp_message *r } else { void *qualifier_response_data = NULL; size_t qualifier_response_data_length = 0; - if (add_pstring_to_malloc("acl=0", &qualifier_response_data, &qualifier_response_data_length) == 0) + if (add_pstring_to_malloc("acl=0", &qualifier_response_data, + &qualifier_response_data_length) == 0) debug(1, "Problem"); - if (add_pstring_to_malloc(deviceIdString, &qualifier_response_data, &qualifier_response_data_length) == 0) + if (add_pstring_to_malloc(deviceIdString, &qualifier_response_data, + &qualifier_response_data_length) == 0) debug(1, "Problem"); - if (add_pstring_to_malloc(featuresString, &qualifier_response_data, &qualifier_response_data_length) == 0) + if (add_pstring_to_malloc(featuresString, &qualifier_response_data, + &qualifier_response_data_length) == 0) debug(1, "Problem"); - if (add_pstring_to_malloc("rsf=0x0", &qualifier_response_data, &qualifier_response_data_length) == 0) + if (add_pstring_to_malloc("rsf=0x0", &qualifier_response_data, + &qualifier_response_data_length) == 0) debug(1, "Problem"); - if (add_pstring_to_malloc("flags=0x4", &qualifier_response_data, &qualifier_response_data_length) == 0) + if (add_pstring_to_malloc("flags=0x4", &qualifier_response_data, + &qualifier_response_data_length) == 0) debug(1, "Problem"); - if (add_pstring_to_malloc("model=Shairport Sync", &qualifier_response_data, &qualifier_response_data_length) == 0) + if (add_pstring_to_malloc("model=Shairport Sync", &qualifier_response_data, + &qualifier_response_data_length) == 0) debug(1, "Problem"); - if (add_pstring_to_malloc("manufacturer=", &qualifier_response_data, &qualifier_response_data_length) == 0) + if (add_pstring_to_malloc("manufacturer=", &qualifier_response_data, + &qualifier_response_data_length) == 0) debug(1, "Problem"); - if (add_pstring_to_malloc("serialNumber=", &qualifier_response_data, &qualifier_response_data_length) == 0) + if (add_pstring_to_malloc("serialNumber=", &qualifier_response_data, + &qualifier_response_data_length) == 0) debug(1, "Problem"); - if (add_pstring_to_malloc("protovers=1.1", &qualifier_response_data, &qualifier_response_data_length) == 0) + if (add_pstring_to_malloc("protovers=1.1", &qualifier_response_data, + &qualifier_response_data_length) == 0) debug(1, "Problem"); - if (add_pstring_to_malloc("srcvers=366.0", &qualifier_response_data, &qualifier_response_data_length) == 0) + if (add_pstring_to_malloc("srcvers=366.0", &qualifier_response_data, + &qualifier_response_data_length) == 0) debug(1, "Problem"); - if (add_pstring_to_malloc(piString, &qualifier_response_data, &qualifier_response_data_length) == 0) + if (add_pstring_to_malloc(piString, &qualifier_response_data, + &qualifier_response_data_length) == 0) debug(1, "Problem"); - if (add_pstring_to_malloc(gidString, &qualifier_response_data, &qualifier_response_data_length) == 0) + if (add_pstring_to_malloc(gidString, &qualifier_response_data, + &qualifier_response_data_length) == 0) debug(1, "Problem"); - if (add_pstring_to_malloc("gcgl=0", &qualifier_response_data, &qualifier_response_data_length) == 0) + if (add_pstring_to_malloc("gcgl=0", &qualifier_response_data, + &qualifier_response_data_length) == 0) debug(1, "Problem"); snprintf(pkString, sizeof(pkString), "pk="); pkString_make(pkString + strlen("pk="), sizeof(pkString) - strlen("pk="), config.airplay_device_id); - if (add_pstring_to_malloc(pkString, &qualifier_response_data, &qualifier_response_data_length) == 0) + if (add_pstring_to_malloc(pkString, &qualifier_response_data, + &qualifier_response_data_length) == 0) debug(1, "Problem"); // debug(1,"qualifier_response_data_length: %u.", qualifier_response_data_length); - - plist_dict_set_item(response_plist, "txtAirPlay", plist_new_data(qualifier_response_data, qualifier_response_data_length)); - + + plist_dict_set_item(response_plist, "txtAirPlay", + plist_new_data(qualifier_response_data, qualifier_response_data_length)); + plist_dict_set_item(response_plist, "features", plist_new_uint(config.airplay_features)); plist_dict_set_item(response_plist, "statusFlags", plist_new_uint(config.airplay_statusflags)); @@ -1598,11 +1613,11 @@ void handle_get_info(__attribute((unused)) rtsp_conn_info *conn, rtsp_message *r plist_dict_set_item(response_plist, "pi", plist_new_string(config.airplay_pi)); plist_dict_set_item(response_plist, "name", plist_new_string(config.service_name)); char *vs = get_version_string(); -// plist_dict_set_item(response_plist, "model", plist_new_string(vs)); + // plist_dict_set_item(response_plist, "model", plist_new_string(vs)); plist_dict_set_item(response_plist, "model", plist_new_string("Shairport Sync")); free(vs); - //pkString_make(pkString, sizeof(pkString), config.airplay_device_id); - //plist_dict_set_item(response_plist, "pk", plist_new_string(pkString)); + // pkString_make(pkString, sizeof(pkString), config.airplay_device_id); + // plist_dict_set_item(response_plist, "pk", plist_new_string(pkString)); plist_to_bin(response_plist, &resp->content, &resp->contentlength); if (resp->contentlength == 0) debug(1, "GET /info Stage 1: response bplist not created!"); @@ -2236,14 +2251,14 @@ void handle_feedback(__attribute__((unused)) rtsp_conn_info *conn, plist_t payload_plist = plist_new_dict(); plist_dict_set_item(payload_plist, "type", plist_new_uint(103)); plist_dict_set_item(payload_plist, "sr", plist_new_real(44100.0)); - + plist_t array_plist = plist_new_array(); plist_array_append_item(array_plist, payload_plist); - + plist_t response_plist = plist_new_dict(); plist_dict_set_item(response_plist, "streams",array_plist); - - plist_to_bin(response_plist, &resp->content, &resp->contentlength); + + plist_to_bin(response_plist, &resp->content, &resp->contentlength); plist_free(response_plist); // plist_free(array_plist); // plist_free(payload_plist); From 3de7e9a5c5110831070e97f3723d9b3d430f5690 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Tue, 7 Dec 2021 12:09:49 +0000 Subject: [PATCH 30/40] Look for at least 0.1 seconds of leadtime, ensure a master clock is at least 0.275 seconds old before use, quieten a few debug messages. --- player.c | 5 +++-- rtp.c | 6 +++--- rtsp.c | 10 +++++----- 3 files changed, 11 insertions(+), 10 deletions(-) diff --git a/player.c b/player.c index 6e1ee80d..6131ad4c 100644 --- a/player.c +++ b/player.c @@ -1062,8 +1062,9 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { conn->first_packet_time_to_play = should_be_time; int64_t lt = conn->first_packet_time_to_play - local_time_now; - - debug(1, "Connection %d: Lead time for first frame %" PRId64 ": %f seconds.", + + if (lt < 100000000) + debug(1, "Connection %d: Short lead time for first frame %" PRId64 ": %f seconds.", conn->connection_number, conn->first_packet_timestamp, lt * 0.000000001); int64_t lateness = local_time_now - conn->first_packet_time_to_play; diff --git a/rtp.c b/rtp.c index f80e32ae..401f4dba 100644 --- a/rtp.c +++ b/rtp.c @@ -1310,7 +1310,7 @@ int get_ptp_anchor_local_time_info(rtsp_conn_info *conn, uint32_t *anchorRTP, // if the master clock and the anchor clock are the same // wait at least this time before using the new master clock // note that mastershipo may be backdated - if (duration_of_mastership < 100000000) { + if (duration_of_mastership < 275000000) { debug(3, "master not old enough yet: %f ms", 0.000001 * duration_of_mastership); response = clock_not_ready; } else if ((duration_of_mastership > 5000000000) || @@ -2254,7 +2254,7 @@ void *rtp_buffered_audio_processor(void *arg) { int streaming_has_started = 0; int play_enabled = 0; uint32_t flush_from_timestamp; - double requested_lead_time = 0.0; // normal lead time minimum -- maybe it should be about 0.1 + double requested_lead_time = 0.1; // normal lead time minimum -- maybe it should be about 0.1 // wait until our timing information is valid @@ -2642,7 +2642,7 @@ void *rtp_buffered_audio_processor(void *arg) { if (pkt->size) { // if (0) { if (pkt->size <= 7) { // no idea about this... - debug(1, "malformed AAC packet skipped."); + debug(2, "malformed AAC packet skipped."); } else { ret = avcodec_send_packet(codec_context, pkt); diff --git a/rtsp.c b/rtsp.c index 177a4b81..4b0827bf 100644 --- a/rtsp.c +++ b/rtsp.c @@ -697,7 +697,7 @@ void cancel_all_RTSP_threads(airplay_stream_c stream_category, int except_this_o ((stream_category == unspecified_stream_category) || (stream_category == conns[i]->airplay_stream_category))) { pthread_cancel(conns[i]->thread); - debug(1, "Connection %d: cancelled.", conns[i]->connection_number); + debug(2, "Connection %d: cancelled.", conns[i]->connection_number); } } for (i = 0; i < nconns; i++) { @@ -706,7 +706,7 @@ void cancel_all_RTSP_threads(airplay_stream_c stream_category, int except_this_o ((stream_category == unspecified_stream_category) || (stream_category == conns[i]->airplay_stream_category))) { pthread_join(conns[i]->thread, NULL); - debug(1, "Connection %d: joined.", conns[i]->connection_number); + debug(2, "Connection %d: joined.", conns[i]->connection_number); free(conns[i]); conns[i] = NULL; } @@ -2625,7 +2625,7 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) uint8_t isRemoteControlOnlyBoolean = 0; plist_get_bool_val(isRemoteControlOnly, &isRemoteControlOnlyBoolean); if (isRemoteControlOnlyBoolean != 0) { - debug(1, "Connection %d: SETUP: Remote Control setup detected.", + debug(2, "Connection %d: SETUP: Remote Control setup detected.", conn->connection_number); conn->airplay_stream_category = remote_control_stream; } else { @@ -2825,7 +2825,7 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) conn->connection_number, err); } - debug(1, "Connection %d: TCP Remote Control event port opened: %u.", + debug(2, "Connection %d: TCP Remote Control event port opened: %u.", conn->connection_number, conn->local_event_port); if (conn->rtp_event_thread != NULL) debug(1, "previous rtp_event_thread allocation not freed, it seems."); @@ -3056,7 +3056,7 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) resp->respcode = 200; } else if (conn->airplay_stream_category == remote_control_stream) { debug(2, "Connection %d: SETUP: Remote Control Stream received.", conn->connection_number); - debug_log_rtsp_message(1, "Remote Control Stream stream (second) message", req); + debug_log_rtsp_message(2, "Remote Control Stream stream (second) message", req); resp->respcode = 200; } else { From dbebdca84d95ee80d34d7eef8c6b29e581b315bd Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Tue, 7 Dec 2021 15:08:16 +0000 Subject: [PATCH 31/40] quieten a debug message --- dacp.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/dacp.c b/dacp.c index d6964133..7184ed73 100644 --- a/dacp.c +++ b/dacp.c @@ -481,7 +481,7 @@ void dacp_monitor_port_update_callback(char *dacp_id, uint16_t port) { // metadata_store.dacp_server_active = dacp_server.scan_enable; // metadata_hub_modify_epilog(ch); } else { - debug(1, "dacp port monitor reporting on an out-of-use remote."); + debug(2, "dacp port monitor reporting on an out-of-use remote."); } } pthread_cond_signal(&dacp_server_information_cv); From fd3d461a164bd4afcfeb76b26bdc7140f2570353 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Tue, 7 Dec 2021 15:09:05 +0000 Subject: [PATCH 32/40] stop removing the play lock at the end of a play session. That's the job of the rtsp thread. --- player.c | 2 +- rtsp.c | 21 +++++++++++++++++---- 2 files changed, 18 insertions(+), 5 deletions(-) diff --git a/player.c b/player.c index 6131ad4c..1feee08f 100644 --- a/player.c +++ b/player.c @@ -1717,7 +1717,7 @@ void player_thread_cleanup_handler(void *arg) { terminate_decoders(conn); // reset_anchor_info(conn); - release_play_lock(conn); + // release_play_lock(conn); conn->rtp_running = 0; pthread_setcancelstate(oldState, NULL); debug(2, "Connection %d: player terminated.", conn->connection_number); diff --git a/rtsp.c b/rtsp.c index 4b0827bf..959944ac 100644 --- a/rtsp.c +++ b/rtsp.c @@ -1879,6 +1879,7 @@ void handle_get(__attribute((unused)) rtsp_conn_info *conn, __attribute((unused) req->contentlength); resp->respcode = 500; } + void handle_post(__attribute((unused)) rtsp_conn_info *conn, __attribute((unused)) rtsp_message *req, __attribute((unused)) rtsp_message *resp) { @@ -2480,6 +2481,9 @@ void teardown_phase_two(rtsp_conn_info *conn) { debug(2, "Connection %d: TEARDOWN mdns_update on %s.", conn->connection_number, get_category_string(conn->airplay_stream_category)); mdns_update(NULL, secondary_txt_records); + debug(1, "Connection %d: TEARDOWN (AP2) release play lock on %s.", conn->connection_number, + get_category_string(conn->airplay_stream_category)); + release_play_lock(conn); } } @@ -2533,6 +2537,9 @@ void handle_teardown(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message "TEARDOWN: synchronously terminating the player thread of RTSP conversation thread %d (2).", conn->connection_number); player_stop(conn); + release_play_lock(conn); + debug(1, "TEARDOWN: release play lock on RTSP conversation thread %d.", + conn->connection_number); activity_monitor_signify_activity(0); // inactive, and should be after command_stop() debug(3, "TEARDOWN: successful termination of playing thread of RTSP conversation thread %d.", conn->connection_number); @@ -2800,6 +2807,8 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) debug(2, "Connection %d: SETUP mdns_update on %s.", conn->connection_number, get_category_string(conn->airplay_stream_category)); mdns_update(NULL, secondary_txt_records); + + resp->respcode = 200; } else { @@ -2862,6 +2871,9 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) debug(2, "Connection %d: SETUP on %s. A \"streams\" array has been found", conn->connection_number, get_category_string(conn->airplay_stream_category)); if (conn->airplay_stream_category == ptp_stream) { + debug(1, "Connection %d: SETUP get_play_lock.", + conn->connection_number); + get_play_lock(conn); // get stream[0] plist_t stream0 = plist_array_get_item(streams, 0); @@ -2939,7 +2951,7 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) case 96: { debug(1, "Connection %d. Realtime Audio Stream Detected.", conn->connection_number); debug_log_rtsp_message(2, "Realtime Audio Stream SETUP incoming message", req); - get_play_lock(conn); + // get_play_lock(conn); conn->airplay_stream_type = realtime_stream; // bind a new UDP port and get a socket conn->local_realtime_audio_port = 0; // any port @@ -2999,7 +3011,7 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) debug(1, "SETUP on Connection %d. Buffered Audio Stream Detected.", conn->connection_number); debug_log_rtsp_message(2, "Buffered Audio Stream SETUP incoming message", req); - get_play_lock(conn); + // get_play_lock(conn); conn->airplay_stream_type = buffered_stream; // get needed stuff @@ -3229,7 +3241,7 @@ void handle_set_parameter_parameter(rtsp_conn_info *conn, rtsp_message *req, if (!strncmp(cp, "volume: ", strlen("volume: "))) { float volume = atof(cp + strlen("volume: ")); - debug(2, "Connection %d: request to set AirPlay Volume to: %f.", conn->connection_number, + debug(1, "Connection %d: request to set AirPlay Volume to: %f.", conn->connection_number, volume); // if we are playing, go ahead and change the volume if (try_to_hold_play_lock(conn) == 0) { @@ -3969,7 +3981,7 @@ static void handle_get_parameter(__attribute__((unused)) rtsp_conn_info *conn, r if ((req->content) && (req->contentlength == strlen("volume\r\n")) && strstr(req->content, "volume") == req->content) { - debug(2, "Connection %d: Current volume (%.6f) requested", conn->connection_number, + debug(1, "Connection %d: Current volume (%.6f) requested", conn->connection_number, config.airplay_volume); char *p = malloc(128); // will be automatically deallocated with the response is deleted if (p) { @@ -4078,6 +4090,7 @@ static void handle_set_parameter(rtsp_conn_info *conn, rtsp_message *req, rtsp_m static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { debug(3, "Connection %d: ANNOUNCE", conn->connection_number); + debug(1, "Connection %d: ANNOUNCE get_play_lock()", conn->connection_number); int get_play_status = get_play_lock(conn); if (get_play_status != -1) { debug(3, "Connection %d: ANNOUNCE has acquired play lock.", conn->connection_number); From 6a58eae3141c26ebc07721cc4a49d3daf84009c7 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Tue, 7 Dec 2021 17:37:16 +0000 Subject: [PATCH 33/40] Quieten a few debug messasges. --- rtsp.c | 14 ++++---------- shairport.c | 4 ++-- 2 files changed, 6 insertions(+), 12 deletions(-) diff --git a/rtsp.c b/rtsp.c index 959944ac..6bc6c1a0 100644 --- a/rtsp.c +++ b/rtsp.c @@ -1345,7 +1345,8 @@ int msg_write_response(rtsp_conn_info *conn, rtsp_message *resp) { }; struct response_t responses[] = { - {200, "OK"}, {400, "Bad Request"}, {403, "Unauthorized"}, {501, "Not Implemented"}}; + {200, "OK"}, {400, "Bad Request"}, {403, "Unauthorized"}, {451, "Unavailable"}, {501, "Not Implemented"}}; + // 451 is really "Unavailable For Legal Reasons"! int found = 0; char *respcode_text = "Unauthorized"; for (i = 0; i < sizeof(responses) / sizeof(struct response_t); i++) { @@ -2481,8 +2482,6 @@ void teardown_phase_two(rtsp_conn_info *conn) { debug(2, "Connection %d: TEARDOWN mdns_update on %s.", conn->connection_number, get_category_string(conn->airplay_stream_category)); mdns_update(NULL, secondary_txt_records); - debug(1, "Connection %d: TEARDOWN (AP2) release play lock on %s.", conn->connection_number, - get_category_string(conn->airplay_stream_category)); release_play_lock(conn); } } @@ -2538,8 +2537,6 @@ void handle_teardown(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message conn->connection_number); player_stop(conn); release_play_lock(conn); - debug(1, "TEARDOWN: release play lock on RTSP conversation thread %d.", - conn->connection_number); activity_monitor_signify_activity(0); // inactive, and should be after command_stop() debug(3, "TEARDOWN: successful termination of playing thread of RTSP conversation thread %d.", conn->connection_number); @@ -2871,8 +2868,6 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) debug(2, "Connection %d: SETUP on %s. A \"streams\" array has been found", conn->connection_number, get_category_string(conn->airplay_stream_category)); if (conn->airplay_stream_category == ptp_stream) { - debug(1, "Connection %d: SETUP get_play_lock.", - conn->connection_number); get_play_lock(conn); // get stream[0] plist_t stream0 = plist_array_get_item(streams, 0); @@ -3241,7 +3236,7 @@ void handle_set_parameter_parameter(rtsp_conn_info *conn, rtsp_message *req, if (!strncmp(cp, "volume: ", strlen("volume: "))) { float volume = atof(cp + strlen("volume: ")); - debug(1, "Connection %d: request to set AirPlay Volume to: %f.", conn->connection_number, + debug(2, "Connection %d: request to set AirPlay Volume to: %f.", conn->connection_number, volume); // if we are playing, go ahead and change the volume if (try_to_hold_play_lock(conn) == 0) { @@ -3981,7 +3976,7 @@ static void handle_get_parameter(__attribute__((unused)) rtsp_conn_info *conn, r if ((req->content) && (req->contentlength == strlen("volume\r\n")) && strstr(req->content, "volume") == req->content) { - debug(1, "Connection %d: Current volume (%.6f) requested", conn->connection_number, + debug(2, "Connection %d: Current volume (%.6f) requested", conn->connection_number, config.airplay_volume); char *p = malloc(128); // will be automatically deallocated with the response is deleted if (p) { @@ -4090,7 +4085,6 @@ static void handle_set_parameter(rtsp_conn_info *conn, rtsp_message *req, rtsp_m static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { debug(3, "Connection %d: ANNOUNCE", conn->connection_number); - debug(1, "Connection %d: ANNOUNCE get_play_lock()", conn->connection_number); int get_play_status = get_play_lock(conn); if (get_play_status != -1) { debug(3, "Connection %d: ANNOUNCE has acquired play lock.", conn->connection_number); diff --git a/shairport.c b/shairport.c index b1faf5c9..ecba335a 100644 --- a/shairport.c +++ b/shairport.c @@ -1459,10 +1459,10 @@ void exit_function() { if (config.daemonise) debug(1, "libdaemon parent exit"); else - debug(1, "exit"); + debug(1, "exit_function libdaemon exit"); } #else - debug(1, "exit"); + debug(1, "exit_function exit"); #endif } else { debug(1, "emergency exit"); From 107bc71e56058bd1aee25f89ccb394417958924a Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Tue, 7 Dec 2021 17:47:45 +0000 Subject: [PATCH 34/40] Stop checking that the timing peers are within the same subnet. --- rtsp.c | 15 +++++++++------ 1 file changed, 9 insertions(+), 6 deletions(-) diff --git a/rtsp.c b/rtsp.c index 6bc6c1a0..7f78b211 100644 --- a/rtsp.c +++ b/rtsp.c @@ -2725,10 +2725,11 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) char buf[32]; memset(buf, 0, sizeof(buf)); inet_ntop(AF_INET6, (void *)&addr6->sin6_addr, buf, sizeof(buf)); - if (!different) { + // don't insist there are in the same subnet... + //if (!different) { // debug(1, "%s is in the same subnet as %s.", buf, ip_address); plist_array_append_item(addresses, plist_new_string(buf)); - } + //} } } } else if (inet_pton(AF_INET, ip_address, &pa4->sin_addr) == 1) { @@ -2738,15 +2739,17 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) ((iap->ifa_flags & IFF_LOOPBACK) == 0) && (iap->ifa_addr->sa_family == AF_INET)) { struct sockaddr_in *addr = (struct sockaddr_in *)(iap->ifa_addr); - struct sockaddr_in *mask = (struct sockaddr_in *)(iap->ifa_netmask); - if ((addr->sin_addr.s_addr & mask->sin_addr.s_addr) == - (pa4->sin_addr.s_addr & mask->sin_addr.s_addr)) { + // not needed if not checking for same subnet + // struct sockaddr_in *mask = (struct sockaddr_in *)(iap->ifa_netmask); + // if ((addr->sin_addr.s_addr & mask->sin_addr.s_addr) == + // (pa4->sin_addr.s_addr & mask->sin_addr.s_addr)) { char buf[32]; memset(buf, 0, sizeof(buf)); inet_ntop(AF_INET, (void *)&addr->sin_addr, buf, sizeof(buf)); + // no longer insisting they are in the same subnet // debug(1, "%s is in the same subnet as %s.", buf, ip_address); plist_array_append_item(addresses, plist_new_string(buf)); - } + // } } } } else { From 765a489db49cd9a512d53564ae22e0b2da9f9dd0 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Tue, 7 Dec 2021 19:37:01 +0000 Subject: [PATCH 35/40] Possibly fix a few memory leaks. Add a bogus exit to allow SPS to quit at the end of a play session, to make it easier to use valgrind. --- rtsp.c | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/rtsp.c b/rtsp.c index 7f78b211..076ba702 100644 --- a/rtsp.c +++ b/rtsp.c @@ -2298,7 +2298,7 @@ void handle_command(__attribute__((unused)) rtsp_conn_info *conn, rtsp_message * uint64_t length = 0; plist_get_data_val(the_item, &buff, &length); // debug(1,"Item %d, length: %" PRId64 " bytes", item_number, length); - if ((length >= strlen("bplist00")) && (strstr(buff, "bplist00") == buff)) { + if ((buff != NULL) && (length >= strlen("bplist00")) && (strstr(buff, "bplist00") == buff)) { // debug(1,"Contains a plist."); plist_t subsidiary_plist = NULL; plist_from_memory(buff, length, &subsidiary_plist); @@ -2315,6 +2315,8 @@ void handle_command(__attribute__((unused)) rtsp_conn_info *conn, rtsp_message * debug(1, "Can't access the plist!"); } } + if (buff != NULL) + free(buff); } } } else { @@ -2521,6 +2523,8 @@ void handle_teardown_2(rtsp_conn_info *conn, __attribute__((unused)) rtsp_messag debug(1, "Connection %d: missing plist!", conn->connection_number); resp->respcode = 451; // don't know what to do here } + debug(1,"Bogus exit for valgrind."); + exit(EXIT_SUCCESS); // } #endif @@ -3080,6 +3084,7 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) plist_free(setupResponsePlist); msg_add_header(resp, "Content-Type", "application/x-apple-binary-plist"); } + plist_free(messagePlist); debug_log_rtsp_message(2, " SETUP response", resp); } #endif From 7258a45bea6cac73fe581f41df177470120b4dfa Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Tue, 7 Dec 2021 19:58:00 +0000 Subject: [PATCH 36/40] Fix a few more memory leaks --- mdns_avahi.c | 2 +- rtsp.c | 8 +++++++- shairport.c | 2 +- 3 files changed, 9 insertions(+), 3 deletions(-) diff --git a/mdns_avahi.c b/mdns_avahi.c index 95984419..7103b1ee 100644 --- a/mdns_avahi.c +++ b/mdns_avahi.c @@ -112,7 +112,7 @@ static void resolve_callback(AvahiServiceResolver *r, AVAHI_GCC_UNUSED AvahiIfIn char portstring[20]; memset(portstring, 0, sizeof(portstring)); snprintf(portstring, sizeof(portstring), "%u", port); - send_ssnc_metadata('dapo', strdup(portstring), strlen(portstring), 0); + send_ssnc_metadata('dapo', portstring, strlen(portstring), 0); #endif } } else { diff --git a/rtsp.c b/rtsp.c index 076ba702..6f46c3f5 100644 --- a/rtsp.c +++ b/rtsp.c @@ -2282,7 +2282,7 @@ void handle_command(__attribute__((unused)) rtsp_conn_info *conn, rtsp_message * if (item != NULL) { char *typeValue = NULL; plist_get_string_val(item, &typeValue); - if (strcmp(typeValue, "updateMRSupportedCommands") == 0) { + if ((typeValue != NULL) && (strcmp(typeValue, "updateMRSupportedCommands") == 0)) { item = plist_dict_get_item(command_dict, "params"); if (item != NULL) { // the item should be a dict @@ -2331,6 +2331,8 @@ void handle_command(__attribute__((unused)) rtsp_conn_info *conn, rtsp_message * "POST /command plist type is \"%s\", but \"updateMRSupportedCommands\" expected.", typeValue); } + if (typeValue != NULL) + free(typeValue); } else { debug(1, "Could not get the \"type\" item."); } @@ -2523,6 +2525,10 @@ void handle_teardown_2(rtsp_conn_info *conn, __attribute__((unused)) rtsp_messag debug(1, "Connection %d: missing plist!", conn->connection_number); resp->respcode = 451; // don't know what to do here } + if (conn->dacp_active_remote != NULL) { + free(conn->dacp_active_remote); + conn->dacp_active_remote = NULL; + } debug(1,"Bogus exit for valgrind."); exit(EXIT_SUCCESS); // } diff --git a/shairport.c b/shairport.c index ecba335a..e2fd0b5e 100644 --- a/shairport.c +++ b/shairport.c @@ -1843,7 +1843,7 @@ int main(int argc, char **argv) { char *uuid = malloc(UUID_STR_LEN); // Produces a UUID string at uuid consisting of lower-case letters uuid_unparse_lower(binuuid, uuid); - config.airplay_pi = strdup(uuid); + config.airplay_pi = uuid; debug(1, "Started in Airplay 2 mode on device \"%s\"!", config.airplay_device_id); #else debug(1, "Started in Airplay 1 mode!"); From 9eea4e4c0c7b3ef0c740062d781bb8dc4f61693c Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Tue, 7 Dec 2021 20:05:37 +0000 Subject: [PATCH 37/40] Another memory leak. --- rtsp.c | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/rtsp.c b/rtsp.c index 6f46c3f5..af7066f9 100644 --- a/rtsp.c +++ b/rtsp.c @@ -2529,6 +2529,10 @@ void handle_teardown_2(rtsp_conn_info *conn, __attribute__((unused)) rtsp_messag free(conn->dacp_active_remote); conn->dacp_active_remote = NULL; } + if (conn->ap2_timing_peer_list_message) { + free(conn->ap2_timing_peer_list_message); + conn->ap2_timing_peer_list_message = NULL; + } debug(1,"Bogus exit for valgrind."); exit(EXIT_SUCCESS); // } From d9b6a28307cbea7656a1eee3b2a6c6b5ca7fce1d Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Tue, 7 Dec 2021 20:29:00 +0000 Subject: [PATCH 38/40] Add a bogus exit for AP1 to make it easier to evaluate valgrind results. --- rtsp.c | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/rtsp.c b/rtsp.c index af7066f9..4396a363 100644 --- a/rtsp.c +++ b/rtsp.c @@ -2533,7 +2533,7 @@ void handle_teardown_2(rtsp_conn_info *conn, __attribute__((unused)) rtsp_messag free(conn->ap2_timing_peer_list_message); conn->ap2_timing_peer_list_message = NULL; } - debug(1,"Bogus exit for valgrind."); + debug(1,"Bogus exit for valgrind -- remember to comment it out!."); exit(EXIT_SUCCESS); // } #endif @@ -2559,6 +2559,8 @@ void handle_teardown(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message conn->connection_number); resp->respcode = 451; } + debug(1,"Bogus exit for valgrind -- remember to comment it out!."); + exit(EXIT_SUCCESS); } void handle_flush(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { From 31a34ae6846f464237f4cbb2293b1bbdd8b070bf Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Tue, 7 Dec 2021 20:34:23 +0000 Subject: [PATCH 39/40] Fix another memory leak. --- rtsp.c | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/rtsp.c b/rtsp.c index 4396a363..2f7da6c5 100644 --- a/rtsp.c +++ b/rtsp.c @@ -2559,6 +2559,10 @@ void handle_teardown(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message conn->connection_number); resp->respcode = 451; } + if (conn->dacp_active_remote != NULL) { + free(conn->dacp_active_remote); + conn->dacp_active_remote = NULL; + } debug(1,"Bogus exit for valgrind -- remember to comment it out!."); exit(EXIT_SUCCESS); } From b938064baebf1f2e8193a03a95bc09e63cc9be78 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Tue, 7 Dec 2021 21:34:53 +0000 Subject: [PATCH 40/40] Add client and server ip metadata for AP2. Remove timing peer list and DACP code only for a full AP2 teardown. --- rtp.c | 5 ----- rtsp.c | 47 +++++++++++++++++++++++++++++------------------ 2 files changed, 29 insertions(+), 23 deletions(-) diff --git a/rtp.c b/rtp.c index 401f4dba..220bb919 100644 --- a/rtp.c +++ b/rtp.c @@ -1003,11 +1003,6 @@ void rtp_setup(SOCKADDR *local, SOCKADDR *remote, uint16_t cport, uint16_t tport conn->request_sent = 0; conn->rtp_running = 1; - -#ifdef CONFIG_METADATA - send_ssnc_metadata('clip', conn->client_ip_string, strlen(conn->client_ip_string), 1); - send_ssnc_metadata('svip', conn->self_ip_string, strlen(conn->self_ip_string), 1); -#endif } } diff --git a/rtsp.c b/rtsp.c index 2f7da6c5..e350b5a4 100644 --- a/rtsp.c +++ b/rtsp.c @@ -526,6 +526,7 @@ void release_hold_on_play_lock(__attribute__((unused)) rtsp_conn_info *conn) { } void release_play_lock(rtsp_conn_info *conn) { + debug(1, "Connection %d: release play lock.", conn->connection_number); debug_mutex_lock(&playing_conn_lock, 1000000, 3); if (playing_conn == conn) { // if we have the player playing_conn = NULL; // let it go @@ -535,6 +536,7 @@ void release_play_lock(rtsp_conn_info *conn) { } int get_play_lock(rtsp_conn_info *conn) { + debug(1, "Connection %d: request play lock.", conn->connection_number); // returns -1 if it failed, 0 if it succeeded and 1 if it succeeded but // interrupted an existing session int response = 0; @@ -590,7 +592,7 @@ int get_play_lock(rtsp_conn_info *conn) { } if ((have_the_player == 1) && (interrupting_current_session == 1)) { - debug(2, "Connection %d: Got player lock", conn->connection_number); + debug(1, "Connection %d: Got player lock", conn->connection_number); response = 1; } else { debug(1, "Connection %d: failed to get player lock", conn->connection_number); @@ -599,7 +601,7 @@ int get_play_lock(rtsp_conn_info *conn) { } if ((have_the_player) && (interrupting_current_session == 0)) { - debug(2, "Connection %d: got player lock.", conn->connection_number); + debug(1, "Connection %d: Got player lock.", conn->connection_number); response = 0; } return response; @@ -2486,6 +2488,14 @@ void teardown_phase_two(rtsp_conn_info *conn) { debug(2, "Connection %d: TEARDOWN mdns_update on %s.", conn->connection_number, get_category_string(conn->airplay_stream_category)); mdns_update(NULL, secondary_txt_records); + if (conn->dacp_active_remote != NULL) { + free(conn->dacp_active_remote); + conn->dacp_active_remote = NULL; + } + if (conn->ap2_timing_peer_list_message) { + free(conn->ap2_timing_peer_list_message); + conn->ap2_timing_peer_list_message = NULL; + } release_play_lock(conn); } } @@ -2509,10 +2519,10 @@ void handle_teardown_2(rtsp_conn_info *conn, __attribute__((unused)) rtsp_messag // we are being asked to close a stream teardown_phase_one(conn); plist_free(streams); - debug(2, "Connection %d: Stream TEARDOWN complete", conn->connection_number); + debug(1, "Connection %d: TEARDOWN phase one complete", conn->connection_number); } else { teardown_phase_two(conn); - debug(2, "Connection %d: non-stream TEARDOWN complete", conn->connection_number); + debug(1, "Connection %d: TEARDOWN phase two complete", conn->connection_number); } //} else { // warn("Connection %d TEARDOWN received without having the player (no ANNOUNCE?)", @@ -2525,16 +2535,8 @@ void handle_teardown_2(rtsp_conn_info *conn, __attribute__((unused)) rtsp_messag debug(1, "Connection %d: missing plist!", conn->connection_number); resp->respcode = 451; // don't know what to do here } - if (conn->dacp_active_remote != NULL) { - free(conn->dacp_active_remote); - conn->dacp_active_remote = NULL; - } - if (conn->ap2_timing_peer_list_message) { - free(conn->ap2_timing_peer_list_message); - conn->ap2_timing_peer_list_message = NULL; - } - debug(1,"Bogus exit for valgrind -- remember to comment it out!."); - exit(EXIT_SUCCESS); // + // debug(1,"Bogus exit for valgrind -- remember to comment it out!."); + // exit(EXIT_SUCCESS); // } #endif @@ -2563,8 +2565,8 @@ void handle_teardown(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message free(conn->dacp_active_remote); conn->dacp_active_remote = NULL; } - debug(1,"Bogus exit for valgrind -- remember to comment it out!."); - exit(EXIT_SUCCESS); + // debug(1,"Bogus exit for valgrind -- remember to comment it out!."); + // exit(EXIT_SUCCESS); } void handle_flush(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { @@ -2637,6 +2639,11 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) debug(2, "Connection %d: SETUP: PTP setup detected.", conn->connection_number); conn->airplay_stream_category = ptp_stream; conn->timing_type = ts_ptp; + get_play_lock(conn); +#ifdef CONFIG_METADATA + send_ssnc_metadata('clip', conn->client_ip_string, strlen(conn->client_ip_string), 1); + send_ssnc_metadata('svip', conn->self_ip_string, strlen(conn->self_ip_string), 1); +#endif } else if (strcmp(timingProtocolString, "NTP") == 0) { debug(1, "Connection %d: SETUP: NTP setup detected.", conn->connection_number); conn->airplay_stream_category = ntp_stream; @@ -2891,7 +2898,6 @@ void handle_setup_2(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) debug(2, "Connection %d: SETUP on %s. A \"streams\" array has been found", conn->connection_number, get_category_string(conn->airplay_stream_category)); if (conn->airplay_stream_category == ptp_stream) { - get_play_lock(conn); // get stream[0] plist_t stream0 = plist_array_get_item(streams, 0); @@ -3214,7 +3220,12 @@ void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { } else { debug(1, "Connection %d: SETUP doesn't contain a Transport header.", conn->connection_number); } - if (resp->respcode != 200) { + if (resp->respcode == 200) { +#ifdef CONFIG_METADATA + send_ssnc_metadata('clip', conn->client_ip_string, strlen(conn->client_ip_string), 1); + send_ssnc_metadata('svip', conn->self_ip_string, strlen(conn->self_ip_string), 1); +#endif + } else { debug(1, "Connection %d: SETUP error -- releasing the player lock.", conn->connection_number); release_play_lock(conn); }