From 54445ee8f5705774085e70a5537647d9f89c7f1d Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Thu, 27 Nov 2025 12:37:16 +0000 Subject: [PATCH] Separate out the debug facilities into their own files. Clean up and add a few associated methods. --- Makefile.am | 4 +- common.c | 187 +-------------------------------- common.h | 2 +- dbus-service.c | 8 +- debug.c | 277 +++++++++++++++++++++++++++++++++++++++++++++++++ debug.h | 67 ++++++++++++ player.c | 2 +- rtp.c | 2 +- rtsp.c | 8 +- shairport.c | 20 ++-- 10 files changed, 370 insertions(+), 207 deletions(-) create mode 100644 debug.c create mode 100644 debug.h diff --git a/Makefile.am b/Makefile.am index d553cf4a..51869f84 100644 --- a/Makefile.am +++ b/Makefile.am @@ -27,7 +27,7 @@ noinst_LIBRARIES = # See below for the flags for the test client program -shairport_sync_SOURCES = shairport.c rtsp.c mdns.c common.c rtp.c player.c audio.c loudness.c activity_monitor.c +shairport_sync_SOURCES = debug.c shairport.c rtsp.c mdns.c common.c rtp.c player.c audio.c loudness.c activity_monitor.c if BUILD_FOR_DARWIN AM_CXXFLAGS = -I/usr/local/include -Wno-multichar -Wall -Wextra -Wno-deprecated-declarations -pthread -DSYSCONFDIR=\"$(sysconfdir)\" @@ -42,7 +42,7 @@ if BUILD_FOR_OPENBSD AM_CFLAGS = -Wno-multichar -Wall -Wextra -pthread -DSYSCONFDIR=\"$(sysconfdir)\" else AM_CXXFLAGS = -Wshadow -fno-common -Wno-multichar -Wall -Wextra -Wno-clobbered -Wno-psabi -pthread -DSYSCONFDIR=\"$(sysconfdir)\" - AM_CFLAGS = -Wshadow -fno-common -Wno-multichar -Wall -Wextra -Wno-clobbered -Wno-psabi -pthread -DSYSCONFDIR=\"$(sysconfdir)\" + AM_CFLAGS = --include=debug.h -Wshadow -fno-common -Wno-multichar -Wall -Wextra -Wno-clobbered -Wno-psabi -pthread -DSYSCONFDIR=\"$(sysconfdir)\" endif endif endif diff --git a/common.c b/common.c index 0e5c75dd..1174db7b 100644 --- a/common.c +++ b/common.c @@ -130,12 +130,8 @@ void set_alsa_out_dev(char *); config_t config_file_stuff; int type_of_exit_cleanup; -uint64_t ns_time_at_startup, ns_time_at_last_debug_message; uint64_t minimum_dac_queue_size; -// always lock use this when accessing the ns_time_at_last_debug_message -static pthread_mutex_t debug_timing_lock = PTHREAD_MUTEX_INITIALIZER; - pthread_mutex_t the_conn_lock = PTHREAD_MUTEX_INITIALIZER; unsigned int sps_format_sample_size_array[] = { @@ -343,8 +339,6 @@ void log_to_syslog() { shairport_cfg config; -volatile int debuglev = 0; - sigset_t pselect_sigset; // note -- don't use this to shutdown from dbus -- see its own code in dbus-service.c @@ -532,93 +526,6 @@ int get_requested_connection_state_to_output() { return requested_connection_sta void set_requested_connection_state_to_output(int v) { requested_connection_state_to_output = v; } -char *generate_preliminary_string(char *buffer, size_t buffer_length, double tss, double tsl, - const char *filename, const int linenumber, const char *prefix) { - char *insertion_point = buffer; - if (config.debugger_show_elapsed_time) { - snprintf(insertion_point, buffer_length, "% 20.9f", tss); - insertion_point = insertion_point + strlen(insertion_point); - } - if (config.debugger_show_relative_time) { - snprintf(insertion_point, buffer_length, "% 20.9f", tsl); - insertion_point = insertion_point + strlen(insertion_point); - } - if (config.debugger_show_file_and_line) { - snprintf(insertion_point, buffer_length, " \"%s:%d\"", filename, linenumber); - insertion_point = insertion_point + strlen(insertion_point); - } - if (prefix) { - snprintf(insertion_point, buffer_length, "%s", prefix); - insertion_point = insertion_point + strlen(insertion_point); - } - return insertion_point; -} - -void _die(const char *thefilename, const int linenumber, const char *format, ...) { - int oldState; - pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); - - char b[16384]; - b[0] = 0; - char *s; - if (debuglev) { - pthread_mutex_lock(&debug_timing_lock); - uint64_t time_now = get_absolute_time_in_ns(); - uint64_t time_since_start = time_now - ns_time_at_startup; - uint64_t time_since_last_debug_message = time_now - ns_time_at_last_debug_message; - ns_time_at_last_debug_message = time_now; - pthread_mutex_unlock(&debug_timing_lock); - char *basec = strdup(thefilename); - char *filename = basename(basec); - s = generate_preliminary_string(b, sizeof(b), 1.0 * time_since_start / 1000000000, - 1.0 * time_since_last_debug_message / 1000000000, filename, - linenumber, " *fatal error: "); - free(basec); - } else { - strncpy(b, "fatal error: ", sizeof(b)); - s = b + strlen(b); - } - va_list args; - va_start(args, format); - vsnprintf(s, sizeof(b) - (s - b), format, args); - va_end(args); - sps_log(LOG_ERR, "%s", b); - pthread_setcancelstate(oldState, NULL); - type_of_exit_cleanup = TOE_emergency; - exit(EXIT_FAILURE); -} - -void _warn(const char *thefilename, const int linenumber, const char *format, ...) { - int oldState; - pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); - char b[16384]; - b[0] = 0; - char *s; - if (debuglev) { - pthread_mutex_lock(&debug_timing_lock); - uint64_t time_now = get_absolute_time_in_ns(); - uint64_t time_since_start = time_now - ns_time_at_startup; - uint64_t time_since_last_debug_message = time_now - ns_time_at_last_debug_message; - ns_time_at_last_debug_message = time_now; - pthread_mutex_unlock(&debug_timing_lock); - char *basec = strdup(thefilename); - char *filename = basename(basec); - s = generate_preliminary_string(b, sizeof(b), 1.0 * time_since_start / 1000000000, - 1.0 * time_since_last_debug_message / 1000000000, filename, - linenumber, " *warning: "); - free(basec); - } else { - strncpy(b, "warning: ", sizeof(b)); - s = b + strlen(b); - } - va_list args; - va_start(args, format); - vsnprintf(s, sizeof(b) - (s - b), format, args); - va_end(args); - sps_log(LOG_WARNING, "%s", b); - pthread_setcancelstate(oldState, NULL); -} - void getErrorText(char *destinationString, size_t destinationStringLength) { #pragma GCC diagnostic push #pragma GCC diagnostic ignored "-Wunused-result" @@ -626,96 +533,6 @@ void getErrorText(char *destinationString, size_t destinationStringLength) { #pragma GCC diagnostic pop } -void _debug(const char *thefilename, const int linenumber, int level, const char *format, ...) { - if (level > debuglev) - return; - int oldState; - pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); - - char b[16384]; - b[0] = 0; - pthread_mutex_lock(&debug_timing_lock); - uint64_t time_now = get_absolute_time_in_ns(); - uint64_t time_since_start = time_now - ns_time_at_startup; - uint64_t time_since_last_debug_message = time_now - ns_time_at_last_debug_message; - ns_time_at_last_debug_message = time_now; - pthread_mutex_unlock(&debug_timing_lock); - char *basec = strdup(thefilename); - char *filename = basename(basec); - char *s = generate_preliminary_string(b, sizeof(b), 1.0 * time_since_start / 1000000000, - 1.0 * time_since_last_debug_message / 1000000000, filename, - linenumber, " "); - free(basec); - va_list args; - va_start(args, format); - vsnprintf(s, sizeof(b) - (s - b), format, args); - va_end(args); - sps_log(LOG_INFO, b); // LOG_DEBUG is hard to read on macOS terminal - pthread_setcancelstate(oldState, NULL); -} - -void _inform(const char *thefilename, const int linenumber, const char *format, ...) { - int oldState; - pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); - char b[16384]; - b[0] = 0; - char *s; - if (debuglev) { - pthread_mutex_lock(&debug_timing_lock); - uint64_t time_now = get_absolute_time_in_ns(); - uint64_t time_since_start = time_now - ns_time_at_startup; - uint64_t time_since_last_debug_message = time_now - ns_time_at_last_debug_message; - ns_time_at_last_debug_message = time_now; - pthread_mutex_unlock(&debug_timing_lock); - char *basec = strdup(thefilename); - char *filename = basename(basec); - s = generate_preliminary_string(b, sizeof(b), 1.0 * time_since_start / 1000000000, - 1.0 * time_since_last_debug_message / 1000000000, filename, - linenumber, " "); - free(basec); - } else { - s = b; - } - va_list args; - va_start(args, format); - vsnprintf(s, sizeof(b) - (s - b), format, args); - va_end(args); - sps_log(LOG_INFO, "%s", b); - pthread_setcancelstate(oldState, NULL); -} - -void _debug_print_buffer(const char *thefilename, const int linenumber, int level, void *vbuf, - size_t buf_len) { - if (level > debuglev) - return; - char *buf = (char *)vbuf; - char *obf = - malloc(buf_len * 4 + 1); // to be on the safe side -- 4 characters on average for each byte - if (obf != NULL) { - char *obfp = obf; - unsigned int obfc; - for (obfc = 0; obfc < buf_len; obfc++) { - snprintf(obfp, 3, "%02X", buf[obfc]); - obfp += 2; - if (obfc != buf_len - 1) { - if (obfc % 32 == 31) { - snprintf(obfp, 5, " || "); - obfp += 4; - } else if (obfc % 16 == 15) { - snprintf(obfp, 4, " | "); - obfp += 3; - } else if (obfc % 4 == 3) { - snprintf(obfp, 2, " "); - obfp += 1; - } - } - }; - *obfp = 0; - _debug(thefilename, linenumber, level, "%s", obf); - free(obf); - } -} - // The following two functions are adapted slightly and with thanks from Jonathan Leffler's sample // code at // https://stackoverflow.com/questions/675039/how-can-i-create-directory-tree-in-c-linux @@ -2039,7 +1856,7 @@ int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time) { int _debug_mutex_lock(pthread_mutex_t *mutex, useconds_t dally_time, const char *mutexname, const char *filename, const int line, int debuglevel) { - if ((debuglevel > debuglev) || (debuglevel == 0)) + if ((debuglevel > debug_level()) || (debuglevel == 0)) return pthread_mutex_lock(mutex); int oldState; pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); @@ -2064,7 +1881,7 @@ int _debug_mutex_lock(pthread_mutex_t *mutex, useconds_t dally_time, const char int _debug_mutex_unlock(pthread_mutex_t *mutex, const char *mutexname, const char *filename, const int line, int debuglevel) { - if ((debuglevel > debuglev) || (debuglevel == 0)) + if ((debuglevel > debug_level()) || (debuglevel == 0)) return pthread_mutex_unlock(mutex); int oldState; pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); diff --git a/common.h b/common.h index 2761915d..531f7f78 100644 --- a/common.h +++ b/common.h @@ -545,7 +545,7 @@ 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; +// extern uint64_t ns_time_at_startup, ns_time_at_last_debug_message; // this is for reading an unsigned 32 bit number, such as an RTP timestamp diff --git a/dbus-service.c b/dbus-service.c index f3b4066b..e2b970d1 100644 --- a/dbus-service.c +++ b/dbus-service.c @@ -516,13 +516,13 @@ gboolean notify_verbosity_callback(ShairportSyncDiagnostics *skeleton, if ((th >= 0) && (th <= 3)) { if (th == 0) debug(1, ">> set log verbosity to %d.", th); - if (((debuglev == 0) && (th != 0)) || ((debuglev != 0) && (th == 0))) + if (((debug_level() == 0) && (th != 0)) || ((debug_level() != 0) && (th == 0))) statistics_row = 0; // if the debug level changes, redraw the header line - debuglev = th; + set_debug_level(th); debug(1, ">> set log verbosity to %d.", th); } else { debug(1, ">> invalid log verbosity: %d. Ignored.", th); - shairport_sync_diagnostics_set_verbosity(skeleton, debuglev); + shairport_sync_diagnostics_set_verbosity(skeleton, debug_level()); } return TRUE; } @@ -1163,7 +1163,7 @@ static void on_dbus_name_acquired(GDBusConnection *connection, const gchar *name free(vs); shairport_sync_diagnostics_set_verbosity( - SHAIRPORT_SYNC_DIAGNOSTICS(shairportSyncDiagnosticsSkeleton), debuglev); + SHAIRPORT_SYNC_DIAGNOSTICS(shairportSyncDiagnosticsSkeleton), debug_level()); // debug(2,">> log verbosity is %d.",debuglev); diff --git a/debug.c b/debug.c new file mode 100644 index 00000000..0aa21689 --- /dev/null +++ b/debug.c @@ -0,0 +1,277 @@ +/* +MIT License + +Copyright (c) 2023--2025 Mike Brady 4265913+mikebrady@users.noreply.github.com + +Permission is hereby granted, free of charge, to any person obtaining a copy +of this software and associated documentation files (the "Software"), to deal +in the Software without restriction, including without limitation the rights +to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +copies of the Software, and to permit persons to whom the Software is +furnished to do so, subject to the following conditions: + +The above copyright notice and this permission notice shall be included in all +copies or substantial portions of the Software. + +THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE +SOFTWARE. +*/ + +#include "debug.h" +#include +#include +#include +#include +#include +#include +#include +#include + +static int debuglev = 0; +int debugger_show_elapsed_time = 0; +int debugger_show_relative_time = 0; +int debugger_show_file_and_line = 1; + +static uint64_t ns_time_at_startup = 0; +static uint64_t ns_time_at_last_debug_message; + +// always lock use this when accessing the ns_time_at_last_debug_message +static pthread_mutex_t debug_timing_lock = PTHREAD_MUTEX_INITIALIZER; + +uint64_t debug_get_absolute_time_in_ns() { + uint64_t time_now_ns; + struct timespec tn; + // 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; +} + +void debug_init(int level, int show_elapsed_time, int show_relative_time, int show_file_and_line) { + ns_time_at_startup = debug_get_absolute_time_in_ns(); + ns_time_at_last_debug_message = ns_time_at_startup; + debuglev = level; + debugger_show_elapsed_time = show_elapsed_time; + debugger_show_relative_time = show_relative_time; + debugger_show_file_and_line = show_file_and_line; +} + +int debug_level() { + return debuglev; +}; + +void set_debug_level(int level) { + debuglev = level; +} + +void increase_debug_level() { + if (debuglev < 3) + debuglev++; +} + +void decrease_debug_level() { + if (debuglev > 0) + debuglev--; +} + +int get_show_elapsed_time() { + return debugger_show_elapsed_time; + +} +void set_show_elapsed_time(int setting) { + debugger_show_elapsed_time = setting; +} +int get_show_relative_timel() { + return debugger_show_relative_time; +} + +void set_show_relative_time(int setting) { + debugger_show_relative_time = setting; +} + +int get_show_file_and_line() { + return debugger_show_file_and_line; +} + +void set_show_file_and_line(int setting) { + debugger_show_file_and_line = setting; +} + +char *generate_preliminary_string(char *buffer, size_t buffer_length, double tss, double tsl, + const char *filename, const int linenumber, const char *prefix) { + size_t space_remaining = buffer_length; + char *insertion_point = buffer; + if (debugger_show_elapsed_time) { + snprintf(insertion_point, space_remaining, "% 20.9f", tss); + insertion_point = insertion_point + strlen(insertion_point); + space_remaining = space_remaining - strlen(insertion_point); + } + if (debugger_show_relative_time) { + snprintf(insertion_point, space_remaining, "% 20.9f", tsl); + insertion_point = insertion_point + strlen(insertion_point); + space_remaining = space_remaining - strlen(insertion_point); + } + if (debugger_show_file_and_line) { + snprintf(insertion_point, space_remaining, " \"%s:%d\"", filename, linenumber); + insertion_point = insertion_point + strlen(insertion_point); + space_remaining = space_remaining - strlen(insertion_point); + } + if (prefix) { + snprintf(insertion_point, space_remaining, "%s", prefix); + insertion_point = insertion_point + strlen(insertion_point); + space_remaining = space_remaining - strlen(insertion_point); + } + return insertion_point; +} + +void _die(const char *filename, const int linenumber, const char *format, ...) { + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); + char b[1024]; + b[0] = 0; + char *s; + if (debuglev) { + pthread_mutex_lock(&debug_timing_lock); + uint64_t time_now = debug_get_absolute_time_in_ns(); + uint64_t time_since_start = time_now - ns_time_at_startup; + uint64_t time_since_last_debug_message = time_now - ns_time_at_last_debug_message; + ns_time_at_last_debug_message = time_now; + pthread_mutex_unlock(&debug_timing_lock); + s = generate_preliminary_string(b, sizeof(b), 1.0 * time_since_start / 1000000000, + 1.0 * time_since_last_debug_message / 1000000000, filename, + linenumber, " *fatal error: "); + } else { + strncpy(b, "fatal error: ", sizeof(b)); + s = b + strlen(b); + } + va_list args; + va_start(args, format); + vsnprintf(s, sizeof(b) - (s - b), format, args); + va_end(args); + // syslog(LOG_ERR, "%s", b); + fprintf(stderr, "%s\n", b); + pthread_setcancelstate(oldState, NULL); + exit(EXIT_FAILURE); +} + +void _warn(const char *filename, const int linenumber, const char *format, ...) { + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); + char b[1024]; + b[0] = 0; + char *s; + if (debuglev) { + pthread_mutex_lock(&debug_timing_lock); + uint64_t time_now = debug_get_absolute_time_in_ns(); + uint64_t time_since_start = time_now - ns_time_at_startup; + uint64_t time_since_last_debug_message = time_now - ns_time_at_last_debug_message; + ns_time_at_last_debug_message = time_now; + pthread_mutex_unlock(&debug_timing_lock); + s = generate_preliminary_string(b, sizeof(b), 1.0 * time_since_start / 1000000000, + 1.0 * time_since_last_debug_message / 1000000000, filename, + linenumber, " *warning: "); + } else { + strncpy(b, "warning: ", sizeof(b)); + s = b + strlen(b); + } + va_list args; + va_start(args, format); + vsnprintf(s, sizeof(b) - (s - b), format, args); + va_end(args); + // syslog(LOG_WARNING, "%s", b); + fprintf(stderr, "%s\n", b); + pthread_setcancelstate(oldState, NULL); +} + +void _debug(const char *filename, const int linenumber, int level, const char *format, ...) { + if (level > debuglev) + return; + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); + char b[1024]; + b[0] = 0; + pthread_mutex_lock(&debug_timing_lock); + uint64_t time_now = debug_get_absolute_time_in_ns(); + uint64_t time_since_start = time_now - ns_time_at_startup; + uint64_t time_since_last_debug_message = time_now - ns_time_at_last_debug_message; + ns_time_at_last_debug_message = time_now; + pthread_mutex_unlock(&debug_timing_lock); + char *s = generate_preliminary_string(b, sizeof(b), 1.0 * time_since_start / 1000000000, + 1.0 * time_since_last_debug_message / 1000000000, filename, + linenumber, " "); + va_list args; + va_start(args, format); + vsnprintf(s, sizeof(b) - (s - b), format, args); + va_end(args); + // syslog(LOG_DEBUG, "%s", b); + fprintf(stderr, "%s\n", b); + pthread_setcancelstate(oldState, NULL); +} + +void _inform(const char *filename, const int linenumber, const char *format, ...) { + int oldState; + pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); + char b[1024]; + b[0] = 0; + char *s; + if (debuglev) { + pthread_mutex_lock(&debug_timing_lock); + uint64_t time_now = debug_get_absolute_time_in_ns(); + uint64_t time_since_start = time_now - ns_time_at_startup; + uint64_t time_since_last_debug_message = time_now - ns_time_at_last_debug_message; + ns_time_at_last_debug_message = time_now; + pthread_mutex_unlock(&debug_timing_lock); + s = generate_preliminary_string(b, sizeof(b), 1.0 * time_since_start / 1000000000, + 1.0 * time_since_last_debug_message / 1000000000, filename, + linenumber, " "); + } else { + s = b; + } + va_list args; + va_start(args, format); + vsnprintf(s, sizeof(b) - (s - b), format, args); + va_end(args); + // syslog(LOG_INFO, "%s", b); + fprintf(stderr, "%s\n", b); + pthread_setcancelstate(oldState, NULL); +} + +void _debug_print_buffer(const char *thefilename, const int linenumber, int level, void *vbuf, + size_t buf_len) { + if (level > debuglev) + return; + char *buf = (char *)vbuf; + char *obf = + malloc(buf_len * 4 + 1); // to be on the safe side -- 4 characters on average for each byte + if (obf != NULL) { + char *obfp = obf; + unsigned int obfc; + for (obfc = 0; obfc < buf_len; obfc++) { + snprintf(obfp, 3, "%02X", buf[obfc]); + obfp += 2; + if (obfc != buf_len - 1) { + if (obfc % 32 == 31) { + snprintf(obfp, 5, " || "); + obfp += 4; + } else if (obfc % 16 == 15) { + snprintf(obfp, 4, " | "); + obfp += 3; + } else if (obfc % 4 == 3) { + snprintf(obfp, 2, " "); + obfp += 1; + } + } + }; + *obfp = 0; + _debug(thefilename, linenumber, level, "%s", obf); + free(obf); + } +} \ No newline at end of file diff --git a/debug.h b/debug.h new file mode 100644 index 00000000..9ba21e95 --- /dev/null +++ b/debug.h @@ -0,0 +1,67 @@ +/* +MIT License + +Copyright (c) 2023--2025 Mike Brady 4265913+mikebrady@users.noreply.github.com + +Permission is hereby granted, free of charge, to any person obtaining a copy +of this software and associated documentation files (the "Software"), to deal +in the Software without restriction, including without limitation the rights +to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +copies of the Software, and to permit persons to whom the Software is +furnished to do so, subject to the following conditions: + +The above copyright notice and this permission notice shall be included in all +copies or substantial portions of the Software. + +THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE +SOFTWARE. +*/ + +#ifndef __DEBUG_H +#define __DEBUG_H + +#include + +#ifdef __cplusplus +#define EXTERNC extern "C" +#else +#define EXTERNC +#endif + +// four level debug message utility giving file and line, total elapsed time, +// interval time warn / inform / debug / die calls. + +// level 0 is no messages, level 3 is most messages +EXTERNC void debug_init(int level, int show_elapsed_time, int show_relative_time, + int show_file_and_line); + +EXTERNC int debug_level(); +EXTERNC void set_debug_level(int level); +EXTERNC void increase_debug_level(); +EXTERNC void decrease_debug_level(); +EXTERNC int get_show_elapsed_time(); +EXTERNC void set_show_elapsed_time(int setting); +EXTERNC int get_show_relative_timel(); +EXTERNC void set_show_relative_time(int setting); +EXTERNC int get_show_file_and_line(); +EXTERNC void set_show_file_and_line(int setting); + +EXTERNC void _die(const char *filename, const int linenumber, const char *format, ...); +EXTERNC void _warn(const char *filename, const int linenumber, const char *format, ...); +EXTERNC void _inform(const char *filename, const int linenumber, const char *format, ...); +EXTERNC void _debug(const char *filename, const int linenumber, int level, const char *format, ...); +EXTERNC void _debug_print_buffer(const char *thefilename, const int linenumber, int level, + void *buf, size_t buf_len); + +#define die(...) _die(__FILE__, __LINE__, __VA_ARGS__) +#define debug(...) _debug(__FILE__, __LINE__, __VA_ARGS__) +#define warn(...) _warn(__FILE__, __LINE__, __VA_ARGS__) +#define inform(...) _inform(__FILE__, __LINE__, __VA_ARGS__) +#define debug_print_buffer(...) _debug_print_buffer(__FILE__, __LINE__, __VA_ARGS__) + +#endif /* __DEBUG_H */ \ No newline at end of file diff --git a/player.c b/player.c index 6462e5e1..f75d4301 100644 --- a/player.c +++ b/player.c @@ -3187,7 +3187,7 @@ int ap2_buffered_nodelay_stream_statistics_print_profile[] = {0, 0, 0, 0, 0, 0, // clang-format on void statistics_item(const char *heading, const char *format, ...) { - if (((statistics_print_profile[statistics_column] == 1) && (debuglev != 0)) || + if (((statistics_print_profile[statistics_column] == 1) && (debug_level() != 0)) || (statistics_print_profile[statistics_column] == 2)) { // include this column? if (was_a_previous_column != 0) { if (statistics_row == 0) diff --git a/rtp.c b/rtp.c index e763f2d9..9c0ddf57 100644 --- a/rtp.c +++ b/rtp.c @@ -2227,7 +2227,7 @@ void *buffered_tcp_reader(void *arg) { descriptor->error_code = errno; } else if (nread == 0) { descriptor->closed = 1; - debug(1, "buffered audio port closed. Terminating the buffered_tcp_reader thread."); + debug(1, "buffered audio port closed by remote end. Terminating the buffered_tcp_reader thread."); finished = 1; } else if (nread > 0) { descriptor->eoq += nread; diff --git a/rtsp.c b/rtsp.c index a101bdab..2563a13a 100644 --- a/rtsp.c +++ b/rtsp.c @@ -967,7 +967,7 @@ char *rtsp_plist_content(rtsp_message *message) { void _debug_log_rtsp_message(const char *filename, const int linenumber, int level, char *prompt, rtsp_message *message) { - if (level > debuglev) + if (level > debug_level()) return; if ((prompt) && (*prompt != '\0')) // okay to pass NULL or an empty list... _debug(filename, linenumber, level, prompt); @@ -2805,9 +2805,9 @@ void teardown_phase_two(rtsp_conn_info *conn) { void handle_teardown_2(rtsp_conn_info *conn, __attribute__((unused)) rtsp_message *req, rtsp_message *resp) { - debug(3, "Connection %d: TEARDOWN 2 %s.", conn->connection_number, + debug(2, "Connection %d: TEARDOWN 2 %s.", conn->connection_number, get_category_string(conn->airplay_stream_category)); - debug_log_rtsp_message(3, "TEARDOWN: ", req); + debug_log_rtsp_message(2, "TEARDOWN: ", req); resp->respcode = 200; msg_add_header(resp, "Connection", "close"); plist_t messagePlist = plist_from_rtsp_content(req); @@ -5331,7 +5331,7 @@ static void *rtsp_conversation_thread_func(void *pconn) { while (conn->stop == 0) { pthread_testcancel(); - int debug_level = 3; // for printing the request and response + int debug_level = 2; // for printing the request and response // check to see if a conn has been zeroed diff --git a/shairport.c b/shairport.c index 20cb0193..f1a9ed47 100644 --- a/shairport.c +++ b/shairport.c @@ -422,11 +422,10 @@ int parse_options(int argc, char **argv) { poptSetOtherOptionHelp(optCon, "[OPTIONS]* "); /* Now do options processing just to get a debug log destination and level */ - debuglev = 0; while ((c = poptGetNextOpt(optCon)) >= 0) { switch (c) { case 'v': - debuglev++; + increase_debug_level(); break; case 'u': inform("Warning: the option -u is no longer needed and is deprecated. Debug and statistics " @@ -807,7 +806,7 @@ int parse_options(int argc, char **argv) { warn("The \"general\" \"log_verbosity\" setting is deprecated. Please use the " "\"diagnostics\" \"log_verbosity\" setting instead."); if ((value >= 0) && (value <= 3)) - debuglev = value; + set_debug_level(value); else die("Invalid log verbosity setting option choice \"%d\". It should be between 0 and 3, " "inclusive.", @@ -817,7 +816,7 @@ int parse_options(int argc, char **argv) { /* Get the verbosity setting. */ if (config_lookup_int(config.cfg, "diagnostics.log_verbosity", &value)) { if ((value >= 0) && (value <= 3)) - debuglev = value; + set_debug_level(value); else die("Invalid diagnostics log_verbosity setting option choice \"%d\". It should be " "between 0 and 3, " @@ -1708,7 +1707,7 @@ int parse_options(int argc, char **argv) { #endif if (tdebuglev != 0) - debuglev = tdebuglev; + set_debug_level(tdebuglev); // now set the initial volume to the default volume config.airplay_volume = @@ -2268,6 +2267,10 @@ const char *av_channel_layout_name(uint64_t channel_layout) { #endif int main(int argc, char **argv) { + // initialise debug messages stuff -- level 1, no elapsed time, relative time, file and line + // the debug level will be reset to zero if no debug level is set + // debug_init(int level, int show_elapsed_time, int show_relative_time, int show_file_and_line) + debug_init(1, 0, 1, 1); memset(&config, 0, sizeof(config)); // also clears all strings, BTW /* Check if we are called with -V or --version parameter */ if (argc >= 2 && ((strcmp(argv[1], "-V") == 0) || (strcmp(argv[1], "--version") == 0))) { @@ -2298,7 +2301,7 @@ int main(int argc, char **argv) { #if LIBAVCODEC_VERSION_INT < AV_VERSION_INT(58, 9, 100) avcodec_register_all(); #endif - if (debuglev == 0) + if (debug_level() == 0) av_log_set_level(AV_LOG_ERROR); else av_log_set_level(AV_LOG_VERBOSE); @@ -2321,8 +2324,7 @@ int main(int argc, char **argv) { pid = getpid(); config.log_fd = -1; conns = NULL; // no connections active - ns_time_at_startup = get_absolute_time_in_ns(); - ns_time_at_last_debug_message = ns_time_at_startup; + #ifdef CONFIG_LIBDAEMON daemon_set_verbosity(LOG_DEBUG); @@ -2698,7 +2700,7 @@ int main(int argc, char **argv) { #endif - debug(2, "Log Verbosity is %d.", debuglev); + debug(2, "Log Verbosity is %d.", debug_level()); config.output = audio_get_output(config.output_name); if (!config.output) {