From 9169bc10b9b6982b9a3ee156b65a3fdcd980989f Mon Sep 17 00:00:00 2001
From: Andrew Dona-Couch -- GitHub drop ICE <github@couchand.com>
Date: Mon, 31 Jan 2022 15:48:10 -0500
Subject: [PATCH] Make Librador logger configurable (#210)

* Refactor librador logging

* Make librador logger configurable
---
 .../librador_shared_library/librador.cpp      | 32 +++++++-
 .../librador_shared_library/librador.h        |  8 ++
 .../librador_shared_library/logging.h         | 11 +++
 .../logging_internal.h                        | 13 +++
 .../librador_shared_library/o1buffer.cpp      |  5 +-
 .../usbcallhandler.cpp                        | 81 ++++++++++---------
 6 files changed, 107 insertions(+), 43 deletions(-)
 create mode 100644 Librador_API/___librador/librador_shared_library/logging.h
 create mode 100644 Librador_API/___librador/librador_shared_library/logging_internal.h

diff --git a/Librador_API/___librador/librador_shared_library/librador.cpp b/Librador_API/___librador/librador_shared_library/librador.cpp
index 25dc2931..f748a164 100644
--- a/Librador_API/___librador/librador_shared_library/librador.cpp
+++ b/Librador_API/___librador/librador_shared_library/librador.cpp
@@ -1,6 +1,7 @@
 #include "librador.h"
 #include "librador_internal.h"
 #include "usbcallhandler.h"
+#include "logging_internal.h"
 
 #include <vector>
 #include <math.h>
@@ -94,7 +95,7 @@ std::vector<uint8_t> * librador_get_digital_data(int channel, double timeWindow_
     int delay_subsamples = round(delay_seconds * subsamples_per_second);
     int numToGet = round(timeWindow_seconds * subsamples_per_second)/interval_subsamples;
 
-    printf("interval_subsamples = %d\ndelay_subsamples = %d\nnumToGet=%d\n", interval_subsamples, delay_subsamples, numToGet);
+    LIBRADOR_LOG(LOG_DEBUG, "interval_subsamples = %d\ndelay_subsamples = %d\nnumToGet=%d\n", interval_subsamples, delay_subsamples, numToGet);
 
     return internal_librador_object->usb_driver->getMany_singleBit(channel, numToGet, interval_subsamples, delay_subsamples);
 }
@@ -295,3 +296,32 @@ int librador_synchronise_end(){
     return internal_librador_object->usb_driver->set_synchronous_pause_state(false);
 }
 */
+
+static void std_logger(void * userdata, const int level, const char * format, va_list ap);
+static librador_logger_p _librador_global_logger = std_logger;
+static void * _librador_global_userdata = NULL;
+
+void librador_global_logger(const int level, const char * format, ...){
+	va_list args;
+	va_start(args, format);
+	if (_librador_global_logger)
+		_librador_global_logger(_librador_global_userdata, level, format, args);
+	va_end(args);
+}
+
+void librador_logger_set(void * userdata, librador_logger_p logger){
+	_librador_global_logger = logger ? logger : std_logger;
+	_librador_global_userdata = userdata;
+}
+
+librador_logger_p librador_logger_get(void){
+	return _librador_global_logger;
+}
+
+void * librador_logger_get_userdata(void){
+	return _librador_global_userdata;
+}
+
+static void std_logger(void * userdata, const int level, const char * format, va_list ap){
+	vfprintf((level > LOG_ERROR) ?  stdout : stderr , format, ap);
+}
diff --git a/Librador_API/___librador/librador_shared_library/librador.h b/Librador_API/___librador/librador_shared_library/librador.h
index 657eb645..67f0d0d7 100644
--- a/Librador_API/___librador/librador_shared_library/librador.h
+++ b/Librador_API/___librador/librador_shared_library/librador.h
@@ -2,7 +2,9 @@
 #define LIBRADOR_H
 
 #include "librador_global.h"
+#include "logging.h"
 #include <vector>
+#include <stdarg.h>
 #include <stdint.h>
 
 int LIBRADORSHARED_EXPORT librador_init();
@@ -52,5 +54,11 @@ int LIBRADORSHARED_EXPORT librador_synchronise_begin();
 int LIBRADORSHARED_EXPORT librador_synchronise_end();
 */
 
+typedef void (*librador_logger_p)(void * userdata, const int level, const char * format, va_list);
+
+void LIBRADORSHARED_EXPORT librador_logger_set(void * userdata, librador_logger_p logger);
+librador_logger_p LIBRADORSHARED_EXPORT librador_logger_get(void);
+void * LIBRADORSHARED_EXPORT librador_logger_get_userdata(void);
+
 
 #endif // LIBRADOR_H
diff --git a/Librador_API/___librador/librador_shared_library/logging.h b/Librador_API/___librador/librador_shared_library/logging.h
new file mode 100644
index 00000000..972cfc17
--- /dev/null
+++ b/Librador_API/___librador/librador_shared_library/logging.h
@@ -0,0 +1,11 @@
+#ifndef LOGGING_H
+#define LOGGING_H
+
+enum {
+    LOG_NONE = 0,
+    LOG_ERROR,
+    LOG_WARNING,
+    LOG_DEBUG,
+};
+
+#endif // LOGGING_H
diff --git a/Librador_API/___librador/librador_shared_library/logging_internal.h b/Librador_API/___librador/librador_shared_library/logging_internal.h
new file mode 100644
index 00000000..4ac61902
--- /dev/null
+++ b/Librador_API/___librador/librador_shared_library/logging_internal.h
@@ -0,0 +1,13 @@
+#ifndef LOGGING_INTERNAL_H
+#define LOGGING_INTERNAL_H
+
+#include "logging.h"
+
+#define LIBRADOR_LOG(level, ...) \
+    do { \
+        librador_global_logger(level, __VA_ARGS__); \
+    } while (0)
+
+void librador_global_logger(const int level, const char * format, ...);
+
+#endif // LOGGING_INTERNAL_H
diff --git a/Librador_API/___librador/librador_shared_library/o1buffer.cpp b/Librador_API/___librador/librador_shared_library/o1buffer.cpp
index 92e80f7b..8aa37fb0 100644
--- a/Librador_API/___librador/librador_shared_library/o1buffer.cpp
+++ b/Librador_API/___librador/librador_shared_library/o1buffer.cpp
@@ -1,4 +1,5 @@
 #include "o1buffer.h"
+#include "logging_internal.h"
 #include <stdio.h>
 #include <stdlib.h>
 #include <stdint.h>
@@ -34,7 +35,7 @@ void o1buffer::add(int value, int address){
         address = address % NUM_SAMPLES_PER_CHANNEL;
     }
     if(address<0){
-        fprintf(stderr, "ERROR: o1buffer::add was given a negative address\n");
+        LIBRADOR_LOG(LOG_ERROR, "ERROR: o1buffer::add was given a negative address\n");
     }
     //Assign the value
     buffer[address] = value;
@@ -88,7 +89,7 @@ int o1buffer::get(int address){
         address = address % NUM_SAMPLES_PER_CHANNEL;
     }
     if(address<0){
-        fprintf(stderr, "ERROR: o1buffer::get was given a negative address\n");
+        LIBRADOR_LOG(LOG_ERROR, "ERROR: o1buffer::get was given a negative address\n");
     }
     //Return the value
     return buffer[address];
diff --git a/Librador_API/___librador/librador_shared_library/usbcallhandler.cpp b/Librador_API/___librador/librador_shared_library/usbcallhandler.cpp
index 965ceb7c..43e02491 100644
--- a/Librador_API/___librador/librador_shared_library/usbcallhandler.cpp
+++ b/Librador_API/___librador/librador_shared_library/usbcallhandler.cpp
@@ -2,6 +2,7 @@
 #include <stdio.h>
 
 #include "o1buffer.h"
+#include "logging_internal.h"
 #include <mutex>
 #include <chrono>
 #include <thread>
@@ -88,20 +89,20 @@ static void LIBUSB_CALL isoCallback(struct libusb_transfer * transfer){
     if(usb_iso_needs_rearming()){
         int error = libusb_submit_transfer(transfer);
         if(error){
-            printf("Error re-arming the endpoint!\n");
+            LIBRADOR_LOG(LOG_DEBUG, "Error re-arming the endpoint!\n");
             begin_usb_thread_shutdown();
             decrement_remaining_transfers();
-            printf("Transfer not being rearmed!  %d armed transfers remaining\n", usb_shutdown_remaining_transfers);
+            LIBRADOR_LOG(LOG_WARNING, "Transfer not being rearmed!  %d armed transfers remaining\n", usb_shutdown_remaining_transfers);
         }
     } else {
         decrement_remaining_transfers();
-        printf("Transfer not being rearmed!  %d armed transfers remaining\n", usb_shutdown_remaining_transfers);
+        LIBRADOR_LOG(LOG_WARNING, "Transfer not being rearmed!  %d armed transfers remaining\n", usb_shutdown_remaining_transfers);
     }
     return;
 }
 
 void usb_polling_function(libusb_context *ctx){
-    printf("usb_polling_function thread spawned\n");
+    LIBRADOR_LOG(LOG_DEBUG, "usb_polling_function thread spawned\n");
     struct timeval tv;
     tv.tv_sec = 1;
     tv.tv_usec = 0;//ISO_PACKETS_PER_CTX*4000;
@@ -120,7 +121,7 @@ usbCallHandler::usbCallHandler(unsigned short VID_in, unsigned short PID_in)
 
     for(int k=0; k<NUM_ISO_ENDPOINTS; k++){
         pipeID[k] = 0x81+k;
-        printf("pipeID %d = %d\n", k, pipeID[k]);
+        LIBRADOR_LOG(LOG_DEBUG, "pipeID %d = %d\n", k, pipeID[k]);
     }
 
     internal_o1_buffer_375_CH1 = new o1buffer();
@@ -135,12 +136,12 @@ usbCallHandler::usbCallHandler(unsigned short VID_in, unsigned short PID_in)
 
 usbCallHandler::~usbCallHandler(){
     //Kill off usb_polling_thread.  Maybe join then get it to detect its own timeout condition.
-    printf("Calling destructor for librador USB call handler\n");
+    LIBRADOR_LOG(LOG_DEBUG, "Calling destructor for librador USB call handler\n");
     begin_usb_thread_shutdown();
 
-    printf("Shutting down USB polling thread...\n");
+    LIBRADOR_LOG(LOG_DEBUG, "Shutting down USB polling thread...\n");
     usb_polling_thread->join();
-    printf("USB polling thread stopped.\n");
+    LIBRADOR_LOG(LOG_DEBUG, "USB polling thread stopped.\n");
     delete usb_polling_thread;
 
     for (int i=0; i<NUM_FUTURE_CTX; i++){
@@ -148,58 +149,58 @@ usbCallHandler::~usbCallHandler(){
             libusb_free_transfer(isoCtx[k][i]);
         }
     }
-    printf("Transfers freed.\n");
+    LIBRADOR_LOG(LOG_DEBUG, "Transfers freed.\n");
 
     if(handle != NULL){
     libusb_release_interface(handle, 0);
-        printf("Interface released\n");
+        LIBRADOR_LOG(LOG_DEBUG, "Interface released\n");
         libusb_close(handle);
-        printf("Device Closed\n");
+        LIBRADOR_LOG(LOG_DEBUG, "Device Closed\n");
     }
     if(ctx != NULL){
         libusb_exit(ctx);
-        printf("Libusb exited\n");
+        LIBRADOR_LOG(LOG_DEBUG, "Libusb exited\n");
     }
 
-    printf("librador USB call handler deleted\n");
+    LIBRADOR_LOG(LOG_DEBUG, "librador USB call handler deleted\n");
 }
 
 
 int usbCallHandler::setup_usb_control(){
-    printf("usbCallHandler::setup_usb_control()\n");
+    LIBRADOR_LOG(LOG_DEBUG, "usbCallHandler::setup_usb_control()\n");
 
     if(ctx != NULL){
-        printf("There is already a libusb context!\n");
+        LIBRADOR_LOG(LOG_ERROR, "There is already a libusb context!\n");
         return 1;
-    } else printf("libusb context is null\n");
+    } else LIBRADOR_LOG(LOG_WARNING, "libusb context is null\n");
 
     //Initialise the Library
     int error;
     error = libusb_init(&ctx);
     if(error){
-        printf("libusb_init FAILED\n");
+        LIBRADOR_LOG(LOG_ERROR, "libusb_init FAILED\n");
         return -1;
-    } else printf("Libusb context initialised\n");
+    } else LIBRADOR_LOG(LOG_DEBUG, "Libusb context initialised\n");
     libusb_set_debug(ctx, 3);
 
     //Get a handle on the Labrador device
     handle = libusb_open_device_with_vid_pid(ctx, VID, PID);
     if(handle==NULL){
-        printf("DEVICE NOT FOUND\n");
+        LIBRADOR_LOG(LOG_ERROR, "DEVICE NOT FOUND\n");
         libusb_exit(ctx);
         ctx = NULL;
         return -2;
     }
-    printf("Device found!!\n");
+    LIBRADOR_LOG(LOG_DEBUG, "Device found!!\n");
 
     //Claim the interface
     error = libusb_claim_interface(handle, 0);
     if(error){
-        printf("libusb_claim_interface FAILED\n");
+        LIBRADOR_LOG(LOG_ERROR, "libusb_claim_interface FAILED\n");
         libusb_close(handle);
         handle = NULL;
         return -3;
-    } else printf("Interface claimed!\n");
+    } else LIBRADOR_LOG(LOG_DEBUG, "Interface claimed!\n");
 /*
     error = libusb_set_interface_alt_setting(handle, 0, 0);
     if(error){
@@ -219,7 +220,7 @@ int usbCallHandler::setup_usb_control(){
 
 int usbCallHandler::setup_usb_iso(){
     int error;
-    printf("usbCallHandler::setup_usb_iso()\n");
+    LIBRADOR_LOG(LOG_DEBUG, "usbCallHandler::setup_usb_iso()\n");
 
     for(int n=0;n<NUM_FUTURE_CTX;n++){
         for (unsigned char k=0;k<NUM_ISO_ENDPOINTS;k++){
@@ -228,7 +229,7 @@ int usbCallHandler::setup_usb_iso(){
             libusb_set_iso_packet_lengths(isoCtx[k][n], ISO_PACKET_SIZE);
             error = libusb_submit_transfer(isoCtx[k][n]);
             if(error){
-                printf("libusb_submit_transfer #%d:%d FAILED with error %d %s\n", n, k, error, libusb_error_name(error));
+                LIBRADOR_LOG(LOG_ERROR, "libusb_submit_transfer #%d:%d FAILED with error %d %s\n", n, k, error, libusb_error_name(error));
                 return error;
             }
         }
@@ -242,7 +243,7 @@ int usbCallHandler::send_control_transfer(uint8_t RequestType, uint8_t Request,
     unsigned char *controlBuffer;
 
     if(!connected){
-        printf("Control packet requested before device has connected!\n");
+        LIBRADOR_LOG(LOG_ERROR, "Control packet requested before device has connected!\n");
         return -1;
     }
 
@@ -253,7 +254,7 @@ int usbCallHandler::send_control_transfer(uint8_t RequestType, uint8_t Request,
 
     int error = libusb_control_transfer(handle, RequestType, Request, Value, Index, controlBuffer, Length, 4000);
     if(error<0){
-        printf("send_control_transfer FAILED with error %s", libusb_error_name(error));
+        LIBRADOR_LOG(LOG_ERROR, "send_control_transfer FAILED with error %s", libusb_error_name(error));
         return error - 100;
     }
     /*
@@ -270,7 +271,7 @@ int usbCallHandler::send_control_transfer(uint8_t RequestType, uint8_t Request,
 int usbCallHandler::avrDebug(void){
     send_control_transfer_with_error_checks(0xc0, 0xa0, 0, 0, sizeof(unified_debug), NULL);
 
-    printf("unified debug is of size %lu\n", sizeof(unified_debug));
+    LIBRADOR_LOG(LOG_DEBUG, "unified debug is of size %lu\n", sizeof(unified_debug));
 
     unified_debug *udsPtr = (unified_debug *) inBuffer;
     uint16_t trfcnt0 = (udsPtr->trfcntH0 << 8) + udsPtr->trfcntL0;
@@ -281,18 +282,18 @@ int usbCallHandler::avrDebug(void){
     uint16_t dma_ch0_cnt = (udsPtr->dma_ch0_cntH << 8) + udsPtr->dma_ch0_cntL;
     uint16_t dma_ch1_cnt = (udsPtr->dma_ch1_cntH << 8) + udsPtr->dma_ch1_cntL;
 
-    printf("%s", udsPtr->header);
-    printf("trfcnt0 = %d\n", trfcnt0);
-    printf("trfcnt1 = %d\n", trfcnt1);
-    printf("medianTrfcnt = %d\n", medianTrfcnt);
-    printf("outOfRange = %d\n", outOfRange);
-    printf("counter = %d\n", counter);
-    printf("calValNeg = %d\n", udsPtr->calValNeg);
-    printf("calValPos = %d\n", udsPtr->calValPos);
-    printf("CALA = %d\n", udsPtr->CALA);
-    printf("CALB = %d\n", udsPtr->CALB);
-    printf("dma_ch0_cnt = %d\n", dma_ch0_cnt);
-    printf("dma_ch1_cnt = %d\n", dma_ch1_cnt);
+    LIBRADOR_LOG(LOG_DEBUG, "%s", udsPtr->header);
+    LIBRADOR_LOG(LOG_DEBUG, "trfcnt0 = %d\n", trfcnt0);
+    LIBRADOR_LOG(LOG_DEBUG, "trfcnt1 = %d\n", trfcnt1);
+    LIBRADOR_LOG(LOG_DEBUG, "medianTrfcnt = %d\n", medianTrfcnt);
+    LIBRADOR_LOG(LOG_DEBUG, "outOfRange = %d\n", outOfRange);
+    LIBRADOR_LOG(LOG_DEBUG, "counter = %d\n", counter);
+    LIBRADOR_LOG(LOG_DEBUG, "calValNeg = %d\n", udsPtr->calValNeg);
+    LIBRADOR_LOG(LOG_DEBUG, "calValPos = %d\n", udsPtr->calValPos);
+    LIBRADOR_LOG(LOG_DEBUG, "CALA = %d\n", udsPtr->CALA);
+    LIBRADOR_LOG(LOG_DEBUG, "CALB = %d\n", udsPtr->CALB);
+    LIBRADOR_LOG(LOG_DEBUG, "dma_ch0_cnt = %d\n", dma_ch0_cnt);
+    LIBRADOR_LOG(LOG_DEBUG, "dma_ch1_cnt = %d\n", dma_ch1_cnt);
 
     return 0;
 }
@@ -404,7 +405,7 @@ int usbCallHandler::set_gain(double newGain){
     else if (newGain == 32) gainMask = 0x05;
     else if (newGain == 64) gainMask = 0x06;
     else{
-      printf("Invalid gain value.  Valid values are 0.1, 1, 2, 4, 8, 16, 32, 64\n");
+      LIBRADOR_LOG(LOG_ERROR, "Invalid gain value.  Valid values are 0.1, 1, 2, 4, 8, 16, 32, 64\n");
       return -1;
     }