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 diff --git a/activity_monitor.c b/activity_monitor.c index 2f5efddf..deeab2b6 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"); @@ -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 3413250c..5ff14195 100644 --- a/audio.h +++ b/audio.h @@ -39,8 +39,9 @@ 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 (*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 void (*volume)(double vol); diff --git a/audio_alsa.c b/audio_alsa.c index f723cb7d..a007c419 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -60,7 +60,9 @@ 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 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); @@ -88,7 +90,9 @@ audio_output audio_alsa = { .flush = &flush, .delay = &delay, .play = &play, - .rate_info = &get_rate_information, + .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 @@ -239,22 +243,18 @@ 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; + +// 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" @@ -439,7 +439,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; } @@ -476,14 +476,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; } @@ -529,7 +529,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; } } @@ -539,8 +539,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 { @@ -559,7 +559,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++; } @@ -569,7 +571,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; } } @@ -614,7 +616,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; } @@ -781,7 +783,8 @@ 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 @@ -1290,16 +1293,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.", @@ -1407,8 +1410,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 +1433,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; } @@ -1572,7 +1575,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; @@ -1587,8 +1590,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 +1634,48 @@ int delay(long *the_delay) { return ret; } +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. + // 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; + + 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 { + *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) + 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); + 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_rate_information(uint64_t *elapsed_time, uint64_t *frames_played) { // elapsed_time is in nanoseconds int response = 0; // zero means okay @@ -1644,6 +1689,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,35 +1717,10 @@ 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; - if (ret == -EPIPE) { /* underrun */ + 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 // sending the samples to be output. If so, it will still be in @@ -1748,8 +1769,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 +1793,9 @@ int do_open(int do_auto_setup) { // set accordingly // do_mute(0); // complete unmute } - + 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. } } else { @@ -2005,8 +2026,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/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 58a5fd72..52e6a882 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,18 @@ 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, + .stats = NULL, + .play = &play, + .volume = NULL, + .parameters = NULL, + .mute = NULL}; diff --git a/audio_sndio.c b/audio_sndio.c index 6ada40ad..2f2239e2 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, @@ -203,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 501c6db2..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, @@ -216,6 +218,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/common.c b/common.c index 866222c2..bbe36780 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 @@ -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); @@ -1208,64 +1210,14 @@ 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. - - // 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_absolute_time_in_ns() { +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_REALTIME, &tn); + clock_gettime(CLOCK_MONOTONIC, &tn); uint64_t tnnsec = tn.tv_sec; tnnsec = tnnsec * 1000000000; uint64_t tnjnsec = tn.tv_nsec; @@ -1277,6 +1229,115 @@ 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 + // 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; +} + +// 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. + clock_gettime(CLOCK_REALTIME, &tn); + uint64_t tnnsec = tn.tv_sec; + 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 + uint64_t time_now_mach; + 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. @@ -1292,8 +1353,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; @@ -1467,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; @@ -1476,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]; @@ -1963,7 +2027,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 +2037,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..d9be0327 100644 --- a/common.h +++ b/common.h @@ -379,8 +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); +#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/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])]) diff --git a/dacp.c b/dacp.c index 35dbabd0..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); @@ -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 @@ -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/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/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/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/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 0084ab5e..1feee08f 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) " @@ -380,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, @@ -1055,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; @@ -1165,9 +1173,9 @@ 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 " - "detected.", - conn->connection_number); + die("an unrecoverable error, \"output_device_stalled\", has been " + "detected.", + conn->connection_number); } } } else { @@ -1296,7 +1304,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; @@ -1354,6 +1362,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 +1475,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; @@ -1544,29 +1557,27 @@ 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 -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}; +// be printed -- 2 means print, 1 means print only in a debug mode, 0 means skip -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}; +// 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_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, - 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_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}; + +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) { // 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, ", "); + strcat(line_of_stats, " "); if (statistics_row == 0) { strcat(line_of_stats, heading); } else { @@ -1611,12 +1622,12 @@ 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 " + " 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.", @@ -1681,7 +1692,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) { @@ -1705,8 +1716,8 @@ void player_thread_cleanup_handler(void *arg) { if (conn->stream.type == ast_apple_lossless) terminate_decoders(conn); - reset_anchor_info(conn); - release_play_lock(conn); + // reset_anchor_info(conn); + // release_play_lock(conn); conn->rtp_running = 0; pthread_setcancelstate(oldState, NULL); debug(2, "Connection %d: player terminated.", conn->connection_number); @@ -1714,6 +1725,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_raw_measurement_time; + uint64_t previous_corrected_measurement_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; @@ -1727,7 +1744,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; @@ -1735,7 +1752,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, @@ -1872,8 +1889,9 @@ void *player_thread_func(void *arg) { conn->playstart = time(NULL); - conn->frame_rate = 0.0; - conn->frame_rate_status = 0; + conn->raw_frame_rate = 0.0; + conn->corrected_frame_rate = 0.0; + conn->frame_rate_valid = 0; conn->input_frame_rate = 0.0; conn->input_frame_rate_starting_point_is_valid = 0; @@ -1994,7 +2012,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 @@ -2003,7 +2021,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 @@ -2014,7 +2032,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 @@ -2063,10 +2081,21 @@ 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 - + uint64_t local_time_now = get_absolute_time_in_ns(); // types okay if (inframe) { inbuf = inframe->data; inbuflength = inframe->length; @@ -2252,8 +2281,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; @@ -2285,6 +2312,150 @@ 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 = 0; + if ((config.output->delay) && (config.no_sync == 0) && (config.output->stats)) { + uint64_t frames_sent_for_play; + uint64_t raw_measurement_time; + uint64_t corrected_measurement_time; + uint64_t actual_delay; + stats_status = + 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); + 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 != 0)) { + uint64_t frames_played_in_this_interval = frames_played - previous_frames_played; + 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.", + // frames_played_in_this_interval, interval, conn->frame_rate); + } + } + + // 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 ((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_raw_measurement_time = raw_measurement_time; + previous_corrected_measurement_time = corrected_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 = 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("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) + ? ((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. @@ -2613,7 +2784,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 @@ -2768,101 +2939,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; - } - - 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; - } - } - - // 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); - statistics_item(" output fps", "%*.2f", 11, conn->frame_rate); - 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 > 0.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; - } } } } @@ -2920,7 +2996,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 effd8b12..edf80837 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 @@ -109,7 +110,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; @@ -171,7 +171,7 @@ typedef struct { player_watchdog_thread; // buffers to delete on exit - signed short *tbuf; + int32_t *tbuf; int32_t *sbuf; char *outbuf; @@ -180,8 +180,9 @@ typedef struct { stats_t *statistics; // for holding the output rate information until printed out at the end of a session - double frame_rate; - int frame_rate_status; + 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 @@ -296,7 +297,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 @@ -408,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); 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 - + + diff --git a/ptp-utilities.c b/ptp-utilities.c index 0f80e913..fa1c6407 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" @@ -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) @@ -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..220bb919 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.", @@ -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 " @@ -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; @@ -1001,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 } } @@ -1029,6 +1026,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 +1050,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; } } @@ -1302,7 +1305,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 < 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) || @@ -1392,6 +1395,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 } } @@ -1469,6 +1473,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; @@ -1564,7 +1570,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 @@ -1751,7 +1758,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."); } @@ -2030,7 +2037,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 +2127,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 +2229,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; @@ -2241,9 +2249,20 @@ 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 - reset_buffer(conn); // in case there is any garbage in the player + double requested_lead_time = 0.1; // 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; + + // 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; @@ -2503,43 +2522,60 @@ 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 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 (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))) { - // 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) { - 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; - //} - } - unsigned char nonce[12]; memset(nonce, 0, sizeof(nonce)); memcpy(nonce + 4, packet + nread - 8, @@ -2580,6 +2616,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(); @@ -2592,66 +2629,77 @@ 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) { - ret = avcodec_send_packet(codec_context, pkt); - if (ret < 0) { - debug(1, "error sending packet to decoder"); + // if (0) { + if (pkt->size <= 7) { // no idea about this... + debug(2, "malformed AAC packet skipped."); } 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); } } } diff --git a/rtsp.c b/rtsp.c index 9e18a3b2..e350b5a4 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) { @@ -493,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 @@ -502,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; @@ -557,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); @@ -566,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; @@ -583,7 +618,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); @@ -607,8 +646,8 @@ 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.", - conn->connection_number); + die("an unrecoverable error, \"unable_to_cancel_play_session\", has been detected.", + conn->connection_number); } } } @@ -655,19 +694,21 @@ 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); - debug(1, "Connection %d: cancelled.", conns[i]->connection_number); + debug(2, "Connection %d: cancelled.", conns[i]->connection_number); } } 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); - debug(1, "Connection %d: joined.", conns[i]->connection_number); + debug(2, "Connection %d: joined.", conns[i]->connection_number); free(conns[i]); conns[i] = NULL; } @@ -1133,7 +1174,9 @@ 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; - int release_buffer = 0; // on exit, don't deallocate the buffer if everything was okay + 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) { warn("Connection %d: rtsp_read_request: can't get a buffer.", conn->connection_number); @@ -1222,7 +1265,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 @@ -1249,9 +1292,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; @@ -1303,7 +1346,9 @@ 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"}, {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++) { @@ -1469,7 +1514,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"); @@ -1512,6 +1557,58 @@ 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)); @@ -1519,15 +1616,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); @@ -1547,11 +1645,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"); @@ -1662,13 +1760,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; } @@ -1694,12 +1793,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 @@ -1710,7 +1809,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; @@ -1748,7 +1847,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); } @@ -1783,8 +1882,10 @@ 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; @@ -2149,7 +2250,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) { @@ -2163,7 +2284,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 @@ -2179,7 +2300,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); @@ -2196,6 +2317,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 { @@ -2210,6 +2333,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."); } @@ -2281,10 +2406,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) { - ptp_send_control_message_string(conn->ap2_timing_peer_list_message); - release_hold_on_play_lock(conn); - } + // 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); + // } } plist_free(addresses_array); resp->respcode = 200; @@ -2321,7 +2446,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 +2472,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 @@ -2362,10 +2488,18 @@ 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); } } - void handle_teardown_2(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message *req, rtsp_message *resp) { @@ -2385,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?)", @@ -2401,6 +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 } + // debug(1,"Bogus exit for valgrind -- remember to comment it out!."); + // exit(EXIT_SUCCESS); // } #endif @@ -2416,6 +2552,7 @@ 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); 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); @@ -2424,6 +2561,12 @@ 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); } void handle_flush(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { @@ -2496,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; @@ -2508,7 +2656,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 { @@ -2604,10 +2752,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) { @@ -2617,15 +2766,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 { @@ -2661,7 +2812,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."); @@ -2682,6 +2834,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 { @@ -2707,7 +2861,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(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."); conn->rtp_event_thread = malloc(sizeof(pthread_t)); @@ -2759,7 +2914,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); @@ -2819,7 +2975,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 @@ -2829,7 +2985,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); @@ -2863,10 +3020,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); @@ -2877,7 +3035,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 @@ -2892,7 +3050,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. @@ -2933,7 +3092,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 { @@ -2947,6 +3106,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 @@ -3060,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); } @@ -3117,7 +3282,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 +3292,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 +3546,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 +3840,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 @@ -3784,7 +3952,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 = @@ -4513,8 +4681,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 +4840,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 +4861,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..e2fd0b5e 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); } @@ -1450,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"); @@ -1798,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); @@ -1833,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!"); @@ -1920,7 +1930,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)) {