more flexible logging (#186)

* more flexible logging

* make log level int for callback

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)

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);

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);
 
 /**

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
 }

library/utils.c

@@ -17,7 +17,11 @@ limitations under the License.
 #include <uv.h>
 #include <uv_mbed/uv_mbed.h>
 #include <ziti/ziti_model.h>
+#include <ziti/ziti_log.h>
+#include <stdarg.h>
+
 #include "utils.h"
+
 #if _WIN32
 #include <time.h>
 #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() {

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);
 }

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,
     };
 

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);