From 1bbc8080d1465e5d9868cdc1e989f9d3cb5e360f Mon Sep 17 00:00:00 2001 From: ekoby <7406535+ekoby@users.noreply.github.com> Date: Fri, 27 Nov 2020 11:58:07 -0500 Subject: [PATCH] more flexible logging (#186) * more flexible logging * make log level int for callback --- deps/CMakeLists.txt | 2 +- inc_internal/ziti_ctrl.h | 8 +- includes/ziti/ziti.h | 6 +- includes/ziti/ziti_log.h | 17 +++-- library/utils.c | 77 ++++++++++++++++++-- library/ziti.c | 3 - library/ziti_ctrl.c | 30 ++++---- programs/sample_http_link/sample_http_link.c | 2 - 8 files changed, 105 insertions(+), 40 deletions(-) diff --git a/deps/CMakeLists.txt b/deps/CMakeLists.txt index b2211b96..6b0a07a2 100644 --- a/deps/CMakeLists.txt +++ b/deps/CMakeLists.txt @@ -4,7 +4,7 @@ include(FetchContent) FetchContent_Declare(uv-mbed GIT_REPOSITORY https://github.com/netfoundry/uv-mbed.git - GIT_TAG v0.9.1 + GIT_TAG v0.9.2 ) set(ENABLE_UM_TESTS OFF CACHE BOOL "" FORCE) FetchContent_MakeAvailable(uv-mbed) diff --git a/inc_internal/ziti_ctrl.h b/inc_internal/ziti_ctrl.h index 5085e7f9..c1ccec02 100644 --- a/inc_internal/ziti_ctrl.h +++ b/inc_internal/ziti_ctrl.h @@ -73,15 +73,17 @@ void ziti_ctrl_pr_post_domain(ziti_controller *ctrl, char *id, char *domain, void (*cb)(void *, ziti_error *, void *), void *ctx); -void ziti_ctrl_pr_post_mac(ziti_controller *ctrl, char *id, char **mac_addresses, int num_addresses, +void ziti_ctrl_pr_post_mac(ziti_controller *ctrl, const char *id, char **mac_addresses, int num_addresses, void (*cb)(void *, ziti_error *, void *), void *ctx); -void ziti_ctrl_pr_post_os(ziti_controller *ctrl, char *id, char *os_type, char *os_version, char *os_build, +void ziti_ctrl_pr_post_os(ziti_controller *ctrl, const char *id, const char *os_type, const char *os_version, + const char *os_build, void (*cb)(void *, ziti_error *, void *), void *ctx); -void ziti_ctrl_pr_post_process(ziti_controller *ctrl, char *id, bool is_running, char *sha_512_hash, char **signers, +void ziti_ctrl_pr_post_process(ziti_controller *ctrl, const char *id, bool is_running, const char *sha_512_hash, + char **signers, int num_signers, void (*cb)(void *, ziti_error *, void *), void *ctx); diff --git a/includes/ziti/ziti.h b/includes/ziti/ziti.h index dd210c1c..e6116fa4 100644 --- a/includes/ziti/ziti.h +++ b/includes/ziti/ziti.h @@ -39,12 +39,12 @@ extern "C" { /** * Flag indicating service `Dial` permission */ -#define ZITI_CAN_DIAL 1 +#define ZITI_CAN_DIAL 1U /** * Flag indicating service `Bind` permission */ -#define ZITI_CAN_BIND 2 +#define ZITI_CAN_BIND 2U /** * The default timeout in milliseconds for connections and write operations to succeed. @@ -222,7 +222,7 @@ typedef void(*ziti_pr_process_cb)(ziti_context ztx, char *id, char *path, bool i * * @see ziti_pr_process_cb */ -typedef void (*ziti_pq_process_cb)(ziti_context ztx, char *id, char *path, +typedef void (*ziti_pq_process_cb)(ziti_context ztx, const char *id, const char *path, ziti_pr_process_cb response_cb); /** diff --git a/includes/ziti/ziti_log.h b/includes/ziti/ziti_log.h index 063beae3..4abff389 100644 --- a/includes/ziti/ziti_log.h +++ b/includes/ziti/ziti_log.h @@ -40,22 +40,23 @@ enum DebugLevel { }; #define ZITI_LOG(level, fmt, ...) do { \ -if (level <= ziti_debug_level) {\ - const char *elapsed = get_elapsed();\ - fprintf(ziti_debug_out, "[%s] " #level "\t" to_str(ZITI_LOG_PREFIX) ":%s:%d %s(): " fmt "\n",\ - elapsed, __FILENAME__, __LINE__, __func__, ##__VA_ARGS__);\ - }\ +if (level <= ziti_debug_level) { ziti_logger(level, __FILE__, __LINE__, __func__, fmt, ##__VA_ARGS__); }\ } while(0) #ifdef __cplusplus extern "C" { #endif -ZITI_FUNC extern const char* (*get_elapsed)(); +typedef void (*log_writer)(int level, const char *loc, const char *msg, size_t msglen); + +ZITI_FUNC extern void +ziti_logger(int level, const char *file, unsigned int line, const char *func, const char *fmt, ...); + ZITI_FUNC extern void init_debug(uv_loop_t *loop); -ZITI_FUNC extern void ziti_set_log(FILE *log, uv_loop_t *loop); + +ZITI_FUNC extern void ziti_set_log(log_writer log, uv_loop_t *loop); + ZITI_FUNC extern int ziti_debug_level; -ZITI_FUNC extern FILE *ziti_debug_out; #ifdef __cplusplus } diff --git a/library/utils.c b/library/utils.c index da0d2166..c35a0229 100644 --- a/library/utils.c +++ b/library/utils.c @@ -17,7 +17,11 @@ limitations under the License. #include #include #include +#include +#include + #include "utils.h" + #if _WIN32 #include #endif @@ -66,6 +70,12 @@ limitations under the License. #define ZITI_ARCH UKNOWN #endif +#define MAX_LOG_LINE (1024 * 2) + +#define LEVEL_LBL(lvl) #lvl, +static const char *const level_labels[] = { + DEBUG_LEVELS(LEVEL_LBL) +}; const char *ziti_get_build_version(int verbose) { if (verbose) { @@ -90,28 +100,38 @@ const char* ziti_git_commit() { } int ziti_debug_level = INFO; -FILE *ziti_debug_out; +static FILE *ziti_debug_out; static bool log_initialized = false; #if _WIN32 #define strcasecmp _stricmp #endif -const char* (*get_elapsed)(); +const char *(*get_elapsed)(); static const char *get_elapsed_time(); + static const char *get_utc_time(); +static void flush_log(uv_prepare_t *p); + +static void uv_mbed_logger(int level, const char *file, unsigned int line, const char *msg); + +static void default_log_writer(int level, const char *loc, const char *msg, size_t msglen); + static uv_loop_t *ts_loop; static uint64_t starttime; static uint64_t last_update; static char elapsed_buffer[32]; static uint64_t clock_offset; -void ziti_set_log(FILE *log, uv_loop_t *loop) { +static uv_prepare_t log_flusher; +static log_writer logger = default_log_writer; + +void ziti_set_log(log_writer log_func, uv_loop_t *loop) { init_debug(loop); - ziti_debug_out = log; - // uv_mbed_set_debug(ziti_debug_level, log); + uv_mbed_set_debug(ziti_debug_level, uv_mbed_logger); + logger = log_func; } void init_debug(uv_loop_t *loop) { @@ -130,12 +150,57 @@ void init_debug(uv_loop_t *loop) { ziti_debug_level = (int) strtol(level, NULL, 10); } ziti_debug_out = stderr; - //uv_mbed_set_debug(ziti_debug_level, ziti_debug_out); + uv_mbed_set_debug(ziti_debug_level, uv_mbed_logger); starttime = uv_now(loop); uv_timeval64_t clock; uv_gettimeofday(&clock); clock_offset = (clock.tv_sec * 1000 + clock.tv_usec / 1000) - starttime; // in millis + + uv_prepare_init(loop, &log_flusher); + uv_unref((uv_handle_t *) &log_flusher); + uv_prepare_start(&log_flusher, flush_log); +} + +void ziti_logger(int level, const char *file, unsigned int line, const char *func, const char *fmt, ...) { + static size_t loglinelen = 1024; + static char *logbuf; + + if (!logbuf) { logbuf = malloc(loglinelen); } + + va_list argp; + va_start(argp, fmt); + char location[128]; + if (func && func[0]) { + snprintf(location, sizeof(location), "%s:%d %s()", file, line, func); + } + else { + snprintf(location, sizeof(location), "%s:%d", file, line); + } + + int len = vsnprintf(logbuf, loglinelen, fmt, argp); + if (len > loglinelen) { + loglinelen = len + 1; + logbuf = realloc(logbuf, loglinelen); + vsnprintf(logbuf, loglinelen, fmt, argp); + } + + if (logger) { logger(level, location, logbuf, len); } +} + +static void default_log_writer(int level, const char *loc, const char *msg, size_t msglen) { + const char *elapsed = get_elapsed(); + fprintf(ziti_debug_out, "[%s] %7s %s ", elapsed, level_labels[level], loc); + fwrite(msg, 1, msglen, ziti_debug_out); + fputc('\n', ziti_debug_out); +} + +static void uv_mbed_logger(int level, const char *file, unsigned int line, const char *msg) { + ziti_logger(level, file, line, NULL, msg); +} + +static void flush_log(uv_prepare_t *p) { + fflush(ziti_debug_out); } static const char *get_elapsed_time() { diff --git a/library/ziti.c b/library/ziti.c index 1a55ff8a..32e5dc4a 100644 --- a/library/ziti.c +++ b/library/ziti.c @@ -710,7 +710,4 @@ static void grim_reaper(uv_prepare_t *p) { if (count > 0) { ZITI_LOG(INFO, "reaped %d closed (out of %d total) connections", count, total); } - - // flush ZITI_LOG once per loop iteration - fflush(ziti_debug_out); } \ No newline at end of file diff --git a/library/ziti_ctrl.c b/library/ziti_ctrl.c index c781b27c..a6e26085 100644 --- a/library/ziti_ctrl.c +++ b/library/ziti_ctrl.c @@ -549,7 +549,7 @@ void ziti_ctrl_pr_post_domain(ziti_controller *ctrl, char *id, char *domain, ziti_pr_domain_req domain_req = { .id = id, .domain = domain, - .typeId = PC_DOMAIN_TYPE, + .typeId = (char *) PC_DOMAIN_TYPE, }; char *body = malloc(1024); @@ -560,7 +560,7 @@ void ziti_ctrl_pr_post_domain(ziti_controller *ctrl, char *id, char *domain, ziti_pr_post(ctrl, body, body_len, cb, ctx); } -void ziti_ctrl_pr_post_mac(ziti_controller *ctrl, char *id, char **mac_addresses, int num_addresses, +void ziti_ctrl_pr_post_mac(ziti_controller *ctrl, const char *id, char **mac_addresses, int num_addresses, void (*cb)(void *, ziti_error *, void *), void *ctx) { @@ -570,8 +570,8 @@ void ziti_ctrl_pr_post_mac(ziti_controller *ctrl, char *id, char **mac_addresses memcpy(addresses, mac_addresses, (num_addresses) * arr_size); ziti_pr_mac_req mac_req = { - .id = id, - .typeId = PC_MAC_TYPE, + .id = (char *) id, + .typeId = (char *) PC_MAC_TYPE, .mac_addresses = addresses, }; @@ -585,15 +585,16 @@ void ziti_ctrl_pr_post_mac(ziti_controller *ctrl, char *id, char **mac_addresses free(addresses); } -void ziti_ctrl_pr_post_os(ziti_controller *ctrl, char *id, char *os_type, char *os_version, char *os_build, +void ziti_ctrl_pr_post_os(ziti_controller *ctrl, const char *id, const char *os_type, const char *os_version, + const char *os_build, void (*cb)(void *, ziti_error *, void *), void *ctx) { ziti_pr_os_req os_req = { - .id = id, - .typeId = PC_OS_TYPE, - .type = os_type, - .version = os_version, - .build = os_build + .id = (char *) id, + .typeId = (char *) PC_OS_TYPE, + .type = (char *) os_type, + .version = (char *) os_version, + .build = (char *) os_build }; char *body = malloc(1024); @@ -604,7 +605,8 @@ void ziti_ctrl_pr_post_os(ziti_controller *ctrl, char *id, char *os_type, char * ziti_pr_post(ctrl, body, body_len, cb, ctx); } -void ziti_ctrl_pr_post_process(ziti_controller *ctrl, char *id, bool is_running, char *sha_512_hash, char **signers, +void ziti_ctrl_pr_post_process(ziti_controller *ctrl, const char *id, bool is_running, const char *sha_512_hash, + char **signers, int num_signers, void (*cb)(void *, ziti_error *, void *), void *ctx) { @@ -614,10 +616,10 @@ void ziti_ctrl_pr_post_process(ziti_controller *ctrl, char *id, bool is_running, memcpy(null_term_signers, signers, num_signers * arr_size); ziti_pr_process_req process_req = { - .id = id, - .typeId = PC_PROCESS_TYPE, + .id = (char *) id, + .typeId = (char *) PC_PROCESS_TYPE, .is_running = is_running, - .hash = sha_512_hash, + .hash = (char *) sha_512_hash, .signers = null_term_signers, }; diff --git a/programs/sample_http_link/sample_http_link.c b/programs/sample_http_link/sample_http_link.c index 4f0e5c8d..59795669 100644 --- a/programs/sample_http_link/sample_http_link.c +++ b/programs/sample_http_link/sample_http_link.c @@ -77,8 +77,6 @@ int main(int argc, char** argv) { loop = uv_default_loop(); DIE(ziti_init(argv[1], loop, on_ziti_init, NULL)); - uv_mbed_set_debug(5, stdout); - // loop will finish after the request is complete and ziti_shutdown is called uv_run(loop, UV_RUN_DEFAULT);