From: Mike Brady Date: Sat, 3 Feb 2018 20:24:58 +0000 (+0000) Subject: Add timing to debug messages, make timing sender wait interruptable eveyr 20 ms,... X-Git-Tag: 3.2d29~85 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=a0bb2993df20be7442c54e9e8aaed3b40aa59ae6;p=thirdparty%2Fshairport-sync.git Add timing to debug messages, make timing sender wait interruptable eveyr 20 ms, thus making TEARDOWN faster. --- diff --git a/common.c b/common.c index dd12d6cd..ea6733ac 100644 --- a/common.c +++ b/common.c @@ -25,6 +25,8 @@ * OTHER DEALINGS IN THE SOFTWARE. */ +#include "common.h" +#include #include #include #include @@ -37,8 +39,6 @@ #include #include #include -#include "common.h" -#include #ifdef COMPILE_FOR_OSX #include @@ -124,11 +124,25 @@ void debug(int level, const char *format, ...) { return; char s[1024]; s[0] = 0; + uint64_t time_now = get_absolute_time_in_fp(); + uint64_t time_since_start = time_now - fp_time_at_startup; + uint64_t time_since_last_debug_message = time_now - fp_time_at_last_debug_message; + fp_time_at_last_debug_message = time_now; + uint64_t divisor = (uint64_t)1 << 32; + double tss = 1.0 * time_since_start / divisor; + double tsl = 1.0 * time_since_last_debug_message / divisor; va_list args; va_start(args, format); vsnprintf(s, sizeof(s), format, args); va_end(args); - daemon_log(LOG_DEBUG, "%s", s); + if ((config.debugger_show_elapsed_time) && (config.debugger_show_relative_time)) + daemon_log(LOG_DEBUG, "|% 20.9f|% 20.9f|%s", tss, tsl, s); + else if (config.debugger_show_relative_time) + daemon_log(LOG_DEBUG, "% 20.9f|%s", tsl, s); + else if (config.debugger_show_elapsed_time) + daemon_log(LOG_DEBUG, "% 20.9f|%s", tss, s); + else + daemon_log(LOG_DEBUG, "%s", s); } void inform(const char *format, ...) { @@ -664,15 +678,15 @@ uint32_t uatoi(const char *nptr) { return r; } - double flat_vol2attn(double vol, long max_db, long min_db) { double vol_setting = min_db; if ((vol <= 0.0) && (vol >= -30.0)) { - vol_setting = ((max_db - min_db)*(30.0+vol)/30)+min_db; - debug(2,"Linear Volume Setting: %f in range %ld to %ld.",vol_setting,min_db,max_db); + vol_setting = ((max_db - min_db) * (30.0 + vol) / 30) + min_db; + debug(2, "Linear Volume Setting: %f in range %ld to %ld.", vol_setting, min_db, max_db); } else if (vol != -144.0) { - debug(1, "Linear volume request value %f is out of range: should be from 0.0 to -30.0 or -144.0.", + debug(1, + "Linear volume request value %f is out of range: should be from 0.0 to -30.0 or -144.0.", vol); } return vol_setting; @@ -738,7 +752,8 @@ double vol2attn(double vol, long max_db, long min_db) { vol_setting = min_db; // for safety, return the lowest setting... } // debug(1,"returning an attenuation of %f.",vol_setting); - debug(2,"Standard profile Volume Setting for Airplay vol %f: %f in range %ld to %ld.",vol,vol_setting,min_db,max_db); + debug(2, "Standard profile Volume Setting for Airplay vol %f: %f in range %ld to %ld.", vol, + vol_setting, min_db, max_db); return vol_setting; } diff --git a/common.h b/common.h index e36aae9a..22ebacc4 100644 --- a/common.h +++ b/common.h @@ -136,7 +136,9 @@ typedef struct { char *piddir; char *computed_piddir; // the actual pid directory to create, if any - int logOutputLevel; // log output level + int logOutputLevel; // log output level + int debugger_show_elapsed_time; // in the debug message, display the time since startup + int debugger_show_relative_time; // in the debug message, display the time since the last one int statistics_requested, use_negotiated_latencies; enum playback_mode_type playback_mode; char *cmd_start, *cmd_stop, *cmd_set_volume; @@ -185,7 +187,7 @@ typedef struct { #ifdef HAVE_METADATA_HUB char *cover_art_cache_dir; #endif - int disable_resend_requests; //set this to stop resend request being made for missing packets + int disable_resend_requests; // set this to stop resend request being made for missing packets } shairport_cfg; @@ -234,9 +236,11 @@ double flat_vol2attn(double vol, long max_db, long min_db); double vol2attn(double vol, long max_db, long min_db); // return a monolithic (always increasing) time in nanoseconds - uint64_t get_absolute_time_in_fp(void); +// time at startup for debugging timing +uint64_t fp_time_at_startup, fp_time_at_last_debug_message; + // this is for reading an unsigned 32 bit number, such as an RTP timestamp long endianness; diff --git a/dacp.c b/dacp.c index 04885d01..06b05b4f 100644 --- a/dacp.c +++ b/dacp.c @@ -301,9 +301,9 @@ void *dacp_monitor_thread_code(void *na) { if (le >= 8) { // here start looking for the contents of the status update if (dacp_tlv_crawl(&sp, &item_size) == 'cmst') { // status - // here, we know that we are receiving playerstatusupdates, so set a flag - metadata_hub_modify_prolog(); - metadata_store.playerstatusupdates_are_received = 1; + // here, we know that we are receiving playerstatusupdates, so set a flag + metadata_hub_modify_prolog(); + metadata_store.playerstatusupdates_are_received = 1; sp -= item_size; // drop down into the array -- don't skip over it le -= 8; char typestring[5]; @@ -545,7 +545,7 @@ void *dacp_monitor_thread_code(void *na) { } // finished possibly writing to the metadata hub - metadata_hub_modify_epilog(); + metadata_hub_modify_epilog(); } else { printf("Status Update not found.\n"); } diff --git a/metadata_hub.c b/metadata_hub.c index b5097c86..8f0f0480 100644 --- a/metadata_hub.c +++ b/metadata_hub.c @@ -77,33 +77,31 @@ void add_metadata_watcher(metadata_watcher fn, void *userdata) { } void metadata_hub_modify_prolog(void) { -// always run this before changing an entry or a sequence of entries in the metadata_hub - debug(1,"locking metadata hub for writing"); + // always run this before changing an entry or a sequence of entries in the metadata_hub + debug(1, "locking metadata hub for writing"); pthread_rwlock_wrlock(&metadata_hub_re_lock); - } void run_metadata_watchers(void) { int i; - debug(1,"locking metadata hub for reading"); + debug(1, "locking metadata hub for reading"); pthread_rwlock_rdlock(&metadata_hub_re_lock); for (i = 0; i < number_of_watchers; i++) { if (metadata_store.watchers[i]) { metadata_store.watchers[i](&metadata_store, metadata_store.watchers_data[i]); } } - debug(1,"unlocking metadata hub for reading"); + debug(1, "unlocking metadata hub for reading"); pthread_rwlock_unlock(&metadata_hub_re_lock); } void metadata_hub_modify_epilog(void) { -// always run this after changing an entry or a sequence of entries in the metadata_hub - debug(1,"unlocking metadata hub for writing"); + // always run this after changing an entry or a sequence of entries in the metadata_hub + debug(1, "unlocking metadata hub for writing"); pthread_rwlock_unlock(&metadata_hub_re_lock); run_metadata_watchers(); } - char *metadata_write_image_file(const char *buf, int len) { // warning -- this removes all files from the directory apart from this one, if it exists @@ -153,7 +151,7 @@ char *metadata_write_image_file(const char *buf, int len) { debug(1, "Unidentified image type of cover art -- jpg extension used."); ext = jpg; } - mode_t oldumask = umask(000); + mode_t oldumask = umask(000); int result = mkpath(config.cover_art_cache_dir, 0777); umask(oldumask); if ((result == 0) || (result == -EEXIST)) { @@ -227,10 +225,10 @@ void metadata_hub_process_metadata(uint32_t type, uint32_t code, char *data, uin // metadata coming in from the audio source or from Shairport Sync itself passes through here // this has more information about tags, which might be relevant: // https://code.google.com/p/ytrack/wiki/DMAP - + // all the following items of metadata are contained in one metadata packet // they are preseded by an 'ssnc' 'mdst' item and followed by an 'ssnc 'mden' item. - + if (type == 'core') { switch (code) { case 'asal': @@ -258,7 +256,7 @@ void metadata_hub_process_metadata(uint32_t type, uint32_t code, char *data, uin case 'ascm': if ((metadata_store.comment == NULL) || (strncmp(metadata_store.comment, data, length) != 0)) { - if (metadata_store.comment) + if (metadata_store.comment) free(metadata_store.comment); metadata_store.comment = strndup(data, length); // debug(1, "MH Comment set to: \"%s\"", metadata_store.comment); @@ -354,13 +352,12 @@ void metadata_hub_process_metadata(uint32_t type, uint32_t code, char *data, uin } } else if (type == 'ssnc') { switch (code) { - + // ignore the following case 'pcst': case 'pcen': - break; - - + break; + case 'mdst': debug(1, "MH Metadata stream processing start."); metadata_hub_modify_prolog(); @@ -371,12 +368,12 @@ void metadata_hub_process_metadata(uint32_t type, uint32_t code, char *data, uin break; case 'PICT': if (length > 16) { - metadata_hub_modify_prolog(); - debug(1, "MH Picture received, length %u bytes.", length); + metadata_hub_modify_prolog(); + debug(1, "MH Picture received, length %u bytes.", length); if (metadata_store.cover_art_pathname) free(metadata_store.cover_art_pathname); metadata_store.cover_art_pathname = metadata_write_image_file(data, length); - metadata_hub_modify_epilog(); + metadata_hub_modify_epilog(); } break; case 'clip': diff --git a/metadata_hub.h b/metadata_hub.h index 70d2fcf7..2a7d8445 100644 --- a/metadata_hub.h +++ b/metadata_hub.h @@ -99,7 +99,7 @@ void add_metadata_watcher(metadata_watcher fn, void *userdata); void metadata_hub_init(void); void metadata_hub_process_metadata(uint32_t type, uint32_t code, char *data, uint32_t length); -// these functions lock and unlock the read-write mutex on the metadata hub and run the watchers afterwards +// these functions lock and unlock the read-write mutex on the metadata hub and run the watchers +// afterwards void metadata_hub_modify_prolog(void); void metadata_hub_modify_epilog(void); - diff --git a/player.c b/player.c index a8397426..c05a958e 100644 --- a/player.c +++ b/player.c @@ -816,9 +816,9 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { // say we have started playing here #ifdef HAVE_METADATA_HUB - metadata_hub_modify_prolog(); + metadata_hub_modify_prolog(); metadata_store.player_state = PS_PLAYING; - metadata_hub_modify_epilog(); + metadata_hub_modify_epilog(); #endif if (reference_timestamp) { // if we have a reference time // debug(1,"First frame seen with timestamp..."); @@ -1106,7 +1106,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { if (do_wait == 0) if ((conn->ab_synced != 0) && (conn->ab_read == conn->ab_write)) { // the buffer is empty! if (notified_buffer_empty == 0) { - debug(2, "Buffers exhausted."); + debug(3, "Buffers exhausted."); notified_buffer_empty = 1; } do_wait = 1; @@ -1159,10 +1159,10 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { seq_t next = seq_sum(conn->ab_read, i); abuf = conn->audio_buffer + BUFIDX(next); if (!abuf->ready) { - if (config.disable_resend_requests==0) { - rtp_request_resend(next, 1, conn); - // debug(1,"Resend %u.",next); - conn->resend_requests++; + if (config.disable_resend_requests == 0) { + rtp_request_resend(next, 1, conn); + // debug(1,"Resend %u.",next); + conn->resend_requests++; } } } @@ -1632,7 +1632,7 @@ static void *player_thread_func(void *arg) { player_volume(config.airplay_volume, conn); int64_t frames_to_drop = 0; - + while (!conn->player_thread_please_stop) { abuf_t *inframe = buffer_get_frame(conn); if (inframe) { @@ -1659,7 +1659,7 @@ static void *player_thread_func(void *arg) { } else if (frames_to_drop) { // debug(2,"%lld frames to drop.",frames_to_drop); frames_to_drop -= inframe->length; - if (frames_to_drop<0) + if (frames_to_drop < 0) frames_to_drop = 0; } else { int enable_dither = 0; @@ -1872,7 +1872,7 @@ static void *player_thread_func(void *arg) { config.resyncthreshold * config.output_rate; // number of samples if ((sync_error > 0) && (sync_error > filler_length)) { debug(1, "Large positive sync error: %lld.", sync_error); - frames_to_drop = sync_error/conn->output_sample_ratio; + frames_to_drop = sync_error / conn->output_sample_ratio; } else if ((sync_error < 0) && ((-sync_error) > filler_length)) { // debug(1, "Large negative sync error: %lld. Inserting silence.", sync_error); size_t silence_length = -sync_error; @@ -2208,8 +2208,6 @@ static void *player_thread_func(void *arg) { if (config.output->stop) config.output->stop(); - usleep(100000); // allow this time to (?) allow the alsa subsystem to finish cleaning up after - // itself. 50 ms seems too short debug(2, "Shut down audio, control and timing threads"); conn->please_stop = 1; @@ -2217,14 +2215,17 @@ static void *player_thread_func(void *arg) { pthread_kill(rtp_control_thread, SIGUSR1); pthread_kill(rtp_timing_thread, SIGUSR1); pthread_join(rtp_timing_thread, NULL); - debug(3, "timing thread joined"); + debug(1, "timing thread joined"); pthread_join(rtp_audio_thread, NULL); - debug(3, "audio thread joined"); + debug(1, "audio thread joined"); pthread_join(rtp_control_thread, NULL); - debug(3, "control thread joined"); + debug(1, "control thread joined"); clear_reference_timestamp(conn); conn->rtp_running = 0; + usleep(100000); // allow this time to (?) allow the alsa subsystem to finish cleaning up after + // itself. 50 ms seems too short + free_audio_buffers(conn); terminate_decoders(conn); // remove flow control and mutexes @@ -2423,10 +2424,11 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c if (config.ignore_volume_control == 1) scaled_attenuation = max_db; else if (config.volume_control_profile == VCP_standard) - scaled_attenuation = vol2attn(airplay_volume, max_db, min_db); + scaled_attenuation = vol2attn(airplay_volume, max_db, min_db); else if (config.volume_control_profile == VCP_flat) - scaled_attenuation = flat_vol2attn(airplay_volume, max_db, min_db); - else debug(1,"Unrecognised volume control profile"); + scaled_attenuation = flat_vol2attn(airplay_volume, max_db, min_db); + else + debug(1, "Unrecognised volume control profile"); if (hw_range_db) { // if there is a hardware mixer @@ -2509,9 +2511,9 @@ void player_flush(int64_t timestamp, rtsp_conn_info *conn) { #endif #ifdef HAVE_METADATA_HUB - metadata_hub_modify_prolog(); - metadata_store.player_state = PS_PAUSED; - metadata_hub_modify_epilog(); + metadata_hub_modify_prolog(); + metadata_store.player_state = PS_PAUSED; + metadata_hub_modify_epilog(); #endif } @@ -2539,9 +2541,9 @@ int player_play(rtsp_conn_info *conn) { pthread_create(pt, &tattr, player_thread_func, (void *)conn); pthread_attr_destroy(&tattr); #ifdef HAVE_METADATA_HUB - metadata_hub_modify_prolog(); - metadata_store.player_state = PS_PLAYING; - metadata_hub_modify_epilog(); + metadata_hub_modify_prolog(); + metadata_store.player_state = PS_PLAYING; + metadata_hub_modify_epilog(); #endif return 0; } @@ -2559,9 +2561,9 @@ void player_stop(rtsp_conn_info *conn) { free(conn->player_thread); conn->player_thread = NULL; #ifdef HAVE_METADATA_HUB - metadata_hub_modify_prolog(); - metadata_store.player_state = PS_STOPPED; - metadata_hub_modify_epilog(); + metadata_hub_modify_prolog(); + metadata_store.player_state = PS_STOPPED; + metadata_hub_modify_epilog(); #endif } else { debug(3, "player thread of RTSP conversation %d is already deleted.", conn->connection_number); diff --git a/rtp.c b/rtp.c index f0fc1492..570a0db5 100644 --- a/rtp.c +++ b/rtp.c @@ -165,7 +165,7 @@ void *rtp_audio_receiver(void *arg) { warn("Audio receiver -- Unknown RTP packet of type 0x%02X length %d.", type, nread); } - debug(3, "Audio receiver -- Server RTP thread interrupted. terminating."); + debug(2, "Audio receiver -- Server RTP thread interrupted. terminating."); close(conn->audio_socket); return NULL; @@ -299,7 +299,7 @@ void *rtp_control_receiver(void *arg) { nread); } - debug(3, "Control RTP thread interrupted. terminating."); + debug(2, "Control RTP thread interrupted. terminating."); close(conn->control_socket); return NULL; @@ -365,12 +365,24 @@ void *rtp_timing_sender(void *arg) { debug(1, "Error %d using send-to to the timing socket: \"%s\".", errno, em); } request_number++; + + // this is to deal with the possibility of missing a timing_sender_stop signal. + // if the signal came in just before the usleep, then it wouldn't cause the sleep to end. + // so, we will wait a maximum time of the wait_interval + + int wait_time; + int wait_interval = 20000; // 20 milliseconds + if (request_number <= 4) - usleep(500000); + wait_time = 500000; else - sleep(3); + wait_time = 3000000; + while ((wait_time > 0) && (conn->timing_sender_stop == 0)) { + usleep(wait_interval); + wait_time -= wait_interval; + } } - debug(3, "rtp_timing_sender thread interrupted. terminating."); + debug(2, "rtp_timing_sender thread interrupted. terminating."); return NULL; } @@ -591,14 +603,14 @@ void *rtp_timing_receiver(void *arg) { } } - debug(3, "Timing thread interrupted. terminating."); + debug(2, "Timing thread interrupted. terminating."); conn->timing_sender_stop = 1; void *retval; pthread_kill(timer_requester, SIGUSR1); debug(3, "Wait for timer requester to exit."); pthread_join(timer_requester, &retval); debug(3, "Closed and terminated timer requester thread."); - debug(3, "Timing RTP thread terminated."); + debug(2, "Timing RTP thread terminated."); close(conn->timing_socket); return NULL; diff --git a/rtsp.c b/rtsp.c index 81afc415..f6f31c07 100644 --- a/rtsp.c +++ b/rtsp.c @@ -80,7 +80,7 @@ enum rtsp_read_request_response { rtsp_read_request_response_immediate_shutdown_requested, rtsp_read_request_response_bad_packet, rtsp_read_request_response_channel_closed, - rtsp_read_request_response_read_error, + rtsp_read_request_response_read_error, rtsp_read_request_response_error }; @@ -518,7 +518,7 @@ static enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, continue; char errorstring[1024]; strerror_r(errno, (char *)errorstring, sizeof(errorstring)); - debug(1,"rtsp_read_request_response_read_error %d: \"%s\".",errno,(char *)errorstring); + debug(1, "rtsp_read_request_response_read_error %d: \"%s\".", errno, (char *)errorstring); reply = rtsp_read_request_response_read_error; goto shutdown; } @@ -665,7 +665,10 @@ static void msg_write_response(int fd, rtsp_message *resp) { } static void handle_record(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { - debug(3, "Connection %d: RECORD", conn->connection_number); + debug(2, "Connection %d: RECORD", conn->connection_number); + + player_play(conn); // the thread better be 0 + resp->respcode = 200; // I think this is for telling the client what the absolute minimum latency // actually is, @@ -696,7 +699,7 @@ static void handle_record(rtsp_conn_info *conn, rtsp_message *req, rtsp_message } } } - usleep(500000); + // usleep(500000); } static void handle_options(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { @@ -708,7 +711,7 @@ static void handle_options(rtsp_conn_info *conn, rtsp_message *req, rtsp_message } static void handle_teardown(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { - debug(3, "Connection %d: TEARDOWN", conn->connection_number); + debug(2, "Connection %d: TEARDOWN", conn->connection_number); // if (!rtsp_playing()) // debug(1, "This RTSP connection thread (%d) doesn't think it's playing, but " // "it's sending a response to teardown anyway",conn->connection_number); @@ -756,7 +759,7 @@ static void handle_flush(rtsp_conn_info *conn, rtsp_message *req, rtsp_message * } static void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { - debug(3, "Connection %d: SETUP", conn->connection_number); + debug(2, "Connection %d: SETUP", conn->connection_number); int cport, tport; int lsport, lcport, ltport; @@ -817,8 +820,6 @@ static void handle_setup(rtsp_conn_info *conn, rtsp_message *req, rtsp_message * strcat(hdr, q); // should unsplice the timing port entry } - player_play(conn); // the thread better be 0 - char *resphdr = alloca(200); *resphdr = 0; sprintf(resphdr, "RTP/AVP/" @@ -1050,14 +1051,13 @@ void metadata_create(void) { char *path = malloc(pl + 1); snprintf(path, pl + 1, "%s", config.metadata_pipename); - mode_t oldumask = umask(000); + mode_t oldumask = umask(000); if (mkfifo(path, 0666) && errno != EEXIST) die("Could not create metadata FIFO %s", path); free(path); umask(oldumask); - } void metadata_open(void) { @@ -1418,12 +1418,16 @@ static void handle_set_parameter(rtsp_conn_info *conn, rtsp_message *req, rtsp_m } static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { - debug(3, "Connection %d: ANNOUNCE", conn->connection_number); + debug(2, "Connection %d: ANNOUNCE", conn->connection_number); int have_the_player = 0; // interrupt session if permitted if (pthread_mutex_trylock(&play_lock) == 0) { have_the_player = 1; + } else if ((playing_conn) && + (playing_conn->connection_number == conn->connection_number)) { // duplicate ANNOUNCE + debug(1, "Duplicate ANNOUNCE, by the look of it!"); + have_the_player = 1; } else { int should_wait = 0; @@ -1494,12 +1498,12 @@ static void handle_announce(rtsp_conn_info *conn, rtsp_message *req, rtsp_messag if (pminlatency) { conn->minimum_latency = atoi(pminlatency); - debug(1, "Minimum latency %d specified", conn->minimum_latency); + debug(3, "Minimum latency %d specified", conn->minimum_latency); } if (pmaxlatency) { conn->maximum_latency = atoi(pmaxlatency); - debug(1, "Maximum latency %d specified", conn->maximum_latency); + debug(3, "Maximum latency %d specified", conn->maximum_latency); } if ((paesiv == NULL) && (prsaaeskey == NULL)) { @@ -1827,7 +1831,7 @@ static void *rtsp_conversation_thread_func(void *pconn) { char *hdr, *auth_nonce = NULL; enum rtsp_read_request_response reply; - + int rtsp_read_request_attempt_count = 1; // 1 means exit immediately while (conn->stop == 0) { @@ -1879,16 +1883,19 @@ static void *rtsp_conversation_thread_func(void *pconn) { int tstop = 0; if (reply == rtsp_read_request_response_immediate_shutdown_requested) tstop = 1; - else if ((reply == rtsp_read_request_response_channel_closed) || (reply == rtsp_read_request_response_read_error)) { + else if ((reply == rtsp_read_request_response_channel_closed) || + (reply == rtsp_read_request_response_read_error)) { if (conn->player_thread) { rtsp_read_request_attempt_count--; - if (rtsp_read_request_attempt_count==0) + if (rtsp_read_request_attempt_count == 0) tstop = 1; else { if (reply == rtsp_read_request_response_channel_closed) - debug(2,"RTSP channel unexpectedly closed -- will try again %d time(s).",rtsp_read_request_attempt_count); + debug(2, "RTSP channel unexpectedly closed -- will try again %d time(s).", + rtsp_read_request_attempt_count); if (reply == rtsp_read_request_response_read_error) - debug(2,"RTSP channel read error -- will try again %d time(s).",rtsp_read_request_attempt_count); + debug(2, "RTSP channel read error -- will try again %d time(s).", + rtsp_read_request_attempt_count); usleep(20000); } } else { @@ -1901,7 +1908,7 @@ static void *rtsp_conversation_thread_func(void *pconn) { debug(3, "Synchronously terminate playing thread of RTSP conversation thread %d.", conn->connection_number); if (conn->player_thread) - debug(1,"RTSP Channel unexpectedly closed or erred -- closing the session."); + debug(1, "RTSP Channel unexpectedly closed or erred -- closing the session."); player_stop(conn); debug(3, "Successful termination of playing thread of RTSP conversation thread %d.", conn->connection_number); diff --git a/scripts/shairport-sync.conf b/scripts/shairport-sync.conf index 4586ba24..bba9db47 100644 --- a/scripts/shairport-sync.conf +++ b/scripts/shairport-sync.conf @@ -150,4 +150,6 @@ diagnostics = // disable_resend_requests = "no"; // set this to yes to stop Shairport Sync from requesting the retransmission of missing packets. Default is "no". // statistics = "no"; // set to "yes" to print statistics in the log // log_verbosity = 0; // "0" means no debug verbosity, "3" is most verbose. +// log_show_time_since_startup = "no"; // set this to yes if you want the time since startup in the debug message -- seconds down to nanoseconds +// log_show_time_since_last_message = "no"; // set this to yes if you want the time since the last debug message in the debug message -- seconds down to nanoseconds }; diff --git a/shairport.c b/shairport.c index 6193857d..24de8a47 100644 --- a/shairport.c +++ b/shairport.c @@ -508,7 +508,8 @@ int parse_options(int argc, char **argv) { /* Get the statistics setting. */ if (config_lookup_string(config.cfg, "general.statistics", &str)) { - warn("The \"general\" \"statistics\" setting is deprecated. Please use the \"diagnostics\" \"statistics\" setting instead."); + warn("The \"general\" \"statistics\" setting is deprecated. Please use the \"diagnostics\" " + "\"statistics\" setting instead."); if (strcasecmp(str, "no") == 0) config.statistics_requested = 0; else if (strcasecmp(str, "yes") == 0) @@ -541,7 +542,8 @@ int parse_options(int argc, char **argv) { /* Get the verbosity setting. */ if (config_lookup_int(config.cfg, "general.log_verbosity", &value)) { - warn("The \"general\" \"log_verbosity\" setting is deprecated. Please use the \"diagnostics\" \"log_verbosity\" setting instead."); + warn("The \"general\" \"log_verbosity\" setting is deprecated. Please use the " + "\"diagnostics\" \"log_verbosity\" setting instead."); if ((value >= 0) && (value <= 3)) debuglev = value; else @@ -555,11 +557,34 @@ int parse_options(int argc, char **argv) { if ((value >= 0) && (value <= 3)) debuglev = value; else - die("Invalid diagnostics log_verbosity setting option choice \"%d\". It should be between 0 and 3, " + die("Invalid diagnostics log_verbosity setting option choice \"%d\". It should be " + "between 0 and 3, " "inclusive.", value); } + /* Get the show elapsed time in debug messages setting. */ + if (config_lookup_string(config.cfg, "diagnostics.log_show_time_since_startup", &str)) { + if (strcasecmp(str, "no") == 0) + config.debugger_show_elapsed_time = 0; + else if (strcasecmp(str, "yes") == 0) + config.debugger_show_elapsed_time = 1; + else + die("Invalid diagnostics log_show_time_since_startup option choice \"%s\". It should be " + "\"yes\" or \"no\""); + } + + /* Get the show relative time in debug messages setting. */ + if (config_lookup_string(config.cfg, "diagnostics.log_show_time_since_last_message", &str)) { + if (strcasecmp(str, "no") == 0) + config.debugger_show_relative_time = 0; + else if (strcasecmp(str, "yes") == 0) + config.debugger_show_relative_time = 1; + else + die("Invalid diagnostics log_show_time_since_last_message option choice \"%s\". It " + "should be \"yes\" or \"no\""); + } + /* Get the statistics setting. */ if (config_lookup_string(config.cfg, "diagnostics.statistics", &str)) { if (strcasecmp(str, "no") == 0) @@ -567,10 +592,10 @@ int parse_options(int argc, char **argv) { else if (strcasecmp(str, "yes") == 0) config.statistics_requested = 1; else - die("Invalid diagnostics statistics option choice \"%s\". It should be \"yes\" or \"no\""); + die("Invalid diagnostics statistics option choice \"%s\". It should be \"yes\" or " + "\"no\""); } - /* Get the disable_resend_requests setting. */ if (config_lookup_string(config.cfg, "diagnostics.disable_resend_requests", &str)) { config.disable_resend_requests = 0; // this is for legacy -- only set by -t 0 @@ -629,7 +654,8 @@ int parse_options(int argc, char **argv) { else if (strcasecmp(str, "flat") == 0) config.volume_control_profile = VCP_flat; else - die("Invalid volume_control_profile choice \"%s\". It should be \"standard\" (default) or \"flat\""); + die("Invalid volume_control_profile choice \"%s\". It should be \"standard\" (default) " + "or \"flat\""); } /* Get the interface to listen on, if specified Default is all interfaces */ @@ -1065,7 +1091,9 @@ void exit_function() { } int main(int argc, char **argv) { - + fp_time_at_startup = get_absolute_time_in_fp(); + fp_time_at_last_debug_message = fp_time_at_startup; + // debug(1,"startup"); daemon_set_verbosity(LOG_DEBUG); memset(&config, 0, sizeof(config)); // also clears all strings, BTW atexit(exit_function); @@ -1443,7 +1471,8 @@ int main(int argc, char **argv) { #endif debug(1, "loudness is %d.", config.loudness); debug(1, "loudness reference level is %f", config.loudness_reference_volume_db); - debug(1, "disable resend requests is %d -- non-zero means \"yes\"", config.disable_resend_requests); + debug(1, "disable resend requests is %d -- non-zero means \"yes\"", + config.disable_resend_requests); uint8_t ap_md5[16];