diff --git a/audio_alsa.c b/audio_alsa.c index 09903519..e2a53ccd 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -166,7 +166,7 @@ void do_snd_mixer_selem_set_playback_dB_all(snd_mixer_elem_t *mix_elem, double v } static int init(int argc, char **argv) { - pthread_mutex_lock(&alsa_mutex); + debug_mutex_lock(&alsa_mutex, 1000, 1); // debug(2,"audio_alsa init called."); const char *str; int value; @@ -219,7 +219,7 @@ static int init(int argc, char **argv) { else if (strcasecmp(str, "yes") == 0) config.no_sync = 1; else { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid disable_synchronization option choice \"%s\". It should be \"yes\" or \"no\""); } } @@ -227,13 +227,13 @@ static int init(int argc, char **argv) { /* Get the mute_using_playback_switch setting. */ if (config_lookup_string(config.cfg, "alsa.mute_using_playback_switch", &str)) { inform("The alsa \"mute_using_playback_switch\" setting is deprecated. " - "Please use the \"use_hardware_mute_if_available\" setting instead."); + "Please use the \"use_hardware_mute_if_available\" setting instead."); if (strcasecmp(str, "no") == 0) config.alsa_use_hardware_mute = 0; else if (strcasecmp(str, "yes") == 0) config.alsa_use_hardware_mute = 1; else { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid mute_using_playback_switch option choice \"%s\". It should be \"yes\" or " "\"no\""); } @@ -246,7 +246,7 @@ static int init(int argc, char **argv) { else if (strcasecmp(str, "yes") == 0) config.alsa_use_hardware_mute = 1; else { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid use_hardware_mute_if_available option choice \"%s\". It should be \"yes\" or " "\"no\""); } @@ -269,7 +269,7 @@ static int init(int argc, char **argv) { else if (strcasecmp(str, "S8") == 0) config.output_format = SPS_FORMAT_S8; else { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid output format \"%s\". It should be \"U8\", \"S8\", \"S16\", \"S24\", " "\"S24_3LE\", \"S24_3BE\" or " "\"S32\"", @@ -288,7 +288,7 @@ static int init(int argc, char **argv) { config.output_rate = value; break; default: - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid output rate \"%d\". It should be a multiple of 44,100 up to 352,800", value); } } @@ -300,7 +300,7 @@ static int init(int argc, char **argv) { else if (strcasecmp(str, "yes") == 0) config.no_mmap = 0; else { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid use_mmap_if_available option choice \"%s\". It should be \"yes\" or \"no\""); } } @@ -309,7 +309,7 @@ static int init(int argc, char **argv) { set_period_size_request = 1; debug(1, "Value read for period size is %d.", value); if (value < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid alsa period size setting \"%d\". It " "must be greater than 0.", value); @@ -323,7 +323,7 @@ static int init(int argc, char **argv) { set_buffer_size_request = 1; debug(1, "Value read for buffer size is %d.", value); if (value < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid alsa buffer size setting \"%d\". It " "must be greater than 0.", value); @@ -362,13 +362,13 @@ static int init(int argc, char **argv) { break; default: help(); - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid audio option -%c specified", opt); } } if (optind < argc) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Invalid audio argument: %s", argv[optind]); } @@ -412,11 +412,11 @@ static int init(int argc, char **argv) { alsa_mix_ctrl); if (snd_ctl_open(&ctl, alsa_mix_dev, 0) < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Cannot open control \"%s\"", alsa_mix_dev); } if (snd_ctl_elem_id_malloc(&elem_id) < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Cannot allocate memory for control \"%s\"", alsa_mix_dev); } snd_ctl_elem_id_set_interface(elem_id, SND_CTL_ELEM_IFACE_MIXER); @@ -462,7 +462,7 @@ static int init(int argc, char **argv) { } alsa_mix_handle = NULL; - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); return 0; } @@ -507,7 +507,7 @@ int open_alsa_device(void) { ret = snd_pcm_hw_params_any(alsa_handle, alsa_params); if (ret < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); ; die("audio_alsa: Broken configuration for device \"%s\": no configurations " "available", @@ -534,7 +534,7 @@ int open_alsa_device(void) { ret = snd_pcm_hw_params_set_access(alsa_handle, alsa_params, access); if (ret < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("audio_alsa: Access type not available for device \"%s\": %s", alsa_out_dev, snd_strerror(ret)); } @@ -562,20 +562,20 @@ int open_alsa_device(void) { sf = SND_PCM_FORMAT_S32; break; default: - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); sf = SND_PCM_FORMAT_S16; // this is just to quieten a compiler warning die("Unsupported output format at audio_alsa.c"); } ret = snd_pcm_hw_params_set_format(alsa_handle, alsa_params, sf); if (ret < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("audio_alsa: Sample format %d not available for device \"%s\": %s", sample_format, alsa_out_dev, snd_strerror(ret)); } ret = snd_pcm_hw_params_set_channels(alsa_handle, alsa_params, 2); if (ret < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("audio_alsa: Channels count (2) not available for device \"%s\": %s", alsa_out_dev, snd_strerror(ret)); } @@ -591,7 +591,7 @@ int open_alsa_device(void) { ret = snd_pcm_hw_params_set_period_size_near(alsa_handle, alsa_params, &period_size_requested, &dir); if (ret < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("audio_alsa: cannot set period size of %lu: %s", period_size_requested, snd_strerror(ret)); snd_pcm_uframes_t actual_period_size; @@ -607,7 +607,7 @@ int open_alsa_device(void) { debug(1, "Attempting to set the buffer size to %lu", buffer_size_requested); ret = snd_pcm_hw_params_set_buffer_size_near(alsa_handle, alsa_params, &buffer_size_requested); if (ret < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("audio_alsa: cannot set buffer size of %lu: %s", buffer_size_requested, snd_strerror(ret)); } @@ -621,19 +621,19 @@ int open_alsa_device(void) { ret = snd_pcm_hw_params(alsa_handle, alsa_params); if (ret < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("audio_alsa: Unable to set hw parameters for device \"%s\": %s.", alsa_out_dev, snd_strerror(ret)); } if (my_sample_rate != desired_sample_rate) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("Can't set the D/A converter to %d.", desired_sample_rate); } ret = snd_pcm_hw_params_get_buffer_size(alsa_params, &actual_buffer_length); if (ret < 0) { - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); die("audio_alsa: Unable to get hw buffer length for device \"%s\": %s.", alsa_out_dev, snd_strerror(ret)); } @@ -817,7 +817,7 @@ int delay(long *the_delay) { if (alsa_handle == NULL) { return -ENODEV; } else { - pthread_mutex_lock(&alsa_mutex); + debug_mutex_lock(&alsa_mutex, 10000, 1); int derr; if (snd_pcm_state(alsa_handle) == SND_PCM_STATE_RUNNING) { *the_delay = 0; // just to see what happens @@ -843,7 +843,7 @@ int delay(long *the_delay) { debug(1, "Error preparing after delay error: \"%s\".", snd_strerror(derr)); } } - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); // here, occasionally pretend there's a problem with pcm_get_delay() // if ((random() % 100000) < 3) // keep it pretty rare // reply = -EPERM; // pretend something bad has happened @@ -855,7 +855,7 @@ static void play(void *buf, int samples) { // debug(3,"audio_alsa play called."); int ret = 0; if (alsa_handle == NULL) { - pthread_mutex_lock(&alsa_mutex); + debug_mutex_lock(&alsa_mutex, 10000, 1); ret = open_alsa_device(); if (ret == 0) { if (audio_alsa.volume) @@ -863,10 +863,10 @@ static void play(void *buf, int samples) { if (audio_alsa.mute) do_mute(0); } - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); } if (ret == 0) { - pthread_mutex_lock(&alsa_mutex); + debug_mutex_lock(&alsa_mutex, 10000, 1); // snd_pcm_sframes_t current_delay = 0; int err; if (snd_pcm_state(alsa_handle) == SND_PCM_STATE_XRUN) { @@ -897,13 +897,13 @@ static void play(void *buf, int samples) { debug(1, "Error preparing after play error: \"%s\".", snd_strerror(err)); } } - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); } } static void flush(void) { // debug(2,"audio_alsa flush called."); - pthread_mutex_lock(&alsa_mutex); + debug_mutex_lock(&alsa_mutex, 10000, 1); int derr; do_mute(1); if (alsa_handle) { @@ -920,7 +920,7 @@ static void flush(void) { alsa_handle = NULL; } - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); } static void stop(void) { @@ -973,10 +973,10 @@ void do_volume(double vol) { // caller is assumed to have the alsa_mutex when us } void volume(double vol) { - pthread_mutex_lock(&alsa_mutex); + debug_mutex_lock(&alsa_mutex, 1000, 1); volume_set_request = 1; // an external request has been made to set the volume do_volume(vol); - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); } /* @@ -999,11 +999,11 @@ static void linear_volume(double vol) { static void mute(int mute_state_requested) { // debug(1,"External Mute Request: %d",mute_state_requested); - pthread_mutex_lock(&alsa_mutex); + debug_mutex_lock(&alsa_mutex, 10000, 1); mute_request_pending = 1; overriding_mute_state_requested = mute_state_requested; do_mute(mute_state_requested); - pthread_mutex_unlock(&alsa_mutex); + debug_mutex_unlock(&alsa_mutex, 3); } void do_mute(int mute_state_requested) { diff --git a/audio_pipe.c b/audio_pipe.c index b81401c5..c080277d 100644 --- a/audio_pipe.c +++ b/audio_pipe.c @@ -54,7 +54,7 @@ static void start(__attribute__((unused)) int sample_rate, } } -static void play(short buf[], int samples) { +static void play(void *buf, int samples) { // if the file is not open, try to open it. char errorstring[1024]; if (fd == -1) { diff --git a/common.c b/common.c index e835ab67..306b3c2f 100644 --- a/common.c +++ b/common.c @@ -795,17 +795,16 @@ uint64_t get_absolute_time_in_fp() { // can't use CLOCK_MONOTONIC_RAW as it's not implemented in OpenWrt clock_gettime(CLOCK_MONOTONIC, &tn); uint64_t tnfpsec = tn.tv_sec; - if (tnfpsec>0x100000000) + if (tnfpsec > 0x100000000) warn("clock_gettime seconds overflow!"); uint64_t tnfpnsec = tn.tv_nsec; - if (tnfpnsec>0x100000000) + if (tnfpnsec > 0x100000000) warn("clock_gettime nanoseconds seconds overflow!"); - tnfpsec = tnfpsec<<32; - tnfpnsec = tnfpnsec<<32; - tnfpnsec = tnfpnsec/1000000000; - - time_now_fp = - tnfpsec + tnfpnsec; // types okay + tnfpsec = tnfpsec << 32; + tnfpnsec = tnfpnsec << 32; + tnfpnsec = tnfpnsec / 1000000000; + + time_now_fp = tnfpsec + tnfpnsec; // types okay #endif #ifdef COMPILE_FOR_OSX uint64_t time_now_mach; @@ -1014,15 +1013,9 @@ void sps_nanosleep(const time_t sec, const long nanosec) { debug(1, "Error in sps_nanosleep of %d sec and %ld nanoseconds: %d.", sec, nanosec, errno); } -char *previous_debug_message = NULL; - int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time, const char *debugmessage, int debuglevel) { - if (previous_debug_message) - free(previous_debug_message); - previous_debug_message = strdup(debugmessage); - useconds_t time_to_wait = dally_time; int r = pthread_mutex_trylock(mutex); while ((r == EBUSY) && (time_to_wait > 0)) { @@ -1033,20 +1026,53 @@ int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time, time_to_wait -= st; r = pthread_mutex_trylock(mutex); } - if (r != 0) { + if ((r != 0) && (debugmessage != NULL)) { char errstr[1000]; if (r == EBUSY) debug(debuglevel, - "error EBUSY waiting for a mutex: \"%s\". Previous debug message was: \"%s\".", - debugmessage, previous_debug_message); + "waiting for a mutex, maximum expected time of %d microseconds exceeded \"%s\".", + dally_time, debugmessage); else - debug(debuglevel, - "error %d: \"%s\" waiting for a mutex: \"%s\". Previous debug message was: \"%s\".", r, - strerror_r(r, errstr, sizeof(errstr)), debugmessage, previous_debug_message); + debug(debuglevel, "error %d: \"%s\" waiting for a mutex: \"%s\".", r, + strerror_r(r, errstr, sizeof(errstr)), debugmessage); } return r; } +int _debug_mutex_lock(pthread_mutex_t *mutex, useconds_t dally_time, const char *filename, + const int line, int debuglevel) { + uint64_t time_at_start = get_absolute_time_in_fp(); + char dstring[1000]; + memset(dstring, 0, sizeof(dstring)); + snprintf(dstring, sizeof(dstring), "%s:%d", filename, line); + debug(3, "debug_mutex_lock at \"%s\".", dstring); + int result = sps_pthread_mutex_timedlock(mutex, dally_time, dstring, debuglevel); + if (result == EBUSY) { + result = pthread_mutex_lock(mutex); + uint64_t time_delay = get_absolute_time_in_fp() - time_at_start; + uint64_t divisor = (uint64_t)1 << 32; + double delay = 1.0 * time_delay / divisor; + debug(debuglevel, + "debug_mutex_lock at \"%s\" expected max wait: %0.9f, actual wait: %0.9f sec.", dstring, + (1.0 * dally_time) / 1000000, delay); + } + return result; +} + +int _debug_mutex_unlock(pthread_mutex_t *mutex, const char *filename, const int line, + int debuglevel) { + char dstring[1000]; + char errstr[512]; + memset(dstring, 0, sizeof(dstring)); + snprintf(dstring, sizeof(dstring), "%s:%d", filename, line); + debug(debuglevel, "debug_mutex_unlock at \"%s\".", dstring); + int r = pthread_mutex_unlock(mutex); + if (r != 0) + debug(1, "error %d: \"%s\" unlocking a mutex: \"%s\".", r, + strerror_r(r, errstr, sizeof(errstr)), dstring); + return r; +} + char *get_version_string() { char *version_string = malloc(200); if (version_string) { diff --git a/common.h b/common.h index e749d5f3..87493cb1 100644 --- a/common.h +++ b/common.h @@ -264,6 +264,17 @@ extern sigset_t pselect_sigset; // wait for the specified time in microseconds -- it checks every 20 milliseconds int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time, const char *debugmessage, int debuglevel); +// wait for the specified time, checking every 20 milliseconds, and block if it can't acquire the +// lock +int _debug_mutex_lock(pthread_mutex_t *mutex, useconds_t dally_time, const char *filename, + const int line, int debuglevel); + +#define debug_mutex_lock(mu, t, d) _debug_mutex_lock(mu, t, __FILE__, __LINE__, d) + +int _debug_mutex_unlock(pthread_mutex_t *mutex, const char *filename, const int line, + int debuglevel); + +#define debug_mutex_unlock(mu, d) _debug_mutex_unlock(mu, __FILE__, __LINE__, d) char *get_version_string(); // mallocs a string space -- remember to free it afterwards diff --git a/player.c b/player.c index 8e51c9c3..3a2b8dc0 100644 --- a/player.c +++ b/player.c @@ -464,9 +464,16 @@ static void free_audio_buffers(rtsp_conn_info *conn) { free(conn->audio_buffer[i].data); } +void player_thread_lock_cleanup(void *arg) { + rtsp_conn_info *conn = (rtsp_conn_info *)arg; + debug(3, "Cleaning up player_thread_lock."); + pthread_rwlock_unlock(&conn->player_thread_lock); +} + void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp, uint8_t *data, int len, rtsp_conn_info *conn) { if (pthread_rwlock_tryrdlock(&conn->player_thread_lock) == 0) { + pthread_cleanup_push(player_thread_lock_cleanup, (void *)conn); if (conn->player_thread != NULL) { // all timestamps are done at the output rate @@ -478,13 +485,13 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp // ignore a request to flush that has been made before the first packet... if (conn->packet_count == 0) { - pthread_mutex_lock(&conn->flush_mutex); + debug_mutex_lock(&conn->flush_mutex, 1000, 1); conn->flush_requested = 0; conn->flush_rtp_timestamp = 0; - pthread_mutex_unlock(&conn->flush_mutex); + debug_mutex_unlock(&conn->flush_mutex, 3); } - pthread_mutex_lock(&conn->ab_mutex); + debug_mutex_lock(&conn->ab_mutex, 30000, 1); conn->packet_count++; conn->time_of_last_audio_packet = get_absolute_time_in_fp(); if (conn->connection_state_to_output) { // if we are supposed to be processing these packets @@ -526,37 +533,6 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp conn->latency, resend_interval); conn->resend_interval = resend_interval; } - if (!conn->ab_buffering) { - int j; - for (j = 1; j <= number_of_resend_attempts; j++) { - // check j times, after a short period of has elapsed, assuming 352 frames per packet - - int back_step = resend_interval * j; - - int32_t sd = seq_diff(conn->ab_read, conn->ab_write, conn->ab_read); - int k; - for (k = -2; k <= 2; k++) { - if ((back_step + k) < sd) { // if it's within the range of frames in use... - int item_to_check = (conn->ab_write - (back_step + k)) & 0xffff; - seq_t next = item_to_check; - abuf_t *check_buf = conn->audio_buffer + BUFIDX(next); - if ((!check_buf->ready) && - (check_buf->resend_level < - j)) { // prevent multiple requests from the same level of lookback - check_buf->resend_level = j; - if (config.disable_resend_requests == 0) { - rtp_request_resend(next, 1, conn); - if ((back_step + k + resend_interval) >= sd) - debug(2, "Last-ditch (#%d) resend request for packet %u in range %u to %u. " - "Looking back %d packets.", - j, next, conn->ab_read, conn->ab_write, back_step + k); - conn->resend_requests++; - } - } - } - } - } - } if (conn->ab_write == seqno) { // expected packet abuf = conn->audio_buffer + BUFIDX(seqno); @@ -621,18 +597,54 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp } // pthread_mutex_lock(&ab_mutex); + int rc = pthread_cond_signal(&conn->flowcontrol); + if (rc) + debug(1, "Error signalling flowcontrol."); + + // if it's at the expected time, do a look back for missing packets + // but release the ab_mutex when doing a resend + if (!conn->ab_buffering) { + int j; + for (j = 1; j <= number_of_resend_attempts; j++) { + // check j times, after a short period of has elapsed, assuming 352 frames per packet + + int back_step = resend_interval * j; + int k; + for (k = -2; k <= 2; k++) { + if ((back_step + k) < + seq_diff(conn->ab_read, conn->ab_write, + conn->ab_read)) { // if it's within the range of frames in use... + int item_to_check = (conn->ab_write - (back_step + k)) & 0xffff; + seq_t next = item_to_check; + abuf_t *check_buf = conn->audio_buffer + BUFIDX(next); + if ((!check_buf->ready) && + (check_buf->resend_level < + j)) { // prevent multiple requests from the same level of lookback + check_buf->resend_level = j; + if (config.disable_resend_requests == 0) { + if ((back_step + k + resend_interval) >= + seq_diff(conn->ab_read, conn->ab_write, conn->ab_read)) + debug(3, "Last-ditch (#%d) resend request for packet %u in range %u to %u. " + "Looking back %d packets.", + j, next, conn->ab_read, conn->ab_write, back_step + k); + debug_mutex_unlock(&conn->ab_mutex, 3); + rtp_request_resend(next, 1, conn); + conn->resend_requests++; + debug_mutex_lock(&conn->ab_mutex, 20000, 1); + } + } + } + } + } + } } - int rc = pthread_cond_signal(&conn->flowcontrol); - if (rc) - debug(1, "Error signalling flowcontrol."); } - pthread_mutex_unlock(&conn->ab_mutex); + debug_mutex_unlock(&conn->ab_mutex, 3); } else { - debug( - 1, - "No player thread while adding a player_put_packet calle was made -- packet discarded."); + debug(1, "player_put_packet discarded packet %d because the player thread was gone."); } - pthread_rwlock_unlock(&conn->player_thread_lock); + pthread_cleanup_pop(1); + // pthread_rwlock_unlock(&conn->player_thread_lock); } else { debug(1, "player_put_packet discarded packet %d because the player thread was locked.", seqno); } @@ -787,12 +799,13 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { abuf_t *curframe = 0; int notified_buffer_empty = 0; // diagnostic only - pthread_mutex_lock(&conn->ab_mutex); + debug_mutex_lock(&conn->ab_mutex, 30000, 1); int wait; long dac_delay = 0; // long because alsa returns a long do { // get the time local_time_now = get_absolute_time_in_fp(); // type okay + debug(3, "buffer_get_frame is iterating"); // if config.timeout (default 120) seconds have elapsed since the last audio packet was // received, then we should stop. @@ -818,13 +831,13 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { conn->connection_state_to_output = rco; // change happening if (conn->connection_state_to_output == 0) { // going off - pthread_mutex_lock(&conn->flush_mutex); + debug_mutex_lock(&conn->flush_mutex, 1000, 1); conn->flush_requested = 1; - pthread_mutex_unlock(&conn->flush_mutex); + debug_mutex_unlock(&conn->flush_mutex, 3); } } - pthread_mutex_lock(&conn->flush_mutex); + debug_mutex_lock(&conn->flush_mutex, 1000, 1); if (conn->flush_requested == 1) { if (config.output->flush) config.output->flush(); @@ -834,7 +847,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { conn->time_since_play_started = 0; conn->flush_requested = 0; } - pthread_mutex_unlock(&conn->flush_mutex); + debug_mutex_unlock(&conn->flush_mutex, 3); uint32_t flush_limit = 0; if (conn->ab_synced) { @@ -1214,10 +1227,10 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { struct timespec time_of_wakeup; time_of_wakeup.tv_sec = sec; time_of_wakeup.tv_nsec = nsec; - pthread_cond_timedwait(&conn->flowcontrol, &conn->ab_mutex, &time_of_wakeup); -// int rc = pthread_cond_timedwait(&flowcontrol,&ab_mutex,&time_of_wakeup); -// if (rc!=0) -// debug(1,"pthread_cond_timedwait returned error code %d.",rc); + // pthread_cond_timedwait(&conn->flowcontrol, &conn->ab_mutex, &time_of_wakeup); + int rc = pthread_cond_timedwait(&conn->flowcontrol, &conn->ab_mutex, &time_of_wakeup); + if (rc != 0) + debug(3, "pthread_cond_timedwait returned error code %d.", rc); #endif #ifdef COMPILE_FOR_OSX uint64_t sec = time_to_wait_for_wakeup_fp >> 32; @@ -1232,7 +1245,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { if (conn->player_thread_please_stop) { debug(3, "buffer_get_frame exiting due to thread stop request."); - pthread_mutex_unlock(&conn->ab_mutex); + debug_mutex_unlock(&conn->ab_mutex, 3); return 0; } @@ -1246,7 +1259,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { curframe->ready = 0; curframe->resend_level = 0; conn->ab_read = SUCCESSOR(conn->ab_read); - pthread_mutex_unlock(&conn->ab_mutex); + debug_mutex_unlock(&conn->ab_mutex, 3); return curframe; } @@ -1294,7 +1307,6 @@ static int stuff_buffer_basic_32(int32_t *inptr, int length, enum sps_format_t l stuffsamp = (rand() % (length - 2)) + 1; // ensure there's always a sample before and after the item - pthread_mutex_lock(&conn->vol_mutex); for (i = 0; i < stuffsamp; i++) { // the whole frame, if no stuffing process_sample(*inptr++, &l_outptr, l_output_format, conn->fix_volume, dither, conn); process_sample(*inptr++, &l_outptr, l_output_format, conn->fix_volume, dither, conn); @@ -1324,7 +1336,6 @@ static int stuff_buffer_basic_32(int32_t *inptr, int length, enum sps_format_t l process_sample(*inptr++, &l_outptr, l_output_format, conn->fix_volume, dither, conn); } } - pthread_mutex_unlock(&conn->vol_mutex); conn->amountStuffed = tstuff; return length + tstuff; } @@ -1437,9 +1448,6 @@ static void *player_thread_func(void *arg) { rc = pthread_mutex_init(&conn->flush_mutex, NULL); if (rc) debug(1, "Error initialising flush_mutex."); - rc = pthread_mutex_init(&conn->vol_mutex, NULL); - if (rc) - debug(1, "Error initialising vol_mutex."); // set the flowcontrol condition variable to wait on a monotonic clock #ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD pthread_condattr_t attr; @@ -2329,20 +2337,25 @@ static void *player_thread_func(void *arg) { mdns_dacp_dont_monitor(conn->dapo_private_storage); #endif - debug(3, "Requesting output device to stop."); + debug(3, "Connection %d: stopping output device.", conn->connection_number); if (config.output->stop) config.output->stop(); - debug(2, "Cancelling timing, control and audio threads"); + debug(2, "Cancelling timing, control and audio threads..."); + debug(2, "Cancel timing thread."); pthread_cancel(rtp_timing_thread); - pthread_cancel(rtp_control_thread); - pthread_cancel(rtp_audio_thread); - debug(2, "Joining terminated threads."); + debug(2, "Join timing thread."); pthread_join(rtp_timing_thread, NULL); debug(2, "Timing thread terminated."); + debug(2, "Cancel control thread."); + pthread_cancel(rtp_control_thread); + debug(2, "Join control thread."); pthread_join(rtp_control_thread, NULL); debug(2, "Control thread terminated."); + debug(2, "Cancel audio thread."); + pthread_cancel(rtp_audio_thread); + debug(2, "Join audio thread."); pthread_join(rtp_audio_thread, NULL); debug(2, "Audio thread terminated."); clear_reference_timestamp(conn); @@ -2362,10 +2375,6 @@ static void *player_thread_func(void *arg) { rc = pthread_mutex_destroy(&conn->ab_mutex); if (rc) debug(1, "Error destroying ab_mutex variable."); - rc = pthread_mutex_destroy(&conn->vol_mutex); - if (rc) - debug(1, "Error destroying vol_mutex variable."); - debug(2, "Connection %d: player thread terminated.", conn->connection_number); if (conn->dacp_id) { free(conn->dacp_id); @@ -2582,9 +2591,8 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c // debug(1,"Software attenuation set to %f, i.e %f out of 65,536, for airplay volume of // %f",software_attenuation,temp_fix_volume,airplay_volume); - pthread_mutex_lock(&conn->vol_mutex); conn->fix_volume = temp_fix_volume; - pthread_mutex_unlock(&conn->vol_mutex); + memory_barrier(); if (config.loudness) loudness_set_volume(software_attenuation / 100); @@ -2617,11 +2625,11 @@ void player_volume(double airplay_volume, rtsp_conn_info *conn) { void do_flush(int64_t timestamp, rtsp_conn_info *conn) { debug(3, "Flush requested up to %u. It seems as if 0 is special.", timestamp); - pthread_mutex_lock(&conn->flush_mutex); + debug_mutex_lock(&conn->flush_mutex, 1000, 1); conn->flush_requested = 1; // if (timestamp!=0) conn->flush_rtp_timestamp = timestamp; // flush all packets up to (and including?) this - pthread_mutex_unlock(&conn->flush_mutex); + debug_mutex_unlock(&conn->flush_mutex, 3); conn->play_segment_reference_frame = 0; conn->play_number_after_flush = 0; #ifdef CONFIG_METADATA @@ -2679,11 +2687,15 @@ int player_play(rtsp_conn_info *conn) { } int player_stop(rtsp_conn_info *conn) { + debug(3, "player_stop"); pthread_rwlock_wrlock(&conn->player_thread_lock); + debug(3, "player_thread_lock acquired"); if (conn->player_thread) { + debug(3, "player_thread exists"); conn->player_thread_please_stop = 1; pthread_cond_signal(&conn->flowcontrol); // tell it to give up pthread_kill(*conn->player_thread, SIGUSR1); + debug(3, "player_thread signalled"); pthread_join(*conn->player_thread, NULL); free(conn->player_thread); conn->player_thread = NULL; diff --git a/player.h b/player.h index 793413ba..3274d648 100644 --- a/player.h +++ b/player.h @@ -106,7 +106,6 @@ typedef struct { // mutexes and condition variables pthread_cond_t flowcontrol; pthread_mutex_t ab_mutex, flush_mutex; - pthread_mutex_t vol_mutex; int fix_volume; uint32_t timestamp_epoch, last_timestamp, maximum_timestamp_interval; // timestamp_epoch of zero means not initialised, could start at 2 diff --git a/rtp.c b/rtp.c index 01c7706d..6a588b0b 100644 --- a/rtp.c +++ b/rtp.c @@ -68,6 +68,9 @@ void rtp_terminate(rtsp_conn_info *conn) { void rtp_audio_receiver_cleanup_handler(void *arg) { debug(3, "Audio Receiver Cleanup."); rtsp_conn_info *conn = (rtsp_conn_info *)arg; + debug(1,"shutdown audio socket."); + shutdown(conn->audio_socket,SHUT_RDWR); + debug(1,"close audio socket."); close(conn->audio_socket); debug(3, "Audio Receiver Cleanup Successful."); } @@ -188,6 +191,9 @@ void *rtp_audio_receiver(void *arg) { void rtp_control_handler_cleanup_handler(void *arg) { debug(3, "Control Receiver Cleanup."); rtsp_conn_info *conn = (rtsp_conn_info *)arg; + debug(1,"shutdown control socket."); + shutdown(conn->control_socket,SHUT_RDWR); + debug(1,"close control socket."); close(conn->control_socket); debug(3, "Control Receiver Cleanup Successful."); } @@ -328,7 +334,7 @@ void *rtp_control_receiver(void *arg) { } } - pthread_mutex_lock(&conn->reference_time_mutex); + debug_mutex_lock(&conn->reference_time_mutex, 1000, 1); // this is for debugging // uint64_t old_remote_reference_time = conn->remote_reference_timestamp_time; @@ -339,7 +345,7 @@ void *rtp_control_receiver(void *arg) { remote_time_of_sync - conn->local_to_remote_time_difference; conn->reference_timestamp = sync_rtp_timestamp; conn->latency_delayed_timestamp = rtp_timestamp_less_latency; - pthread_mutex_unlock(&conn->reference_time_mutex); + debug_mutex_unlock(&conn->reference_time_mutex, 3); // this is for debugging /* @@ -471,6 +477,9 @@ void rtp_timing_receiver_cleanup_handler(void *arg) { rtsp_conn_info *conn = (rtsp_conn_info *)arg; pthread_cancel(conn->timer_requester); pthread_join(conn->timer_requester, NULL); + debug(1,"shutdown timing socket."); + shutdown(conn->timing_socket,SHUT_RDWR); + debug(1,"close timing socket."); close(conn->timing_socket); debug(3, "Timing Receiver Cleanup Successful."); } @@ -812,8 +821,8 @@ void rtp_setup(SOCKADDR *local, SOCKADDR *remote, uint16_t cport, uint16_t tport inet_ntop(conn->connection_ip_family, self_addr, conn->self_ip_string, sizeof(conn->self_ip_string)); - debug(2, "Connection %d: SETUP -- Connection from %s to self at %s.", - conn->connection_number,conn->client_ip_string, conn->self_ip_string); + debug(2, "Connection %d: SETUP -- Connection from %s to self at %s.", conn->connection_number, + conn->client_ip_string, conn->self_ip_string); // set up a the record of the remote's control socket struct addrinfo hints; @@ -891,21 +900,21 @@ void rtp_setup(SOCKADDR *local, SOCKADDR *remote, uint16_t cport, uint16_t tport void get_reference_timestamp_stuff(int64_t *timestamp, uint64_t *timestamp_time, uint64_t *remote_timestamp_time, rtsp_conn_info *conn) { // types okay - pthread_mutex_lock(&conn->reference_time_mutex); + debug_mutex_lock(&conn->reference_time_mutex, 1000, 1); *timestamp = conn->reference_timestamp; *timestamp_time = conn->reference_timestamp_time; // if ((*timestamp == 0) && (*timestamp_time == 0)) { // debug(1,"Reference timestamp is invalid."); //} *remote_timestamp_time = conn->remote_reference_timestamp_time; - pthread_mutex_unlock(&conn->reference_time_mutex); + debug_mutex_unlock(&conn->reference_time_mutex, 3); } void clear_reference_timestamp(rtsp_conn_info *conn) { - pthread_mutex_lock(&conn->reference_time_mutex); + debug_mutex_lock(&conn->reference_time_mutex, 1000, 1); conn->reference_timestamp = 0; conn->reference_timestamp_time = 0; - pthread_mutex_unlock(&conn->reference_time_mutex); + debug_mutex_unlock(&conn->reference_time_mutex, 3); } void rtp_request_resend(seq_t first, uint32_t count, rtsp_conn_info *conn) { @@ -934,11 +943,21 @@ void rtp_request_resend(seq_t first, uint32_t count, rtsp_conn_info *conn) { resend_error_backoff_time)) { if ((config.diagnostic_drop_packet_fraction == 0.0) || (drand48() > config.diagnostic_drop_packet_fraction)) { + // put a time limit on the sendto + + struct timeval timeout; + timeout.tv_sec = 0; + timeout.tv_usec = 100000; + + if (setsockopt(conn->control_socket, SOL_SOCKET, SO_SNDTIMEO, (char *)&timeout, + sizeof(timeout)) < 0) + debug(1, "Can't set timeout on resend request socket."); + if (sendto(conn->control_socket, req, sizeof(req), 0, (struct sockaddr *)&conn->rtp_client_control_socket, msgsize) == -1) { char em[1024]; strerror_r(errno, em, sizeof(em)); - debug(1, "Error %d using send-to to an audio socket: \"%s\". Backing off for 1/16th of a " + debug(1, "Error %d using sendto to an audio socket: \"%s\". Backing off for 1/16th of a " "second.", errno, em); conn->rtp_time_of_last_resend_request_error_fp = time_of_sending_fp; diff --git a/rtsp.c b/rtsp.c index 4299167a..0267e7f5 100644 --- a/rtsp.c +++ b/rtsp.c @@ -637,7 +637,7 @@ static void msg_write_response(int fd, rtsp_message *resp) { pktfree -= n; p += n; if (pktfree <= 1024) - die("Attempted to write overlong RTSP packet"); + die("Attempted to write overlong RTSP packet 1"); } // Here, if there's content, write the Content-Length header ... @@ -648,21 +648,22 @@ static void msg_write_response(int fd, rtsp_message *resp) { pktfree -= n; p += n; if (pktfree <= 1024) - die("Attempted to write overlong RTSP packet"); + die("Attempted to write overlong RTSP packet 2"); + debug(1, "Content is \"%s\"", resp->content); + memcpy(p, resp->content, resp->contentlength); + pktfree -= resp->contentlength; + p += resp->contentlength; } + n = snprintf(p, pktfree, "\r\n"); + pktfree -= n; + p += n; + + if (pktfree <= 1024) + die("Attempted to write overlong RTSP packet 3"); + if (write(fd, pkt, p - pkt) != p - pkt) debug(1, "Error writing an RTSP packet -- requested bytes not fully written."); - - // Here, if there's content, write it - if (resp->contentlength) { - debug(1, "Content is \"%s\"", resp->content); - if (write(fd, resp->content, resp->contentlength) != resp->contentlength) - debug(1, "Error writing RTSP content -- requested bytes not fully written."); - } - - if (write(fd, "\r\n", strlen("\r\n")) != strlen("\r\n")) - debug(1, "Error terminating RTSP content."); } static void handle_record(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { @@ -709,9 +710,10 @@ static void handle_options(rtsp_conn_info *conn, __attribute__((unused)) rtsp_me rtsp_message *resp) { debug(3, "Connection %d: OPTIONS", conn->connection_number); resp->respcode = 200; - msg_add_header(resp, "Public", "ANNOUNCE, SETUP, RECORD, " - "PAUSE, FLUSH, TEARDOWN, " - "OPTIONS, GET_PARAMETER, SET_PARAMETER"); + msg_add_header(resp, "Public", + "ANNOUNCE, SETUP, RECORD, " + "PAUSE, FLUSH, TEARDOWN, " + "OPTIONS, GET_PARAMETER, SET_PARAMETER"); } static void handle_teardown(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message *req, @@ -767,7 +769,8 @@ static void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message * char *ar = msg_get_header(req, "Active-Remote"); if (ar) { - debug(2, "Connection %d: SETUP -- Active-Remote string seen: \"%s\".", conn->connection_number, ar); + debug(2, "Connection %d: SETUP -- Active-Remote string seen: \"%s\".", conn->connection_number, + ar); // get the active remote char *p; conn->dacp_active_remote = strtoul(ar, &p, 10); @@ -775,13 +778,14 @@ static void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message * send_metadata('ssnc', 'acre', ar, strlen(ar), req, 1); #endif } else { - debug(2, "Connection %d: SETUP -- Note: no Active-Remote information the SETUP Record.",conn->connection_number); + debug(2, "Connection %d: SETUP -- Note: no Active-Remote information the SETUP Record.", + conn->connection_number); conn->dacp_active_remote = 0; } ar = msg_get_header(req, "DACP-ID"); if (ar) { - debug(2, "Connection %d: SETUP -- DACP-ID string seen: \"%s\".",conn->connection_number, ar); + debug(2, "Connection %d: SETUP -- DACP-ID string seen: \"%s\".", conn->connection_number, ar); if (conn->dacp_id) // this is in case SETUP was previously called free(conn->dacp_id); conn->dacp_id = strdup(ar); @@ -789,7 +793,8 @@ static void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message * send_metadata('ssnc', 'daid', ar, strlen(ar), req, 1); #endif } else { - debug(2, "Connection %d: SETUP doesn't include DACP-ID string information.",conn->connection_number); + debug(2, "Connection %d: SETUP doesn't include DACP-ID string information.", + conn->connection_number); if (conn->dacp_id) // this is in case SETUP was previously called free(conn->dacp_id); conn->dacp_id = NULL; @@ -797,14 +802,14 @@ static void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message * char *hdr = msg_get_header(req, "Transport"); if (!hdr) { - debug(1, "Connection %d: SETUP doesn't contain a Transport header.",conn->connection_number); + debug(1, "Connection %d: SETUP doesn't contain a Transport header.", conn->connection_number); goto error; } char *p; p = strstr(hdr, "control_port="); if (!p) { - debug(1, "Connection %d: SETUP doesn't specify a control_port.",conn->connection_number); + debug(1, "Connection %d: SETUP doesn't specify a control_port.", conn->connection_number); goto error; } p = strchr(p, '=') + 1; @@ -812,7 +817,7 @@ static void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message * p = strstr(hdr, "timing_port="); if (!p) { - debug(1, "Connection %d: SETUP doesn't specify a timing_port.",conn->connection_number); + debug(1, "Connection %d: SETUP doesn't specify a timing_port.", conn->connection_number); goto error; } p = strchr(p, '=') + 1; @@ -820,27 +825,31 @@ static void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message * if (conn->rtp_running) { if ((conn->remote_control_port != cport) || (conn->remote_timing_port != tport)) { - warn("Connection %d: Duplicate SETUP message with different control (old %u, new %u) or timing (old %u, new " - "%u) ports! This is probably fatal!",conn->connection_number, - conn->remote_control_port, cport, conn->remote_timing_port, tport); + warn("Connection %d: Duplicate SETUP message with different control (old %u, new %u) or " + "timing (old %u, new " + "%u) ports! This is probably fatal!", + conn->connection_number, conn->remote_control_port, cport, conn->remote_timing_port, + tport); } else { - warn("Connection %d: Duplicate SETUP message with the same control (%u) and timing (%u) ports. This is " - "probably not fatal.",conn->connection_number, - conn->remote_control_port, conn->remote_timing_port); + warn("Connection %d: Duplicate SETUP message with the same control (%u) and timing (%u) " + "ports. This is " + "probably not fatal.", + conn->connection_number, conn->remote_control_port, conn->remote_timing_port); } } else { rtp_setup(&conn->local, &conn->remote, cport, tport, conn); } if (conn->local_audio_port == 0) { - debug(1, "Connection %d: SETUP seems to specify a null audio port.",conn->connection_number); + debug(1, "Connection %d: SETUP seems to specify a null audio port.", conn->connection_number); goto error; } char resphdr[256] = ""; - snprintf(resphdr, sizeof(resphdr), "RTP/AVP/" - "UDP;unicast;interleaved=0-1;mode=record;control_port=%d;" - "timing_port=%d;server_" - "port=%d", + snprintf(resphdr, sizeof(resphdr), + "RTP/AVP/" + "UDP;unicast;interleaved=0-1;mode=record;control_port=%d;" + "timing_port=%d;server_" + "port=%d", conn->local_control_port, conn->local_timing_port, conn->local_audio_port); msg_add_header(resp, "Transport", resphdr); @@ -1358,7 +1367,7 @@ static void handle_set_parameter(rtsp_conn_info *conn, rtsp_message *req, rtsp_m char *ct = msg_get_header(req, "Content-Type"); if (ct) { -// debug(2, "SET_PARAMETER Content-Type:\"%s\".", ct); + // debug(2, "SET_PARAMETER Content-Type:\"%s\".", ct); #ifdef CONFIG_METADATA // It seems that the rtptime of the message is used as a kind of an ID that @@ -1880,11 +1889,13 @@ static void *rtsp_conversation_thread_func(void *pconn) { int debug_level = 3; // for printing the request and response reply = rtsp_read_request(conn, &req); if (reply == rtsp_read_request_response_ok) { - if (strcmp(req->method,"OPTIONS")!=0) - debug_level=2; - debug(debug_level, "RTSP thread %d received an RTSP Packet of type \"%s\":", conn->connection_number, + if (strcmp(req->method, "OPTIONS") != + 0) // the options message is very common, so don't log it until level 3 + debug_level = 2; + debug(debug_level, + "RTSP thread %d received an RTSP Packet of type \"%s\":", conn->connection_number, req->method), - debug_print_msg_headers(debug_level, req); + debug_print_msg_headers(debug_level, req); resp = msg_init(); resp->respcode = 400; diff --git a/scripts/shairport-sync.conf b/scripts/shairport-sync.conf index 74cbb4ff..2f7f1378 100644 --- a/scripts/shairport-sync.conf +++ b/scripts/shairport-sync.conf @@ -17,7 +17,7 @@ general = // output_backend = "alsa"; // Run "shairport-sync -h" to get a list of all output_backends, e.g. "alsa", "pipe", "stdout". The default is the first one. // mdns_backend = "avahi"; // Run "shairport-sync -h" to get a list of all mdns_backends. The default is the first one. // port = 5000; // Listen for service requests on this port -// udp_port_base = 6001; // start allocating UDP ports from this port number when needed +// udp_port_base = 6001; // start allocating UDP ports from this port number when needed // udp_port_range = 100; // look for free ports in this number of places, starting at the UDP port base. Allow at least 10, though only three are needed in a steady state. // drift_tolerance_in_seconds = 0.002; // allow a timing error of this number of seconds of drift away from exact synchronisation before attempting to correct it // resync_threshold_in_seconds = 0.050; // a synchronisation error greater than this number of seconds will cause resynchronisation; 0 disables it